Community Packages

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!
Tasklist

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
Task Type Bug Report
Category Packages
Status Closed
Assigned To Christian Hesse (eworm)
Architecture All
Severity High
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

Description:
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
Comment by Robin Becker (replabrobin) - Sunday, 13 February 2022, 10:33 GMT
I refined the problem somewhat. It seems the problem lies exclusively in the transition of at between 3.2.2-1 => 3.2.4-1. I got confused because although pkg installation says

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.
Comment by Christian Hesse (eworm) - Tuesday, 15 February 2022, 09:36 GMT
Uh, will have to look into this in detail...
Hast the issue been reported upstream?
Comment by Robin Becker (replabrobin) - Tuesday, 15 February 2022, 09:54 GMT
I have not seen this elsewhere. In addition I have another (unmentionable non-systemd x86_64) Arch derivative where version 3.2.4 behaves as expected so the at change may not be the whole issue.
Comment by Robin Becker (replabrobin) - Monday, 28 February 2022, 12:50 GMT
There's an upstream bug report here

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.
Comment by Christian Hesse (eworm) - Monday, 28 February 2022, 13:05 GMT
Pushed the latest release, should fix the issue. Thanks!

Loading...