FF-Perf: Websocket events appear to be dropped

[dechdev]

Test: 25 broadcasts, 25 private messages, one subscription

In this test, 25 workers were kicked off for both broadcasts and private messages. Shortly after the test is kicked off, workers are not receiving websocket events, preventing them from proceeding. The ff-perf.log has logs of message IDs and event IDs that can be used to correlate to the firefly logs that are also attached. Every minute, the perf test checks for messages that have not been confirmed in > 1 minute, do a Ctrl+F for Delinquent Messages and you will see the messageID that has not been confirmed yet, along with the time it was sent at.

log_ethconnect_0.log.zip
log_firefly_core_0.log.zip
ff-perf.log

[dechdev]

Run after commit 82f55af

ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[peterbroadhurst]

Quick script to extract how many times we see each msgid in the list:

for msgid in `grep 'Sent with Message ID' ff-perf.log | awk '{ print $9 }'`; do echo "   $msgid"; grep -c "$msgid" ff-perf.log; done  | head -n 100

[dechdev]

Ran again with new logs:
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[peterbroadhurst]

After #496 the run here shows this:

{"log":"[2022-02-08T19:00:14.904Z]  WARN Mismatched nexthash or author group=56913fa99c1b3efb491845762e4b1d43eb4c02dde916a694a8bb93fa51a6d00d topic=default context=8047f2adddffc76a145086d3a6d1b672dade28979b5bdf28ea880376b74c97d0 pin=672e60525642b2e39650252d152ee549042f44520c6861321fe34b49e93f2e57 nextHash=\u003cnil\u003e dbtx=Y1GWIkK1 pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T19:00:14.904190859Z"}

Chasing this context back, I found this was the last pin that was committed:

{"log":"[2022-02-08T19:00:13.509Z] DEBUG Incrementing NextPin=752808d9080cdc4f0ffe5defdb3070db822179f85b78280ede1d92a56e587903 - Nonce=22 Topic=default Group=56913fa99c1b3efb491845762e4b1d43eb4c02dde916a694a8bb93fa51a6d00d NewNextPin=f1eb02cdff4d38fa86f406542d7b1ae51b138caf2d56301ba25580ef54c63de4 dbtx=U9YVIdnU pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T19:00:13.509847559Z"}

Then the next one doesn't get aggregated:

{"log":"[2022-02-08T19:00:13.510Z] DEBUG Incrementing NextPin=f1eb02cdff4d38fa86f406542d7b1ae51b138caf2d56301ba25580ef54c63de4 - Nonce=23 Topic=default Group=56913fa99c1b3efb491845762e4b1d43eb4c02dde916a694a8bb93fa51a6d00d NewNextPin=1072abefdd229b4acd6f0a111a0ed1ad5ad8303b4dd2240461e8cb68c3d79c03 dbtx=U9YVIdnU pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T19:00:13.510862388Z"}
{"log":"[2022-02-08T19:00:13.510Z] DEBUG Aggregating pin 0000000030 batch=b92d2c71-3efa-47e3-bacb-ba33451b9940 hash=1072abefdd229b4acd6f0a111a0ed1ad5ad8303b4dd2240461e8cb68c3d79c03 masked=true dbtx=U9YVIdnU pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T19:00:13.510878976Z"}

Adding more debug

[dechdev]

Running with only broadcasts - 25 workers:
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[peterbroadhurst]

The above broadcast run shows many messages sent, then c568abbe-881e-43c9-a57c-8e133ec60caa gets stuck with:

{"log":"[2022-02-08T19:13:30.211Z] DEBUG Message c568abbe-881e-43c9-a57c-8e133ec60caa pinned at sequence 215 blocked by earlier context 7\ufffd\ufffd\ufffd\ufffd\u0019h}\u0013/\ufffd\ufffdQܦ)\ufffdd\ufffdĕ\ufffd\ufffdA\ufffd\ufffd\u0013:3\ufffdh\ufffd at sequence 206 dbtx=o2e59tT9 pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T19:13:30.211291916Z"}

[dechdev]

25 broadcast/25 private - Only one message succeeds before test halts
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[peterbroadhurst]

Latest run investigation ongoing to see why the first message is not matching here:

{"log":"[2022-02-08T20:13:21.515Z] DEBUG Aggregating pin 0000000005 batch=94870286-6ffe-4f96-abdd-046ee1506248 index=0 hash=5539a8f94dc5d76196247e1bf756c856570e780070f0fe0d87a602719452f7ee masked=true dbtx=NNgyCqWj pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T20:13:21.51606254Z"}
{"log":"[2022-02-08T20:13:21.522Z] DEBUG Group=fdacb9a418887b4e4388b38b2b91d70d20f35f6c988af8d276bfbd4006ca4bcc topic=default context=b17d858f3d37d4fa4c4812091c020686431b9fb6d3dc32ff20717a1ba09496d4 zeroHashes=[0cb7504e98fab01e5c98791c410aa499a8f12d0bc9107e54275bc67703041ce3 733ef69f3711c29bf2c5c66605e4e197f129f35123a4c05929f8f4fe605bda30] dbtx=NNgyCqWj pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T20:13:21.522634133Z"}
{"log":"[2022-02-08T20:13:21.522Z]  WARN No match for zerohash on context: group=fdacb9a418887b4e4388b38b2b91d70d20f35f6c988af8d276bfbd4006ca4bcc topic=default context=b17d858f3d37d4fa4c4812091c020686431b9fb6d3dc32ff20717a1ba09496d4 pin=423e71f8e95dee03dd01f60dda659e3046f3032e57e7afaab4322855969daa9c dbtx=NNgyCqWj pid=1 role=aggregator\n","stream":"stderr","time":"2022-02-08T20:13:21.522731251Z"}

[dechdev]

25 broadcast/25 private - New debug logs
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[dechdev]

25 broadcast/25 private - More debug logs
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[dechdev]

25 broadcast/25 private - after #499
ff-perf.log
log_ethconnect_0.log
log_firefly_core_0.log

[peterbroadhurst]

Looks like a rewind issue maybe in this one:

{"log":"[2022-02-08T23:04:52.318Z] DEBUG Marking rewind to sequence=35 (previous=27) pid=1 role=batchmgr\n","stream":"stderr","time":"2022-02-08T23:04:52.318674632Z"}

But we don't go back and pick up 6736bf65-88bb-4f68-9cdc-ad322a3107f4