On 07/04/2020 09:03, Samuel Sieb wrote:
On 4/6/20 11:07 PM, Terry Barnaby wrote:
This system has been in use for 10 years or more on various Fedora versions. However about 18 months ago I have seen a problem where cron will start two backups with identical start times occasionally.
I have had to add a file lock system in the bbackup-beam to cope with this.
Any idea on why cron might start the same job off twice at the same time ? Could there be a time change issue with chronyd ?
Have you checked the logs to see when the jobs were started and if there are any relevant messages? _______________________________________________
Yes, there is nothing unusual in /var/log/cron:
Apr 6 22:01:01 beam CROND[651585]: (root) CMD (run-parts /etc/cron.hourly) Apr 6 22:01:01 beam run-parts[651585]: (/etc/cron.hourly) starting 0anacron Apr 6 22:01:01 beam run-parts[651585]: (/etc/cron.hourly) finished 0anacron Apr 6 23:01:01 beam CROND[652722]: (root) CMD (/src/bbackup/bbackup-beam) Apr 6 23:01:01 beam CROND[652721]: (root) CMD (run-parts /etc/cron.hourly) Apr 6 23:01:01 beam run-parts[652721]: (/etc/cron.hourly) starting 0anacron Apr 6 23:01:01 beam CROND[652720]: (root) CMDOUT (Waking up 70:85:c2:0f:68:07...) Apr 6 23:01:01 beam run-parts[652721]: (/etc/cron.hourly) finished 0anacron Apr 6 23:01:21 beam CROND[652720]: (root) CMDOUT (Starting Backup)
I do note that /etc/cron.hourly is performed at a minute past the hour as well though ...
/var/log/messages
Feb 24 23:00:03 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.214 from 00:25:b3:e6:a9:18 via enp4s0 Feb 24 23:00:03 beam dhcpd[1743]: DHCPACK on 192.168.201.214 to 00:25:b3:e6:a9:18 via enp4s0 Feb 24 23:00:05 beam systemd[1]: Starting system activity accounting tool... Feb 24 23:00:05 beam systemd[1]: sysstat-collect.service: Succeeded. Feb 24 23:00:05 beam systemd[1]: Started system activity accounting tool. Feb 24 23:00:05 beam audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 24 23:00:05 beam audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 24 23:00:41 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.241 from 70:85:c2:0f:68:07 via enp4s0 Feb 24 23:00:41 beam dhcpd[1743]: DHCPACK on 192.168.201.241 to 70:85:c2:0f:68:07 via enp4s0 Feb 24 23:00:59 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.26 from 84:1b:5e:70:2a:c9 via enp4s0 Feb 24 23:00:59 beam dhcpd[1743]: DHCPACK on 192.168.201.26 to 84:1b:5e:70:2a:c9 via enp4s0 Feb 24 23:01:01 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.250 from 4c:60:de:e4:29:2d via enp4s0 Feb 24 23:01:01 beam dhcpd[1743]: DHCPACK on 192.168.201.250 to 4c:60:de:e4:29:2d via enp4s0 Feb 24 23:01:20 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.28 from 00:50:c2:e2:f0:db via enp4s0 Feb 24 23:01:20 beam dhcpd[1743]: DHCPACK on 192.168.201.28 to 00:50:c2:e2:f0:db via enp4s0 Feb 24 23:01:32 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.8 from 00:d8:61:a0:a4:06 via enp4s0 Feb 24 23:01:32 beam dhcpd[1743]: DHCPACK on 192.168.201.8 to 00:d8:61:a0:a4:06 via enp4s0 Feb 24 23:02:21 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.214 from 00:25:b3:e6:a9:18 via enp4s0 Feb 24 23:02:21 beam dhcpd[1743]: DHCPACK on 192.168.201.214 to 00:25:b3:e6:a9:18 via enp4s0 Feb 24 23:03:10 beam dhcpd[1743]: DHCPREQUEST for 192.168.201.241 from 70:85:c2:0f:68:07 via enp4s0
In the backup log:
Bbackup / /usr/beam /home /src /srcOld /dist /opt /scratch /data/svn /data/www /data/vwt /data/www /data1/kvm /data/database /data/vwt /data/backup at Mon 6 Apr 23:01:01 BST 2020 Bbackup / /usr/beam /home /src /srcOld /dist /opt /scratch /data/svn /data/www /data/vwt /data/www /data1/kvm /data/database /data/vwt /data/backup at Mon 6 Apr 23:01:01 BST 2020 Backup aborted as locked by another backup Bbackup completed status: 0 at Tue 7 Apr 11:12:00 BST 2020
The bbackup-beam shell script is pretty basic and I can't see how this could have an issue like this.
The same system has been running since 2009 without any issues. This problem started happening around Fedora27 or perhaps Fedora29 I think.
Terry