Add style guide for using after actions for logging

[tony-rowan]

What

Add a new rule that says we should use after_action callbacks to perform logging, rather than including it in the action itself or using a before_action.

Why

This is a style I've been following for a while after suggestion from our chapter lead and I often suggest it myself on PRs I review so I thought it would be good to bring it up to discuss and solidify it.

Anything else

Original discussion thread: https://github.com/cookpad/global-web/pull/33788#discussion_r1046661187

[tejanium]

I can see the benefit of doing "side-effect" outside of the method, but TBH, I personally don't like to have callback like this, because:

0. Similar to https://github.com/cookpad/global-style-guides/tree/main/rspec#avoid-using-context, I find it hard to jump the file up and down to discover what a method does. I'm fine if the before_action is something that applied to all actions so we don't repeat ourselves.

   context "when condition A" do
     before do
       # setup for condition A
     end
   
     it "does something a" do
       # ...
     end
   end
   
   ## Good
   it "does something a when condition A" do
     # setup for condition A
     # expect a
   end

1. It can be really awkward if we have a condition inside the method and need to have separate logging. Then we make an exception to the rule.

   def show
     if true
       log_true
     else
       log_false
     end
   end

2. Awkward, specific, and redundant naming and option https://github.com/cookpad/global-web/blob/2852a76c9bfcfec461053f4977e9b3f769268645/app/controllers/cookbooks_controller.rb#L3-L4

    before_action -> { log_index_visit_activity }, only: :index
    before_action -> { log_show_visit_activity }, only: :show

3. Easy-to-forget constraint that will make adding a new action in the controller risky https://github.com/cookpad/global-web/blob/2852a76c9bfcfec461053f4977e9b3f769268645/app/controllers/me/recipes_controller.rb#L3-L3

   diff --git a/foo_controller.rb b/foo_controller.rb
   index f17de70eb6..a9b3fa1132 100644
   --- a/foo_controller.rb
   +++ b/foo_controller.rb
   before_action :log_visit
   
   def show
     ...
   end
   
   +  def index
   +    ...
   +  end
   +

Having said that, if this is something we collectively agreed upon, I don't mind. 👍

[Bodacious]

I know it can be a bit tedious, but I tend to prefer avoiding callbacks that are specific to an action or just the actions within a controller.

Calling these in-line, rather than in a filter, provides greater clarity on what's being called when. It's clear what happens in happy path vs. sad path, etc.

I think when we see the pattern (before|after)_action :callback, only: (one-action)—with one action, it's a clear sign that the method call probably belongs in the controller action.

We also shouldn't think of logging as second-class work, even though it can seem repetitive. Defining it explicitly in the controller action keeps it at the same level of abstraction and importance as loading records from the DB, redirecting, etc.

[jesseclark]

I am in favor of this.

In the Snowplow logging implementation, I am using before_action to call the configuration methods that setup the data to be passed to the client for logging.

We have implemented Snowplow activity logging for Search related activities and screen view activities so far and there are only a few cases where we are setting contexts for multiple actions in the before_action calls but as we move into other sections of the app and start logging more activities related to user interactions with elements of the page, I expect this to increase.

Approaching this from the perspective of working towards complete logging coverage, I find it much easier to look at the block of before_actions and see what contexts and screen names are being set for which actions and to spot any that are missing and may still need logging to be implemented than to have to scroll through all of the actions and look for logging related methods sprinkled among the rest of the action code.

Regarding some of the other comment against this proposal:

It can be really awkward if we have a condition inside the method and need to have separate logging. Then we make an exception to the rule.

def show
  if true
    log_true
  else
    log_false
  end
end

This conditional is still logging-related and should be moved into the callback method. No need to make an exception to the style guide here.

2. Awkward, specific, and redundant naming and option https://github.com/cookpad/global-web/blob/2852a76c9bfcfec461053f4977e9b3f769268645/app/controllers/cookbooks_controller.rb#L3-L4

 before_action -> { log_index_visit_activity }, only: :index
 before_action -> { log_show_visit_activity }, only: :show

We will need methods with these "redundant" names in both approaches. The only real difference I see is that in this version, the redundancy is with the only: bit, but in the other approach, the redundancy is with calling log_index_visit_activity within the index action.

Easy-to-forget constraint that will make adding a new action in the controller risky

Logging should be part of the specification for when a piece of functionality is completed, but it won't always be implemented at the same time as the actions themselves.

Also, neither does having the logging calls in each action method give us a guarantee that devs adding a new action will add logging because one of the other actions does.

We also shouldn't think of logging as second-class work, even though it can seem repetitive. Defining it explicitly in the controller action keeps it at the same level of abstraction and importance as loading records from the DB, redirecting, etc.

It doesn't seem to me that using a callback versus using method calls from within the action impacts the perception of logging as second-class work. One could even make the argument that by using callbacks, it makes logging a standard part of the request lifecycle and thereby elevates it to being something that should always be addressed.

[tejanium]

This conditional is still logging-related and should be moved into the callback method. No need to make an exception to the style guide here.

ah sorry, bad example, it's not logging related specific, but something like

def show
  if android?
    @foo = android_stuff
    log_android_stuff
  elsif ios?
    @foo = ios_stuff
    log_ios_stuff
  end
end

Also, neither does having the logging calls in each action method give us a guarantee that devs adding a new action will add logging because one of the other actions does.

But it does guarantee that we're not accidentally logging where we don't mean to do logging

[lucianghinda]

I am in favour of this proposal.

