[META] MatrixSyncMaxTimeoutReached in several scenarios [DO NOT PICK UP]

[karlb]

I encountered the following error in multiple nodes when running the bf6 scenario locally:

Traceback (most recent call last):
  File "/home/karl/raiden/raiden/network/transport/matrix/client.py", line 281, in listen_forever
    self._sync(timeout_ms)
  File "/home/karl/raiden/raiden/network/transport/matrix/client.py", line 498, in _sync
    f"Processing Matrix response took {processing_time_in_seconds}s, "
raiden.exceptions.MatrixSyncMaxTimeoutReached: Processing Matrix response took 25.108961582183838s, poll timeout is 20s.

Logs for only two of the nodes are attached to keep the zip below githubs 10MB limit. run_101.zip

Update

We are working on this Meta-Issue in several sub-issues & PRs. Current Assumption is: Deepcopy takes on average more than 1s, since copying the old state with this one huge token_network takes time. If there are more than 20 messages being sent, we get this timeout. Our ScenarioPlayer Token Netwrok is simply too big.

• Reproducing #5562
• Proper Analysis of deepcopy #5565
• Proxy Manager #5559
• Response Queue #5275
• Ignore broadcasting rooms #5343
• Filtering room messages #5535
• Message dispatching #5537

[palango]

Happens for me as well in BF6

This is what happens in this time:

