test-logprof.py from test_utils_testsuite / test_utils_testsuite3 in ubuntu_qrt_apparmor failing on Azure Standard_A2_v2

[Po-Hsu Lin]

This issue can be found on M-generic 6.5.0-34.34 and M-lowlatency 6.5.0-27.28.1 on Azure instance Standard_A2_v2

The test-logprof.py test from ApparmorTestsuites.test_utils_testsuite and test_utils_testsuite3 failed with:
$ sudo python3 ./test-logprof.py
E
======================================================================
ERROR: test_0 (__main__.TestLogprof.test_0)
test 'ping'
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/mine/source/mantic/apparmor-4.0.0~alpha2/utils/test/common_test.py", line 90, in stub_test
    self._run_test(test_data, expected)
  File "/tmp/mine/source/mantic/apparmor-4.0.0~alpha2/utils/test/./test-logprof.py", line 99, in _run_test
    self.process.wait(timeout=0.2)
  File "/usr/lib/python3.11/subprocess.py", line 1264, in wait
    return self._wait(timeout=timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/subprocess.py", line 2038, in _wait
    raise TimeoutExpired(self.args, timeout)
subprocess.TimeoutExpired: Command '['/usr/bin/python3', '../aa-logprof', '--json', '--configdir', './', '-f', './logprof/ping.auditlog', '-d', '/tmp/aa-test-7feu1ddr/profiles', '--no-check-mountpoint']' timed out after 0.2 seconds

----------------------------------------------------------------------
Ran 1 test in 1.831s

FAILED (errors=1)

The fail rate is almost 100%, 3 successful out of 100 attempts

If you bump the timeout to 0.3 and it will pass. We need this patch to be backported to apparmor on Mantic, or keep it as a patch file in q-r-t:
https://gitlab.com/apparmor/apparmor/-/commit/dd9b7b358f0dd0887767a5840ed7f7499aa50ee6

[Po-Hsu Lin (cypressyew)]

This issue can be found on openstack ARM64 instance with M/M-lowlatency as well.

[Georgia Garcia (georgiag)]

I added the suggested patch to QRT:
https://code.launchpad.net/~georgiag/qa-regression-testing/+git/qa-regression-testing/+merge/465526

[Po-Hsu Lin (cypressyew)]

Hello Garcia,
thanks for add that patch, I can see that we're now using this 0.3 seconds timeout now.

However we have found there are still some exceptions that will still fail with this 0.3 seconds timeout:
* M-lowlatency-64k 6.5.0-41.41.1 openstack ARM64 instance
* M-lowlatency 6.5.0-41.41.1 bare-metal ARM64 node "wright-kerenl"
* M-64k 6.5.0-41.41 openstack ARM64 instance

Perhaps we will need a longer timeout.

[Christian Boltz (cboltz)]

There are several places in test-logprof.py with a 0.3s timeout. Can you please show the detailed error message to make it clear where we need a longer timeout?

[Po-Hsu Lin (cypressyew)]

Hi Christian,
sorry for the late reply, I saw the following failure with Noble-lowlatency 6.8.0-36.36.1 AMR64 instances on openstack:

 ERROR: test_0 (__main__.TestLogprof.test_0)
 test 'ping'
 ----------------------------------------------------------------------
 Traceback (most recent call last):
   File "/tmp/testlib3kk_zswu/source/noble/apparmor-4.0.0-beta3/utils/test/common_test.py", line 90, in stub_test
     self._run_test(test_data, expected)
   File "/tmp/testlib3kk_zswu/source/noble/apparmor-4.0.0-beta3/utils/test/test-logprof.py", line 99, in _run_test
     self.process.wait(timeout=0.3)
   File "/usr/lib/python3.12/subprocess.py", line 1264, in wait
     return self._wait(timeout=timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/usr/lib/python3.12/subprocess.py", line 2045, in _wait
     raise TimeoutExpired(self.args, timeout)
 subprocess.TimeoutExpired: Command '['/usr/bin/python3', '../aa-logprof', '--json', '--configdir', './', '-f', './logprof/ping.auditlog', '-d', '/tmp/aa-test-wcpdfssw/profiles', '--no-check-mountpoint']' timed out after 0.3 seconds

 ----------------------------------------------------------------------
 Ran 1 test in 3.599s
 ERROR: test_0 (__main__.TestLogprof.test_0)
 test 'ping'
 ----------------------------------------------------------------------
 Traceback (most recent call last):
   File "/tmp/testlib3kk_zswu/source/noble/apparmor-4.0.0-beta3/utils/test/common_test.py", line 90, in stub_test
     self._run_test(test_data, expected)
   File "/tmp/testlib3kk_zswu/source/noble/apparmor-4.0.0-beta3/utils/test/test-logprof.py", line 99, in _run_test
     self.process.wait(timeout=0.3)
   File "/usr/lib/python3.12/subprocess.py", line 1264, in wait
     return self._wait(timeout=timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
   File "/usr/lib/python3.12/subprocess.py", line 2045, in _wait
     raise TimeoutExpired(self.args, timeout)
 subprocess.TimeoutExpired: Command '['/usr/bin/python3', '../aa-logprof', '--json', '--configdir', './', '-f', './logprof/ping.auditlog', '-d', '/tmp/aa-test-wcpdfssw/profiles', '--no-check-mountpoint']' timed out after 0.3 seconds

 ----------------------------------------------------------------------
 Ran 1 test in 3.599s

[Christian Boltz (cboltz)]

Thanks!

https://gitlab.com/apparmor/apparmor/-/merge_requests/1268 increases the timeout to 0.4 seconds.

[Georgia Garcia (georgiag)]

Added to QRT in MR https://code.launchpad.net/~georgiag/qa-regression-testing/+git/qa-regression-testing/+merge/468941

[Brian Murray (brian-murray)]

Ubuntu 23.10 (Mantic Minotaur) has reached end of life, so this bug will not be fixed for that specific release.