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

Groups > linux.debian.bugs.dist > #1016873 > unrolled thread

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

Back to article view | Back to linux.debian.bugs.dist

Contents

  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

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

Package: apt-listbugs
Version: 0.1.32
Severity: normal

for some days/weeks now, i get this mail every day:

--------------------------
From: apt-listbugs timer <root@ugly>
To: root
Subject: prefclean output on ugly

/usr/libexec/apt-listbugs/prefclean:
E: getaddrinfo: Temporary failure in name resolution (bugs.debian.org:80)
E: Exiting with error
---------------------------

the program works just fine when invoked from the command line, and 
these errors are a little bit too consistent to be actual network 
outages, so i suspect a permission problem in the configuration of the 
systemd timer (note that apparmor is enabled).

-- System Information:
Debian Release: bullseye/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'unstable'), (500, 'stable'), (1, 'experimental-debug')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.7.0-1-amd64 (SMP w/8 CPU cores)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=C, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=C (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages apt-listbugs depends on:
ii  apt             2.1.6
ii  ruby            1:2.7+1
ii  ruby-debian     0.3.10+b3
ii  ruby-gettext    3.3.3-2
ii  ruby-soap4r     2.0.5-4
ii  ruby-unicode    0.4.4-2+b11
ii  ruby-xmlparser  0.7.3-3+b4

Versions of packages apt-listbugs recommends:
ii  ruby-httpclient  2.8.3-2

-- no debconf information

[toc] | [next] | [standalone]

#1016941

[Multipart message — attachments visible in raw view] — view raw

Control: tags -1 + moreinfo


On Tue, 07 Jul 2020 11:36:43 +0200 Oswald Buddenhagen wrote:

> Package: apt-listbugs
> Version: 0.1.32
> Severity: normal
> 
> for some days/weeks now, i get this mail every day:
> 
> --------------------------
> From: apt-listbugs timer <root@ugly>
> To: root
> Subject: prefclean output on ugly
> 
> /usr/libexec/apt-listbugs/prefclean:
> E: getaddrinfo: Temporary failure in name resolution (bugs.debian.org:80)
> E: Exiting with error
> ---------------------------

Hello Oswald,
thanks for your bug report.

What you are experiencing is awkward, I have never seen anything like
this.

Please let me understand:

 • when did it begin? just after upgrading to apt-listbugs/0.1.32 ?
   or in some other point in time?

 • what happens if you try the following (as root)?

     # rm /var/spool/apt-listbugs/lastprefclean
     # /usr/libexec/apt-listbugs/prefclean

> 
> the program works just fine when invoked from the command line,

When you say "the program", do you mean "apt-listbugs" or
"/usr/libexec/apt-listbugs/prefclean" ?

> and 
> these errors are a little bit too consistent to be actual network 
> outages, so i suspect a permission problem in the configuration of the 
> systemd timer (note that apparmor is enabled).

I see that AppArmor is enabled, but it is enabled on my system as well,
and I do not experience any DNS issues in running the systemd timer...

Do you happen to have any special AppArmor configuration?
Mine is just the default that comes with current Debian testing.

Do you happen to know whether anything relevant has recently changed in
unstable (but not yet in testing)?

Is there anything else you are aware of, that could help in the
investigation?


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1016952

On Tue, Jul 07, 2020 at 07:46:50PM +0200, Francesco Poli wrote:
> • when did it begin?
>
i don't remember - i tend to ignore non-critical errors at first.
the journal doesn't say when it began, either, as it says that the 
sevice "succeeded" despite the error mail ...

but there are actually clues in the journal:

there is a report every hour despite it claiming to be a daily job.  
that's weird at least.

more importantly, there is another report (outside the hourly schedule) 
right after waking up from sleep - and this one could plausibly 
consistently run into a dns failure, as it runs before the network stack 
is restarted. so it's systemd-related, just differently than i thought.

[toc] | [prev] | [next] | [standalone]

#1016991

[Multipart message — attachments visible in raw view] — view raw

On Tue, 7 Jul 2020 20:17:15 +0200 Oswald Buddenhagen wrote:

> On Tue, Jul 07, 2020 at 07:46:50PM +0200, Francesco Poli wrote:
> > • when did it begin?
> >
> i don't remember - i tend to ignore non-critical errors at first.

Mmmh, that's unfortunate: I think that knowing this would have helped a
bit...

> the journal doesn't say when it began, either, as it says that the 
> sevice "succeeded" despite the error mail ...
> 
> but there are actually clues in the journal:
> 
> there is a report every hour despite it claiming to be a daily job.  
> that's weird at least.

It works this way by design.

Basically, when the job completes without issues, it drops the date
into /var/spool/apt-listbugs/lastprefclean .
When the job encounters issues, it exits (with status 0).

The job is attempted hourly (with a randomized delay), but it does
nothing if it has already dropped the date
into /var/spool/apt-listbugs/lastprefclean on the same day (where "day"
is a 24 h time interval, starting at 7:00 a.m. local time).

The rationale is: the job must be attempted at various times, since the
network could be down sometimes.
But it must be completed (at most) once per day.

> 
> more importantly, there is another report (outside the hourly schedule) 
> right after waking up from sleep -

This must be due to "OnActiveSec=5min".
See /lib/systemd/system/apt-listbugs.timer

> and this one could plausibly 
> consistently run into a dns failure, as it runs before the network stack 
> is restarted.

Was your system offline 5 min after waking up from sleep?
If so, then it's the expected behavior...

> so it's systemd-related, just differently than i thought.

We still have to understand why it cannot query the DNS from the
systemd timer, while you are able to do so from the command line.

Please reply to the other questions in my previous message.



-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1016993

On Tue, Jul 07, 2020 at 10:53:59PM +0200, Francesco Poli wrote:
>On Tue, 7 Jul 2020 20:17:15 +0200 Oswald Buddenhagen wrote:
>> there is a report every hour despite it claiming to be a daily job.  
>> that's weird at least.
>
>It works this way by design. [...]
>The rationale is: the job must be attempted at various times, since the
>network could be down sometimes.
>
i see. you actually want anacron-like functionality with network 
awareness. i guess systemd should be doing something like that ...

>Was your system offline 5 min after waking up from sleep?
>
no, my point was that this is happening *right* after waking up. there 
is no delay.

>Please reply to the other questions in my previous message.
>
the only one which seems relevant would be the one about recent changes, 
to which i can speculate that this possibly started with the recent-ish 
systemd v245.6 upgrade.

[toc] | [prev] | [next] | [standalone]

#1017885

[Multipart message — attachments visible in raw view] — view raw

On Tue, 7 Jul 2020 23:08:03 +0200 Oswald Buddenhagen wrote:

> On Tue, Jul 07, 2020 at 10:53:59PM +0200, Francesco Poli wrote:
> >On Tue, 7 Jul 2020 20:17:15 +0200 Oswald Buddenhagen wrote:
> >> there is a report every hour despite it claiming to be a daily job.  
> >> that's weird at least.
> >
> >It works this way by design. [...]
> >The rationale is: the job must be attempted at various times, since the
> >network could be down sometimes.
> >
> i see. you actually want anacron-like functionality with network 
> awareness. i guess systemd should be doing something like that ...

I researched this a lot, studying the systemd documentation, but I
haven't found a satisfying strategy to get what I wanted.
Hence, I implemented it by myself.

> 
> >Was your system offline 5 min after waking up from sleep?
> >
> no, my point was that this is happening *right* after waking up. there 
> is no delay.

Mmmh, I am not sure what happens with systemd timers, if the machine is
put to sleep.
Could it be that the timer was just about to be triggered, when the
machine woke up?

> 
> >Please reply to the other questions in my previous message.
> >
> the only one which seems relevant would be the one about recent changes, 
> to which i can speculate that this possibly started with the recent-ish 
> systemd v245.6 upgrade.

Well, I am using systemd/245.6-2 right now, and I do not experience
your DNS issues. So I cannot reproduce the bug.

I would love to help you, but, please help me to help you!   :-)

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


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1017933

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

