Your message dated Wed, 4 Sep 2019 13:58:57 +0300
with message-id <[email protected]>
and subject line Re: Bug#894602: found it, a fantastic race :)
has caused the Debian Bug report #894602,
regarding [dpkg] Strange cron error mails from executing /etc/cron.daily/dpkg
to be marked as done.
This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.
(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact [email protected]
immediately.)
--
894602: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=894602
Debian Bug Tracking System
Contact [email protected] with problems
--- Begin Message ---
Package: dpkg
Version: 1.18.24
Severity: normal
--- Please enter the report below this line. ---
Hi,
since a couple of days, I'm getting strange error mails from cron
daemon with subject
"Cron <root@mail> test -x /usr/sbin/anacron || ( cd / && run-
parts --report /etc/cron.daily )"
from some hosts. They're all related to executing /etc/cron.daily/dpkg
but with slightly different content. One host even sends 2(!) mails.
Here's the content:
Host1:
/etc/cron.daily/dpkg:
cp: cannot create regular file 'dpkg.status': File exists
mv: cannot move './/dpkg.status.5.gz' to './/dpkg.status.6.gz': No such
file or directory
mv: cannot move './/dpkg.status.4.gz' to './/dpkg.status.5.gz': No such
file or directory
mv: cannot move './/dpkg.status.3.gz' to './/dpkg.status.4.gz': No such
file or directory
mv: cannot move './/dpkg.status.2.gz' to './/dpkg.status.3.gz': No such
file or directory
mv: cannot move './/dpkg.status.1.gz' to './/dpkg.status.2.gz': No such
file or directory
cp: cannot create regular file 'dpkg.diversions': File exists
gzip: .//dpkg.diversions.0: No such file or directory
mv: cannot move './/dpkg.diversions.0.gz' to './/dpkg.diversions.1.gz':
No such file or directory
mv: cannot move 'dpkg.diversions' to './/dpkg.diversions.0': No such
file or directory
/etc/cron.daily/logrotate:
error: error renaming temp state file /var/lib/logrotate/status.tmp
run-parts: /etc/cron.daily/logrotate exited with return code 1
Host2:
/etc/cron.daily/dpkg:
mv: cannot move './/dpkg.status.5.gz' to './/dpkg.status.6.gz': No such
file or directory
mv: cannot stat './/dpkg.status.4.gz': No such file or directory
mv: cannot stat './/dpkg.status.2.gz': No such file or directory
gzip: .//dpkg.diversions.0: No such file or directory
cp: cannot create regular file 'dpkg.statoverride': File exists
Host3 (mail1):
/etc/cron.daily/dpkg:
mv: cannot move './/dpkg.status.2.gz' to './/dpkg.status.3.gz': No such
file or directory
cp: cannot create regular file 'dpkg.diversions': File exists
gzip: .//dpkg.diversions.0: No such file or directory
mv: cannot stat './/dpkg.statoverride.4.gz': No such file or directory
mv: cannot stat './/dpkg.statoverride.2.gz': No such file or directory
mv: cannot stat './/dpkg.statoverride.1.gz': No such file or directory
gzip: .//dpkg.statoverride.0: No such file or directory
mv: cannot stat './/dpkg.statoverride.0.gz': No such file or directory
Host3 (mail2):
/etc/cron.daily/dpkg:
cp: cannot create regular file 'dpkg.status': File exists
mv: cannot move './/dpkg.status.5.gz' to './/dpkg.status.6.gz': No such
file or directory
mv: cannot stat './/dpkg.status.4.gz': No such file or directory
mv: cannot stat './/dpkg.status.3.gz': No such file or directory
mv: cannot move './/dpkg.status.1.gz' to './/dpkg.status.2.gz': No such
file or directory
gzip: .//dpkg.status.0: No such file or directory
mv: cannot stat './/dpkg.status.0.gz': No such file or directory
mv: cannot stat 'dpkg.status': No such file or directory
mv: cannot stat './/dpkg.diversions.0.gz': No such file or directory
mv: cannot stat 'dpkg.diversions': No such file or directory
mv: cannot stat './/dpkg.statoverride.5.gz': No such file or directory
mv: cannot stat './/dpkg.statoverride.3.gz': No such file or directory
/etc/cron.daily/logrotate:
error: destination /var/lib/logrotate/status.tmp already exists,
renaming to /var/lib/logrotate/status.tmp-2018040206.backup
error: error renaming temp state file /var/lib/logrotate/status.tmp
run-parts: /etc/cron.daily/logrotate exited with return code 1
If I execute /etc/cron.daily/dpkg manually, it always finishes without
error.
In case it matters, these hosts are setup as LXC-based OS containers
running on libvirt. But I think I've seen these mails from physical
hosts in the past as well.
--- System information. ---
Architecture:
Kernel: Linux 4.14.0-0.bpo.3-amd64
Debian Release: 9.4
600 stretch-backports vwakviie2ienjx6t.onion
500 syncthing apt.syncthing.net
500 stable www.deb-multimedia.org
500 stable vwakviie2ienjx6t.onion
500 stable sgvtcaew4bxjd7ln.onion
500 stable repo.saltstack.com
500 stable dl.google.com
500 stable archive.grahamedgecombe.com
--- Package information. ---
Depends (Version) | Installed
=======================-+-============
tar (>= 1.28-1) | 1.29b-1.1
Package's Recommends field is empty.
Suggests (Version) | Installed
============================-+-===========
apt | 1.4.8
debsig-verify |
Bye...
Dirk
--
Dirk Heinrichs
GPG Public Key: D01B367761B0F7CE6E6D81AAD5A2E54246986015
Sichere Internetkommunikation: http://www.retroshare.org
Privacy Handbuch: https://www.privacy-handbuch.de
signature.asc
Description: This is a digitally signed message part
--- End Message ---
--- Begin Message ---
Ok, found it. It is completely my fault, has exactly nothing to do
with dpkg package.
Some years ago, out of curiocity, I tried to "emulate" cron.{hourly,etc}
using systemd timers. And left /etc/systemd/system/cron-daily.{timer,service}
to run run-parts /etc/cron.daily at exactly the same time when regular cron
does this. And forgot about it.
Now, two instances of /etc/cron.daily/dpkg are run in parallel each night,
at exactly the same time, hitting all the possible races here, which are
a lot.
For example, this:
On Tue, 3 Sep 2019 10:20:58 +0300 Michael Tokarev <[email protected]> wrote:
> The first error is from `cp' - can't create dpkg.status, EEXIST.
> Well, cp shouldn't get this erro, it should just replace the
> file content and be done with that, but okay, at least we can
> assume this file exist. Fine.
apparently `cp' checks for file existance first, finds out that the file
does NOT exist, and tries to create it. Meanwhile, other `cp' run from
systemd did the same and actually created the file. So this cp fails
with EEXIST.
And so on with all other reported failures.
This is actually fascinating, how exactly we hit all the races here.
Very interesting case.
Closing the dpkg bugreport now. Yet the case is really interesting.
Thanks,
/mjt
--- End Message ---
