test: Wait before cleanup on exit

Empact commented at 7:34 am on January 15, 2019: member

This operation can fail due to log file contention, waiting should reduce this occurance.

An alternative is to retry, but that requires quite a few lines in Python so this seems more appropriate.

 0[00:27:35] Traceback (most recent call last):
 1[00:27:35]   File "C:\projects\bitcoin/test/functional/feature_notifications.py", line 88, in <module>
 2[00:27:35]     NotificationsTest().main()
 3[00:27:35]   File "C:\projects\bitcoin\test\functional\test_framework\test_framework.py", line 223, in main
 4[00:27:35]     shutil.rmtree(self.options.tmpdir)
 5[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 507, in rmtree
 6[00:27:35]     return _rmtree_unsafe(path, onerror)
 7[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 386, in _rmtree_unsafe
 8[00:27:35]     _rmtree_unsafe(fullname, onerror)
 9[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 386, in _rmtree_unsafe
10[00:27:35]     _rmtree_unsafe(fullname, onerror)
11[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 391, in _rmtree_unsafe
12[00:27:35]     onerror(os.unlink, fullname, sys.exc_info())
13[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 389, in _rmtree_unsafe
14[00:27:35]     os.unlink(fullname)
15[00:27:35] PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\appveyor\\AppData\\Local\\Temp\\1\\test_runner_20190115_020102\\feature_notifications_45\\node0\\regtest\\debug.log'

https://ci.appveyor.com/project/DrahtBot/bitcoin/builds/21618398

fanquake added the label Tests on Jan 15, 2019

promag commented at 12:46 pm on January 15, 2019: member

but that requires quite a few lines in Python

I think it’s preferable.

laanwj commented at 2:06 pm on January 15, 2019: member

Retrying is definitely preferable—fixed waits are a waste of valuable testing time when they’re not necessary, and fragile otherwise.

MarcoFalke commented at 4:43 pm on January 15, 2019: member

Why is shutdown not blocking until the logs are flushed :(

Empact force-pushed on Jan 15, 2019

in test/functional/test_framework/util.py:207 in 803c1db954 outdated

200@@ -201,6 +201,14 @@ def str_to_b64str(string):
201 def satoshi_round(amount):
202     return Decimal(amount).quantize(Decimal('0.00000001'), rounding=ROUND_DOWN)
203 
204+def no_exception(predicate, action):
205+    try:
206+        predicate()
207+    except Exception as e:

MarcoFalke commented at 10:32 pm on January 15, 2019:

I’d prefer to pass in the exception here over a wildcard . Or, since this is only used once, could just make the function def inline in test_framework.py

Empact force-pushed on Jan 15, 2019

test: Wait before cleanup on exit

This operation can fail due to log file contention, retrying should reduce this occurance.

[00:27:35] Traceback (most recent call last):
[00:27:35]   File "C:\projects\bitcoin/test/functional/feature_notifications.py", line 88, in <module>
[00:27:35]     NotificationsTest().main()
[00:27:35]   File "C:\projects\bitcoin\test\functional\test_framework\test_framework.py", line 223, in main
[00:27:35]     shutil.rmtree(self.options.tmpdir)
[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 507, in rmtree
[00:27:35]     return _rmtree_unsafe(path, onerror)
[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 386, in _rmtree_unsafe
[00:27:35]     _rmtree_unsafe(fullname, onerror)
[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 386, in _rmtree_unsafe
[00:27:35]     _rmtree_unsafe(fullname, onerror)
[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 391, in _rmtree_unsafe
[00:27:35]     onerror(os.unlink, fullname, sys.exc_info())
[00:27:35]   File "C:\Python37-x64\lib\shutil.py", line 389, in _rmtree_unsafe
[00:27:35]     os.unlink(fullname)
[00:27:35] PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\appveyor\\AppData\\Local\\Temp\\1\\test_runner_20190115_020102\\feature_notifications_45\\node0\\regtest\\debug.log'
https://ci.appveyor.com/project/DrahtBot/bitcoin/builds/21618398

2a9d4e5838

Empact force-pushed on Jan 15, 2019

Empact commented at 2:06 am on January 16, 2019: member

The shutdown is unrelated - logging deals with /test_framework.log. This is the debug log for node0, which is apparently still active despite this being the last log entries. Not sure where the access is coming from:

0[00:27:35]  node0 2019-01-15T02:08:41.638177Z BerkeleyEnvironment::Flush: wallet.dat checkpoint 
1[00:27:35]  node0 2019-01-15T02:08:41.644178Z BerkeleyEnvironment::Flush: wallet.dat detach 
2[00:27:35]  node0 2019-01-15T02:08:41.645176Z BerkeleyEnvironment::Flush: wallet.dat closed 
3[00:27:35]  node0 2019-01-15T02:08:41.645176Z BerkeleyEnvironment::Flush: Flush(true) took               9ms 
4[00:27:35]  node0 2019-01-15T02:08:41.674177Z [default wallet] Releasing wallet 
5[00:27:35]  node0 2019-01-15T02:08:41.674177Z Shutdown: done

MarcoFalke commented at 4:07 pm on January 17, 2019: member

I mean logging.shutdown https://docs.python.org/3/library/logging.html#logging.shutdown

The doc doesn’t really say if it is async or sync

Empact commented at 9:33 pm on January 17, 2019: member

I think they’re distinct concerns, because they concern different files/folders. Seems logging operates ontest_framework.log, at least in this context, vs node0/regtest/debug.log.

https://github.com/bitcoin/bitcoin/blob/cd42553b1178a48a16017eff0b70669c84c3895c/test/functional/test_framework/test_framework.py#L395-L398

I’m not clear on is what would be accessing the log though. Shutdown has occurred by this point so I don’t think it could be node0 bitcoind.

Empact commented at 4:09 am on January 25, 2019: member

I haven’t seen this since, so we may want to hold on it until it shows up again.

Empact commented at 11:20 pm on January 30, 2019: member

Closing pending possible future sighting.

Empact closed this on Jan 30, 2019

DrahtBot locked this on Dec 16, 2021

test: Wait before cleanup on exit #15171