Server-side logging per reflex action

[piotrwodz]

Type of PR (feature, enhancement, bug fix, etc.)

Feature

Description

Server-side logging per reflex action.

This PR adds:

• logger class responsible for printing a colorized log per reflex action (green - success / yellow - halted / red - error)
• stimulus reflex config initializer template
• generator for that template :point_up (usage: rails generate stimulus_reflex::config)
• config class handling specific user's configuration found in config/initializer/stimulus_reflex.rb (this class is initializing debugging and logging and defining accessors for them)
• logger attribute to reflex class
• finally invoking of logger after commiting session

Log message does not include a round-trip duration. Indeed, I am not sure how to know the exact exuction time. Any suggestions would be appreciated. Other than that, I covered all columns mentioned in the description of the issue.

Fixes #264

Why should this be added

Currently there is no server-side logging per reflex action. It would be nice to have one 👍

It's also a good compliment to shutting off the highly verbose ActionCable logs. This gives you the information you need, not a core memory dump.

Usage

This PR will install a default logging format that looks like this:

The developer can modify this Reflex log message format to their own taste. The message format can be redefined in the SR initializer by returning a String from a passed proc.

Available tokens:
session_id, session_id_full, reflex_info, operation, reflex_id, reflex_id_full, mode, selector, operation_counter, connection_id, connection_id_full, timestamp

Available colors:
red, green, yellow, blue, magenta, cyan, white.

Some examples of how a developer can define colorized Reflex log formats:

config.logging = proc { "[#{session_id}] #{operation_counter.magenta} #{reflex_info.green} -> #{selector.cyan} via #{mode} Morph (#{operation.yellow})" }

config.logging = proc { "[#{session_id}] #{operation_counter.magenta} #{reflex_info.green} -> #{selector.cyan} via #{mode} Morph" }

config.logging = proc { "[#{session_id_full}] Reflex with id #{reflex_id.blue} #{reflex_info.green} via (#{mode.yellow}) for #{connection.cyan} at #{timestamp.magenta}" }

Advanced usage allows specifying ActiveRecord attributes for objects in the list of ActionCable Connection identifiers. For example, let's say your Connection class has identified_by :current_user and this points to your applications User model. If your user is logged in and the User model has an email attribute, you could specify a logging format such as:

config.logging = proc { "#{reflex_info.green} -> #{selector.cyan} for #{email.red}" }

This will display the logged-in user's email address in red. If there is no user logged in, the logger will output -.

Checklist

• My code follows the style guidelines of this project
• Checks (StandardRB & Prettier-Standard) are passing

[marcoroth]

Thanks @piotrwodz for your contribution. I just left some comments.

The other thing I noticed: ActionCable logs two pretty long messages in between the server-side log entry you added. This makes it really hard to spot the reflex action log.

StimulusReflex::Channel#receive({"target"=>"FolderReflex#edit", "args"=>[], "url"=>"http://localhost:3000/", "attrs"=>{"class"=>"fa fa-pen btn btn-light", "data-reflex"=>"click->FolderReflex#edit", "data-reflex-dataset"=>"combined", "data-action"=>"click->folders#__perform", "checked"=>false, "selected"=>false, "tag_name"=>"I"}, "dataset"=>{"data-controller"=>"folders", "data-folder-id"=>"64", "data-reflex-root"=>"#folder_64", "data-reflex"=>"click->FolderReflex#edit", "data-reflex-dataset"=>"combined", "data-action"=>"click->folders#__perform"}, "selectors"=>["#folder_64"], "reflexId"=>"4425aa17-b097-4c22-b3a1-9f323e06beb4", "permanent_attribute_name"=>"data-reflex-permanent", "params"=>{}})