I think this is a perfect example for a callback: logging and having a clarify about when logging should happen before or after (as in this proposal) adds more sense to what the data means.

[Bodacious]

It doesn't seem to me that using a callback versus using method calls from within the action impacts the perception of logging as second-class work. One could even make the argument that by using callbacks, it makes logging a standard part of the request lifecycle and thereby elevates it to being something that should always be addressed.

@jesseclark thank you for responding to my point. I think "second-class work" was a poor choice of phrase on my part. But what I meant to say was that we read an action definition, we can see that the action does X, Y, and Z. When we move something out of the action it's not so readily visible, and I don't see a strong case for treating logging differently from the other work an action does.

I think it makes sense for something like authentication, which we use the same method for across each action, and always call it by default (in API). But if the logging methods are defined differently per action or controller, then I would be just as happy to have those method calls included as part of the action body.

In any case, I'm happy to go with the majority preference on this 🤓

[tony-rowan]

Thanks for the disussion all, this has been great 🙇 I'm really glad I opened the PR now 😄

I'm sorry for dropping this and then leaving it for a few days though - I didn't expect to be so busy, nor did I expect so much interest.

---

There are have been some great points here, some I've not thought of before. Allow me to respond to a couple of them.

It can be really awkward if we have a condition inside the method and need to have separate logging. Then we make an exception to the rule.

I don't really see it as duplication or a problem if we check the same condition twice in different methods. In fact I think I prefer this to the alternative. The methods are all single purpose and easy to read and change independently.

def index
  compute_response
  log_show
end

private 

def compute_response
  if android?
    android_specific_something
  else
    generic_thing
  end
end 

def log_show
  if android?
    android_specific_logging
  else
    generic_logging
  end
end 

When we move something out of the action it's not so readily visible, and I don't see a strong case for treating logging differently from the other work an action does.

I would argue that, in a nicely factored controller, usage of callbacks doesn't really harm readability, but their usage does have a functional component. We often use callbacks that are specific to controllers and actions as it gives use the early return path without handling nested conditionals. While it's true some actions will have different logging for the happy and sad path (thinking about the authentication controllers) for the most part this is simply something that has to happen as long as the action is successful.

Which brings me nicely onto my final point...

---

Thank you all for your comments and I've certainly learned something from this but I'm still in favour of this proposal. My reasoning for this is actually a little more functional than stylistic. By using an after_action the logging doesn't occur if an error happens somewhere in the controller action, which is a little more combersome to acheieve without using after_actions. I believe this is benefitial for two reasons: 1) our metrics are less prone to lying so we make better decisions with the data we have available and 2) we get another channel for warning us of problems, if an action is silently failing we might not notice, but are more likely to notice if there is an associated metric that has tanked.

[tony-rowan]

Another point to consider - does this need to be in the style guide? If there isn't a consensus and no one feels that strongly (correct me if I'm wrong) maybe it should be another thing that's left to personal preference?

[Bodacious]

By using an after_action the logging doesn't occur if an error happens somewhere in the controller action, which is a little more combersome to acheieve without using after_actions

That's a very good point, @tony-rowan. Can I just clarify, that you mean exceptions, and not HTTP errors? I don't mean to be pedantic, but an error (something like the following) would still call the after action filter.

after_action :do_thing, only: [:index]
def index 
  render_404 if x == y
end

[tony-rowan]

@Bodacious Yes, I mean unexpected and unhandled exceptions, rather than intentionally returning error codes. I should have used more clear language, given the context 😄

[tejanium]

By using an after_action the logging doesn't occur if an error happens somewhere in the controller action, which is a little more combersome to acheieve without using after_actions

Can you elaborate on this point?

def show
  @user = User.find(1/0)
  log_show
end

Wouldn't this inline also won't call log_show?

[tony-rowan]

By using an after_action the logging doesn't occur if an error happens somewhere in the controller action, which is a little more combersome to acheieve without using after_actions

Can you elaborate on this point?

def show
  @user = User.find(1/0)
  log_show
end

Wouldn't this inline also won't call log_show?

Yes, but this would 😉

def show
  log_show
  @user = User.find(1/0)
end

[tejanium]

ah of course... it's similar to when the dev uses before_action instead of after_action then 😬

[tejanium]

Just to clarify my position again. I am still in favor of the inline method instead of a callback for logging, as I don't see a strong argument and benefit of using it for logging, if any, I think it makes the code harder to reason as you need to get up and down to see what a controller method does.

[jesseclark]

If we don't reach a consensus in favor of this. We should clarify if we are leaving it up to the developer or if we will try to agree to add a style guide for avoiding controller callbacks for a single action.

As I have been implementing the logging setup for Snowplow, I have been doing so in before_action callbacks for the reasons I mentioned above. If we are now going to say we don't want to do this anymore, there will be a bit of rework to move the callbacks I have added so far.

[tony-rowan]

Thanks @tejanium for clarifying your stance, and while I understand your point, I personally don't find it convincing enough to change my mind.

I think it makes the code harder to reason as you need to get up and down to see what a controller method does.

For two (related) reasons:

1. Most controllers really should be small enough that scrolling up and down isn't that big a problem and...
2. If it is large enough that scrolling up and down makes it difficult to understand what's happening, then I don't see using callbacks being any worse for that than private methods etc.

So, I'm still in favour.

---

Thanks all for your input, it's been a more in depth discussion that I thought we'd have about this. Since we don't seem to be reaching a consensus and in lieu of anyone with very strong objecttions I think we should close this with the action that it is up to personal preference of the developer and the particular controller they're working on.