Intermittent failure in feature_startupnotify.py #25644

On the master branch: https://cirrus-ci.com/task/6066973032316928

172/245 - feature_startupnotify.py failed, Duration: 2 s
stdout:
2022-07-19T08:56:44.366000Z TestFramework (INFO): Initializing test directory C:\Users\ContainerAdministrator\AppData\Local\Temp\test_runner_₿_🏃_20220719_080912\feature_startupnotify_71
2022-07-19T08:56:44.962000Z TestFramework (INFO): Test -startupnotify command is run when node starts
2022-07-19T08:56:46.019000Z TestFramework (INFO): Test -startupnotify is executed once
2022-07-19T08:56:46.019000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\test_framework.py", line 133, in main
    self.run_test()
  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\feature_startupnotify.py", line 34, in run_test
    assert_equal(file_content.count(FILE_NAME), 1)
  File "C:\Users\ContainerAdministrator\AppData\Local\Temp\cirrus-ci-build\test\functional\test_framework\util.py", line 51, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(0 == 1)

Didn't find an existing open issue but looks to be the same Win64 CI failure reported in #23967 (comment).

Another one https://cirrus-ci.com/task/6651261758996480

https://cirrus-ci.com/task/5251963611774976?logs=functional_tests#L45

Does echo flush on windows? If not, it could make sense to call sync after echo (if that is possible), or run wait_until?

This is likely caused by filesystem virtualization (e.g. C:\Windows\System32 to C:\Windows\SysWow64) if the call does not use a proper authorization token for administrator elevation. The basic "system()" call of the C RTL does not do that.

So you need to run the system() call by first providing a starting "current directory" that is accessible to the user with which the command will be executed; if you don't, the process will be created with a default directory, and not necessarily the "home" folder of that user. Notice that you're attempting to run a Python command from within a Container (which implements virtualization of the filesystem, redirecting them to other locations in the temp folder, and some other resources like the registry). May be instead of using "system()" from the C RTL on Windows, we should use the native Win32 API "CreateProcess[AW]" that allows you to specify more completely the startup environment, plus passing some other authorization tokens (e.g. for UAC)?

Or is it specific to the external Python installation, forcing it to run in a sandboxing container? Do you use Python downloaded from the MS Store and running as an UWP app or the native installation? Another alternative is to not start Python directly, but start a .CMD shell script (or a shortcut) stored in the user environment, and then let that script select the proper working directory to launch Python and passing it its parameters.

This is likely caused by filesystem virtualization (...)

This sounds like a deterministic explanation, why would it lead to failures that are intermittent?

