At commands not working on tumbleweed/wsl2: Exec failed for mail command: No such file or directory

ray_gllisse · March 5, 2025, 1:30pm

Hi,
I am using tumbleweed on WSL2
I have installed at command, checked atd was active and running
When I submit a request with at command, it gets listed according to atq but doesn’t get executed
Example of command submitted:
$ at now +1 minutes <<E

echo “Hello”>>/home/cedric/tmp/at_cmd_res.txt
E
ls -l /home/cedric/tmp/at_cmd_res.txt
-rw-rw-rw- 1 cedric cedric 37 Mar 5 12:36 /home/cedric/tmp/at_cmd_res.txt

Checking journalcl -xe output , there’s an error message:
Exec failed for mail command: No such file or directory

which mail pointed to /usr/bin/mail which was a symbolink link to /usr/bin/alts

lrwxrwxrwx 1 root root 4 Feb 23 2024 /usr/bin/mail → alts
12:56 cedric@kakakopSuseWsl:~$ ls -l /usr/bin/alts

I tried to mock an email agent by making /usr/bin/mail be a symbolic link to a script that just echoes “hello from fake mail”

$ sudo ln -f -s ~/.local/bin/mail /usr/bin/
13:00 cedric@kakakopSuseWsl:~$ sh mail
hello from fake mail

Still, the same error message gets listed by journalctl -xe and commands don’t get executed

The same at commands work on Ubuntu22-04 on wsl2
Any idea ?
Thanks !

arvidjaar · March 5, 2025, 1:33pm

strace whatever command produced this error message, find out what it does.

ray_gllisse · March 5, 2025, 1:45pm

I guess the message is output by atd without being 100% sure of it, but how can I strace atd ?
I have also tried without luck to submit command with at -M flag, to show that I don’t want any email to be send

arvidjaar · March 5, 2025, 1:47pm

strace -p PID-of-atd

ray_gllisse · March 5, 2025, 1:53pm

Thanks,
Here’s the output captured when the same at command was submitted