{"ts":"2019-12-12 13:25:27.469085","ev":"Sync called"}
{"ts":"2019-12-12 13:25:27.472231","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.508859","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.535896","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.570843","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.596944","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.626690","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.657208","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.694511","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.728075","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.787440","ev":"Request successful"}
{"ts":"2019-12-12 13:25:27.792670","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.842376","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.876171","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.910323","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.938451","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:27.975781","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.007385","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.046240","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.078262","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.108513","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.137391","ev":"Starting _handle_response"}
{"ts":"2019-12-12 13:25:28.138726","ev":"Changing user presence state"}
{"ts":"2019-12-12 13:25:28.139595","ev":"Changing address reachability state"}
{"ts":"2019-12-12 13:25:28.140506","ev":"State changes"}
{"ts":"2019-12-12 13:25:28.354174","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:28.356796","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.357224","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.358473","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:28.360212","ev":"Message received"}
{"ts":"2019-12-12 13:25:28.363798","ev":"State changes"}
{"ts":"2019-12-12 13:25:28.509015","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:28.511606","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.512901","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:28.514792","ev":"Message received"}
{"ts":"2019-12-12 13:25:28.518406","ev":"State changes"}
{"ts":"2019-12-12 13:25:28.746277","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:28.747373","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.748882","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:28.750796","ev":"Message received"}
{"ts":"2019-12-12 13:25:28.753555","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:28.755533","ev":"State changes"}
{"ts":"2019-12-12 13:25:28.866895","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:28.867636","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.870587","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:28.875535","ev":"Message received"}
{"ts":"2019-12-12 13:25:28.884514","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:28.885116","ev":"Send"}
{"ts":"2019-12-12 13:25:28.885749","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.886101","ev":"Existing room"}
{"ts":"2019-12-12 13:25:28.886663","ev":"Send raw"}
{"ts":"2019-12-12 13:25:28.890311","ev":"Send async"}
{"ts":"2019-12-12 13:25:28.891020","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:28.891299","ev":"Send"}
{"ts":"2019-12-12 13:25:28.891621","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.891801","ev":"Existing room"}
{"ts":"2019-12-12 13:25:28.892066","ev":"Send raw"}
{"ts":"2019-12-12 13:25:28.894693","ev":"Send async"}
{"ts":"2019-12-12 13:25:28.895204","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:28.895467","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:28.896237","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.901618","ev":"Request successful"}
{"ts":"2019-12-12 13:25:28.926653","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.962577","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:28.989119","ev":"Whitelist"}
{"ts":"2019-12-12 13:25:28.990074","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:28.993920","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.029030","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.063572","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.092129","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.130057","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.155225","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:29.155720","ev":"Send"}
{"ts":"2019-12-12 13:25:29.156183","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:29.156436","ev":"Existing room"}
{"ts":"2019-12-12 13:25:29.156801","ev":"Send raw"}
{"ts":"2019-12-12 13:25:29.162190","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:29.162655","ev":"Send"}
{"ts":"2019-12-12 13:25:29.163115","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:29.163367","ev":"Existing room"}
{"ts":"2019-12-12 13:25:29.163742","ev":"Send raw"}
{"ts":"2019-12-12 13:25:29.166204","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.200714","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.240925","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.272337","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.308456","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.338049","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.368017","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.401321","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.406196","ev":"Request successful"}
{"ts":"2019-12-12 13:25:29.434223","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.478410","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.511645","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.541892","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.596375","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.624345","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.634577","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:29.635016","ev":"Send"}
{"ts":"2019-12-12 13:25:29.635352","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:29.635633","ev":"No room for receiver"}
{"ts":"2019-12-12 13:25:29.651523","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.678161","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.714351","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.741785","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.766637","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.790758","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.819163","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.844676","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.877342","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.903821","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.909495","ev":"Request successful"}
{"ts":"2019-12-12 13:25:29.927559","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.955408","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:29.982980","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:30.010243","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:30.046050","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:30.077973","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:30.106596","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:30.131871","ev":"State changes"}
{"ts":"2019-12-12 13:25:30.239648","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:30.413150","ev":"Request successful"}
{"ts":"2019-12-12 13:25:30.917211","ev":"Request successful"}
{"ts":"2019-12-12 13:25:31.422216","ev":"Request successful"}
{"ts":"2019-12-12 13:25:31.926525","ev":"Request successful"}
{"ts":"2019-12-12 13:25:32.304350","ev":"Created private room"}
{"ts":"2019-12-12 13:25:32.304841","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:32.430136","ev":"Request successful"}
{"ts":"2019-12-12 13:25:32.608115","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:32.608590","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:32.932743","ev":"Request successful"}
{"ts":"2019-12-12 13:25:32.994725","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:32.995103","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:33.431497","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:33.432266","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:33.436498","ev":"Request successful"}
{"ts":"2019-12-12 13:25:33.896441","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:33.897423","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:33.946564","ev":"Request successful"}
{"ts":"2019-12-12 13:25:34.002877","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:34.003300","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:34.449961","ev":"Request successful"}
{"ts":"2019-12-12 13:25:34.570992","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:34.571414","ev":"Send"}
{"ts":"2019-12-12 13:25:34.571758","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:34.571951","ev":"Existing room"}
{"ts":"2019-12-12 13:25:34.572227","ev":"Send raw"}
{"ts":"2019-12-12 13:25:34.601037","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:34.601428","ev":"Send"}
{"ts":"2019-12-12 13:25:34.601768","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:34.601959","ev":"Existing room"}
{"ts":"2019-12-12 13:25:34.602236","ev":"Send raw"}
{"ts":"2019-12-12 13:25:34.637224","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:34.637611","ev":"Send"}
{"ts":"2019-12-12 13:25:34.637959","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:34.638210","ev":"No room for receiver"}
{"ts":"2019-12-12 13:25:34.778868","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:34.779798","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:34.953077","ev":"Request successful"}
{"ts":"2019-12-12 13:25:35.455671","ev":"Request successful"}
{"ts":"2019-12-12 13:25:35.873246","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:35.873827","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:35.958953","ev":"Request successful"}
{"ts":"2019-12-12 13:25:36.462736","ev":"Request successful"}
{"ts":"2019-12-12 13:25:36.966797","ev":"Request successful"}
{"ts":"2019-12-12 13:25:37.462173","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:37.463294","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:37.470768","ev":"Request successful"}
{"ts":"2019-12-12 13:25:37.658674","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:37.855291","ev":"Channel room"}
{"ts":"2019-12-12 13:25:37.855754","ev":"Healthcheck"}
{"ts":"2019-12-12 13:25:37.975127","ev":"Request successful"}
{"ts":"2019-12-12 13:25:38.244862","ev":"Fetched user presences"}
{"ts":"2019-12-12 13:25:38.260135","ev":"State changes"}
{"ts":"2019-12-12 13:25:38.378292","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:38.380986","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:38.382106","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:38.383569","ev":"Delivered message received"}
{"ts":"2019-12-12 13:25:38.385136","ev":"State changes"}
{"ts":"2019-12-12 13:25:38.574838","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:38.577022","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:38.578841","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:38.580247","ev":"Delivered message received"}
{"ts":"2019-12-12 13:25:38.581645","ev":"State changes"}
{"ts":"2019-12-12 13:25:38.684360","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:38.687592","ev":"Message received"}
{"ts":"2019-12-12 13:25:38.690932","ev":"State changes"}
{"ts":"2019-12-12 13:25:38.810107","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:38.812310","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:38.813890","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:38.815101","ev":"Delivered message received"}
{"ts":"2019-12-12 13:25:38.816356","ev":"State changes"}
{"ts":"2019-12-12 13:25:38.929743","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:38.933169","ev":"Message received"}
{"ts":"2019-12-12 13:25:38.936696","ev":"State changes"}
{"ts":"2019-12-12 13:25:39.127037","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:39.129314","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:39.133477","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:39.138229","ev":"Message received"}
{"ts":"2019-12-12 13:25:39.143472","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:39.145514","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:39.145985","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:39.147150","ev":"Request successful"}
{"ts":"2019-12-12 13:25:39.227857","ev":"Whitelist"}
{"ts":"2019-12-12 13:25:39.228901","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:39.639135","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:39.652366","ev":"Request successful"}
{"ts":"2019-12-12 13:25:39.794921","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:39.795615","ev":"Send"}
{"ts":"2019-12-12 13:25:39.796216","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:39.796508","ev":"Existing room"}
{"ts":"2019-12-12 13:25:39.796933","ev":"Send raw"}
{"ts":"2019-12-12 13:25:39.853294","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:39.853719","ev":"Send"}
{"ts":"2019-12-12 13:25:39.854117","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:39.854338","ev":"Existing room"}
{"ts":"2019-12-12 13:25:39.854807","ev":"Send raw"}
{"ts":"2019-12-12 13:25:40.156370","ev":"Request successful"}
{"ts":"2019-12-12 13:25:40.296471","ev":"Received new block"}
{"ts":"2019-12-12 13:25:40.345785","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.372394","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.400252","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.433095","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.462184","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.489956","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.514938","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.542317","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.568092","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.595487","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.629363","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.660225","ev":"Request successful"}
{"ts":"2019-12-12 13:25:40.661477","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.691570","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.725212","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.755425","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.783364","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.810639","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.839052","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.865819","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.894249","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.924404","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.950458","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:40.978038","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.007870","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.039201","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.080541","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.108111","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.140260","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.169470","ev":"Request successful"}
{"ts":"2019-12-12 13:25:41.179704","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.209935","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.250775","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.341509","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.369892","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.406822","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.439177","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.444044","ev":"Created private room"}
{"ts":"2019-12-12 13:25:41.444754","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:41.477745","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.520275","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.554523","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.590177","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.617784","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.653055","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.677112","ev":"Request successful"}
{"ts":"2019-12-12 13:25:41.680522","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.709845","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.731831","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:41.732318","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:41.746722","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.782235","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.812735","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.855196","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.884867","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.914850","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.947173","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:41.976337","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.007806","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.033949","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.067140","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.083444","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:42.084545","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:42.095097","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.135755","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.172675","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.180285","ev":"Request successful"}
{"ts":"2019-12-12 13:25:42.202485","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.243292","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.282394","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.317023","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.348116","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.387272","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.414732","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.444630","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.494415","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.519466","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:42.519904","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:42.522183","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.547408","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.573993","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.607786","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.642133","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.670266","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.685204","ev":"Request successful"}
{"ts":"2019-12-12 13:25:42.709624","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.769386","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.809076","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.837338","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.870115","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.904310","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.930522","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.957539","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:42.987349","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.018249","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.051562","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.083443","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.087375","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:43.088051","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:43.117003","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.146246","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.186713","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.191270","ev":"Request successful"}
{"ts":"2019-12-12 13:25:43.217785","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.304599","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.332289","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.359814","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.385879","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.418141","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.444674","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.471438","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.496283","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.525226","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.552026","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.598318","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.652830","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.691104","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.698766","ev":"Request successful"}
{"ts":"2019-12-12 13:25:43.724232","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.748751","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.773133","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.808506","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.838828","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.852443","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:43.852828","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:43.871925","ev":"StatelessFilter: querying new entries"}
{"ts":"2019-12-12 13:25:43.899442","ev":"State changes"}
{"ts":"2019-12-12 13:25:44.025745","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:44.146970","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:44.147362","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:44.201915","ev":"Request successful"}
{"ts":"2019-12-12 13:25:44.642579","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:44.643050","ev":"Send"}
{"ts":"2019-12-12 13:25:44.643440","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:44.643722","ev":"No room for receiver"}
{"ts":"2019-12-12 13:25:44.704347","ev":"Request successful"}
{"ts":"2019-12-12 13:25:44.938411","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:44.939009","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:45.066986","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:45.067558","ev":"Send"}
{"ts":"2019-12-12 13:25:45.068045","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:45.068297","ev":"Existing room"}
{"ts":"2019-12-12 13:25:45.068664","ev":"Send raw"}
{"ts":"2019-12-12 13:25:45.117593","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:45.118680","ev":"Send"}
{"ts":"2019-12-12 13:25:45.119739","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:45.120286","ev":"Existing room"}
{"ts":"2019-12-12 13:25:45.120928","ev":"Send raw"}
{"ts":"2019-12-12 13:25:45.208743","ev":"Request successful"}
{"ts":"2019-12-12 13:25:45.711285","ev":"Request successful"}
{"ts":"2019-12-12 13:25:46.214238","ev":"Request successful"}
{"ts":"2019-12-12 13:25:46.527618","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:46.528630","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:46.717645","ev":"Request successful"}
{"ts":"2019-12-12 13:25:47.225548","ev":"Request successful"}
{"ts":"2019-12-12 13:25:47.731639","ev":"Request successful"}
{"ts":"2019-12-12 13:25:48.234606","ev":"Request successful"}
{"ts":"2019-12-12 13:25:48.737505","ev":"Request successful"}
{"ts":"2019-12-12 13:25:48.895107","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:48.895960","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:49.152382","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:49.153077","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:49.243327","ev":"Request successful"}
{"ts":"2019-12-12 13:25:49.644935","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:49.748795","ev":"Request successful"}
{"ts":"2019-12-12 13:25:50.253294","ev":"Request successful"}
{"ts":"2019-12-12 13:25:50.322622","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:50.324232","ev":"Send"}
{"ts":"2019-12-12 13:25:50.325160","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:50.325664","ev":"Existing room"}
{"ts":"2019-12-12 13:25:50.326199","ev":"Send raw"}
{"ts":"2019-12-12 13:25:50.369419","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:50.370287","ev":"Send"}
{"ts":"2019-12-12 13:25:50.370997","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:50.371347","ev":"Existing room"}
{"ts":"2019-12-12 13:25:50.371872","ev":"Send raw"}
{"ts":"2019-12-12 13:25:50.758359","ev":"Request successful"}
{"ts":"2019-12-12 13:25:51.264385","ev":"Request successful"}
{"ts":"2019-12-12 13:25:51.766639","ev":"Request successful"}
{"ts":"2019-12-12 13:25:52.270273","ev":"Request successful"}
{"ts":"2019-12-12 13:25:52.490189","ev":"Peer has not joined from invite yet, should join eventually"}
{"ts":"2019-12-12 13:25:52.490600","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:52.676608","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:52.772971","ev":"Request successful"}
{"ts":"2019-12-12 13:25:52.872418","ev":"Channel room"}
{"ts":"2019-12-12 13:25:52.872947","ev":"Healthcheck"}
{"ts":"2019-12-12 13:25:53.255299","ev":"Fetched user presences"}
{"ts":"2019-12-12 13:25:53.267834","ev":"State changes"}
{"ts":"2019-12-12 13:25:53.373520","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:53.376807","ev":"Delivered message received"}
{"ts":"2019-12-12 13:25:53.378158","ev":"State changes"}
{"ts":"2019-12-12 13:25:53.561421","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:53.564938","ev":"Message received"}
{"ts":"2019-12-12 13:25:53.568981","ev":"State changes"}
{"ts":"2019-12-12 13:25:53.709762","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:53.712496","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:53.714046","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:53.716786","ev":"Message received"}
{"ts":"2019-12-12 13:25:53.722317","ev":"State changes"}
{"ts":"2019-12-12 13:25:53.928428","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:53.931078","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:53.940896","ev":"Incoming messages"}
{"ts":"2019-12-12 13:25:53.947060","ev":"Message received"}
{"ts":"2019-12-12 13:25:53.953070","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:53.955013","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:53.955325","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:53.956173","ev":"Request successful"}
{"ts":"2019-12-12 13:25:54.033757","ev":"Whitelist"}
{"ts":"2019-12-12 13:25:54.034236","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:54.463617","ev":"Request successful"}
{"ts":"2019-12-12 13:25:54.650202","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:54.972671","ev":"Request successful"}
{"ts":"2019-12-12 13:25:55.480938","ev":"Request successful"}
{"ts":"2019-12-12 13:25:55.565908","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:55.566312","ev":"Send"}
{"ts":"2019-12-12 13:25:55.566709","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:55.566983","ev":"Existing room"}
{"ts":"2019-12-12 13:25:55.567273","ev":"Send raw"}
{"ts":"2019-12-12 13:25:55.624144","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:55.624532","ev":"Send"}
{"ts":"2019-12-12 13:25:55.624869","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:55.625056","ev":"Existing room"}
{"ts":"2019-12-12 13:25:55.625329","ev":"Send raw"}
{"ts":"2019-12-12 13:25:55.759692","ev":"Created private room"}
{"ts":"2019-12-12 13:25:55.760146","ev":"Fetching room members"}
{"ts":"2019-12-12 13:25:55.943157","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:55.983963","ev":"Request successful"}
{"ts":"2019-12-12 13:25:56.137610","ev":"Channel room"}
{"ts":"2019-12-12 13:25:56.138077","ev":"Healthcheck"}
{"ts":"2019-12-12 13:25:56.493342","ev":"Request successful"}
{"ts":"2019-12-12 13:25:56.526888","ev":"Fetched user presences"}
{"ts":"2019-12-12 13:25:56.542710","ev":"State changes"}
{"ts":"2019-12-12 13:25:56.648460","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:56.651925","ev":"Message received"}
{"ts":"2019-12-12 13:25:56.655211","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:56.656692","ev":"State changes"}
{"ts":"2019-12-12 13:25:56.770066","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:56.773828","ev":"Message received"}
{"ts":"2019-12-12 13:25:56.778370","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:56.780100","ev":"State changes"}
{"ts":"2019-12-12 13:25:56.886441","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:56.890070","ev":"Message received"}
{"ts":"2019-12-12 13:25:56.894188","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:56.895714","ev":"State changes"}
{"ts":"2019-12-12 13:25:57.069364","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:57.073635","ev":"Message received"}
{"ts":"2019-12-12 13:25:57.078409","ev":"Message already in queue - ignoring"}
{"ts":"2019-12-12 13:25:57.080038","ev":"State changes"}
{"ts":"2019-12-12 13:25:57.185954","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:57.194341","ev":"Message received"}
{"ts":"2019-12-12 13:25:57.202796","ev":"Retrying message"}
{"ts":"2019-12-12 13:25:57.203101","ev":"Partner not reachable. Skipping."}
{"ts":"2019-12-12 13:25:57.203998","ev":"Request successful"}
{"ts":"2019-12-12 13:25:57.279865","ev":"Whitelist"}
{"ts":"2019-12-12 13:25:57.280446","ev":"Room ids for address"}
{"ts":"2019-12-12 13:25:57.280687","ev":"Existing room"}
{"ts":"2019-12-12 13:25:57.281054","ev":"Healthcheck"}
{"ts":"2019-12-12 13:25:57.653678","ev":"Fetched user presences"}
{"ts":"2019-12-12 13:25:57.669646","ev":"State changes"}
{"ts":"2019-12-12 13:25:57.814726","ev":"Sent a PFS Capacity Update"}
{"ts":"2019-12-12 13:25:57.818578","ev":"Broadcast"}
{"ts":"2019-12-12 13:25:57.821734","ev":"Request successful"}
{"ts":"2019-12-12 13:25:57.848002","ev":"Received new balance proof, creating message for Monitoring Service."}
{"ts":"2019-12-12 13:25:57.852579","ev":"Raiden events"}
{"ts":"2019-12-12 13:25:57.855617","ev":"Exception thrown during sync"}

[Dominik1999]

Next steps (Planning 16.12.):

• Keep bf6 in test suite
• Try to get faster (caching address formatting)
• Looking at the flamegraph and executing the issues: < Link the issues of flamegraph analysis >

[czepluch]

Also happened for PFS9 on 15th of December

Logs:

• Scenario log
• node0
• node1
• node2
• node3
• node4

[czepluch]

Happened in BF1 on 16th of December

Logs:

• Scenario log
• node0
• node1
• node2
• node3
• node4

[czepluch]

Also happened in pfs9 on 16th of December

Logs:

• Scenario log
• node0
• node1
• node2
• node3
• node4

[palango]

Looks like something like this also happened on 15th of December for BF1 where it fails with:

"message": "HTTP status code \"500\" while fetching http://127.0.0.1:36201/api/v1/channels/0x62083c80353Df771426D209eF578619EE68D5C7A/0xae8037d15CE130D298611a937c1142f9c3A22189. Expected 200: Internal Server Error

Logs:

• Scenario logs
• node0
• node1
• node2
• node3
• node4

Edit: this is what logged between the sync call and the exception.

{"ts":"2019-12-14 23:15:21.304040","e":"Sync called"}
{"ts":"2019-12-14 23:15:22.369123","e":"Memory report"}
{"ts":"2019-12-14 23:15:22.371014","e":"Request successful"}
{"ts":"2019-12-14 23:15:30.170140","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:15:30.175119","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:15:31.233098","e":"Memory report"}
{"ts":"2019-12-14 23:15:31.234278","e":"Request successful"}
{"ts":"2019-12-14 23:15:39.007941","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:15:40.071890","e":"Memory report"}
{"ts":"2019-12-14 23:15:40.073191","e":"Request successful"}
{"ts":"2019-12-14 23:15:47.813439","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:15:47.814656","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:15:47.823459","e":"Starting _handle_response"}
{"ts":"2019-12-14 23:15:48.892223","e":"Memory report"}
{"ts":"2019-12-14 23:15:48.894873","e":"Request successful"}
{"ts":"2019-12-14 23:15:56.671900","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:15:56.676709","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:15:57.748388","e":"Memory report"}
{"ts":"2019-12-14 23:15:57.750835","e":"Request successful"}
{"ts":"2019-12-14 23:16:05.512255","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:05.516853","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:06.588836","e":"Memory report"}
{"ts":"2019-12-14 23:16:06.626612","e":"Request successful"}
{"ts":"2019-12-14 23:16:14.388118","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:14.394146","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:15.442436","e":"Memory report"}
{"ts":"2019-12-14 23:16:15.480194","e":"Request successful"}
{"ts":"2019-12-14 23:16:23.245943","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:23.250903","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:24.304371","e":"Memory report"}
{"ts":"2019-12-14 23:16:24.307144","e":"Request successful"}
{"ts":"2019-12-14 23:16:32.076805","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:32.084264","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:33.136103","e":"Memory report"}
{"ts":"2019-12-14 23:16:33.138253","e":"Request successful"}
{"ts":"2019-12-14 23:16:40.901933","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:40.906917","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:41.965674","e":"Memory report"}
{"ts":"2019-12-14 23:16:42.004077","e":"Request successful"}
{"ts":"2019-12-14 23:16:49.736813","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:49.744413","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:50.823482","e":"Memory report"}
{"ts":"2019-12-14 23:16:50.860981","e":"Request successful"}
{"ts":"2019-12-14 23:16:58.616133","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:16:58.617620","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:16:59.700139","e":"Memory report"}
{"ts":"2019-12-14 23:16:59.702555","e":"Request successful"}
{"ts":"2019-12-14 23:17:07.499492","e":"wait_for_withdraw_complete"}
{"ts":"2019-12-14 23:17:07.504104","e":"StatelessFilter: querying new entries"}
{"ts":"2019-12-14 23:17:07.511063","e":"Exception thrown during sync"}

[rakanalh]

Got the same error:

Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/home/rakan/Brainbot/raiden/raiden/network/transport/matrix/client.py", line 280, in listen_forever
    self._sync(timeout_ms)
  File "/home/rakan/Brainbot/raiden/raiden/network/transport/matrix/client.py", line 497, in _sync
    f"Processing Matrix response took {processing_time_in_seconds}s, "
raiden.exceptions.MatrixSyncMaxTimeoutReached: Processing Matrix response took 122.0680296421051s, poll timeout is 20s.
2019-12-16T15:06:25Z <Greenlet "GMatrixClient.listen_forever user_id:@0x61783591bf55beba80ae9d824e8144d4cd6d0e48:transport03.raiden.network" at 0x7fa5dd121ae8: <bound method GMatrixClient.listen_forever of <raiden.network.transport.matrix.client.GMatrixClient object at 0x7fa5d7f06cf8>>(20000, None)> failed with MatrixSyncMaxTimeoutReached

Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/home/rakan/Brainbot/raiden/raiden/network/transport/matrix/transport.py", line 446, in _run
    self._broadcast_worker()
  File "/home/rakan/Brainbot/raiden/raiden/network/transport/matrix/transport.py", line 620, in _broadcast_worker
    self._broadcast_event.wait(self._config["retry_interval"])
  File "src/gevent/event.py", line 240, in gevent._event.Event.wait
  File "src/gevent/event.py", line 140, in gevent._event._AbstractLinkable._wait
  File "src/gevent/event.py", line 117, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/event.py", line 119, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 63, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