While this should be trivial to fix if my guess is right that Windows is lacking a sync (https://github.com/bitcoin/bitcoin/issues/25644#issuecomment-1203844130), this shouldn't hold up 24.0, so removed the milestone.

https://cirrus-ci.com/task/4922376723365888 No longer Windows only, this was the macOs job.

And Linux :(

https://cirrus-ci.com/task/5400637706338304?logs=ci#L3516

 test  2023-01-04T10:36:17.921000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 134, in main
                                       self.run_test()
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/feature_startupnotify.py", line 34, in run_test
                                       assert_equal(file_content.count(FILE_NAME), 1)
                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/util.py", line 56, in assert_equal
                                       raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
                                   AssertionError: not(0 == 1)

If this helps fix the issue: I'm able to reproduce the failure in about 10 seconds with rr in chaos mode.

seq 1000 | xargs -i -P 64 rr record --chaos python test/functional/feature_startupnotify.py

(executes 1000 runs of rr in batches of 64)

2023-01-04T13:34:22.841000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/home/aureleoules/Projects/bitcoin/test/functional/test_framework/test_framework.py", line 134, in main
    self.run_test()
  File "/home/aureleoules/Projects/bitcoin/test/functional/feature_startupnotify.py", line 34, in run_test
    assert_equal(file_content.count(FILE_NAME), 1)
  File "/home/aureleoules/Projects/bitcoin/test/functional/test_framework/util.py", line 56, in assert_equal
    raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
AssertionError: not(0 == 1)
2023-01-04T13:34:22.857000Z TestFramework (INFO): Initializing test directory /run/user/1000/bitcoin_func_test_zknwzzne

If you run with #26811 it will print an empty string?

I was curious to try @aureleoules rr program and #26811 did indeed print an empty string L14:

  1   2023-01-04T14:29:54.686000Z TestFramework (DEBUG): PRNG seed is: 7643513174202788517
    1 2023-01-04T14:29:54.686000Z TestFramework (DEBUG): Setting up network thread
    2 2023-01-04T14:29:54.688000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_3urm5j1v
    3 2023-01-04T14:29:54.688000Z TestFramework (DEBUG): Copy cache directory /home/will/src/bitcoin/test/cache/node0 to node 0
    4 2023-01-04T14:29:55.883000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
    5 2023-01-04T14:29:56.866000Z TestFramework.node0 (DEBUG): RPC successfully started
    6 2023-01-04T14:29:56.869000Z TestFramework (DEBUG): Generate a block with current time
    7 2023-01-04T14:29:56.869000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
    8 2023-01-04T14:29:57.047000Z TestFramework (INFO): Test -startupnotify command is run when node starts
    9 2023-01-04T14:29:57.047000Z TestFramework.node0 (DEBUG): Stopping node
   10 2023-01-04T14:29:57.385000Z TestFramework.node0 (DEBUG): Node stopped
   11 2023-01-04T14:29:57.455000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
   12 2023-01-04T14:29:59.014000Z TestFramework.node0 (DEBUG): RPC successfully started
   13 2023-01-04T14:29:59.140000Z TestFramework (INFO): Test -startupnotify is executed once
   14 2023-01-04T14:29:59.141000Z TestFramework (DEBUG): Read
   15 2023-01-04T14:29:59.142000Z TestFramework (ERROR): Assertion failed
   16 Traceback (most recent call last):
   17   File "/home/will/src/bitcoin/test/functional/test_framework/test_framework.py", line 134, in main
   18     self.run_test()
   19   File "test/functional/feature_startupnotify.py", line 35, in run_test
   20     assert_equal(file_content.count(FILE_NAME), 1)
   21   File "/home/will/src/bitcoin/test/functional/test_framework/util.py", line 56, in assert_equal
   22     raise AssertionError("not(%s)" % " == ".join(str(arg) for arg in (thing1, thing2) + args))
   23 AssertionError: not(0 == 1)
   24 2023-01-04T14:29:59.156000Z TestFramework (DEBUG): Closing down network thread
   25 2023-01-04T14:29:59.213000Z TestFramework (INFO): Stopping nodes
   26 2023-01-04T14:29:59.213000Z TestFramework.node0 (DEBUG): Stopping node
   27 2023-01-04T14:29:59.649000Z TestFramework.node0 (DEBUG): Node stopped
   28 2023-01-04T14:29:59.649000Z TestFramework (WARNING): Not cleaning up dir /tmp/bitcoin_func_test_3urm5j1v
   29 2023-01-04T14:29:59.649000Z TestFramework (ERROR): Test failed. Test logging available at /tmp/bitcoin_func_test_3urm5j1v/test_framework.log
   30 2023-01-04T14:29:59.650000Z TestFramework (ERROR):
   31 2023-01-04T14:29:59.651000Z TestFramework (ERROR): Hint: Call /home/will/src/bitcoin/test/functional/combine_logs.py '/tmp/bitcoin_func_test_3urm5j1v' to consolidate all logs
   32 2023-01-04T14:29:59.651000Z TestFramework (ERROR):
   33 2023-01-04T14:29:59.652000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
   34 2023-01-04T14:29:59.652000Z TestFramework (ERROR): https://github.com/bitcoin/bitcoin/issues
   35 2023-01-04T14:29:59.652000Z TestFramework (ERROR):

edit: FWIW I had to run rr with record command e.g.: rr record --chaos -n python test/functional/feature_startupnotify.py otherwise the --chaos flag didn't work

There'd be https://docs.python.org/3.8/library/os.html#os.sync , but it only works on Unix.

If no one knows how to fix the test, it should be disabled temporarily to not waste CI resources further.