14:49 cedric@kakakopSuseWsl:~$ sudo strace -p 123784
strace: Process 123784 attached
restart_syscall(<... resuming interrupted clock_nanosleep ...>) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=173776, si_uid=1000} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
newfstatat(AT_FDCWD, ".", {st_mode=S_IFDIR|S_ISVTX|0770, st_size=4096, ...}, 0) = 0
openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
fstat(4, {st_mode=S_IFDIR|S_ISVTX|0770, st_size=4096, ...}) = 0
getdents64(4, 0x555b6eeff400 /* 4 entries */, 32768) = 112
newfstatat(AT_FDCWD, "a0000f01bace3e", {st_mode=S_IFREG|0700, st_size=13413, ...}, 0) = 0
getdents64(4, 0x555b6eeff400 /* 0 entries */, 32768) = 0
close(4)                                = 0
timer_settime(0, TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=1741182600, tv_nsec=0}}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=5, tv_nsec=0}, {tv_sec=0, tv_nsec=513297381}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGHUP {si_signo=SIGHUP, si_code=SI_TIMER, si_timerid=0, si_overrun=0, si_int=1427898496, si_ptr=0x555b551c0080} ---
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
newfstatat(AT_FDCWD, ".", {st_mode=S_IFDIR|S_ISVTX|0770, st_size=4096, ...}, 0) = 0
openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
fstat(4, {st_mode=S_IFDIR|S_ISVTX|0770, st_size=4096, ...}) = 0
getdents64(4, 0x555b6eeff400 /* 4 entries */, 32768) = 112
newfstatat(AT_FDCWD, "a0000f01bace3e", {st_mode=S_IFREG|0700, st_size=13413, ...}, 0) = 0
setreuid(474, 0)                        = 0
setregid(474, 0)                        = 0
link("a0000f01bace3e", "=0000f01bace3e") = 0
setregid(0, 474)                        = 0
setreuid(0, 474)                        = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f8b9fd88ad0) = 173814
getdents64(4, 0x555b6eeff400 /* 0 entries */, 32768) = 0
close(4)                                = 0
timer_settime(0, TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=1741186200, tv_nsec=0}}, NULL) = 0
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=3600, tv_nsec=0}, {tv_sec=3599, tv_nsec=962046225}) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=173814, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 173814
wait4(-1, 0x7ffd4ef69764, WNOHANG, NULL) = -1 ECHILD (No child processes)
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
newfstatat(AT_FDCWD, ".", {st_mode=S_IFDIR|S_ISVTX|0770, st_size=4096, ...}, 0) = 0
openat(AT_FDCWD, ".", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4

I am not used to using strace, is this output useful ?

arvidjaar · March 5, 2025, 1:56pm

It forks so you need to follow childs as well.

strace -f ...

See man strace.

ray_gllisse · March 5, 2025, 2:06pm

Ok,
The output is 2000 lines long, what should be looked for ?
Isn’t it another way to find out why atd doesn’t work as expected than looking for system calls ?

arvidjaar · March 5, 2025, 2:42pm

You can upload it to the https://paste.opensuse.org/

Read man page if it has any debug option, try running it with these debug options.

ray_gllisse · March 5, 2025, 4:58pm

Here is the strace file of atd
I have tried to grep for ‘fail’ ‘mail’ and looked for exec syscall

cat ~/tmp/strace_atd | egrep 'exec.{0,2}\(' 
[pid 178393] execve("/usr/sbin/unix_chkpwd", ["/usr/sbin/unix_chkpwd", "cedric", "chkexpiry"], 0x7f8b9fd03228 /* 0 vars */) = 0
[pid 178398] execve("/bin/sh", ["sh"], 0x7ffd4ef69a28 /* 0 vars */) = 0

neither exited with non-zero value

I tried to use AI to get some help about this strace …
Actually, I also tried atd on opensuse on my laptop on a bare metal installation, not on WSL2, then I don’t get any erro messages but no commands are executed although they appear in at queue using atq
Thanks for your help !

ray_gllisse · March 5, 2025, 5:17pm

back on wsl2, I stopped atd that was started by systemd and launched it in foreground with debug option:

~$ sudo /usr/sbin/atd -d -f

Then I issued on another terminal an at command that got queued but not executed without error message on the terminal where the at command was issued, nor on the one where atd is in foreground, and this time journalctl -xe didn’t show any errors …

arvidjaar · March 5, 2025, 5:44pm

Out of curiosity I installed at on Tumbleweed and I cannot reproduce it. I do not have any mail command at all. So far

Your error message does not say /bin/mail or anything similar - it says “mail command” which could be anything.
There is no evidence that this message comes from atd.

Show the actual logs not some random line out of nowhere. Start in one terminal as root

journalctl --full --no-pager --follow

run your at job in another terminal and post journalctl output.

ray_gllisse · March 5, 2025, 6:06pm

Here is the journalctl output with atd launched in the foreground by command sudo /usr/sbin/atd -d -f

Mar 05 18:53:41 kakak sudo[9036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 05 18:53:41 kakak sudo[9036]: pam_unix(sudo:session): session closed for user root
Mar 05 18:53:41 kakak sudo[9042]:   cedric : TTY=pts/12 ; PWD=/home/cedric ; USER=root ; COMMAND=/usr/bin/systemctl status postgresql
Mar 05 18:53:41 kakak sudo[9042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 05 18:53:41 kakak sudo[9042]: pam_unix(sudo:session): session closed for user root
Mar 05 18:53:41 kakak sudo[9048]:   cedric : TTY=pts/12 ; PWD=/home/cedric ; USER=root ; COMMAND=/usr/bin/systemctl status cron
Mar 05 18:53:41 kakak sudo[9048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 05 18:53:41 kakak sudo[9048]: pam_unix(sudo:session): session closed for user root
Mar 05 18:53:49 kakak sudo[9202]:   cedric : TTY=pts/11 ; PWD=/home/cedric ; USER=root ; COMMAND=/usr/sbin/atd -d -f
Mar 05 18:53:49 kakak sudo[9202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 05 18:58:00 kakak systemd[1]: Started Session c15 of User cedric.
Mar 05 18:58:00 kakak atd[9429]: pam_unix(atd:session): session opened for user cedric(uid=1000) by cedric(uid=474)
Mar 05 18:58:00 kakak atd[9429]: pam_unix(atd:session): session closed for user cedric
Mar 05 18:58:00 kakak systemd[1]: session-c15.scope: Deactivated successfully.
Mar 05 19:00:00 kakak CRON[9464]: (root) CMD (run-parts /etc/cron.hourly)
Mar 05 19:00:00 kakak CRON[9463]: (root) CMDEND (run-parts /etc/cron.hourly)

No errors, but the file is not written, nothing happens

arvidjaar · March 5, 2025, 7:19pm

You did not describe what you did nor what you expected to happen.

ray_gllisse · March 5, 2025, 7:38pm

$ at now +1 minutes
warning: commands will be executed using /bin/sh
at Wed Mar 5 20:35:00 2025
at> echo hello >/home/cedric/tmp/a.txt
at>
job 31 at Wed Mar 5 20:35:00 2025
20:34 cedric@kakakopSuseWsl:~$ atq
31 Wed Mar 5 20:35:00 2025 a cedric

The file /home/cedric/tmp/a.txt doesn’t get modified

arvidjaar · March 6, 2025, 4:16am

[pid 178398] execve("/bin/sh", ["sh"], 0x7ffd4ef69a28 /* 0 vars */) = 0
...
[pid 178398] read(0, "#!/bin/sh\n# atrun uid=1000 gid=1"..., 8192) = 8192
[pid 178398] umask(022)                 = 022
[pid 178398] fstat(2, {st_mode=S_IFREG|0600, st_size=51, ...}) = 0
[pid 178398] write(2, "sh: line 26: BASHOPTS: readonly "..., 41) = 41
[pid 178398] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
[pid 178398] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 178398] exit_group(1)              = ?

Examine file at created, try to run it manually, see what it does and why it fails. That is how you debug the problems.

The strace output already provides the hint what is wrong.

ray_gllisse · March 6, 2025, 2:15pm

Hello,
Thanks for your help !
I am not sure to understand the hints you gave
Which file has at created ?
between line 1873 : execve(“/bin/sh”, [“sh”], 0x7ffd4ef69a28 /* 0 vars */) = 0 and
line 2047 [pid 178398] exit_group(1) = ?
the process tries to open several libraries that are missing, but there are no
file created by pid 178398 between those 2 system calls , at least no file created with open or openat with O_CREAT and no creat syscall neither between lines 1873 and 2047

Sorry if my answer is dumb, it’s the first time I am looking in sys calls to try to debug a program

arvidjaar · March 6, 2025, 2:25pm

write(2, "sh: line 26: BASHOPTS: readonly "..., 41) = 41

ray_gllisse · March 6, 2025, 3:09pm

sh writes on stderr a message saying on line 26 BASHOPTS: readonly
before that message, there’s a read syscall:
read(0, “#!/bin/sh\n# atrun uid=1000 gid=1”…, 8192) = 8192

I guess the error message is related to the data read from stdin after redirection of stdin to a regular file. But I don’t see where a file redirection has been done. No dup2 instruction
Thus I don’t see which script is executed by sh provoking an error message with the execution of its 26th line
Do you have more hints ?

ray_gllisse · March 6, 2025, 3:30pm

using this command find ~cedric -maxdepth 1 -type f -exec grep -nH BASHOPTS {} ;
I found among the different results this line
/home/cedric/.bash_history:2190:echo 'sh: line 26: BASHOPTS: readonly '|wc -c
Thus I encountered in the past, this same error message, and did a character count with wc but no idea what this was for.

ray_gllisse · March 6, 2025, 4:00pm

I finally found the error thanks to you , I had written an “export BASHOPTS” instruction in my ~/.bashrc
Googling, I found a post telling not to export BASHOPTS as it is not a environment variable
After deletion of this export BASHOPTS instruction, atd restart and new bash program launched without this faulty instruction, it works !!
Strangely though, I don’t find in the strace file any mention of this ~/.bashrc file, probably because it has been loaded by atd before I connected strace to the atd process
This slight error in ~/.bashrc doesn’t prevent atd from running jobs on ubuntu or kali .