puma keeps writing to the logrotated file, even after being issued a phased-restart

[gingerlime]

Sorry, it's not the best bug report, I know. I hope to be able to troubleshoot and provide more details, but hope it's still something ... We've been trying to upgrade our puma 3.x since 4.0 came out, but we noticed some issues every time... The latest release looked promising, but sadly we still experienced some trouble.

Steps to reproduce

This is very tricky, because this bug seems to appear after some time, and we can't pinpoint exactly what's causing it... given the issues however, our staging system isn't stable, and therefore I only have limited access to our staging environment to be able to reproduce it, which makes it even harder.

We're seeing issues that might relate to logrotate and/or when reloading or restarting puma. In some cases a restart will seem to work (puma processes are there), but no socket file is created, or it "goes missing". In other cases (probably related to logrotate), it looks like the reload process doesn't work properly? (we're seeing "older" assets returned for example)

snippet from puma.log (sanitized slightly).

snippet from nginx error.log after restarting

systemd puma.socket
systemd puma.service
puma.rb

logrotate script runs systemctl reload puma.service

Expected behavior

No weirdness :)

Actual behavior

It's complicated ...

System configuration

Ruby version: 2.5.3
Rails version: 5.2.3
Puma version: 4.1.1

[nateberkopec]

Thanks. Sounds like you're dealing with #1842. If you think you are not (if 3.11 exhibits the same behavior for example, you are not experiencing the same issue), please reopen.

[gingerlime]

Thanks @nateberkopec ... I'll keep an eye on the discussion on #1842 somehow missed it. Didn't test 3.11, but 3.12 works fine for us for a while. Upgrading to 4.x so far always caused issues.

[nateberkopec]

Reopening with #1842 (comment)

[gingerlime]

Thanks for re-opening. I think this is pretty much the same as #1988

[gingerlime]

I updated the repo at https://github.com/gingerlime/puma-test-socket to include the logrotate issue. At least parts of it... After logrotate (using phased-restart), the logs keep being written to the rotated log file (puma.log.1), and the new file is empty...

I couldn't reproduce this other weird error with Could not find nio4r-2.5.1 in any of the sources (Bundler::GemNotFound) ... I suspect this only happens when the Gemfile itself updates? not sure yet... but will try to reproduce if I can.

[gingerlime]

hmm... the logrotate issue seems to also happen with 3.12 so perhaps it's unrelated.

[gingerlime]

using latest master resolves the restart issues for me, but the logrotate issue still exists. see https://github.com/gingerlime/puma-test-socket for details how to reproduce (even after using latest master in Gemfile)

What I essentially see is that puma keeps writing to the logrotated file, even after being issued a phased-restart.

[gingerlime]

To be fair, I think this issue existed in 3.x so perhaps the title is misleading at this point, if we want to focus on the logs... Happy to change the title and/or open a separate issue.

[nateberkopec]

No problem. Title changed.

[mcg]

@gingerlime what does your logrotate config look like? Rather than have logrotate restart puma, we use copytruncate.

[gingerlime]

@mcg The logrotate file is included in the repo https://github.com/gingerlime/puma-test-socket/blob/master/logrotate. It doesn't use copytruncate. Seems to work with our rails logs, sidekiq etc though (with the right postrotate scripts in place)...

[gingerlime]

Found #880 (comment)

So I guess we can close it as duplicate? although I still wonder if puma can re-open log files on phased restart (or maybe I'm missing something here).

[mcg]

@gingerlime Ah. Missed that. Anyhow, if you need a workaround that doesn't require restarts this works well for us:

/var/www/app/shared/log/*.log {
  maxsize 500M
  daily
  missingok
  rotate 14
  compress
  delaycompress
  notifempty
  copytruncate
}

[gingerlime]

Thanks @mcg! I'm a bit embarrassed that it didn't occur to me. I guess in the midst of the restart issues, I didn't even stop to wonder and immediately bundled those two issues together. Later on, even after realising it's not connected and also existed with 3.x somehow I still couldn't connect the dots.

This definitely seems like an appropriate -- and simple -- solution. But still the puma behaviour feels unexpected to me.

Happy to close this though. It's definitely not new.