Move logging into Rack middleware

[BRMatt]

At the moment:

• Requests that get handled by Rack middleware are not logged by lograge, which leads to situations where you can have invisible requests hitting your app
• 404 errors caused by invalid uris (e.g. no route that can handle them) trigger stack frames, not lograge lines. I think that's related to the middleware point, but I'm not entirely sure

@roidrage Would you mind if I submit a PR to move the logging from the LogSubscriber to middleware?

[roidrage]

How about having a middleware that triggers these errors and transmits them as notifications to the LogSubscriber?

[BRMatt]

How about having a middleware that triggers these errors and transmits them as notifications to the LogSubscriber?

Not quite following, do you mean "captures these errors"? A middleware like that would probably be able to handle the errors raised by the routing stack, but unless there's a way to reliably differentiate between requests that are handled by rails and requests handled by middleware we might end up with duplicate entries for requests.

I take it you'd prefer to move as little stuff as possible out of the log subscriber?

[zmoazeni]

Hi @roidrage @BRMatt, I'm actually running into a very similar issue. It has to do with the timing of the Notification subscribers and middleware.

Another issue which I think might be tied to #72 is that logging from middleware on outbound responses are not available to lograge.

To try and put the timing in perspective:

1. Middleware runs until we get to the Rails dispatch code
2. Rails dispatch code runs. Might be successful or raise an error
3. Part of the dispatch cycle is to kick off ActiveSupport::Notifications.
4. Lograge sends information to the log
5. All the middleware runs on the way out to serve the response

After step number 4, anything logged from the middleware is lost to lograge.

[roidrage]

Thanks for laying out the issue. I'm generally open to suggestions here on how to improve this or code contributions.

[zmoazeni]

@roidrage Right on. I might take a crack at a pull request where lograge does the final commit in a middleware just to see what you think of the design.

One other problem I'm coming up against is that the idea of overriding append_info_to_payload breaks down for uncaught exceptions.

# from the readme
class ApplicationController < ActionController::Base
  def append_info_to_payload(payload)
    super
    payload[:host] = request.host
  end
end

append_info_to_payload won't be called if an exception bubbles up. (At least in Rails 3.2) So an uncaught exceptional request would lose the host= key in this case.

[thoughtpunch]

@zmoazeni did you make any headway with this? Not logging Rack requests is the single thing holding me back from using Lograge for every Rails app

@roidrage can we make Rack integration a dev priority?

[zmoazeni]

We wrote something custom for our app that uses the Middleware design and replaced lograge. I haven't spent any time thinking about it in terms of lograge though. On Jan 1, 2015 2:37 PM, "Dan Barrett" notifications@github.com wrote:

@zmoazeni https://github.com/zmoazeni did you make any headway with this? Not logging Rack requests is the single thing holding me back from using Lograge for every Rails app

@roidrage https://github.com/roidrage can we make Rack integration a dev priority?

— Reply to this email directly or view it on GitHub https://github.com/roidrage/lograge/issues/48#issuecomment-68495782.

[mperrando]

I am investigating this issue. I've build a quick and dirty middleware that is actually working.

This middleware can be installed in parallel with the default Rails logger middleware, or it can substitute that. The middleware is also responsible for registering the Subscriber. This approach should replace the make the Lograge#remove_existing_log_subscriptionsmethod redundant and the config.lograge.enabled deprecated (not sure about this).

Data is passed from one space to the other using a Thread variable.

I have some considerations and ideas

1. when something goes wrong before the Rails notifications are triggered, the formatting and writing of the logs are lost: this two phases must be moved into the Rack space
2. we need two type of custom_options callbacks: one that runs in the Rails space and one that runs in the Rack space; in the Rails space we can have some important information that is lost when we return back to the Rack space, while, more common information (such as request timestamp, user agent, host) are accessible in the Rack space, also when the Rails action fails
3. the current Subscriber should be refactored so that it does only the data collection, while formatting and writing passes to the middleware
4. the Lograge configuration should be accessible both from the Subscriber (Rails space) and from the middleware (Rack space), so it should be extracted to its own class
5. the new middleware logs everything, so only logs the "not found"s, but also all the assets managed by the asset pipeline, but this could be managed by a new ignore_custom that runs in the Rack space
6. a new ignore_custom that is called in the Rack space should be considered (see above)

That's all.

You can take a look at the (awful) code.

[eprothro]

Any thoughts or updates on this? I agree with @thoughtpunch, we want simple KVP logging in production and this issue is the only reason I'm not using lograge.

[Silex]

This is also the showstopper for me. We need all logs to be formatted the lograge way, or none.

[benlovell]

I'm happy to help out with trying to get something landed but I'm not in a position where I can see this through myself. All contributions welcome! 👍

[zmoazeni]

We ended up migrating away from lograge and writing a replacement that was based on middleware. We have been considering open sourcing it, but before we did, I'd prefer to work with you all to keep this project going and help existing users who need this.

That said, I haven't looked too deeply at it lately to see what it would take to PR and merge with the existing code. The crux of it would be completely retooling the log_subscriber.rb, which is the majority of the code in this project.

However, if the project contributors are open to a largish PR for discussion, I can spend some time figuring out how to make that happen. My main reservation is that big PRs don't typically go over well without some discussion about the expectations beforehand.

[Silex]

@zmoazeni: big +1, wether it ends up improving lograge or creating a new gem. I'll try to help either ways.

Not having a decent straightforward solution to good logs in Rails in 2017 is really annoying.

[eprothro]

@zmoazeni @Silex I'm also up to collaborate.

We have a Json formatter that makes working with ELK and/or cloud services (logentries, etc) excellent. On our list is to clean up the plumbing (middleware/railties/sidekiq support) and extract into an open source gem, so our interests are probably aligned.

[Silex]

@roidrage, @zmoazeni, @eprothro: ping

[eprothro]

Not sure this is the right place to do this, but here it goes.

Here's what I would like to see:

• per logger key/value tagging
• per request key/value tagging
• JSON and KVP formatting option
  • Default to something like {msg: "some plain message"} for non mergeable log arg.
• Transparent Rails 4 and 5 support (e.g. integrate if available, not a dependency -- if it has to be one, split out into separate rails-* gem)
• Transparent Sidekiq support (sidekiq process's logger)
• Rack implementation
• Ability to change logger level without process restart

Potential contributors:

1. Are we roughly aligned?
2. Is revamping lograge the right move, or spin off?

[zmoazeni]

That's cool. We will probably start out with a separate codebase.

I have mainly been waiting to gauge the contributor's interest in this, but totally understand if they want lograge wants to continue down its existing design. It also saves an awkward huge PR and my time to put that together if there's no interest in merging that functionality.

So we'll start out by releasing our stuff as a separate gem. I'll pass this on to our team.

[Silex]

@zmoazeni: ping me when you have something, I'll test/debug/implement some features :-)

[Silex]

Any news?

[eprothro]

Before we spin-off, does anyone have any experience with http://rocketjob.github.io/semantic_logger ?

[zmoazeni]

Sorry, I haven't prioritized splitting out the code yet.

@eprothro thanks for sharing that project. I did a quick dive into the docs and the code. It certainly looks interesting, but it looks like it's fundamentally different than lograge and what my team needs on our projects which is to bundle all log entries for the entire request/unit-of-work. Meaning each line of output would be formatted individually with that project.

Though perhaps someone could write a custom file appender with SemanticLogger to collect, detect, and then write to the log as a single unit. It looks like elasticsearch appender is doing a bit of that with a Concurrent::TimerTask but it's still just flushing individual bits of logs in bulk.

[Silex]

Ha! In http://rocketjob.github.io/semantic_logger/rails.html the logs looks good, very similar to the lograge ones. I'll give it a try.

[Silex]

Ok FYI I switched to http://rocketjob.github.io/semantic_logger and I find it fantastic! I just had to tweak it a little to have the behavior I wanted and the maintainer is really helpful.

[raivil]

Hey, do we have any updates on this?

I'm trying to configure better logging for Sidekiq Web UI and it doesn't play well with Lograge since it's a simple rack app.

I wasn't aware of http://rocketjob.github.io/semantic_logger and will check it out.

Best,

[swrobel]

Has anyone who's moved to semantic_logger found a formatter that is similar to lograge? I've tried setting it to one_line but that just seems to strip linebreaks out of the already-verbose logs that semantic_logger generates.

[luong-komorebi]

I suggest sticking with lograge and try to fork it, improve the maintenance status of it. Semantic logger does some sneaky monkey patches under the hood so setting up and running it does open the door for some really unexpected problem

[supairish]

@swrobel For a single line json output in semantic_logger create an appender using the json formatter, it would be a single line output then. See Appenders , docs are pretty good around all the output possibilities