Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tests are failing on arm and aarch64 #1057

Closed
kristapsk opened this issue Oct 21, 2021 · 8 comments · Fixed by #1423
Closed

Tests are failing on arm and aarch64 #1057

kristapsk opened this issue Oct 21, 2021 · 8 comments · Fixed by #1423

Comments

@kristapsk
Copy link
Member

    def checkNotifs(self):
>       assert self.client_factory.notifs == 1
E       AssertionError: assert 0 == 1
E        +  where 0 = <autobahn.twisted.websocket.WebSocketClientFactory object at 0x7f78dc6c70>.notifs
E        +    where <autobahn.twisted.websocket.WebSocketClientFactory object at 0x7f78dc6c70> = <test_wallet_rpc.TrialTestWRPC_WS testMethod=test_notif>.client_factory

jmclient/test/test_wallet_rpc.py:125: AssertionError
@AdamISZ
Copy link
Member

AdamISZ commented Oct 21, 2021

Thanks for that. My suspicion is it might be timing related(?). I tried to make those tests all use deferreds, i.e. each step of the process waits for the previous to complete, but it doesn't currently work like that for the websocket test (checkNotifs is called after a 0.1 second wait).

I'm not sure when I'll get round to looking at it, but maybe you could edit this line to wait for say 1 second, to see if it's about timing, just to check my hypothesis.

@kristapsk
Copy link
Member Author

Does not help, tried to increase that number even to 10 seconds.

@kristapsk
Copy link
Member Author

Same happens also on 32-bit ARM (Raspbian). Both are based on RaspiBolt tutorial.

@kristapsk kristapsk changed the title Tests are failing on aarch64 Tests are failing on arm and aarch64 Oct 24, 2021
@whitslack
Copy link
Contributor

Same happens on x86_64.

============================================================= FAILURES =============================================================
___________________________________________________ TrialTestWRPC_WS.test_notif ____________________________________________________

self = <test_wallet_rpc.TrialTestWRPC_WS testMethod=test_notif>

    def checkNotifs(self):
>       assert self.client_factory.notifs == 1
E       assert 0 == 1
E        +  where 0 = <autobahn.twisted.websocket.WebSocketClientFactory object at 0x7f80e43e9090>.notifs
E        +    where <autobahn.twisted.websocket.WebSocketClientFactory object at 0x7f80e43e9090> = <test_wallet_rpc.TrialTestWRPC_WS testMethod=test_notif>.client_factory

self       = <test_wallet_rpc.TrialTestWRPC_WS testMethod=test_notif>

jmclient/test/test_wallet_rpc.py:181: AssertionError
------------------------------------------------------- Captured stdout call -------------------------------------------------------
User data location: .
2022-09-16 14:56:12,583 [DEBUG]  rpc: getblockchaininfo []
2022-09-16 14:56:12,587 [DEBUG]  rpc: listwallets []
2022-09-16 14:56:12,589 [DEBUG]  rpc: getwalletinfo []
2022-09-16 14:56:12,850 [DEBUG]  rpc: getnewaddress []
2022-09-16 14:56:12,870 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:12,934 [DEBUG]  rpc: sendtoaddress ['bcrt1q9u497juc35ks6x3u4ugpknyhytndz9jraav3rz', 2.0]
2022-09-16 14:56:14,288 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:14,316 [DEBUG]  rpc: sendtoaddress ['bcrt1qh2yae8jgqe259kde3llqv3hwp4k9f8c6kk34s6', 2.0]
2022-09-16 14:56:15,540 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:15,567 [DEBUG]  rpc: sendtoaddress ['bcrt1qx37es2nmve0epc9cvj94687z3amap7dlc0eh4w', 2.0]
2022-09-16 14:56:16,883 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:16,900 [DEBUG]  rpc: sendtoaddress ['bcrt1qyqq7xgmsg6x3ldfdnqr2jz2wudt2xew5tkxn2a', 2.0]
2022-09-16 14:56:18,308 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:18,319 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
2022-09-16 14:56:18,326 [DEBUG]  rpc: listaddressgroupings []
2022-09-16 14:56:18,942 [INFO]  Detected new wallet, performing initial import
2022-09-16 14:56:18,943 [DEBUG]  requesting detailed wallet history
2022-09-16 14:56:18,958 [DEBUG]  rpc: listlabels []
2022-09-16 14:56:19,032 [DEBUG]  rpc: listunspent [0]
2022-09-16 14:56:20,128 [DEBUG]  bitcoind sync_unspent took 1.0983452796936035sec
2022-09-16 14:56:20,148 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,150 [WARNING]  Connection had broken pipe, attempting reconnect.
2022-09-16 14:56:20,159 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,169 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,176 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,185 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,196 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,211 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,224 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
2022-09-16 14:56:20,242 [DEBUG]  rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
-------------------------------------------------------- Captured log call ---------------------------------------------------------
DEBUG    joinmarket:blockchaininterface.py:232 rpc: getblockchaininfo []
DEBUG    joinmarket:blockchaininterface.py:232 rpc: listwallets []
DEBUG    joinmarket:blockchaininterface.py:232 rpc: getwalletinfo []
DEBUG    joinmarket:blockchaininterface.py:232 rpc: getnewaddress []
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: sendtoaddress ['bcrt1q9u497juc35ks6x3u4ugpknyhytndz9jraav3rz', 2.0]
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: sendtoaddress ['bcrt1qh2yae8jgqe259kde3llqv3hwp4k9f8c6kk34s6', 2.0]
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: sendtoaddress ['bcrt1qx37es2nmve0epc9cvj94687z3amap7dlc0eh4w', 2.0]
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: sendtoaddress ['bcrt1qyqq7xgmsg6x3ldfdnqr2jz2wudt2xew5tkxn2a', 2.0]
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: listaddressgroupings []
INFO     joinmarket:wallet_service.py:559 Detected new wallet, performing initial import
DEBUG    joinmarket:wallet_service.py:748 requesting detailed wallet history
DEBUG    joinmarket:blockchaininterface.py:232 rpc: listlabels []
DEBUG    joinmarket:blockchaininterface.py:232 rpc: listunspent [0]
DEBUG    joinmarket:wallet_service.py:846 bitcoind sync_unspent took 1.0983452796936035sec
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
WARNING  joinmarket:jsonrpc.py:113 Connection had broken pipe, attempting reconnect.
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q58r5yvy6m6m98lzxtuvzd97jmm0jjx6kmqjxn5']
DEBUG    joinmarket:blockchaininterface.py:232 rpc: generatetoaddress [1, 'bcrt1q9axcq6ujnzcxrael3dlp2qf20eeph2uktefr28']