raiden.exceptions.MatrixSyncMaxTimeoutReached: Processing Matrix response took 122.0680296421051s, poll timeout is 20s.
2019-12-16T15:06:55Z <Greenlet "MatrixTransport._run node:0x61783591BF55beBa80Ae9D824E8144d4Cd6D0E48" at 0x7fa5dd1217b8: <bound method MatrixTransport._run of <MatrixTransport node:0x61783591BF55beBa80Ae9D824E8144d4Cd6D0E48 id:4ef06c39-b0e2-4e92-9424-29ff7c65ee6c>>> failed with MatrixSyncMaxTimeoutReached

Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/home/rakan/Brainbot/raiden/raiden/api/rest.py", line 441, in _run
    self.wsgiserver.serve_forever()
  File "/home/rakan/.pyenv/versions/raiden/lib/python3.7/site-packages/gevent/baseserver.py", line 364, in serve_forever
    self._stop_event.wait()
  File "src/gevent/event.py", line 240, in gevent._event.Event.wait
  File "src/gevent/event.py", line 140, in gevent._event._AbstractLinkable._wait
  File "src/gevent/event.py", line 117, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/event.py", line 119, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 63, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
AssertionError: Waiting for protocol messages requires a running transport.
2019-12-16T15:06:56Z <Greenlet "APIServer|Greenlet-3" at 0x7fa5d4ed6048: <bound method APIServer._run of <raiden.api.rest.APIServer object at 0x7fa5d555ba90>>> failed with AssertionError

