Any way to execute Rails post-request logging steps?

[renchap]

Currently when a request is made to a Rodauth action, the start of the request is logged but not the after-request part.

# Rodauth action
Started POST "/auth/verify-account-resend" for 127.0.0.1 at 2021-04-29 22:19:31 +0200

# Normal rails action
Processing by PagesController#home as */*
  Rendered pages/home.html.erb within layouts/application (Duration: 69.1ms | Allocations: 26436)
  Rendered layout layouts/application.haml (Duration: 126.0ms | Allocations: 51847)
Completed 200 OK in 129ms (Views: 126.6ms | ActiveRecord: 0.0ms | Allocations: 53063)

If would be nice to have at least the "Completed …" row.
The first "Processing" row could be used to indicate that the request is handled by Rodauth as well.

I do not really understand how it is currently handled, but a quick search in Rails's code shows that this logging is done here:
https://github.com/rails/rails/blob/f95c0b7e96eb36bc3efc0c5beffbb9e84ea664e4/actionpack/lib/action_controller/log_subscriber.rb#L20

I also noticed that Rodauth requests are not showing in my production logs (using lograge) and I think this is related.

Do you think there can be an improvement here and there is a way to properly call the standard "after request" Rails code so all of this is handled like if it was a real Rails request? If you have ideas / pointers I can try things but for now I am not sure where to start and I dont know Rails/Rack/Rode internals enough.

I am also wondering if this may be related to the issue I just opened: #40

[janko]

The main reason you're not seeing standard Rails request logging is because requests to Rodauth endpoints are not handled inside a controller, they are handled before the request even reaches the Rails router. There is some controller integration regarding callbacks and rescue blocks, but that doesn't trigger the logging.

What you see is probably logging on the Rack middleware level, which is much more rudimentary than controller logging. I think what you're seeing a request being logged after it has been completed, but I could be wrong. Note that any middleware that handles requests will have this limitation, one other example being OmniAuth.

I can investigate whether Rails provides some tools for improving logging of requests not handled by the Rails router. The first line of the logs would definitely need to be different, as the requests won't be handled by controller actions, but the rest doesn't seem controller-specific.

[janko]

So, Rack-level logging is handled in Rails by the Rails::Rack::Logger middleware. As we've seen, it logs the start of the request, but doesn't output the end.

It does instrument the whole request though, which should allow rodauth-rails to hook into it and display logs in a way that you described. I will work on this.

[renchap]

Awesome!

It would be amazing to have standard Rails logs working for Rodauth-related requests. It looks like the way lograge does it is by attaching itself as an ActiveSupport::LogSubscriber

https://github.com/roidrage/lograge/blob/1729eab7956bb95c5992e4adab251e4f93ff9280/lib/lograge.rb#L151-L153

Feel free to ask if you want me to run some tests and test if it works fine with the various integrations we are using (lograte, datadog…)

[renchap]

I tested the latest master and it works well for me, including parameters filtering 🎉

FYI, here is how it looks with lograge + json enabled on my app:

{"type":"INFO","time":"2021-05-08T14:12:11.407+02:00","message":{"msg":"Processing by RodauthApp as 
{"type":"INFO","time":"2021-05-08T14:12:11.407+02:00","message":{"msg":"  Parameters: 003e\"[FILTERED]\", \"locale\"=\u003e:en}"}}
{"type":"INFO","time":"2021-05-08T14:12:11.632+02:00","message":{"msg":"Completed 200 OK in 225ms s | Allocations: 49828)\n\n"}}

This is lograge's behaviour when a text message is sent to the logger.

A normal request generates structured messages like this:

{"type":"INFO","time":"2021-05-08T14:12:12.480+02:00","message":{"method":"GET","path":"/albums/oprbYwfEvU.json","format":"json","controller":"AlbumsController","action":"show","status":200,"duration":433.52,"view":7.61,"db":286.27,"type":"lograge_json","params":{"id":"oprbYwfEvU","format":"json",},"request_id":"fa3055b5-2d6a-4af4-9cc2-0fb8f5756d9c","http_host":"dev.local","user_id":980204182,"ip":"127.0.0.1","user_agent":"NotosMobile/12 CFNetwork/1237 Darwin/20.4.0"}}

(note: some of those fileds come from my lograge configuration:

    lograge.custom_payload do |controller|
      {
        request_id: controller.request.uuid,
        http_host: controller.request.host,
        user_id: controller.rodauth&.session_value,
        ip: controller.request.remote_ip,
        user_agent: controller.request.user_agent,
      }
    end

[janko]

@renchap I've pushed an update to instrumentation, which now uses the same event name & namespace as regular controller requests. Would you mind testing it out, and letting me know whether it works with Lograge? Once you confirm, I'll make a release.

[janko]

Hmm, for some reason the total view rendering runtime isn't included in the "Completed" line. I felt like it was in the original implementation. I'm investigating.

[janko]

Total view rendering time is now displayed as well 🤘🏻

[renchap]

I pushed your latest commit to production and logs are working fine, I am even able to link the logs & traces in Datadog as expected. Great job here! 🎉