[toc] | [prev] | [next] | [standalone]

#1018007

[Multipart message — attachments visible in raw view] — view raw

On Tue, 14 Jul 2020 10:36:23 +0200 Oswald Buddenhagen wrote:

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

That's a sensible suggestion: unfortunately, I haven't yet got around
to it.
But I would love to see the mechanism more implemented on the systemd
side, and less on the script side...

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

Do you mean that your "no network when apt-listbugs timer runs" only
happens immediately after a wake-up from a suspended state and only
when the system has had no chance to run the timer between 7:00 a.m.
and the wake-up itself?

If this is the case, then I apologize for not understanding before!

Since I do not use any suspend mechanism on my boxes, this could well
explain why I do not experience the same issue...

[...]
> here's a log of the wakeup:
> 
[...]
> 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: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: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
[...]

Well, it really looks like the apt-listbugs timer is run before the
network is brought up again.

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

And I suppose /var/spool/apt-listbugs/lastprefclean modification time
is somewhat later, between 10:20 and 10:40 a.m.

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

No offense was intended: I was just saying that replying to questions
may (sometimes) help in understanding the issue and in investigating
the cause...


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1018037

On Tue, Jul 14, 2020 at 10:51:06PM +0200, Francesco Poli wrote:
>Do you mean that your "no network when apt-listbugs timer runs" only
>happens immediately after a wake-up from a suspended state and only
>when the system has had no chance to run the timer between 7:00 a.m.
>and the wake-up itself?
>
yes