scenario-player-run_bf1_basic_functionality_2019-12-16T15:34:42.log

node0 node1 node2 node3 node5

[Dominik1999]

Also happened in bf6, see node0 http://68.183.70.168:8000/scenario-player/scenarios/bf6_stress_hub_node/node_23_000/

[Dominik1999]

in case that helps, flamegraphs of a bf6 scenario flamegraphs_bf6_nodes.zip

[czepluch]

On dec 19th BF1 also failed with a similar looking error to this. I do not find the error described in https://github.com/raiden-network/raiden/issues/5472#issuecomment-567062654 though. But the .stdout for node000 does look quite weird. It's like Raiden was started twice.

Logs:

• Scenario log
• node0
• node1
• node2
• node3
• node4

[czepluch]

BF6 failed on dec 19th with FATAL: Processing Matrix response took 25.210399389266968s, poll timeout is 20s. in node000

Logs:

• Scenario log
• node0
• node1
• node2
• node3
• node4
• node5
• node6
• node7
• node8
• node9

[czepluch]

Similar to https://github.com/raiden-network/raiden/issues/5498#issuecomment-567385288 MS2 also failed with a REST API error, but none of the node logs has the FATAL error. Let me know if I instead should reopen the https://github.com/raiden-network/raiden/issues/5472 issue and put those that file like this one there.

