Please read this before reporting a bug:
https://wiki.archlinux.org/title/Bug_reporting_guidelines
Do NOT report bugs when a package is just outdated, or it is in the AUR. Use the 'flag out of date' link on the package page, or the Mailing List.
REPEAT: Do NOT report bugs for outdated packages!
https://wiki.archlinux.org/title/Bug_reporting_guidelines
Do NOT report bugs when a package is just outdated, or it is in the AUR. Use the 'flag out of date' link on the package page, or the Mailing List.
REPEAT: Do NOT report bugs for outdated packages!
FS#73759 - at-3.2.4 and linux-5.16.4 fails to execute jobs at expected time
Attached to Project:
Community Packages
Opened by Robin Becker (replabrobin) - Saturday, 12 February 2022, 12:00 GMT
Last edited by Christian Hesse (eworm) - Monday, 28 February 2022, 13:05 GMT
Opened by Robin Becker (replabrobin) - Saturday, 12 February 2022, 12:00 GMT
Last edited by Christian Hesse (eworm) - Monday, 28 February 2022, 13:05 GMT
|
DetailsDescription:
after update to at-3.2.4 and linux-5.16.4 the at command no longer executes at the specified time. In fact it waits for another at command before executing. Additional info: * package version(s) at-3.2.4 linux-5.16.4 * config and/or log files etc. * link to upstream bug report, if any Steps to reproduce: I run this shell command ############################################################################## #!/bin/sh OUT=/tmp/atd-test-$$.out trap "rm -f $OUT" EXIT cat /dev/null > "$OUT" chmod 666 "$OUT" echo "date >> $OUT" | at now + 1 min echo -e "\e[1;31m\xE2\x9D\x8C waiting\e[0m" tail -F "$OUT" | \ while read line; do echo -e "\e[1;32m\e[1A\e[K\xE2\x9C\x94 $line read OK\e[0m" && exit 0 done ############################################################################## watching the clock shows that the command does not execute until another at command is executed. Example robin@minikat:~ $ tatd warning: commands will be executed using /bin/sh job 4174 at Sat Feb 12 10:53:00 2022 ❌ waiting ^C robin@minikat:~ $ tatd warning: commands will be executed using /bin/sh job 4175 at Sat Feb 12 10:55:00 2022 ❌ waiting ^C robin@minikat:~ $ atrm 4175 robin@minikat:~ The journalctl -f output shows that the command executes when I run the second at command at 10:54; it should have executed at 10:53. ############################################################################## Feb 12 10:54:15 minikat audit[2286]: USER_ACCT pid=2286 uid=2 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat kernel: audit: type=1101 audit(1644663255.785:80): pid=2286 uid=2 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat kernel: audit: type=1006 audit(1644663255.785:81): pid=2286 uid=2 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=4 res=1 Feb 12 10:54:15 minikat kernel: audit: type=1300 audit(1644663255.785:81): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7ffec05d5880 a2=4 a3=3e8 items=0 ppid=395 pid=2286 auid=1000 uid=2 gid=2 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4 comm="atd" exe="/usr/bin/atd" key=(null) Feb 12 10:54:15 minikat kernel: audit: type=1327 audit(1644663255.785:81): proctitle=2F7573722F62696E2F617464002D66 Feb 12 10:54:15 minikat kernel: audit: type=1105 audit(1644663255.785:82): pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat kernel: audit: type=1103 audit(1644663255.785:83): pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat audit[2286]: SYSCALL arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7ffec05d5880 a2=4 a3=3e8 items=0 ppid=395 pid=2286 auid=1000 uid=2 gid=2 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4 comm="atd" exe="/usr/bin/atd" key=(null) Feb 12 10:54:15 minikat audit: PROCTITLE proctitle=2F7573722F62696E2F617464002D66 Feb 12 10:54:15 minikat audit[2286]: USER_START pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat audit[2286]: CRED_ACQ pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat atd[2286]: pam_unix(atd:session): session opened for user robin(uid=1000) by (uid=2) Feb 12 10:54:15 minikat atd[2286]: pam_env(atd:setcred): deprecated reading of user environment enabled Feb 12 10:54:15 minikat atd[2286]: pam_env(atd:setcred): deprecated reading of user environment enabled Feb 12 10:54:15 minikat audit[2286]: CRED_DISP pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat audit[2286]: USER_END pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat atd[2286]: pam_unix(atd:session): session closed for user robin Feb 12 10:54:15 minikat kernel: audit: type=1104 audit(1644663255.792:84): pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 10:54:15 minikat kernel: audit: type=1106 audit(1644663255.792:85): pid=2286 uid=2 auid=1000 ses=4 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' ############################################################################## A good run looks like this ############################################################################## This is the good run with linux-5.16.3.arch1-1-x86_64 and at-3.2.2-1-x86_64 Linux minikat 5.16.3-arch1-1 #1 SMP PREEMPT Thu, 27 Jan 2022 14:18:25 +0000 x86_64 GNU/Linux $ tatd warning: commands will be executed using /bin/sh job 4180 at Sat Feb 12 11:28:00 2022 ✔ Sat 12 Feb 11:28:00 GMT 2022 read OK robin@minikat:~ #no need for another run as the first has worked as expected ############################################################################## This is the good run with linux-5.16.3.arch1-1-x86_64 and at-3.2.2-1-x86_64 Linux minikat 5.16.3-arch1-1 #1 SMP PREEMPT Thu, 27 Jan 2022 14:18:25 +0000 x86_64 GNU/Linux Feb 12 11:28:00 minikat audit[1649]: USER_ACCT pid=1649 uid=2 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat audit[1649]: SYSCALL arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7fff512527b0 a2=4 a3=3e8 items=0 ppid=364 pid=1649 auid=1000 uid=2 gid=2 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4 comm="atd" exe="/usr/bin/atd" key=(null) Feb 12 11:28:00 minikat audit: PROCTITLE proctitle=2F7573722F62696E2F617464002D66 Feb 12 11:28:00 minikat audit[1649]: USER_START pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat audit[1649]: CRED_ACQ pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat atd[1649]: pam_unix(atd:session): session opened for user robin(uid=1000) by (uid=2) Feb 12 11:28:00 minikat atd[1649]: pam_env(atd:setcred): deprecated reading of user environment enabled Feb 12 11:28:00 minikat kernel: audit: type=1101 audit(1644665280.896:83): pid=1649 uid=2 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_time acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat kernel: audit: type=1006 audit(1644665280.896:84): pid=1649 uid=2 old-auid=4294967295 auid=1000 tty=(none) old-ses=4294967295 ses=4 res=1 Feb 12 11:28:00 minikat kernel: audit: type=1300 audit(1644665280.896:84): arch=c000003e syscall=1 success=yes exit=4 a0=7 a1=7fff512527b0 a2=4 a3=3e8 items=0 ppid=364 pid=1649 auid=1000 uid=2 gid=2 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4 comm="atd" exe="/usr/bin/atd" key=(null) Feb 12 11:28:00 minikat kernel: audit: type=1327 audit(1644665280.896:84): proctitle=2F7573722F62696E2F617464002D66 Feb 12 11:28:00 minikat kernel: audit: type=1105 audit(1644665280.896:85): pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat kernel: audit: type=1103 audit(1644665280.896:86): pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat kernel: audit: type=1104 audit(1644665280.903:87): pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat kernel: audit: type=1106 audit(1644665280.903:88): pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat audit[1649]: CRED_DISP pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix,pam_env acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat audit[1649]: USER_END pid=1649 uid=2 auid=1000 ses=4 msg='op=PAM:session_close grantors=pam_loginuid,pam_limits,pam_unix acct="robin" exe="/usr/bin/atd" hostname=? addr=? terminal=? res=success' Feb 12 11:28:00 minikat atd[1649]: pam_env(atd:setcred): deprecated reading of user environment enabled Feb 12 11:28:00 minikat atd[1649]: pam_unix(atd:session): session closed for user robin |
This task depends upon
Closed by Christian Hesse (eworm)
Monday, 28 February 2022, 13:05 GMT
Reason for closing: Fixed
Additional comments about closing: at 3.2.5-1
Monday, 28 February 2022, 13:05 GMT
Reason for closing: Fixed
Additional comments about closing: at 3.2.5-1
Reloading system manager configuration...
this doesn't seem to affect behaviour. I do see a difference after
sudo systemctl restart atd
and indeed the problem is repaired with a full transition at 3.2.4-1 => 3.2.2-1. Looking at the repo history
https://salsa.debian.org/debian/at/-/commit/ed66814021a342580ebee57bcbae58d71b82164f
it seems timer changes were made in atd.c so it's likely this is an issue/conflict with an upstream change.
Hast the issue been reported upstream?
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1004972
I will try building from the latest upstream and see if it fixes my problems.