>And I suppose /var/spool/apt-listbugs/lastprefclean modification time
>is somewhat later, between 10:20 and 10:40 a.m.
>
yes, from the next regular timer wakeup at 10:38.

[toc] | [prev] | [next] | [standalone]

#1018241

[Multipart message — attachments visible in raw view] — view raw

Control: reassign -1 systemd
Control: affects -1 + apt-listbugs
Control: tags -1 - moreinfo



On Wed, 15 Jul 2020 10:49:16 +0200 Oswald Buddenhagen wrote:

> On Tue, Jul 14, 2020 at 10:51:06PM +0200, Francesco Poli wrote:
> >Do you mean that your "no network when apt-listbugs timer runs" only
> >happens immediately after a wake-up from a suspended state and only
> >when the system has had no chance to run the timer between 7:00 a.m.
> >and the wake-up itself?
> >
> yes
[...]

OK, after researching a bit more about systemd timers, I think this is
a bug in systemd. I am consequently reassigning your bug report to
package systemd.


Dear Debian systemd maintainers, please let me describe the issue
experienced by Oswald (user of package apt-listbugs).

Package apt-listbugs (of which I am the maintainer) ships the following
timer unit:

  $ cat /lib/systemd/system/apt-listbugs.timer 
  # This file is part of apt-listbugs
  #
  # Copyright (C) 2019       Francesco Poli <invernomuto@paranoici.org>
  #
  #  This program is free software; you can redistribute it and/or modify
  #  it under the terms of the GNU General Public License as published by
  #  the Free Software Foundation; either version 2 of the License, or
  #  (at your option) any later version.
  #
  #  This program is distributed in the hope that it will be useful,
  #  but WITHOUT ANY WARRANTY; without even the implied warranty of
  #  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  #  GNU General Public License for more details.
  #
  #  You should have received a copy of the GNU General Public License with
  #  the Debian GNU/Linux distribution in file /usr/share/common-licenses/GPL-2;
  #  if not, write to the Free Software Foundation, Inc., 51 Franklin St,
  #  Fifth Floor, Boston, MA 02110-1301, USA.
  
  
  [Unit]
  Description=Daily apt-listbugs preferences cleanup
  After=network.target network-online.target
  
  [Timer]
  OnActiveSec=5min
  OnCalendar=*-*-* *:20
  RandomizedDelaySec=20min
  
  [Install]
  WantedBy=timers.target


