4.0.1->4.1.0, Rails logs flushing incorrectly #1906
Description
Steps to reproduce
I can't seem to reproduce the issue locally, so I'll try my best to explain what happened.
-
Deployed an existing Rails app on Heroku after upgrading Puma from 4.0.1 to 4.1.0.
-
Made some requests. App works fine. Checked the logs.
-
Request logs were absent. (Heroku Router logs were present.)
-
Rebooted the application and all previous request logs were dumped at once with the wrong times (app shutdown time).
Expected behavior
Request logs should appear right after they happen.
Actual behavior
Request logs are dumped after the application exits instead, preventing real-time logging and breaking log times.
Reverting to Puma 4.0.1 restores intended behavior.
System configuration
Ruby version: 2.6.1
Rails version: 6.0.0.rc2
Puma version: 4.1.0
Log Dump
Aug 12 01:38:13 app app/web.1: => Booting Puma
Aug 12 01:38:13 app app/web.1: => Rails 6.0.0.rc2 application starting in production
Aug 12 01:38:13 app app/web.1: => Run `rails server --help` for more startup options
Aug 12 01:38:15 app app/web.1: ** [NewRelic][2019-08-12 08:38:12 +0000 web.1 (4)] INFO : Starting the New Relic agent version 6.5.0.357 in "production" environment.
... more NewRelic logs ...
Aug 12 01:38:15 app app/web.1: Puma starting in single mode...
Aug 12 01:38:15 app app/web.1: * Version 4.1.0 (ruby 2.6.1-p33), codename: Fourth and One
Aug 12 01:38:15 app app/web.1: * Min threads: 2, max threads: 2
Aug 12 01:38:15 app app/web.1: * Environment: production
Aug 12 01:38:15 app app/web.1: * Listening on tcp://0.0.0.0:56371
Aug 12 01:38:15 app app/web.1: Use Ctrl-C to stop
Aug 12 01:38:15 app heroku/web.1: State changed from starting to up
<missing request logs>
Aug 12 01:38:43 app heroku/router: at=info method=GET path="/songs" host=...
<missing request logs>
Aug 12 01:38:43 app heroku/router: at=info method=GET path="/stats/current" host=...
<missing request logs>
Aug 12 01:38:43 app heroku/router: at=info method=GET path="/session" host=...
<missing request logs>
Aug 12 01:38:43 app heroku/router: at=info method=GET path="/videos" host=...
<missing request logs>
Aug 12 01:38:43 app heroku/router: at=info method=GET path="/artists" host=...
<missing request logs>
Aug 12 01:38:47 app heroku/router: at=info method=GET path="/session" host=...
<missing request logs>
Aug 12 01:39:54 app heroku/router: at=info method=GET path="/session" host=...
<missing request logs>
Aug 12 01:40:30 app heroku/router: at=info method=HEAD path="/" host=...
Aug 12 01:42:09 app heroku/web.1: Restarting
Aug 12 01:42:09 app heroku/web.1: State changed from up to starting
Aug 12 01:42:09 app heroku/web.1: Stopping all processes with SIGTERM
Aug 12 01:42:10 app app/web.1: - Gracefully stopping, waiting for requests to finish
Aug 12 01:42:10 app app/web.1: === puma shutdown: 2019-08-12 08:42:09 +0000 ===
Aug 12 01:42:10 app app/web.1: - Goodbye!
Aug 12 01:42:10 app app/web.1: ** [NewRelic][2019-08-12 08:38:16 +0000 web.1 (4)] INFO : Reporting to: https://rpm.newrelic.com/accounts/???/applications/???
Aug 12 01:42:10 app app/web.1: I, [2019-08-12T08:38:42.779002 #4] INFO -- : [5379ed03-308c-4863-be83-7a6ee678ba4a] Started GET "/stats/current" for 172.69.3.170 at 2019-08-12 08:38:42 +0000
Aug 12 01:42:10 app app/web.1: I, [2019-08-12T08:38:42.780675 #4] INFO -- : [5379ed03-308c-4863-be83-7a6ee678ba4a] Processing by StatsController#current as HTML
Aug 12 01:42:10 app app/web.1: I, [2019-08-12T08:38:42.791294 #4] INFO -- : [d0892f85-4464-4689-b8b5-d9a55e0c3d8f] Started GET "/session" for 172.69.3.170 at 2019-08-12 08:38:42 +0000
Aug 12 01:42:10 app app/web.1: I, [2019-08-12T08:38:42.791978 #4] INFO -- : [d0892f85-4464-4689-b8b5-d9a55e0c3d8f] Processing by SessionsController#index as HTML
... rest of previous request logs dumped with the wrong times ...