Folder Load (0.2ms)  SELECT "folders".* FROM "folders" WHERE "folders"."id" = $1 ORDER BY "folders"."name" ASC LIMIT $2  [["id", 64], ["LIMIT", 1]]
  ↳ app/reflexes/folder_reflex.rb:20:in `edit'
  Rendered application/_actions.html.erb (Duration: 0.0ms | Allocations: 9)
  Rendered application/_layout_switch.html.erb (Duration: 0.0ms | Allocations: 8)
  Rendered folders/_parent_folder.html.erb (Duration: 0.0ms | Allocations: 5)
  Rendered collection of folders/_item.html.erb [0 times] (Duration: 0.0ms | Allocations: 3)
  Rendered collection of documents/_item.html.erb [0 times] (Duration: 0.0ms | Allocations: 3)
  Rendered folders/_empty.html.erb (Duration: 0.0ms | Allocations: 5)
  Rendered folders/_folder.html.erb (Duration: 2.3ms | Allocations: 1353)
  Rendered application/_actions.html.erb (Duration: 0.0ms | Allocations: 9)


[ActionCable] Broadcasting to StimulusReflex::Channel:b7fe26c2a9926a4ae566789057e761c3: {"cableReady"=>true, "operations"=>{"morph"=>[{"selector"=>"#folder", "html"=>"[... a lot of html in here]", [...], "morph"=>:page}}]}}

StimulusReflex::Logger logging success for reflex action:
[b7fe26c2a9926a4ae566789057e761c3] LayoutReflex#set_layout (page: ##folder) for b7fe26c2a9926a4ae566789057e761c3 at 2020-10-26 00:08:57 +0100

StimulusReflex::Channel transmitting {"cableReady"=>true, "operations"=>{"morph"=>[{"selector"=>"#layout-switch", "html"=>"\n  <div class=\"btn-group\" role=\"group\" aria-label=\"Basic example\">\n    <button type=\"button\" data-reflex=\"click-&gt;LayoutReflex#set_layout\" data-layout=\"list\" id=\"layout-list\" class=\"btn btn-ou... (via streamed from StimulusReflex::Channel:b7fe26c2a9926a4ae566789057e761c3)

Do we have an option to manipulate that output and/or the order of them?

[leastbad]

Regarding the issue of initializers, I've asked @RolandStuder if he'd be willing to address this: https://discordapp.com/channels/629472241427415060/733725826411135107/770050840111087659

[piotrwodz]

Do we have an option to manipulate that output and/or the order of them?

@marcoroth The output of [ActionCable] Broadcasting can be manipulated. I am not sure about the output of StimulusReflex::Channel transmitting though.

Re changing the order: it just does not seem right to me. There are several operations happening on a reflex before its action is being logged. I would prefer not to change their order. In fact, some of these operations build reflex action log.

Personally, what I find verbose is the output of StimulusReflex::Channel#receive but I do not think it is a scope of this PR.

[piotrwodz]

@marcoroth On a second thought, all these long messages appearing around my reflex action log are verbose ☝️ Their output gets duplicated.

@leastbad What is your opinion on that? I would prefer improving these ActionCable messages in a separate PR.

[leastbad]

Hey @piotrwodz, I'm a bit fuzzy on the context in which you're referring to changing the order.

You could be talking about:

• which debug elements are displayed, in which order
• when the debug message is emitted, in relationship to the ActionCable message
• at what stage of the server-side Reflex processing do you want to emit the message

Help me drill down and I'll give you a better answer. :)

[piotrwodz]

@leastbad This is the context I was referring to. In particular whether it is possible to manipulate the output and/or the order of ActionCable messages.

[leastbad]

Hi @piotrwodz, I appreciate you allowing me the opportunity to express myself more clearly.

While I might not always have time/capacity to act (or even respond) to every conversation, the one thing I do do here is read everything that transpires, as carefully as I am able. The intention of my question, then, is that I'm feeling a bit lost when the topic of "order" comes up. Thanks to the ambiguity of technical language, the intentions expressed in this thread simply aren't as nakedly obvious as you believe that they are... hence me asking for clarification and why I suggested three possible interpretations. Unfortunately, pointing me to a message I'd already read doesn't fix this for me; it's like speaking slowly and loudly to someone who doesn't speak the same language. 😁

When I wrote the original issue, I had a vision for a solution where developers could craft their own debug message based on the information that they wanted to see. Front and center in this hope was that you could change the order in which the information was displayed by changing the the order in which the keys were specified. In the example cited:

[215a1c85] Example#hello in 8ms (selector: #notification) for "leastbad" at 2020-07-07 15:04:13

might be generated by:

config.logging = [:session, :reflex, :benchmark, :operation, :identifier, :timestamp]

while

2020-07-07 15:04:13 Example#hello for "leastbad"

would be generated by:

config.logging = [:timestamp, :reflex, :identifier]

Now, the subtle difference here is that in this example, there's no "at " before the timestamp... so that means we can adapt our little DSL to understand strings as well as symbols, perhaps:

config.logging = [:session, :reflex, :benchmark, :operation, :identifier, "at ", :timestamp]

or perhaps it makes more sense to express this as a string? I honestly don't know, but I was excited to have the conversation:

config.logging = ->(context) { "#{context.session} for #{context.identifier}" }

Awesome! Now, I also brought up the notion of using color. I see that you've run with setting a color for the whole line, which is a good start, but the main reason I'm excited for color is to break up the individual elements of a log line, making it far easier to parse in a log analyzer.

I can imagine defining color using both the array and lambda approaches:

config.logging = ->(context) { "#{context.session} for \e[1;32m#{context.identifier}" }

config.logging = [:timestamp, :reflex, "\e[1;32m", :identifier]

As for the relationship to the standard Rails ActionCable broadcast log line... it's [currently] my view that once you have AC/SR/CR setup and working properly in your application, you really don't need the noise of seeing a huge multi-line blob of text showing all of the attributes coming in OR the huge multi-line blob of text showing the CableReady operation hash data being sent back to the client. It was my hope that the single line debug we're discussing in this PR would become the preferred log output that you run with in production, and in development when nothing is going horribly wrong. That if you were actively debugging a problem with data not arriving as expected, you'd turn on the full debug and go over every detail.

So, with the above all said, the order in which this debug line appears in relationship to the standard ActionCable log blobs seems somewhat moot because they are really designed for different phases of the application development lifecycle.

Does that make sense?

Curious for your reaction to any/all of this.

[RolandStuder]

@piotrwodz #339 is merged, so you can now use the StimulusReflex.config, maybe you want rebase or merge and handle the conflicts, so @leastbad does not have to do it.

[leastbad]

💆‍♂️

[piotrwodz]

Hey @leastbad 👋 Thank you for your feedback. I find it valuable and I can see clearly where you are going with it. Let me attack mentioned aspects one by one:

1. Crafting debug message:
   Seems reasonable to me. Your examples provide more flexibility of a printed output. Indeed, developers might have different needs when it comes to what and how they want to see that output 👍
   I prefer to aim at:
   config.logging = %w[reflex session for identifier operation at timestamp]
   This is a mix of reflex-related strings (e.g. session, operation etc.) and custom strings in between them that can formulate a sentence together.
2. Colors:
   Indeed, I took a different approach here. My intention was to emphasize whether a reflex was successful, halted or with some errors. Hence, three colors used.
   Your suggestion of having a different color per log element (e.g. green for reflex, yellow for operation etc.) is achievable 👍 I like that array-based approach.
3. Relationship to the standard Rails ActionCable broadcast log line:
   Now you are talking! Muting standard verbose messaging completely and printing only the reflex log is an improvement. It can be controlled through debug configurable variable. I would like to give it a go 👍

[leastbad]

Awesome! I love it when a plan comes together.

Pretty much the only thing I'm a bit fuzzy on is your use of %w... what if I want to include the word "reflex" in my output? What if I want to insert non-alphanumeric characters like - or [braces]? I figured that an array of symbols and strings would immediately remove any ambiguity.

Can you think of a different approach that is similarly flexible?

[leastbad]

Hey @piotrwodz, I had originally hoped to get this into v3.4.0 but from my perspective, it makes more sense to spend some time on this over the next weeks and get it perfect. Do you agree?

[piotrwodz]

Hi @leastbad Sure thing! I am working towards the completion as we outlined above. It should be released once we are happy with the final implementation 👍

[RolandStuder]

I made a force push, if you want to work on this branch you should reset to the remote repo state:
https://www.scivision.dev/git-pull-after-force-push/

[leastbad]

I have just run git reset piotrwodz/logger-server-side --hard and nothing is on fire.

What is the status of the config_logger stuff you guys were discussing? I have had my eyes and brain elsewhere, but I'd like to be able to tell Nate that this branch could be merged...

[piotrwodz]

@leastbad I am going to incorporate what Roland and me discussed yesterday but I am out half a day today. Will take care of it in later hours. Hope you can wait for it!

[piotrwodz]

@leastbad @RolandStuder I think it is ready to go! 🚗 🚀

[RolandStuder]

I am doing some further learning. Im at my depths here. But I think we could get the API even down do
{"session_id".red}by using instance_eval we could then actually get rid of the method_missing stuff, and allow the lambda or prod to just access whatever is available in the Logger instance.

So I would propose to wait still a couple of days. I'll try to get it working today.

[leastbad]

Getting rid of the method_missing would undermine why I wrote it, wouldn't it? That is, I want to be able to access AR attributes on objects in the connection's identifiers.

[leastbad]

Also, just a meta observation: you guys might be taking something that was as good as done and thinking about it too much. I am going to re-read all of the comments again, but it's not at all clear to me what is being improved right now. I say this with kindness, not frustration; i just know it all seemed done on Friday, but now it somehow isn't anymore.

[piotrwodz]

@leastbad I agree.

FYI: the current state of this PR is the same as what we had on Friday. I am good to call it: done!

[leastbad]

Great work, @piotrwodz and @RolandStuder. I just tested it again and all looks good. I also added some words to the PR description. Hopefully @hopsoft will have some time to check it out soon.

[hopsoft]

Looks like we have a conflict. Happy to approve once resolved.