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. ;)
