Heisenbug: `tests/su/10_su_sulog_success/su.test`
alejandro-colomar opened this issue · 2 comments
I've seen that test fail in a PR, in which I wouldn't expect it to fail. When trying to reproduce it, I wasn't able, not even in the same PR. Let's just document that it has happened, in case we see it again.
The only thing we know until now, is that the following failed once:
tests/su/10_su_sulog_success/su.test
And it was in
Here's the action that failed:
I've experienced it again, spuriously in a branch that has been working for a long time, and without any changes (just reorganizing the commits internally), it failed in one rebase, and worked again in the next. Here are the logs:
set -e
cd tests
trap 'cat testsuite.log' ERR
sudo ./run_some
trap - ERR
shell: /usr/bin/script -q -e -c "bash {0}"
+: test passed
-: test failed
.+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++-++++++++++++
75 test(s) passed
1 test(s) failed
log written in 'testsuite.log'
the following tests failed:
./su/10_su_sulog_success/su.test
###############################################################################
#
# Test: ./su/10_su_sulog_success/su.test
#
###############################################################################
#
# Rationale: su can be used to switch to a non-root user
#
###############################################################################
# switch to the passwordless 'testsuite' user
# and expect a '$ ' prompt
spawn /bin/su testsuite
<r/work/shadow/shadow/tests/su/10_su_sulog_success$
# make sure we are now 'testsuite'
# id should return 'uid=424243(testsuite) gid=424243 groups=424243'
<r/work/shadow/shadow/tests/su/10_su_sulog_success$ id
uid=424243(testsuite) gid=424243 groups=424243
<r/work/shadow/shadow/tests/su/10_su_sulog_success$
# now switch to user 'myuser'
# and expect a password prompt
<r/work/shadow/shadow/tests/su/10_su_sulog_success$ su myuser
Password:
# password 'myuserF00barbaz' sent
# expect prompt '$ '
myuser@fv-az665-93:~/runner/work/shadow/shadow/tests/su/10_su_sulog_success$
# make sure we are 'myuser'
# id should return '(myuser).*(myuser).*(myuser)
myuser@fv-az665-93:~/runner/work/shadow/shadow/tests/su/10_su_sulog_success$
<work/shadow/shadow/tests/su/10_su_sulog_success$ id �������������������������
uid=424242(myuser) gid=424242(myuser) groups=424242(myuser)
myuser@fv-az665-93:~/runner/work/shadow/shadow/tests/su/10_su_sulog_success$
<rk/shadow/shadow/tests/su/10_su_sulog_success$ exit �������������������������
exit
PASS
Check /var/log/sulog...--- tmp/sulog 2024-04-15 09:46:00.007612162 +0000
+++ data/sulog 2024-04-15 09:41:43.570603193 +0000
@@ -1,3 +1 @@
2 /var/log/sulog
-SU 04/15 09:45 + /dev/pts/2 root-testsuite
-SU 04/15 09:45 + /dev/pts/2 testsuite-myuser
###############################################################################
#
# Status of test ./su/10_su_sulog_success/su.test: FAILURE
#
###############################################################################
Here are the logs:
https://github.com/shadow-maint/shadow/actions/runs/8686919201/job/23819371890#step:9:3544
This sounds like Undefined Behavior somewhere? @hallyn , would you mind having a look at it?
It could be a race condition in the test, maybe? I hope it's not a bug in id(1) (although id(1) is not setuid, so it wouldn't be that bad).