Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.debian.bugs.dist > #1017933

Bug#964438: apt-listbugs: dns error when running from cron job

From Oswald Buddenhagen <oswald.buddenhagen@gmx.de>
Newsgroups linux.debian.bugs.dist
Subject Bug#964438: apt-listbugs: dns error when running from cron job
Date 2020-07-14 10:40 +0200
Message-ID <AsoDL-2Pm-7@gated-at.bofh.it> (permalink)
References (5 earlier) <ApSoG-7UJ-9@gated-at.bofh.it> <Aq30J-6br-5@gated-at.bofh.it> <Asel4-504-17@gated-at.bofh.it> <ApSoG-7UJ-9@gated-at.bofh.it> <Asel4-504-17@gated-at.bofh.it>
Organization linux.* mail to news gateway

Show all headers | View raw

On Mon, Jul 13, 2020 at 11:25:21PM +0200, Francesco Poli wrote:
>I haven't found a satisfying strategy to get what I wanted.
>
ok, fair enough. please make sure the maintainers know about this 
requirement if you haven't done so yet.

>Could it be that the timer was just about to be triggered, when the
>machine woke up?
>
that's implausible, because the suspensions and wakeups are essentially 
random (measured against "your" schedule), while the problem appears 
with utter regularity (whenever the wakeup happens on the next day, as 
defined by your mechanism).

>Well, I am using systemd/245.6-2 right now, and I do not experience
>your DNS issues. So I cannot reproduce the bug.
>
it's wrong to concentrate on the dns problem in particular. the question 
is why the service is started so early during wakeup, literally during 
the same second, even before many drivers have woken up, and several 
seconds before avahi and dhclient get their turn at restoring network 
normality.

about the same time (order is random) systemd-sleep is logging 
resumption, so maybe the kernel is being funny (the driver timing seems 
weird)? but then, the weird user space sequencing seems more likely due 
to a bad service config, except that anacron and several other apt 
services are fired as well. anyway, the boot log says:

   Linux version 5.7.0-1-amd64 #1 SMP Debian 5.7.6-1 (2020-06-24)

and with

   Linux version 5.6.0-2-amd64 #1 SMP Debian 5.6.14-1 (2020-05-23)

and systemd 245.5 the timing was apparently the same already. i haven't 
gone further back (the logs were rotated out already), but as far as the 
most recent updates go, these were clearly dead ends.

here's a log of the wakeup:

Jul 14 09:53:46 ugly kernel: ACPI: Low-level resume complete
Jul 14 09:53:46 ugly kernel: PM: Restoring platform NVS memory
Jul 14 09:53:46 ugly kernel: Enabling non-boot CPUs ...
Jul 14 09:53:46 ugly kernel: x86: Booting SMP configuration:
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Jul 14 09:53:46 ugly kernel: CPU1 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Jul 14 09:53:46 ugly kernel: CPU2 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Jul 14 09:53:46 ugly kernel: CPU3 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 4 APIC 0x1
Jul 14 09:53:46 ugly kernel: CPU4 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 5 APIC 0x3
Jul 14 09:53:46 ugly kernel: CPU5 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 6 APIC 0x5
Jul 14 09:53:46 ugly kernel: CPU6 is up
Jul 14 09:53:46 ugly kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
Jul 14 09:53:46 ugly kernel: CPU7 is up
Jul 14 09:53:46 ugly kernel: ACPI: Waking up from system sleep state S3
Jul 14 09:53:46 ugly kernel: hpet: Lost 6587 RTC interrupts
Jul 14 09:53:46 ugly kernel: sd 1:0:0:0: [sdb] Starting disk
Jul 14 09:53:46 ugly kernel: sd 0:0:0:0: [sda] Starting disk
Jul 14 09:53:46 ugly kernel: sd 6:0:0:0: [sdc] Starting disk
Jul 14 09:53:46 ugly kernel: nuvoton-cir 00:02: activated
Jul 14 09:53:46 ugly kernel: OOM killer enabled.
Jul 14 09:53:46 ugly systemd[1]: Started Run anacron jobs.
Jul 14 09:53:46 ugly systemd-sleep[789697]: System resumed.
Jul 14 09:53:46 ugly kernel: Restarting tasks ... done.
Jul 14 09:53:46 ugly kernel: PM: suspend exit
Jul 14 09:53:46 ugly systemd[1]: Starting Daily apt upgrade and clean activities...
Jul 14 09:53:46 ugly systemd[1]: Starting Daily apt-listbugs preferences cleanup...
Jul 14 09:53:46 ugly kernel: ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 14 09:53:46 ugly kernel: ata1.00: supports DRM functions and may not be fully accessible
Jul 14 09:53:46 ugly kernel: ata1.00: disabling queued TRIM support
Jul 14 09:53:46 ugly kernel: ata1.00: supports DRM functions and may not be fully accessible
Jul 14 09:53:46 ugly kernel: ata1.00: disabling queued TRIM support
Jul 14 09:53:46 ugly kernel: ata1.00: configured for UDMA/133
Jul 14 09:53:46 ugly anacron[789710]: Anacron 2.3 started on 2020-07-14
Jul 14 09:53:46 ugly anacron[789710]: Will run job `cron.daily' in 5 min.
Jul 14 09:53:46 ugly anacron[789710]: Jobs will be executed sequentially
Jul 14 09:53:47 ugly systemd[1]: apt-daily-upgrade.service: Succeeded.
Jul 14 09:53:47 ugly systemd[1]: Finished Daily apt upgrade and clean activities.
Jul 14 09:53:47 ugly systemd[1]: apt-listbugs.service: Succeeded.
Jul 14 09:53:47 ugly systemd[1]: Finished Daily apt-listbugs preferences cleanup.
Jul 14 09:53:50 ugly kernel: e1000e 0000:00:19.0 eth0: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
Jul 14 09:53:50 ugly kernel: ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 14 09:53:50 ugly kernel: ata2.00: configured for UDMA/133
Jul 14 09:53:50 ugly systemd-sleep[789799]: /dev/sdb:
Jul 14 09:53:50 ugly systemd-sleep[789799]:  setting Advanced Power Management level to 0xfe (254)
Jul 14 09:53:50 ugly systemd-sleep[789799]:  APM_level        = 254
Jul 14 09:53:51 ugly kernel: ata17: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata16: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata14: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata15: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata13: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata12: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata11: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata18: SATA link down (SStatus 0 SControl 300)
Jul 14 09:53:51 ugly kernel: ata7: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
Jul 14 09:53:51 ugly kernel: ata7.00: configured for UDMA/133
Jul 14 09:53:51 ugly kernel: ata8: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Jul 14 09:53:51 ugly kernel: ata8.00: configured for UDMA/100
Jul 14 09:53:51 ugly avahi-daemon[821]: Withdrawing address record for 192.168.178.20 on eth0.
Jul 14 09:53:51 ugly avahi-daemon[821]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.178.20.
Jul 14 09:53:51 ugly avahi-daemon[821]: Interface eth0.IPv4 no longer relevant for mDNS.
Jul 14 09:53:51 ugly systemd[1]: Stopping Network Time Synchronization...
Jul 14 09:53:51 ugly systemd[1]: systemd-timesyncd.service: Succeeded.
Jul 14 09:53:51 ugly systemd[1]: Stopped Network Time Synchronization.
Jul 14 09:53:51 ugly systemd[1]: Starting Network Time Synchronization...
Jul 14 09:53:51 ugly systemd[1]: Started Network Time Synchronization.
Jul 14 09:53:51 ugly dhclient[1005]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8
Jul 14 09:53:51 ugly dhclient[1005]: DHCPOFFER of 192.168.178.20 from 192.168.178.1
Jul 14 09:53:51 ugly dhclient[1005]: DHCPREQUEST for 192.168.178.20 on eth0 to 255.255.255.255 port 67
Jul 14 09:53:51 ugly dhclient[1005]: DHCPACK of 192.168.178.20 from 192.168.178.1
Jul 14 09:53:51 ugly systemd[1]: Reloading LSB: start Samba SMB/CIFS daemon (smbd).
Jul 14 09:53:51 ugly systemd[1]: Reloaded LSB: start Samba SMB/CIFS daemon (smbd).
Jul 14 09:53:51 ugly avahi-daemon[821]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.178.20.
Jul 14 09:53:51 ugly avahi-daemon[821]: New relevant interface eth0.IPv4 for mDNS.
Jul 14 09:53:51 ugly avahi-daemon[821]: Registering new address record for 192.168.178.20 on eth0.IPv4.
Jul 14 09:53:51 ugly systemd[1]: Stopping Network Time Synchronization...
Jul 14 09:53:51 ugly systemd[1]: systemd-timesyncd.service: Succeeded.
Jul 14 09:53:51 ugly systemd[1]: Stopped Network Time Synchronization.
Jul 14 09:53:51 ugly systemd[1]: Starting Network Time Synchronization...
Jul 14 09:53:52 ugly systemd[1]: Started Network Time Synchronization.
Jul 14 09:53:52 ugly systemd-timesyncd[790036]: Initial synchronization to time server 192.168.178.1:123 (192.168.178.1).
Jul 14 09:53:52 ugly dhclient[1005]: bound to 192.168.178.20 -- renewal in 1698 seconds.
Jul 14 09:53:56 ugly systemd[1]: systemd-suspend.service: Succeeded.
[a few more user space things happen here, but they look boring]

today's fail-mail is dated '14 Jul 2020 09:53:47 +0200'.

>If you do not reply to my questions, I will not be able to investigate
>and I will have no other choice than closing this bug report as
>unreproducible...
>
i think i'm quite capable of judging what's relevant in cases like this, 
so don't make it too easy for yourself to dismiss the issue. ;)

Back to linux.debian.bugs.dist | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread

Thread

Bug#964438: apt-listbugs: dns error when running from cron job Oswald Buddenhagen <oswald.buddenhagen@gmx.de> - 2020-07-07 11:50 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-07 20:00 +0200
    Bug#964438: apt-listbugs: dns error when running from cron job Oswald Buddenhagen <oswald.buddenhagen@gmx.de> - 2020-07-07 20:30 +0200
      Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-07 23:00 +0200
        Bug#964438: apt-listbugs: dns error when running from cron job Oswald Buddenhagen <oswald.buddenhagen@gmx.de> - 2020-07-07 23:10 +0200
          Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-13 23:40 +0200
            Bug#964438: apt-listbugs: dns error when running from cron job Oswald Buddenhagen <oswald.buddenhagen@gmx.de> - 2020-07-14 10:40 +0200
              Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-14 23:00 +0200
                Bug#964438: apt-listbugs: dns error when running from cron job Oswald Buddenhagen <oswald.buddenhagen@gmx.de> - 2020-07-15 11:00 +0200
                Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-16 23:20 +0200
                Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-16 23:50 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-17 18:20 +0200
    Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-26 21:40 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-26 22:50 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-26 22:50 +0200
    Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-26 23:30 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-26 23:30 +0200
  Bug#964438: apt-listbugs: dns error when running from cron job Francesco Poli <invernomuto@paranoici.org> - 2020-07-27 23:40 +0200

csiph-web