However, unlike @kristapsk, I was able to get the test to pass by increasing the delays. However, adding delays to make a unit test pass is an anti-pattern and is not the correct answer here. The speed and load of the system should affect only how long a program takes to execute, not whether it executes correctly.

@AdamISZ
Copy link
Member

AdamISZ commented Jan 6, 2023

Reviewing this again in view of recent test failures (including #1421 ): if we look at the relevant portion of the test code:

d = task.deferLater(reactor, 0.1, self.fire_tx_notif)
# create a small delay between the instruction to send
# the notification, and the checking of its receipt,
# otherwise the client will be queried before the notification
# arrived:
d.addCallback(self.wait_to_receive)
return d
def wait_to_receive(self, res):
d = task.deferLater(reactor, 0.1, self.checkNotifs)
return d
def checkNotifs(self):
assert self.client_factory.notifs == 1
def fire_tx_notif(self):
self.daemon.wss_factory.sendTxNotification(self.test_tx,
test_tx_hex_txid)

... the sequence of events is: 1/ schedule the firing of the notification, then 2/ add a callback after that notification firing event, which waits again before calling checkNotifs to check the notification is received.

Is there some reason we could imagine that the message over the network gets substantially delayed, in some situations? There is some intrinsic timing dependence here, the logic is "the test passes if the notification is received, after some time" - so perhaps I just have to allow the test to repeatedly try to receive the notification, if there is some weird situation where simple localhost test code experiences a substantial network delay? Best I can think of is to just try in a loop, maybe 10 times, over 10 seconds; we have to give up at some point but obviously usually there should be no meaningful delay.

Note that this is websocket code using autobahn. I cannot currently reproduce the error on my machine, and I currently don't know what circumstances could cause it, and can't really debug without the ability to reproduce, I can only guess. This is an example of the timings I see (code lines are as above):

Just before line 168:  2023-01-06 12:04:33.052028
Just after line 168:  2023-01-06 12:04:33.052101
line 184:  2023-01-06 12:04:33.152938
line 177:  2023-01-06 12:04:33.157826
2023-01-06 12:04:33,159 [INFO]  Text message received: {"txid": <txinfo snipped>}

The first two are basically instant of course; we just scheduled a future call on line 168, so it takes no time. Then there is the expect 0.1 delay before the notification gets "fired" and sent over the wire. Then there is a less predictable delay before the callback from that sending code returns - it's about 0.06 seconds here and seems to stay around that area, on my machine, in this test, but the whole point of it being a callback is it shouldn't matter. The only issue is the delta between when 'text message received' arrives and when the call to checkNotifs occurs, which is currently 0.1 seconds after the call to sendNotification occurs.

I'll build a PR based around that looping idea (but with no additional delay by default) and just see if it passes.

@kristapsk
Copy link
Member Author

I'm still having this on Odroid HC4 (arm64) running Ubuntu Server (focal) / RaspiBolt:

self = <test_wallet_rpc.TrialTestWRPC_WS testMethod=test_notif>

    def checkNotifs(self):
        if self.attempt_receipt_counter > 10:
>           assert False
E           AssertionError: assert False

jmclient/test/test_wallet_rpc.py:194: AssertionError

@kristapsk
Copy link
Member Author

Solved with #1534?

kristapsk pushed a commit to kristapsk/joinmarket-clientserver that referenced this issue Jan 5, 2024
This may or may not fix JoinMarket-Org#1057 and other test failures. Since the network
delay in receiving the message is unknown (but expected to be very
small, usually), we keep trying to receive notification of the
transaction message in the websocket test 10 times for a total of 2
seconds (on the assumption that if it takes longer than that, something
else is wrong).
@kristapsk
Copy link
Member Author

Tests are passing for me on 64-bit ARM now, cannot reproduce anymore.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants