tracer wants me to unnecessarily restart services

[philfry]

Hi all,

tracer doesn't recognize daemon restarts that have taken place by the rpm upgrade process.
For example, tonight at 04:02 rspamd has been updated. The %postun section of the rpm's spec restarted rspamd.

$ LC_TIME=C rpm -q rspamd --qf '%{installtime:date}\n'
Wed Apr 17 04:02:39 2019

$ for pid in $(pgrep rspamd); do ls -ld --full-time /proc/${pid}; done
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:02:44.522252555 +0200 /proc/25085
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25782
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25783
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25784
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25785
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25786
dr-xr-xr-x. 9 _rspamd _rspamd 0 2019-04-17 04:04:25.406933900 +0200 /proc/25787

Also, there are no (relevant) deleted open files:

$ for pid in $(pgrep rspamd); do lsof -n -p ${pid} | awk '/ DEL /{print $NF}'; done | sort -u
/dev/zero

tracer still wants me to restart rspamd, though:

$ tracer --version
0.7.1
$ tracer -ae
You should restart:
  * Some applications using:
      systemctl restart rspamd

$ tracer --show-resource packages
Date           Time      Package name                            
-------------------------------------------------------
2019-04-17     04:02     rspamd                                  
2019-04-17     04:02     rspamd-debuginfo

I've got no idea where tracer gets its timestamps from:

$ tracer -ae -t 1555466554
$ tracer -ae -t 1555466553
You should restart:
  * Some applications using:
      systemctl restart rspamd
$ LC_TIME=C date -d @1555466553
Wed Apr 17 04:02:33 CEST 2019

And that's what the yum history database shows:

