deltachat-core-rust icon indicating copy to clipboard operation
deltachat-core-rust copied to clipboard

tests/test_iroh_webxdc.py::test_two_parallel_realtime_simultaneously is flaky

Open link2xt opened this issue 7 months ago • 0 comments

I have seen it failing a few times already. There is not much useful in the logs:

2024-07-01T18:20:29.7156016Z py: commands[0]> pytest -n6
2024-07-01T18:20:32.0374916Z ============================= test session starts =============================
2024-07-01T18:20:32.0377437Z platform win32 -- Python 3.12.4, pytest-8.2.2, pluggy-1.5.0
2024-07-01T18:20:32.0378523Z cachedir: .tox\py\.pytest_cache
2024-07-01T18:20:32.0380355Z rootdir: D:\a\deltachat-core-rust\deltachat-core-rust\deltachat-rpc-client
2024-07-01T18:20:32.0381662Z configfile: tox.ini
2024-07-01T18:20:32.0382549Z plugins: deltachat-rpc-client-1.141.1, timeout-2.3.1, xdist-3.6.1
2024-07-01T18:20:32.0391157Z timeout: 300.0s
2024-07-01T18:20:32.0392136Z timeout method: thread
2024-07-01T18:20:32.0393392Z timeout func_only: False
2024-07-01T18:20:32.0395841Z created: 6/6 workers
2024-07-01T18:20:32.0397056Z 6 workers [49 items]
2024-07-01T18:20:32.0397356Z 
2024-07-01T18:20:32.0397577Z scheduling tests via LoadScheduling
2024-07-01T18:20:32.0397975Z 
2024-07-01T18:20:32.0398311Z tests/test_iroh_webxdc.py::test_realtime_simultaneously 
2024-07-01T18:20:32.0399183Z tests/test_chatlist_events.py::test_download_on_demand 
2024-07-01T18:20:32.0399927Z tests/test_chatlist_events.py::test_delivery_status 
2024-07-01T18:20:32.0400897Z tests/test_chatlist_events.py::test_multidevice_sync_chat 
2024-07-01T18:20:32.0401749Z tests/test_iroh_webxdc.py::test_no_duplicate_messages 
2024-07-01T18:20:47.8686719Z ********************************************************************************
2024-07-01T18:20:47.8690805Z account 2: waiting for realtime data [(Message(account=Account(manager=<deltachat_rpc_client.deltachat.DeltaChat object at 0x00000190B5AE9C70>, id=2), id=13), [10])]
2024-07-01T18:20:47.8691736Z 
2024-07-01T18:20:52.8943525Z tests/test_securejoin.py::test_qr_setup_contact 
2024-07-01T18:20:52.9355609Z [gw1] [  2%] PASSED tests/test_chatlist_events.py::test_download_on_demand 
2024-07-01T18:20:55.2463241Z tests/test_chatlist_events.py::test_imap_sync_seen_msgs 
2024-07-01T18:20:55.2466351Z [gw4] [  4%] PASSED tests/test_iroh_webxdc.py::test_no_duplicate_messages 
2024-07-01T18:20:58.6593370Z tests/test_iroh_webxdc.py::test_no_reordering 
2024-07-01T18:20:58.6903683Z [gw0] [  6%] PASSED tests/test_chatlist_events.py::test_delivery_status 
2024-07-01T18:20:59.8654755Z tests/test_chatlist_events.py::test_delivery_status_failed 
2024-07-01T18:20:59.9067951Z [gw2] [  8%] PASSED tests/test_chatlist_events.py::test_multidevice_sync_chat 
2024-07-01T18:21:08.0193246Z tests/test_iroh_webxdc.py::test_realtime_sequentially 
2024-07-01T18:21:08.0603747Z [gw5] [ 10%] PASSED tests/test_securejoin.py::test_qr_setup_contact 
2024-07-01T18:21:14.0376494Z tests/test_securejoin.py::test_qr_securejoin[True] 
2024-07-01T18:21:14.0584861Z [gw0] [ 12%] PASSED tests/test_chatlist_events.py::test_delivery_status_failed 
2024-07-01T18:21:17.6743127Z ********************************************************************************
2024-07-01T18:21:17.6743935Z waiting for incoming message on ac2
2024-07-01T18:21:17.6746064Z 
2024-07-01T18:21:19.4362915Z tests/test_securejoin.py::test_setup_contact_resetup 
2024-07-01T18:21:19.4474356Z [gw4] [ 14%] PASSED tests/test_iroh_webxdc.py::test_no_reordering 
2024-07-01T18:21:19.5184879Z ********************************************************************************
2024-07-01T18:21:19.5185543Z waiting for incoming message on ac1
2024-07-01T18:21:19.5188528Z 
2024-07-01T18:21:21.4749878Z ********************************************************************************
2024-07-01T18:21:21.4750857Z sending realtime data ac1 -> ac2
2024-07-01T18:21:21.4753992Z 
2024-07-01T18:21:21.4845169Z tests/test_securejoin.py::test_qr_readreceipt 
2024-07-01T18:21:21.4848286Z [gw2] [ 16%] PASSED tests/test_iroh_webxdc.py::test_realtime_sequentially 
2024-07-01T18:21:28.1313010Z tests/test_securejoin.py::test_verified_group_recovery 
2024-07-01T18:21:28.1725262Z [gw1] [ 18%] PASSED tests/test_chatlist_events.py::test_imap_sync_seen_msgs 
2024-07-01T18:21:33.8000699Z tests/test_securejoin.py::test_qr_securejoin[False] 
2024-07-01T18:21:33.8310542Z [gw5] [ 20%] PASSED tests/test_securejoin.py::test_qr_securejoin[True] 
2024-07-01T18:21:50.7571384Z tests/test_securejoin.py::test_verified_group_member_added_recovery 
2024-07-01T18:21:50.7881614Z [gw1] [ 22%] PASSED tests/test_securejoin.py::test_qr_securejoin[False] 
2024-07-01T18:21:51.7810508Z tests/test_securejoin.py::test_qr_securejoin_contact_request 
2024-07-01T18:21:51.8430608Z [gw4] [ 24%] PASSED tests/test_securejoin.py::test_qr_readreceipt 
2024-07-01T18:21:57.2500173Z tests/test_securejoin.py::test_qr_new_group_unblocked 
2024-07-01T18:21:57.2810270Z [gw0] [ 26%] PASSED tests/test_securejoin.py::test_setup_contact_resetup 
2024-07-01T18:22:19.0409936Z tests/test_securejoin.py::test_qr_join_chat_with_pending_bobstate_issue4894 
2024-07-01T18:22:19.0820328Z [gw2] [ 28%] PASSED tests/test_securejoin.py::test_verified_group_recovery 
2024-07-01T18:22:21.8977066Z tests/test_securejoin.py::test_aeap_flow_verified 
2024-07-01T18:22:21.9387016Z [gw1] [ 30%] PASSED tests/test_securejoin.py::test_qr_securejoin_contact_request 
2024-07-01T18:22:28.1573839Z tests/test_securejoin.py::test_securejoin_after_contact_resetup 
2024-07-01T18:22:28.1985111Z [gw5] [ 32%] PASSED tests/test_securejoin.py::test_verified_group_member_added_recovery 
2024-07-01T18:22:54.5222462Z tests/test_securejoin.py::test_gossip_verification 
2024-07-01T18:22:54.5532745Z [gw0] [ 34%] PASSED tests/test_securejoin.py::test_qr_join_chat_with_pending_bobstate_issue4894 
2024-07-01T18:22:54.5745584Z tests/test_something.py::test_system_info 
2024-07-01T18:22:54.5747536Z [gw0] [ 36%] PASSED tests/test_something.py::test_system_info 
2024-07-01T18:22:56.7923381Z tests/test_something.py::test_configure_starttls 
2024-07-01T18:22:56.8030719Z [gw0] [ 38%] PASSED tests/test_something.py::test_configure_starttls 
2024-07-01T18:22:58.6479870Z tests/test_something.py::test_account 
2024-07-01T18:22:58.6794031Z [gw2] [ 40%] PASSED tests/test_securejoin.py::test_aeap_flow_verified 
2024-07-01T18:22:58.9430246Z tests/test_something.py::test_sleep 
2024-07-01T18:22:58.9739676Z [gw4] [ 42%] PASSED tests/test_securejoin.py::test_qr_new_group_unblocked 
2024-07-01T18:23:01.2117702Z tests/test_securejoin.py::test_withdraw_securejoin_qr 
2024-07-01T18:23:01.2427094Z [gw5] [ 44%] PASSED tests/test_securejoin.py::test_gossip_verification 
2024-07-01T18:23:03.3676912Z tests/test_something.py::test_acfactory 
2024-07-01T18:23:03.3783277Z [gw5] [ 46%] PASSED tests/test_something.py::test_acfactory 
2024-07-01T18:23:03.7026094Z tests/test_something.py::test_is_bot 
2024-07-01T18:23:03.7029505Z [gw2] [ 48%] PASSED tests/test_something.py::test_sleep 
2024-07-01T18:23:06.7634544Z tests/test_something.py::test_contact 
2024-07-01T18:23:06.7841232Z [gw2] [ 51%] PASSED tests/test_something.py::test_contact 
2024-07-01T18:23:08.3034599Z tests/test_something.py::test_wait_next_messages 
2024-07-01T18:23:08.3142324Z [gw0] [ 53%] PASSED tests/test_something.py::test_account 
2024-07-01T18:23:11.1486162Z tests/test_something.py::test_chat 
2024-07-01T18:23:11.1693306Z [gw5] [ 55%] PASSED tests/test_something.py::test_is_bot 
2024-07-01T18:23:14.2164451Z tests/test_something.py::test_bot 
2024-07-01T18:23:14.2373368Z [gw2] [ 57%] PASSED tests/test_something.py::test_wait_next_messages 
2024-07-01T18:23:19.4064836Z tests/test_something.py::test_import_export_backup 
2024-07-01T18:23:19.4374129Z [gw2] [ 59%] PASSED tests/test_something.py::test_import_export_backup 
2024-07-01T18:23:19.7314761Z tests/test_something.py::test_provider_info 
2024-07-01T18:23:19.7318399Z [gw2] [ 61%] PASSED tests/test_something.py::test_provider_info 
2024-07-01T18:23:19.8144599Z [gw0] [ 63%] PASSED tests/test_something.py::test_chat 
2024-07-01T18:23:19.8152374Z tests/test_something.py::test_mdn_doesnt_break_autocrypt 
2024-07-01T18:23:22.6916514Z tests/test_something.py::test_import_export_keys 
2024-07-01T18:23:22.7125596Z [gw4] [ 65%] PASSED tests/test_securejoin.py::test_withdraw_securejoin_qr 
2024-07-01T18:23:29.7798567Z tests/test_something.py::test_message 
2024-07-01T18:23:29.8005961Z [gw4] [ 67%] PASSED tests/test_something.py::test_message 
2024-07-01T18:23:34.9544023Z tests/test_something.py::test_download_limit_chat_assignment[3] 
2024-07-01T18:23:34.9751204Z [gw0] [ 69%] PASSED tests/test_something.py::test_import_export_keys 
2024-07-01T18:23:35.8491870Z tests/test_something.py::test_reactions_for_a_reordering_move 
2024-07-01T18:23:35.8701458Z [gw2] [ 71%] PASSED tests/test_something.py::test_mdn_doesnt_break_autocrypt 
2024-07-01T18:23:38.3838183Z tests/test_something.py::test_reaction_to_partially_fetched_msg 
2024-07-01T18:23:38.4146684Z [gw5] [ 73%] PASSED tests/test_something.py::test_bot 
2024-07-01T18:23:38.4459396Z tests/test_something.py::test_openrpc_command_line 
2024-07-01T18:23:38.4465833Z [gw5] [ 75%] PASSED tests/test_something.py::test_openrpc_command_line 
2024-07-01T18:23:47.9140154Z tests/test_webxdc.py::test_webxdc 
2024-07-01T18:23:47.9349061Z [gw5] [ 77%] PASSED tests/test_webxdc.py::test_webxdc 
2024-07-01T18:23:49.1806384Z tests/test_webxdc.py::test_webxdc_insert_lots_of_updates 
2024-07-01T18:23:49.2015573Z [gw2] [ 79%] PASSED tests/test_something.py::test_reaction_to_partially_fetched_msg 
2024-07-01T18:23:50.8324063Z tests/test_vcard.py::test_vcard 
2024-07-01T18:23:50.8538113Z [gw0] [ 81%] PASSED tests/test_something.py::test_reactions_for_a_reordering_move 
2024-07-01T18:23:52.5668303Z tests/test_something.py::test_markseen_contact_request 
2024-07-01T18:23:56.3724215Z [gw5] [ 83%] PASSED tests/test_webxdc.py::test_webxdc_insert_lots_of_updates 
2024-07-01T18:23:57.8514524Z [gw2] [ 85%] PASSED tests/test_vcard.py::test_vcard 
2024-07-01T18:24:05.6104277Z [gw0] [ 87%] PASSED tests/test_something.py::test_markseen_contact_request 
2024-07-01T18:24:05.6514836Z [gw4] [ 89%] PASSED tests/test_something.py::test_download_limit_chat_assignment[3] 
2024-07-01T18:24:22.9295834Z tests/test_something.py::test_download_limit_chat_assignment[2] 
2024-07-01T18:24:36.6030108Z [gw4] [ 91%] PASSED tests/test_something.py::test_download_limit_chat_assignment[2] 
2024-07-01T18:24:36.6339963Z [gw1] [ 93%] PASSED tests/test_securejoin.py::test_securejoin_after_contact_resetup 
2024-07-01T18:24:36.6545832Z tests/test_something.py::test_email_address_validity 
2024-07-01T18:25:32.1770834Z [gw1] [ 95%] PASSED tests/test_something.py::test_email_address_validity 
2024-07-01T18:25:32.1771978Z [gw3] node down: Not properly terminated
2024-07-01T18:25:32.5524988Z [gw3] [ 97%] FAILED tests/test_iroh_webxdc.py::test_realtime_simultaneously 
2024-07-01T18:25:32.5525749Z 
2024-07-01T18:25:32.5526009Z replacing crashed worker gw3
2024-07-01T18:25:32.5526651Z 
2024-07-01T18:25:40.5094543Z ********************************************************************************
2024-07-01T18:25:40.5095343Z msg 13: got correct realtime data [10]
2024-07-01T18:25:40.5096836Z 
2024-07-01T18:25:40.5155076Z tests/test_iroh_webxdc.py::test_two_parallel_realtime_simultaneously 
2024-07-01T18:25:40.6484229Z [gw6] [100%] PASSED tests/test_iroh_webxdc.py::test_two_parallel_realtime_simultaneously 
2024-07-01T18:25:40.6485055Z 
2024-07-01T18:25:40.6485362Z ================================== FAILURES ===================================
2024-07-01T18:25:40.6486244Z __________________________ tests/test_iroh_webxdc.py __________________________
2024-07-01T18:25:40.6488394Z [gw3] win32 -- Python 3.12.4 D:\a\deltachat-core-rust\deltachat-core-rust\deltachat-rpc-client\.tox\py\Scripts\python.EXE
2024-07-01T18:25:40.6490370Z worker 'gw3' crashed while running 'tests/test_iroh_webxdc.py::test_realtime_simultaneously'
2024-07-01T18:25:40.6491515Z =========================== short test summary info ===========================
2024-07-01T18:25:40.6492434Z FAILED tests/test_iroh_webxdc.py::test_realtime_simultaneously
2024-07-01T18:25:40.6493300Z ================== 1 failed, 48 passed in 310.11s (0:05:10) ===================
2024-07-01T18:25:40.6911217Z py: exit 1 (310.98 seconds) D:\a\deltachat-core-rust\deltachat-core-rust\deltachat-rpc-client> pytest -n6 pid=1124
2024-07-01T18:25:40.6936675Z   py: FAIL code 1 (332.37=setup[21.39]+cmd[310.98] seconds)
2024-07-01T18:25:40.6937437Z   evaluation failed :( (332.69 seconds)
2024-07-01T18:25:40.8144475Z ##[error]Process completed with exit code 1.
2024-07-01T18:25:40.8328619Z Post job cleanup.

This is from commit https://github.com/deltachat/deltachat-core-rust/commit/7a5dca2645b8988e4d76028b0673a991b74b6dad

link2xt avatar Jul 01 '24 18:07 link2xt