• Scenario log
• node0
• node1

[Dominik1999]

happened again 2 times tonight, see bf1 node logs

--------- Starting ---------
Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/usr/local/lib/python3.7/site-packages/raiden/network/transport/matrix/client.py", line 300, in listen_forever
    self._sync(timeout_ms)
  File "/usr/local/lib/python3.7/site-packages/raiden/network/transport/matrix/client.py", line 478, in _sync
    f"Time between syncs exceeded timeout:  "
raiden.exceptions.MatrixSyncMaxTimeoutReached: Time between syncs exceeded timeout:  22.342976808547974s > 22s.
2020-01-14T22:38:55Z <Greenlet "GMatrixClient._sync_worker user_id:@0x51a8708b8cb5261e564bf2c1bccead79933bee26:transport04.raiden.network" at 0x7fc598404598: <bound method GMatrixClient.listen_forever of <raiden.network.transport.matrix.client.GMatrixClient object at 0x7fc5974886d8>>(20000, None)> failed with MatrixSyncMaxTimeoutReached

Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/usr/local/lib/python3.7/site-packages/raiden/network/transport/matrix/transport.py", line 469, in _run
    self._broadcast_worker()
  File "/usr/local/lib/python3.7/site-packages/raiden/network/transport/matrix/transport.py", line 644, in _broadcast_worker
    self._broadcast_event.wait(self._config.retry_interval)
  File "src/gevent/event.py", line 240, in gevent._event.Event.wait
  File "src/gevent/event.py", line 140, in gevent._event._AbstractLinkable._wait
  File "src/gevent/event.py", line 117, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/event.py", line 119, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 63, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
raiden.exceptions.MatrixSyncMaxTimeoutReached: Time between syncs exceeded timeout:  22.342976808547974s > 22s.
2020-01-14T22:38:56Z <Greenlet "MatrixTransport._run node:0x51A8708b8cB5261e564bf2C1bCCeAD79933Bee26" at 0x7fc598404378: <bound method MatrixTransport._run of <MatrixTransport node:0x51A8708b8cB5261e564bf2C1bCCeAD79933Bee26 id:b9f029da-e69e-494e-9571-3a8000e43105>>> failed with MatrixSyncMaxTimeoutReached

