Logging stops after a while (thread safety)

[nathany]

We are having an issue where our Rails logs output (to STDOUT) for a few minutes after boot (on Heroku dynos) but then quit. The other Heroku logs continue (router, runtime metrics) so it seems to be a problem in Ruby-land.

This seems to only occur when using log_tags or when enabling the lograge gem: roidrage/lograge#65

config.log_tags = [
  lambda { |req|
    session = ActiveRecord::SessionStore::Session.find_by_session_id(req.cookie_jar["_jobber_session_id"])
    return unless session
    user_id = session.data["user_credentials_id"]
    "user_id=#{user_id}" if user_id
  }
]

MRI 2.1, Rails 4.0.2, Puma 2.7.1 with 8 threads 6 threads.

Last week we upgraded from Rails 3.2.16 to 4.0.2. We believe that is when the issue surfaced, though a few weeks ago we switched from Unicorn to Puma as well.

Has anyone else ran into an issue like this? Particularly with a threaded web server.

[rafaelfranca]

@nathany could you create an application reproducing this issue? Or maybe you could provide more information.

Right now it will be difficult fix your problem if we don't know why it happens.

[nathany]

I'll keep trying to narrow down the issue. (For example, to see if it still happens if we don't do an ActiveRecord find in log_tags).

Just getting this in front of people in case anyone else has ran into it. Also mentioned on the Heroku forums: https://discussion.heroku.com/t/rails-logging-stalls-a-few-minutes-after-boot/455

Might it be related to using a threaded webserver? #9065

[nathany]

I tried this with a hard coded log_tag instead of the session query as well as disabling Heroku's log-runtime-metrics. Still experiencing the issue.

[nathany]

The behaviour matches what is described here:

logs show up fine in the beginning but after a while it seems as if logging stopped working

LoggerSilence in Rails 4.0.2 could be the problem. #10836

Being likely a threading issue, the unpredictably makes me unsure if it's specific to tagged logging. Though I noticed rails_stdout_logging uses ActiveSupport::TaggedLogging.

[nathany]

So I've been looking through our dependencies for a potential race condition when silencing logs:

ack "silence" `bundle show --paths`

It doesn't look like LoggerSilence is being used anymore: rails/activerecord-session_store#5

• Is ActiveSupport::Deprecation.silence thread safe? Removed deprecation silencing from produciton.rb but that didn't help.
• What about silence_warnings and with_warnings?

I am seeing an IOError: stream closed in our logs coming from openssl:

/vendor/ruby-2.1.0/lib/ruby/2.1.0/openssl/digest.rb:64 in "write"
/vendor/ruby-2.1.0/lib/ruby/2.1.0/openssl/digest.rb:64 in "warn"

warn('Digest::Digest is deprecated; use Digest')

And in several other places. Might be related. See puma/puma#173

[schneems]

Do you still see this issue using the Rails beta or master?

[nathany]

@schneems We haven't been able to run our app under Rails 4.1 rc yet, currently waiting for this fix: thoughtbot/shoulda-matchers#434 among a number of deprecations to fix (only recently upgraded to Rails 4).

We've not reproduced the issue outside of production with real traffic yet, I should look into how to simulate traffic against our app in development.

Then I could probably allocate some time to build a minimal Rails app running under Puma to reproduce the issue.

[nathany]

I do wonder if #12684 Kernel#silence_stream leaking file descriptors is related. All our specs are passing on Rails 4.0.4 rc1, so we'll try it in production once released and report back.

[nathany]

Our app is now on Rails 4.0.4 and still exhibiting the issue. I am reproducing it in development using a production-like environment:

Running abbench with concurrency I see the first few logs and then it quits logging:

ab -n 1000 -c 6 http://localhost.dev:3000/

Restarting the server and running abbench without concurrency I will see the logs for as long as abbench is running:

ab -n 1000 -c 1 http://localhost.dev:3000/

I'm now creating a smaller Rails app to see if I can reproduce the problem there.

[schneems]

Sorry you're seeing this behavior but thanks for the continued feedback ❤️. If we can get a repro demo app it could be huge.

[nathany]

Here is a sample app to reproduce the issue:

https://github.com/GetJobber/logging_example

It seems related to activerecord-session_store, pg and rails_12factor under a threaded web server (puma).

It is possible that some other ActiveRecord access would cause the same issue as well, but activerecord-session_store is where I first hit it.

[schneems]

I was able to reproduce given the steps you sent me. However I did notice a problem.

You're starting with rails s this currently extends the logger to output to STDOUT. This is fixed in 4.1 but not 4.0 #11060

So what's happening is that rails_12factor is setting your logger to use STDOUT, and then by starting the command with rails s you're also outputting to STDOUT. So you should actually be seeing double logs while running in production this way.

Running via puma directly RACK_ENV=production puma config.ru -p 3000 instead of rails s will cause the mysterious disappearing logging to go away.

[nathany]

@schneems Thanks for taking a look.

We don't actually use rails s in production. I was unaware of that issue and was simplifying the command for purposes of the README. I had seen the same problem with rails s and with bin/puma -p 3000 -e production -t 6:6.

I also see the logging stall when starting with RACK_ENV=production puma config.ru -p 3000.

Have you tried increasing the number of hits from ab to see if logging stalls before it's done?
ab -n 1000 -c 6 http://localhost.dev:3000/. If it's a threading issue, I don't know the exact point where logging stalls, just that it does.

I see the same problem with Rails 4.1.0.rc1 and github: 'rails/rails' (4.2.0.alpha).

Our production Procfile currently contains:

web: bundle exec puma -p $PORT -e ${RACK_ENV:-development} -C config/puma.rb 2>&1

(the 2>&1 is a recent addition since the problem started)

[nathany]

Fyi, I tried removing activerecord-session_store in the example and doing some other queries instead:

In the controller:

@users = User.all.to_a

Or in production.rb (with a user present in the DB):

config.log_tags = [
  lambda { |req|
    user = User.first
    return unless user
    "user_id=#{user.login}"
  }
]

Neither case caused the issue, so it seems be specific to something activerecord-session_store 0.1.0 is doing.

Maybe:

rails/activerecord-session_store#19

[nathany]

Verified that rails/activerecord-session_store#19 is the issue in my logging example.

[robin850]

@nathany : Thanks a lot for your quick feedback!

[kjwierenga]

Just for posterity. I had a similar issue upgrading from Rails 3 to Rails 4. Logging to STDOUT stopped (after one request) because of the obsolete quiet_assets gem still in my Gemfile. Removing this gem fixed the issue (and adding config.assets.quiet = true to environments/development.rb).