This should not happen: ... boundary.pony at line 361 (Boundary.receive_ack())

[slfritchie]

Is this a bug, feature request, or feedback?

Bug

What is the current behavior?

Rarely, Boundary.receive_ack() fails on a debug-build-only Invariant() check, for example:

1573255713.777674,Rcvd msg at OutgoingBoundary
1573255713.777684,Received AckDataReceivedMsg at Boundary
1573255713.777700,DEBUG,none,acked_seq_id 513 > _lowest_queue_id 4912

1573255713.777704,not (acked_seq_id 513 > _lowest_queue_id 4912)
Invariant violated in /home/vagrant/wallaroo/lib/wallaroo/core/boundary/boundary.pony at line 361

Full logs are available at http://wallaroolabs-dev.s3.amazonaws.com/logs/logs.1573255937.tar.gz: the crash is reported in tmp/wallaroo.0.1573255716.

What is the expected behavior?

No crash

What OS and version of Wallaroo are you using?

Ubuntu Xenial/16.04 LTS + master branch @ commit 40fdf14 + merge connector-sink-fixes / PR #3042 + merge gh3020 / PR #3055 + diff at https://gist.github.com/slfritchie/9ad8665f14b5f79cd859a9e731cc9290

Steps to reproduce?

$ export WALLAROO_TOP=/your/path/to/top/of/wallaroo/repo
$ cd $WALLAROO_TOP
$ dd if=$HOME/wallaroo/testing/data/market_spread/nbbo/r3k-symbols_nbbo-fixish.msg bs=1000000 count=1 | od -x | sed 's/^/T/' | sed -n
'1,/T3641060/p' | perl -ne 'print "\0\0\0"; print "1"; print' > /tmp/input-file.txt
$ cd testing/correctness/scripts/effectively-once
$ export WALLAROO_THRESHOLDS='*.8'
$ export WALLAROO_BIN=$WALLAROO_TOP/examples/pony/passthrough/passthrough
$ . ./sample-env-vars.sh
$ make -C ../../../..     PONYCFLAGS="--verbose=1 -d -Dresilience -Dtrace -Dcheckpoint_trace -Didentify_routing_ids"
build-examples-pony-passthrough build-testing-tools-external_sender     build-utils-cluster_shrinker build-utils-data_receiver
build-testing-tools-fixed_length_message_blaster
$ ./master-crasher.sh 2 no-sanity crash0 crash1 crash-sink

[slfritchie]

This crash still happens on today's master branch at commit 9680d93 (after merges of PR #3058 and #3057), see logs at http://wallaroolabs-dev.s3.amazonaws.com/logs/logs.1574111685.tar.gz

[slfritchie]

From the logs.1574111685.tar.gz collection:

$ zcat /tmp/wallaroo.0.1574111508.gz | egrep 'DEBUG,none|Injecting'
1574111505.980820,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 0
1574111505.980974,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 0
1574111506.064922,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 0
1574111506.092519,DEBUG,none,worker initializer target_worker worker1 acked_seq_id 1533 > _lowest_queue_id 0
1574111506.115522,Injecting blocking barrier CheckpointRollbackBarrierToken(Rollback 95, Checkpoint 114) with blocking completion token CheckpointRollbackResumeBarrierToken(Rollback 95, Checkpoint 114)
1574111508.061055,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 1
1574111508.062179,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 1
1574111508.062266,DEBUG,none,received: worker initializer target_worker worker1 sn.last_id_seen 1
1574111508.065809,Injecting blocking barrier CheckpointRollbackBarrierToken(Rollback 96, Checkpoint 114) with blocking completion token CheckpointRollbackResumeBarrierToken(Rollback 96, Checkpoint 114)
1574111508.098573,Injecting barrier CheckpointRollbackResumeBarrierToken(Rollback 96, Checkpoint 114)
1574111508.106961,Injecting barrier CheckpointBarrierToken(115)
1574111508.783765,DEBUG,none,worker initializer target_worker worker1 acked_seq_id 513 > _lowest_queue_id 1533