Flaky tests TestExecModule/Item_Set_user and TestExecModule/Item_Setting_and_getting_an_user

[adombeck]

Examples of failing CI jobs:

• https://github.com/ubuntu/authd/actions/runs/15611824409/job/43974369489
• https://github.com/ubuntu/authd/actions/runs/15642453208/job/44072755005
• https://github.com/ubuntu/authd/actions/runs/15685469571/job/44187418265

❌ TestExecModule/Item_Set_user (20ms)
      exec_test.go:387: Created service file at /tmp/TestExecModuleItem_Set_user4020967284/002/exec-module
      exec_test.go:392: 
          	Error Trace:	/home/runner/work/authd-private/authd-private/pam/integration-tests/exec_test.go:392
          	Error:      	Not equal: 
          	            	expected: "an user"
          	            	actual  : ""
          	            	
          	            	Diff:
          	            	--- Expected
          	            	+++ Actual
          	            	@@ -1 +1 @@
          	            	-an user
          	            	+
          	Test:       	TestExecModule/Item_Set_user
          	Messages:   	Item 2 value mismatch
      helpers_test.go:328: Could not read artifact "/tmp/TestExecModuleItem_Set_user4020967284/001/exec-module.log": open /tmp/TestExecModuleItem_Set_user4020967284/001/exec-module.log: no such file or directory
❌ TestExecModule/Item_Setting_and_getting_an_user (20ms)
      exec_test.go:387: Created service file at /tmp/TestExecModuleItem_Setting_and_getting_an_user3085153475/002/exec-module
      exec_test.go:392: 
          	Error Trace:	/home/runner/work/authd-private/authd-private/pam/integration-tests/exec_test.go:392
          	Error:      	Not equal: 
          	            	expected: "the-user"
          	            	actual  : ""
          	            	
          	            	Diff:
          	            	--- Expected
          	            	+++ Actual
          	            	@@ -1 +1 @@
          	            	-the-user
          	            	+
          	Test:       	TestExecModule/Item_Setting_and_getting_an_user
          	Messages:   	Item 2 value mismatch
      helpers_test.go:328: Could not read artifact "/tmp/TestExecModuleItem_Setting_and_getting_an_user3085153475/001/exec-module.log": open /tmp/TestExecModuleItem_Setting_and_getting_an_user3085153475/001/exec-module.log: no such file or directory

[adombeck]

These tests are old (added in March 2024), but I only recall seeing them fail in the last few weeks 🤔

[3v1n0]

See for example: https://github.com/ubuntu/authd/actions/runs/15642453208/job/44072755005

helpers_test.go:328: Could not read artifact "/tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log": open /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log: no such file or directory

The interesting part here is that exec-module.log is not there, but it's one of the first thing that the module should have created as we use a service file such as:

auth	[success=done new_authtok_reqd=done ignore=ignore default=die]	/tmp/TestExecModule2702653366/001/pam_authd_exectestexecmodule.so	--exec-debug --exec-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log -- /tmp/TestExecModule2702653366/002/exec-client -client-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log [{"act": <"SetItem">, "args": <[<2>, <"an user">\]>}]
auth	requisite	pam_debug.so auth=incomplete cred=incomplete acct=incomplete prechauthtok=incomplete chauthtok=incomplete open_session=incomplete close_session=incomplete
account	[success=done new_authtok_reqd=done ignore=ignore default=die]	/tmp/TestExecModule2702653366/001/pam_authd_exectestexecmodule.so	--exec-debug --exec-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log -- /tmp/TestExecModule2702653366/002/exec-client -client-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log [{"act": <"SetItem">, "args": <[<2>, <"an user">\]>}]
account	requisite	pam_debug.so auth=incomplete cred=incomplete acct=incomplete prechauthtok=incomplete chauthtok=incomplete open_session=incomplete close_session=incomplete
password	[success=done new_authtok_reqd=done ignore=ignore default=die]	/tmp/TestExecModule2702653366/001/pam_authd_exectestexecmodule.so	--exec-debug --exec-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log -- /tmp/TestExecModule2702653366/002/exec-client -client-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log [{"act": <"SetItem">, "args": <[<2>, <"an user">\]>}]
password	requisite	pam_debug.so auth=incomplete cred=incomplete acct=incomplete prechauthtok=incomplete chauthtok=incomplete open_session=incomplete close_session=incomplete
session	[success=done new_authtok_reqd=done ignore=ignore default=die]	/tmp/TestExecModule2702653366/001/pam_authd_exectestexecmodule.so	--exec-debug --exec-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log -- /tmp/TestExecModule2702653366/002/exec-client -client-log /tmp/TestExecModuleItem_Set_user877767020/001/exec-module.log [{"act": <"SetItem">, "args": <[<2>, <"an user">\]>}]
session	requisite	pam_debug.so auth=incomplete cred=incomplete acct=incomplete prechauthtok=incomplete chauthtok=incomplete open_session=incomplete close_session=incomplete

So... I'm wondering, isn't the client even started? We always use the same log file, but in theory the logs are appended and the various calls happens through performAllPAMActions that does not parallel tests

[3v1n0]

Oh, maybe that's testing.go:1399: race detected during execution of test ?!

[adombeck]

I also see it in non-race tests, e.g. https://github.com/ubuntu/authd/actions/runs/15611824409/job/43974369489

[3v1n0]

My feeling is more related to races of pam.go itself here, maybe we can avoid by some os locking... Let's try

[3v1n0]

Maybe is something like this https://github.com/ubuntu/authd/actions/runs/15703467996/job/44243650461? Although that fails since the client crashes somehow...