Bug 2196754

Summary:	logrotate and psacct, after log rotation psacct stops
Product:	[Fedora] Fedora	Reporter:	Norman Gaywood <ngaywood>
Component:	psacct	Assignee:	Jan Rybar <jrybar>
Status:	NEW ---	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	38	CC:	jrybar, kdudka, lzaoral, ngaywood, svashisht, vmihalko
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:		Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Norman Gaywood 2023-05-10 06:31:02 UTC

After a log rotate for psacct, processes are logged in /var/account/pacct for a few processes, after which nothing is logged.
After the next log rotate, a few processes are logged again and then again stop.

This happens in Fedora 38 and 37
log rotation works properly in RHEL 8
The configuration file /etc/logrotate.d/psacct is identical across RHEL8 and Fedora 37,38

When the logging has stopped "systemctl restart psacct.service" will restart the logging correctly until the next log rotation.

Reproducible: Always

Steps to Reproduce:
1. dnf install psacct logrotate
2. systemctl enable --now psacct.service logrotate.service
3. After midnight observe the output of lastcomm

Actual Results:
After a log rotate (after midnight):
# lastcomm
logrotate S root __ 0.04 secs Wed May 10 00:01
logrotate S root __ 0.04 secs Wed May 10 00:01
sh root __ 0.00 secs Wed May 10 00:01
grep root __ 0.00 secs Wed May 10 00:01
cat root __ 0.00 secs Wed May 10 00:01
accton S root __ 0.00 secs Wed May 10 00:01
#

Expected Results:
lastcomm should still be logging processes.

systemctl restart psacct.service will make psacct restart logging until the next rotation.

Fedora 38:
rpm -q logrotate psacct
logrotate-3.21.0-2.fc38.x86_64
psacct-6.6.4-15.fc38.2.x86_64

and on a Fedora 37:
rpm -q logrotate psacct
logrotate-3.20.1-3.fc37.x86_64
psacct-6.6.4-14.fc37.x86_64

Comment 1 Kamil Dudka 2023-05-10 13:52:15 UTC

logrotate just executes the `postrotate` script embedded in /etc/logrotate.d/psacct.  Both /usr/sbin/accton and /etc/logrotate.d/psacct are owned by psacct.

Comment 2 Norman Gaywood 2023-05-15 21:41:38 UTC

An observation. I modified /etc/logrotate.d/psacct in the postrotate stanza to do a sleep and another accton:

/var/account/pacct {
    compress
    delaycompress
    notifempty
    daily
    rotate 31
    create 0600 root root
    postrotate
       if /usr/bin/systemctl --quiet is-active psacct.service ; then
           /usr/sbin/accton /var/account/pacct | /usr/bin/grep -v "Turning on process accounting, file set to '/var/account/pacct'." | /usr/bin/cat
           sleep 120
           /usr/sbin/accton /var/account/pacct | /usr/bin/grep -v "Turning on process accounting, file set to '/var/account/pacct'." | /usr/bin/cat
       fi
    endscript
}

The result was that psacct stopped again after logrotate finished. This is the output of lastcomm many hours after the logrotate:

# lastcomm
logrotate        S     root     __         0.05 secs Tue May 16 00:01
logrotate        S     root     __         0.05 secs Tue May 16 00:01
sh                     root     __         0.00 secs Tue May 16 00:01
cat                    root     __         0.00 secs Tue May 16 00:03
grep                   root     __         0.00 secs Tue May 16 00:03
accton           S     root     __         0.00 secs Tue May 16 00:03
accton                 root     __         0.00 secs Tue May 16 00:03
sleep                  root     __         0.00 secs Tue May 16 00:01
ThreadPoolForeg   F  X ngaywood __         0.01 secs Tue May 16 00:02
chrome            F  X ngaywood __         0.22 secs Mon May 15 23:56
chrome            F  X ngaywood __         0.08 secs Tue May 16 00:01
systemd-userwor  S     root     __         0.00 secs Mon May 15 23:57
systemd-userwor  S     root     __         0.01 secs Mon May 15 23:57
kworker/dying     F    root     __         0.00 secs Mon May 15 23:51
systemd-userwor  S     root     __         0.00 secs Mon May 15 23:56
ThreadPoolForeg   F  X ngaywood __         0.05 secs Tue May 16 00:00
grep                   root     __         0.00 secs Tue May 16 00:01
cat                    root     __         0.00 secs Tue May 16 00:01
accton           S     root     __         0.00 secs Tue May 16 00:01
#

Comment 3 Norman Gaywood 2023-06-27 05:31:29 UTC

I work around this problem with the following crontab entry:

10  0 * * *  /opt/sbin/restart-psacct

The /opt/sbin/restart-psacct script is:

#!/usr/bin/bash
# Something is wrong with the interaction of logrotate and psaact
# psacct stops after the logrotate
# https://bugzilla.redhat.com/show_bug.cgi?id=2196754
# Run this a few minutes after logrotate that happens at midnight

if /usr/bin/systemctl --quiet is-active psacct.service
then
    /usr/sbin/accton /var/account/pacct | /usr/bin/grep -v "Turning on process accounting, file set to '/var/account/pacct'." | /usr/bin/cat
fi

Comment 4 Norman Gaywood 2023-06-27 05:33:43 UTC

This looks like the same bug:

https://github.com/amazonlinux/amazon-linux-2023/issues/197