<div dir="ltr"><div>On Thu, 17 Oct 2019 at 19:46, Michael Galea via talk <<a href="mailto:talk@gtalug.org" target="_blank">talk@gtalug.org</a>> wrote:<br></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On 2019-10-17 1:59 p.m., Giles Orr via talk wrote:<br>
> <br>
> We have a bunch of new(ish) Debian 10 VMs, and logrotate is failing to <br>
> rotate our non-standard logs. Unfortunately we deleted all the old <br>
> Debian 9 VMs before I noticed this problem, so they're not readily <br>
> available for comparison. The logrotate config files worked fine on <br>
> Debian 9 (provisioning is with Ansible, so it's consistent). The <br>
> failures aren't detailed enough to help. Here's the config:<br>
> <br>
> # /etc/logrotate.d/ruby<br>
> /opt/rubyapp/log/*.log {<br>
> daily<br>
> missingok<br>
> rotate 28<br>
> compress<br>
> delaycompress<br>
> copytruncate<br>
> }<br>
> <br>
> The parent configuration is standard Debian 10:<br>
> <br>
> # /etc/logrotate.conf<br>
> # (system-supplied comments removed)<br>
> weekly<br>
> rotate 4<br>
> create<br>
> include /etc/logrotate.d<br>
> <br>
> Unfortunately my paranoia is such that I'm redacting or modifying <br>
> machine names and folder names ... I apologize for that. But I don't <br>
> think the path involved is the problem.<br>
> <br>
> Here's one of the errors:<br>
> <br>
> # systemctl status logrotate.service<br>
> ● logrotate.service - Rotate log files<br>
> Loaded: loaded (/lib/systemd/system/logrotate.service; static; <br>
> vendor preset: enabled)<br>
> Active: failed (Result: exit-code) since Thu 2019-10-17 00:00:17 <br>
> EDT; 12h ago<br>
> Docs: man:logrotate(8)<br>
> man:logrotate.conf(5)<br>
> Process: 29004 ExecStart=/usr/sbin/logrotate /etc/logrotate.conf <br>
> (code=exited, status=1/FAILURE)<br>
> Main PID: 29004 (code=exited, status=1/FAILURE)<br>
> <br>
> Oct 17 00:00:01 acctserver systemd[1]: Starting Rotate log files...<br>
> Oct 17 00:00:14 acctserver logrotate[8621]: error: unable to open <br>
> /opt/rubyapp/log/newrelic_agent.log.1 for compression<br>
> Oct 17 00:00:14 acctserver logrotate[8621]: error: unable to open <br>
> /opt/rubyapp/log/puma.stderr.log.1 for compression<br>
> Oct 17 00:00:14 acctserver logrotate[8621]: error: unable to open <br>
> /opt/rubyapp/log/puma.stdout.log.1 for compression<br>
> Oct 17 00:00:14 acctserver logrotate[8621]: error: unable to open <br>
> /opt/rubyapp/log/traffic.log.1 for compression<br>
> Oct 17 00:00:17 acctserver systemd[1]: logrotate.service: Main <br>
> process exited, code=exited, status=1/FAILURE<br>
> Oct 17 00:00:17 acctserver systemd[1]: logrotate.service: Failed <br>
> with result 'exit-code'.<br>
> Oct 17 00:00:17 acctserver systemd[1]: Failed to start Rotate log <br>
> files.<br>
> <br>
> Here's the folder contents:<br>
> <br>
> # cd /opt/rubyapp/log<br>
> # ls -l<br>
> -rw-rw-r--+ 1 root root 1982 Oct 16 15:08 newrelic_agent.log<br>
> -rw-rw-r--+ 1 root root 7194 Oct 16 13:37 newrelic_agent.log.1<br>
> -rw-rw-r--+ 1 root root 2549 Oct 10 17:45 <br>
> newrelic_agent.log.2.gz<br>
> -rw-rw-r--+ 1 root root 154290 Oct 17 12:34 puma.stderr.log<br>
> -rw-rw-r--+ 1 root root 573253 Oct 16 13:37 puma.stderr.log.1<br>
> -rw-rw-r--+ 1 root root 512648 Oct 10 17:45 puma.stderr.log.2.gz<br>
> -rw-rw-r--+ 1 root root 238 Oct 16 15:08 puma.stdout.log<br>
> -rw-rw-r--+ 1 root root 722 Oct 16 13:37 puma.stdout.log.1<br>
> -rw-rw-r--+ 1 root root 701 Oct 10 17:45 puma.stdout.log.2.gz<br>
> -rw-rw-r--+ 1 root root 4747006453 Oct 17 12:37 traffic.log<br>
> -rw-rw-r--+ 1 root root 15668065757 Oct 10 17:55 traffic.log.1<br>
> -rw-rw-r--+ 1 root root 850646513 Sep 20 18:12 traffic.log.2.gz<br>
> <br>
> I note that in /var/log/ - where logrotate continues to work fine - that <br>
> files are owned mostly root:adm (what is 'adm', and does it matter in <br>
> this context?) and the permissions are 640 rather than 664. There are <br>
> ACLs attached to the files/folder shown above ... does _that_ matter? <br>
> Where this gets weirder is that if I run 'logrotate --force <br>
> /etc/logrotate.d/ruby' it gets rotated fine. It runs fine if run by <br>
> hand, it fails if run on a SystemD timer. Which suggests a difference <br>
> in permissions, but don't timers run as root:root?<br>
> <br>
> Any thoughts appreciated. As you can see, these are damn big logs, and <br>
> we have this problem across multiple machines so I'd really like to fix <br>
> it ...<br>
> <br>
> Errors on other servers aren't always consistent with this: a fix for <br>
> this may or may not help with them, so I may be coming back for more.<br>
> <br>
> Thanks all.<br>
> <br>
> -- <br>
> Giles<br><br>
I note that the versions of logrotate in stable (and also in unstable) <br>
have Bug<br>
"#831764 [logrotate] logrotate: does not rotate logs if delaycompress is <br>
used" logged against them. I'm not sure your problem sounds like the one <br>
posted in the bug report though.<br>
<br>
I think I remember from a previous life that logrotate will fail if the <br>
logging entity (rubyapp?) holds the file open. In that case you can try <br>
and use the post-rotate directive to "killall -hup .. " the entity, <br>
which should kick it off the file.<br>
<br>
Does /var/lib/logrotate/status have anything to say about the log? It <br>
should indicate when the last rotate occurred.<br></blockquote><div><br></div><div>Yup, Ruby does hold the file open, but the logrotate option 'copytruncate' was created for exactly that reason and worked on Debian 9: again, this works when run by hand on Debian 10, which I think suggests that's not the problem.</div><div><br></div><div>I was aware of the /var/lib/logrotate/status file, but didn't look at it closely until you mentioned it. And in looking at it closely, it mostly looks as it should BUT I see a problem, an artifact of a previous attempt to do log rotation on the parent folder:</div><div><br></div><div> "/opt/rubyapp/*.log" 2019-9-17-0:0:0</div><div> "/opt/rubyapp/log/traffic.log" 2019-10-18-0:0:5<br> "/opt/rubyapp/log/puma.stdout.log" 2019-10-18-0:0:5</div><div><br></div><div>(lots of other lines deleted). Notice that first line: we've been inconsistent across our projects about where the Ruby/Puma logs were stored, so I tried to rotate the logs in both places. I've removed that artifact. It's a long shot, but at this point I'm giving percentage to long shots ...</div></div><div class="gmail_quote"><br></div><div class="gmail_quote">I'm also removing "delaycompress" from one of the hosts, we'll see if that does anything. Again, seems like a long shot, but ...</div><div class="gmail_quote"><br></div><div class="gmail_quote">Thanks.<br></div><div class="gmail_quote"><br></div>-- <br><div dir="ltr">Giles<br><a href="https://www.gilesorr.com/" target="_blank">https://www.gilesorr.com/</a><br><a href="mailto:gilesorr@gmail.com" target="_blank">gilesorr@gmail.com</a></div></div>