# query taken from rpm.py
$ sqlite3 /var/lib/yum/history/*sqlite 'select pkgtups.name, max(datetime(trans_end.timestamp, "unixepoch", "localtime")) from trans_beg join trans_end join trans_data_pkgs join pkgtups on trans_beg.tid = trans_end.tid and trans_data_pkgs.tid=trans_beg.tid and trans_data_pkgs.pkgtupid=pkgtups.pkgtupid where pkgtups.name = "rspamd";' 
rspamd|2019-04-17 04:02:46

unfortunately, there's no debug output:

$ tracer -ae -vv
You should restart:
  * Some applications using:
      systemctl restart rspamd

Any clues?

[skobyda]

Any hope of getting this fixed? We are having the same problem when updating cockpit-ws package, which restarts cockpit service, yet tracer tells to restart it again. This forces us to filter it out of tracer results manually.

[tux93]

We recently encountered the same issue in combination with Foreman + Katello and I suspect Satellite would be affected too

Our reproducer is as follows:

1. Install an EL8 client
2. subscribe it to foreman / sattelite
3. install the katello-host-tools-tracer package
4. Update for example rsyslog
5. tracer (and by extension foreman) will report rsyslog needing to be restarted despite the service already having been restarted during the package transaction

# dnf upgrade -d 10 rsyslog
timer: config: 5 ms
Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, playground, product-id, repoclosure, repodiff, repograph, repomanage, reposync, subscription-manager, tracer-upload, uploadprofile
Updating Subscription Management repositories.
DNF version: 4.4.2
Command: dnf upgrade -d 10 rsyslog
Installroot: /
Releasever: 8
cachedir: /var/cache/dnf
Base command: upgrade
Extra commands: ['upgrade', '-d', '10', 'rsyslog']
User-Agent: constructed: 'libdnf (Rocky Linux 8.4; generic; Linux.x86_64)'
Saltstack latest for EL8                                                                                                                                                                             20 kB/s | 2.1 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Saltstack_for_EL8_Saltstack_latest_for_EL8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Saltstack_for_EL8_Saltstack_latest_for_EL8: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
Rocky 8 Extras                                                                                                                                                                                       24 kB/s | 2.4 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_Extras' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_Extras: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
Rocky 8 AppStream                                                                                                                                                                                    28 kB/s | 2.8 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream: using metadata from Mon 20 Jun 2022 08:07:26 UTC.
Rocky Client 8                                                                                                                                                                                       20 kB/s | 2.1 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_Client_Rocky_Client_8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_Client_Rocky_Client_8: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
Rocky 8 BaseOS                                                                                                                                                                                       23 kB/s | 2.4 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_BaseOS' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_BaseOS: using metadata from Mon 20 Jun 2022 08:07:24 UTC.
Puppet 6 for EL 8                                                                                                                                                                                    19 kB/s | 1.8 kB     00:00
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Puppet_6_for_EL_8_Puppet_6_for_EL_8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Puppet_6_for_EL_8_Puppet_6_for_EL_8: using metadata from Mon 20 Jun 2022 08:07:23 UTC.
timer: sack setup: 2293 ms
Completion plugin: Generating completion cache...
--> Starting dependency resolution
---> Package rsyslog.x86_64 8.1911.0-7.el8.1 will be upgraded
---> Package rsyslog.x86_64 8.2102.0-5.el8 will be an upgrade
--> Finished dependency resolution
timer: depsolve: 1008 ms
Dependencies resolved.
====================================================================================================================================================================================================================================
 Package                                 Architecture                           Version                                        Repository                                                                                      Size
====================================================================================================================================================================================================================================
Upgrading:
 rsyslog                                 x86_64                                 8.2102.0-5.el8                                 a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream                                 751 k

Transaction Summary
====================================================================================================================================================================================================================================
Upgrade  1 Package

Total download size: 751 k
Is this ok [y/N]: y
Downloading Packages:
rsyslog-8.2102.0-5.el8.x86_64.rpm                                                                                                                                                                   4.5 MB/s | 751 kB     00:00
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Total                                                                                                                                                                                               4.4 MB/s | 751 kB     00:00
Running transaction check
Transaction check succeeded.
Running transaction test
Transaction test succeeded.
timer: transaction test: 862 ms
Running transaction
RPM transaction start.
  Preparing        :                                                                                                                                                                                                            1/1
  Running scriptlet: rsyslog-8.2102.0-5.el8.x86_64                                                                                                                                                                              1/1
Upgrade: rsyslog-8.2102.0-5.el8.x86_64
  Upgrading        : rsyslog-8.2102.0-5.el8.x86_64                                                                                                                                                                              1/2
  Running scriptlet: rsyslog-8.2102.0-5.el8.x86_64                                                                                                                                                                              1/2
Upgraded: rsyslog-8.1911.0-7.el8.1.x86_64
  Running scriptlet: rsyslog-8.1911.0-7.el8.1.x86_64                                                                                                                                                                            2/2
  Cleanup          : rsyslog-8.1911.0-7.el8.1.x86_64                                                                                                                                                                            2/2
  Running scriptlet: rsyslog-8.1911.0-7.el8.1.x86_64                                                                                                                                                                            2/2
RPM transaction over.
  Verifying        : rsyslog-8.2102.0-5.el8.x86_64                                                                                                                                                                              1/2
  Verifying        : rsyslog-8.1911.0-7.el8.1.x86_64                                                                                                                                                                            2/2
timer: verify transaction: 281 ms
timer: transaction: 2887 ms
Completion plugin: Generating completion cache...
Installed products updated.
User-Agent: constructed: 'libdnf (Rocky Linux 8.4; generic; Linux.x86_64)'
Cleaning up.
User-Agent: constructed: 'libdnf (Rocky Linux 8.4; generic; Linux.x86_64)'
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Saltstack_for_EL8_Saltstack_latest_for_EL8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Saltstack_for_EL8_Saltstack_latest_for_EL8: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_Extras' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_Extras: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream: using metadata from Mon 20 Jun 2022 08:07:26 UTC.
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_Client_Rocky_Client_8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_Client_Rocky_Client_8: using metadata from Mon 20 Jun 2022 08:07:22 UTC.
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_BaseOS' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_BaseOS: using metadata from Mon 20 Jun 2022 08:07:24 UTC.
reviving: 'a3f0d7d9-3440-42c6-8ade-24e11461687d_Puppet_6_for_EL_8_Puppet_6_for_EL_8' can be revived - repomd matches.
a3f0d7d9-3440-42c6-8ade-24e11461687d_Puppet_6_for_EL_8_Puppet_6_for_EL_8: using metadata from Mon 20 Jun 2022 08:07:23 UTC.
timer: sack setup: 1528 ms
Uploading Tracer Profile
Upgraded: rsyslog-8.2102.0-5.el8.x86_64

Upgraded:
  rsyslog-8.2102.0-5.el8.x86_64

Complete!
Cleaning up.
/var/cache/dnf/a3f0d7d9-3440-42c6-8ade-24e11461687d_Rocky_8_Rocky_8_AppStream-b8012483736f1b60/packages/rsyslog-8.2102.0-5.el8.x86_64.rpm removed

# journalctl -u rsyslog
-- Logs begin at Mon 2022-06-20 09:48:38 UTC, end at Mon 2022-06-20 10:12:42 UTC. --
Jun 20 09:48:53 systemd[1]: Starting System Logging Service...
Jun 20 09:48:53 rsyslogd[1225]: [origin software="rsyslogd" swVersion="8.1911.0-7.el8.1" x-pid="1225" x-info="https://www.rsyslog.com"] start
Jun 20 09:48:53 systemd[1]: Started System Logging Service.
Jun 20 09:48:53 rsyslogd[1225]: imjournal: journal files changed, reloading...  [v8.1911.0-7.el8.1 try https://www.rsyslog.com/e/0 ]
Jun 20 09:54:55 systemd[1]: Stopping System Logging Service...
Jun 20 09:54:55 rsyslogd[1225]: [origin software="rsyslogd" swVersion="8.1911.0-7.el8.1" x-pid="1225" x-info="https://www.rsyslog.com"] exiting on signal 15.
Jun 20 09:54:55 systemd[1]: rsyslog.service: Succeeded.
Jun 20 09:54:55 systemd[1]: Stopped System Logging Service.
Jun 20 09:54:55 systemd[1]: Starting System Logging Service...
Jun 20 09:54:55 rsyslogd[1685]: [origin software="rsyslogd" swVersion="8.2102.0-5.el8" x-pid="1685" x-info="https://www.rsyslog.com"] start
Jun 20 09:54:55 systemd[1]: Started System Logging Service.
Jun 20 09:54:55 rsyslogd[1685]: imjournal: journal files changed, reloading...  [v8.2102.0-5.el8 try https://www.rsyslog.com/e/0 ]

dnf correctly reports nothing to do:

# dnf needs-restarting -d 10
timer: config: 7 ms
Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, playground, product-id, repoclosure, repodiff, repograph, repomanage, reposync, subscription-manager, tracer-upload, uploadprofile
Updating Subscription Management repositories.
DNF version: 4.4.2
Command: dnf needs-restarting -d 10
Installroot: /
Releasever: 8
cachedir: /var/cache/dnf
Base command: needs-restarting
Extra commands: ['needs-restarting', '-d', '10']
User-Agent: constructed: 'libdnf (Rocky Linux 8.4; generic; Linux.x86_64)'
timer: sack setup: 282 ms
Cleaning up.

tracer claims rsyslog needing to be restarted:

# tracer --verbose
You should restart:
  * Some applications using:
      systemctl restart rsyslog

Tracer version:

# dnf list --installed python3-tracer
Updating Subscription Management repositories.
Installed Packages
python3-tracer.noarch                                                0.7.8-2.el8

[anarcat]

i think this might be an issue that we've found in a bespoke homegrown script we used to use before we switched to needrestart - it's not any deleted page that matters, you need to select only executable ones....