Traceback (most recent call last):
  File "src/gevent/greenlet.py", line 716, in gevent._greenlet.Greenlet.run
  File "/usr/local/lib/python3.7/site-packages/raiden/raiden_service.py", line 373, in _run
    self.stop_event.wait()
  File "src/gevent/event.py", line 240, in gevent._event.Event.wait
  File "src/gevent/event.py", line 140, in gevent._event._AbstractLinkable._wait
  File "src/gevent/event.py", line 117, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/event.py", line 119, in gevent._event._AbstractLinkable._wait_core
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/_greenlet_primitives.py", line 63, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File "src/gevent/__greenlet_primitives.pxd", line 35, in gevent.__greenlet_primitives._greenlet_switch
raiden.exceptions.MatrixSyncMaxTimeoutReached: Time between syncs exceeded timeout:  22.342976808547974s > 22s.
2020-01-14T22:38:56Z <Greenlet "RaidenService._run node:0x51A8708b8cB5261e564bf2C1bCCeAD79933Bee26" at 0x7fc5984046a8: <bound method RaidenService._run of <RaidenService node:0x51A8708b8cB5261e564bf2C1bCCeAD79933Bee26>>> failed with MatrixSyncMaxTimeoutReached

ReturnCode.FATAL
--------- Stopped ---------

.... and pfs3 (logs are lost)

[karlb]

This happened in two scenarios overnight. According to the idle timing, load has not been the problem:

bf4_multi_payments_same_node/node_505_005/run-505.log:
MatrixSyncMaxTimeoutReached('Time between syncs exceeded timeout:  36.908530473709106s > 35s. The thread had 26 context_switches, and idled 0.973104701048447% of the time.')

bf5_join_and_leave/node_505_002/run-505.log:
MatrixSyncMaxTimeoutReached('Time between syncs exceeded timeout:  55.85460376739502s > 35s. The thread had 44 context_switches, and idled 0.9939996189602991% of the time.')

Is the idle timing meaningful, or were we unable to fix the problems with it?

[palango]

Logs for a recent local scenario failure:

{"timestamp":"2020-01-28 10:40:17.095096","event":"Sync called"}
{"timestamp":"2020-01-28 10:40:18.906135","event":"Matrix started"}
{"timestamp":"2020-01-28 10:40:18.906558","event":"Alarm task started"}
{"timestamp":"2020-01-28 10:40:18.906786","event":"Raiden Service started"}
{"timestamp":"2020-01-28 10:40:18.906993","event":"Raiden started"}
{"timestamp":"2020-01-28 10:40:18.924528","event":"REST API starting"}
{"timestamp":"2020-01-28 10:40:18.926470","event":"REST API started"}
{"timestamp":"2020-01-28 10:40:19.006730","event":"Request successful"}
{"timestamp":"2020-01-28 10:40:22.331114","event":"Idle"}
{"timestamp":"2020-01-28 10:40:23.962575","event":"Received new block"}
{"timestamp":"2020-01-28 10:40:23.963152","event":"Synchronizing blockchain events"}
{"timestamp":"2020-01-28 10:40:23.963457","event":"StatelessFilter: querying new entries"}
{"timestamp":"2020-01-28 10:40:24.001767","event":"StatelessFilter: fetched new entries"}
{"timestamp":"2020-01-28 10:40:24.043142","event":"State changes"}
{"timestamp":"2020-01-28 10:40:24.048644","event":"Copied state before applying state changes"}
{"timestamp":"2020-01-28 10:40:24.049122","event":"Raiden events"}
{"timestamp":"2020-01-28 10:40:24.049760","event":"Synchronized to a new confirmed block"}
{"timestamp":"2020-01-28 10:40:33.930954","event":"Idle"}
{"timestamp":"2020-01-28 10:40:39.148144","event":"Received new block"}
{"timestamp":"2020-01-2s 10:40:39.148406","event":"Synchronizing blockchain events"}
{"timestamp":"2020-01-28 10:40:39.148577","event":"StatelessFilter: querying new entries"}
{"timestamp":"2020-01-28 10:40:39.175494","event":"StatelessFilter: fetched new entries"}
{"timestamp":"2020-01-28 10:40:39.206188","event":"State changes"}
{"timestamp":"2020-01-28 10:40:39.209718","event":"Copied state before applying state changes"}
{"timestamp":"2020-01-28 10:40:39.210034","event":"Raiden events"}
{"timestamp":"2020-01-28 10:40:39.210324","event":"Synchronized to a new confirmed block"}
{"timestamp":"2020-01-28 10:40:43.937790","event":"Idle"}
{"timestamp":"2020-01-28 10:40:53.791819","event":"Sync returned"}

I find it quite surprising that we have multiple Idles in there.

[palango]

Full logs for the above range:

logs-during-sync.log

[palango]

Completet logs incl. switch logs.

Archive.zip

[hackaugusto]

the problem from the logs above will be fixed by this issue: https://github.com/raiden-network/raiden/issues/5774

[palango]

@Dominik1999 Can we close this now?