The goal here is to have the corresponding (Type=oneshot) service unit
executed 5 min after the activation of the timer unit and hourly, with
a random delay between 0 and 20 min, and anyway after the network link
is available and working.
The service unit should *not* catch up with missed executions (the timer
has no Persistent=true directive). 

I think the above directives are the ones needed to achieve the stated
goal.
And they seem to work correctly after boot (when at least 5 min and at
most 25 min are waited, before triggering the service) and during
normal operation (when the service is triggered hourly with a delay
between 0 and 20 min).

On the other hand, the original bug reporter (Oswald) sees that the
service is triggered immediately after each wake-up from sleep.
Before the network has had a chance to become available and working.


Please take a look at the bug log, especially [message#37], which
include a log of the wake-up.

[message#37]: <https://bugs.debian.org/964438#37>


I think this is a bug in systemd.
If this is the case, please investigate/fix the issue and/or forward my
bug report upstream, as appropriate.

Otherwise, please tell me what's wrong in the timer unit, as I cannot
really figure it out by myself, despite several attempts to find the
answer in the documentation or on the web...   :-(

Thanks for your time and for any help you may provide!
Bye.


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1018245

[Multipart message — attachments visible in raw view] — view raw

Control: retitle -1 systemd: timer triggers service immediately after wake-up from sleep


I forgot to change the bug report title...
Doing so now.


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1018346

[Multipart message — attachments visible in raw view] — view raw

On Fri, 17 Jul 2020 01:46:06 +0200 Michael Biebl wrote:

> Control: reassign -1 apt-listbugs
> 
> Am 16.07.20 um 23:11 schrieb Francesco Poli:
> 
> >   [Unit]
> >   Description=Daily apt-listbugs preferences cleanup
> >   After=network.target network-online.target
> 
> 
> > On the other hand, the original bug reporter (Oswald) sees that the
> > service is triggered immediately after each wake-up from sleep.
> > Before the network has had a chance to become available and working.
> 
> Please see https://www.freedesktop.org/wiki/Software/systemd/NetworkTarget/
> 
> network-online.target is only relevant during boot, once the target has
> been reached, it will stay up, it is not dynamic.
> I.e. you can't use that to delay the execution of a service after
> suspend-resume.
> 
> If your service has such dynamic needs, this can't be expressed via
> network-online.target and you should instead implement that in your
> service directly.
> 
> Reassigning accordingly.

Hello Michael, thanks for your prompt reply.

OK, I acknowledge that the network-online.target check is not reliable
enough, I was aware of that.

But anyway, let's pretend the network check is completely absent.

Why is the service triggered *immediately* during wake-up?
It should wait at least 5 min (OnActiveSec=5min) or be triggered on the
basis of the calendar scheduling (OnCalendar=*-*-* *:20) with a random
delay (RandomizedDelaySec=20min).

And it should *not* catch up with missed execution chances (since the
timer is *not* a Persistent=true one).

What am I missing here?


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019386

[Multipart message — attachments visible in raw view] — view raw

Control: reassign -1 systemd


On Fri, 17 Jul 2020 18:11:08 +0200 Francesco Poli wrote:

> On Fri, 17 Jul 2020 01:46:06 +0200 Michael Biebl wrote:
[...]
> > network-online.target is only relevant during boot, once the target has
> > been reached, it will stay up, it is not dynamic.
> > I.e. you can't use that to delay the execution of a service after
> > suspend-resume.
[...]
> > 
> > Reassigning accordingly.
> 
> Hello Michael, thanks for your prompt reply.
> 
> OK, I acknowledge that the network-online.target check is not reliable
> enough, I was aware of that.
> 
> But anyway, let's pretend the network check is completely absent.
> 
> Why is the service triggered *immediately* during wake-up?
> It should wait at least 5 min (OnActiveSec=5min) or be triggered on the
> basis of the calendar scheduling (OnCalendar=*-*-* *:20) with a random
> delay (RandomizedDelaySec=20min).
> 
> And it should *not* catch up with missed execution chances (since the
> timer is *not* a Persistent=true one).
> 
> What am I missing here?

Dear Michael,
I am still convinced that this is a bug in systemd, as explained above.
I am reassigning back the bug report to package systemd.

If you think that the timer unit can be modified so that it behaves as
intended, please tell me how I should modify it.
Just to recap the intended behavior: the timer should trigger the
corresponding oneshot service 5 min after the timer activation and then
hourly, with a random delay between 0 and 20 min, *without* catching up
with missed execution chances, and it should *not* trigger the service
immediately during a wake-up from sleep.

Otherwise, please investigate/fix the issue and/or forward my
bug report upstream, as appropriate.

Thanks for your time and understanding.
Bye.


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019401

[Multipart message — attachments visible in raw view] — view raw

On Sun, 26 Jul 2020 22:22:55 +0200 Michael Biebl wrote:

[...]
> Afaics, the problem is, that your service does not properly handle the
> case, when the network is not available.

It does, that's the reason why the operation is attempted hourly.

> Even if systemd would delay timer events after a resume: How long should
> it wait? 30s, 1min? How would that robustly solve your problem? How
> would that guarantee that after 1min network is available?

It should wait at least 5 min (as specified in OnActiveSec=5min),
because we are almost sure that immediately during wake-up is too early.
Hence, attempting the operation during wake-up is a bad idea.
If 5 min after wake-up is still too early to have a working network,
no big deal, the service will try again hourly...


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019402

[Multipart message — attachments visible in raw view] — view raw

On Sun, 26 Jul 2020 22:06:23 +0200 Michael Biebl wrote:

> Am 26.07.20 um 21:36 schrieb Francesco Poli:
[...]
> > Dear Michael,
> > I am still convinced that this is a bug in systemd, as explained above.
> > I am reassigning back the bug report to package systemd.
> > 
> > If you think that the timer unit can be modified so that it behaves as
> > intended, please tell me how I should modify it.
> > Just to recap the intended behavior: the timer should trigger the
> > corresponding oneshot service 5 min after the timer activation and then
> > hourly, with a random delay between 0 and 20 min, *without* catching up
> > with missed execution chances, and it should *not* trigger the service
> > immediately during a wake-up from sleep.
> 
> Maybe this is a misunderstanding.

It's possible. And it may well be on my side.
Let's try and clarify...

> Persistent=true is relevant when you
> reboot/power down a system. In your case, the system is suspended and
> woken up again.

Exactly!
So why does it trigger *immediately* during wake-up?

Was the timer inactive during sleep and then re-activated during
wake-up?
If this is the case, then it should wait at least 5 min
(OnActiveSec=5min) or trigger on the basis of the calendar scheduling
(OnCalendar=*-*-* *:20) with a random delay (RandomizedDelaySec=20min).

Was the timer still considered active during sleep?
If this is the case, then the OnActiveSec=5min trigger should not
happen at all during wake-up and the timer should just trigger on the
basis of the calendar scheduling (OnCalendar=*-*-* *:20) with a random
delay (RandomizedDelaySec=20min).

Yet, the timer triggers during each wake-up, without waiting.
This is why I think the bug is in systemd.



-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019405

[Multipart message — attachments visible in raw view] — view raw

On Sun, 26 Jul 2020 22:49:06 +0200 Michael Biebl wrote:

> Am 26.07.20 um 22:38 schrieb Francesco Poli:
> > On Sun, 26 Jul 2020 22:06:23 +0200 Michael Biebl wrote:
[...]
> >> Persistent=true is relevant when you
> >> reboot/power down a system. In your case, the system is suspended and
> >> woken up again.
> > 
> > Exactly!
> > So why does it trigger *immediately* during wake-up?
> > 
> 
> Because the timer elapsed.

When?
During sleep?

So it catches up with missed execution chances, doesn't it?

If this is confirmed, then maybe the bug is exactly that the Persistent
directive does not apply to sleeping time (only to down time).
Or, in other words, that, after sleep, every timer is necessarily
considered as Persistent=true, even when it should be Persistent=false.


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019404

[Multipart message — attachments visible in raw view] — view raw

On Sun, 26 Jul 2020 22:48:18 +0200 Michael Biebl wrote:

> Am 26.07.20 um 22:43 schrieb Francesco Poli:
> > On Sun, 26 Jul 2020 22:22:55 +0200 Michael Biebl wrote:
> > 
> > [...]
> >> Afaics, the problem is, that your service does not properly handle the
> >> case, when the network is not available.
> > 
> > It does, that's the reason why the operation is attempted hourly.
> 
> The bug report was about apt-listbugs throwing an error if network is
> not available.

We can argue that the service should be more silent in case of network
errors, or maybe it's OK that it throws an error.
But that's not the point.

The point is that the timer triggers during wake-up, while it should
behave as it does during a boot (wait for at least 5 min and then
trigger hourly, with a random delay).

> 
> >> Even if systemd would delay timer events after a resume: How long should
> >> it wait? 30s, 1min? How would that robustly solve your problem? How
> >> would that guarantee that after 1min network is available?
> > 
> > It should wait at least 5 min (as specified in OnActiveSec=5min),
> 
> That is not what OnActiveSec=5min means

Then I think the systemd.timer(5) man page should be clarified.
It states:

           │OnActiveSec=       │ Defines a timer relative   │
           │                   │ to the moment the timer    │
           │                   │ unit itself is activated.  │

I thought this meant that an OnActiveSec=5min timer triggers 5 min
after being activated.
And the timer is either inactive during sleep (then it's activated
again during wake-up and it should wait 5 min before triggering) or
considered as active during sleep (but then the OnActiveSec should have
already happened 5 min after boot and should not happen again during
wake-up).

What did I fail to understand?



-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [next] | [standalone]

#1019533

[Multipart message — attachments visible in raw view] — view raw

On Sun, 26 Jul 2020 23:43:53 +0200 Michael Biebl wrote:

> Am 26.07.20 um 23:20 schrieb Francesco Poli:
[...]
> > If this is confirmed, then maybe the bug is exactly that the Persistent
> > directive does not apply to sleeping time (only to down time).
> 
> I don't consider that a bug. Persistent is only documented as affecting
> a powered down system.

But there must be a way to set a timer that does *not* catch up with
missed runs, during both downtime and sleep time!

If there isn't, then I would call this a missing feature.
And I would say that this can be reported upstream as a feature request.

If, on the other hand, there indeed is a way, please tell me how I can
modify the timer.

Is there a way to cause the timer to automatically become inactive,
immediately before the system goes to sleep, and then to automatically
be re-activated, immediately after the system is woken up?
If I interpret the documentation correctly, this would prevent a
Persistent=false timer to catch up with missed runs during sleep time.
And it would cause a OnActiveSec=5min timer to trigger 5 min after the
wake-up (+ the randomized delay).
Is this possible?

Speaking about the randomized delay, shouldn't it be applied to
catch-ups too, when Persistent=true?
Or at least, you seem to have written so, when talking about
[anacron.timer]...

[anacron.timer]: <https://salsa.debian.org/debian/anacron/-/commit/fdf6f9ec46bda512c061616b18c9ed7031682331>

Could you please clarify? I may be misinterpreting what you wrote.

Thanks for your time and patience.


-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
..................................................... Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE

[toc] | [prev] | [standalone]

Back to top | Article view | linux.debian.bugs.dist

csiph-web