Heisenbug: `tests/su/10_su_sulog_success/su.test`

[alejandro-colomar]

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

• https://github.com/shadow-maint/shadow/pull/955

[alejandro-colomar]

Here's the action that failed:

• https://github.com/shadow-maint/shadow/actions/runs/7988856130

[alejandro-colomar]

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