investigate rare TestMultiChequeSimulation bug

[mortelli]

It seems there is a rare error occurring in TestMultiChequeSimulation when running the function as it is on the swap-multi-cheque-bug branch.

Test by opening a terminal in github.com/ethersphere/swarm and running:

for i in `seq 1000`; do /usr/local/go/bin/go test -count=1 -timeout 15s github.com/ethersphere/swarm/swap -run ^TestMultiChequeSimulation$; done > log.txt

(be aware that the default timeout for go test is 10 minutes, while this test in particular is programmed to time out at 10 seconds)

To run until the first failure:

while /usr/local/go/bin/go test -count=1 github.com/ethersphere/swarm/swap -run ^TestMultiChequeSimulation$; do :; done

[mortelli]

possible cause elucidated here

[mortelli]

possible cause elucidated here

this does indeed seem to be the case for at least some of the failures.

summary: when it's the creditor's turn to process messages, not all of the messages which would increase the debt up to where a cheque is needed are able to be accounted for before the cheque message arrives.

this causes the cheque to be perceived as a debt cheque at the moment it's processed.

sample output:

...
iteration 201 
balance towards CREDITOR is now -19829614073004 
balance towards CREDITOR is now 0 
sending cheque for 19829614073004 to CREDITOR 
balance towards DEBITOR is now 392665625208 
balance towards DEBITOR is now 588998437812 
balance towards DEBITOR is now 785331250416 
balance towards DEBITOR is now 981664063020 
balance towards DEBITOR is now 1177996875624 
balance towards DEBITOR is now 1374329688228 
balance towards DEBITOR is now 1570662500832 
balance towards DEBITOR is now 1766995313436 
balance towards DEBITOR is now 1963328126040 
balance towards DEBITOR is now 2159660938644 
balance towards DEBITOR is now 2355993751248 
balance towards DEBITOR is now 2552326563852 
balance towards DEBITOR is now 2748659376456 
balance towards DEBITOR is now 2944992189060 
balance towards DEBITOR is now 3141325001664 
balance towards DEBITOR is now 3337657814268 
balance towards DEBITOR is now 3533990626872 
balance towards DEBITOR is now 3730323439476 
balance towards DEBITOR is now 3926656252080 
balance towards DEBITOR is now 4122989064684 
balance towards DEBITOR is now 4319321877288 
balance towards DEBITOR is now 4515654689892 
balance towards DEBITOR is now 4711987502496 
balance towards DEBITOR is now 4908320315100 
balance towards DEBITOR is now 5104653127704 
balance towards DEBITOR is now 5300985940308 
balance towards DEBITOR is now 5497318752912 
balance towards DEBITOR is now 5693651565516 
balance towards DEBITOR is now 5889984378120 
balance towards DEBITOR is now 6086317190724 
balance towards DEBITOR is now 6282650003328 
balance towards DEBITOR is now 6478982815932 
balance towards DEBITOR is now 6675315628536 
balance towards DEBITOR is now 6871648441140 
balance towards DEBITOR is now 7067981253744 
balance towards DEBITOR is now 7264314066348 
balance towards DEBITOR is now 7460646878952 
balance towards DEBITOR is now 7656979691556 
balance towards DEBITOR is now 7853312504160 
balance towards DEBITOR is now 8049645316764 
balance towards DEBITOR is now 8245978129368 
balance towards DEBITOR is now 8442310941972 
balance towards DEBITOR is now 8638643754576 
balance towards DEBITOR is now 8834976567180 
balance towards DEBITOR is now 9031309379784 
balance towards DEBITOR is now 9227642192388 
balance towards DEBITOR is now 9423975004992 
balance towards DEBITOR is now 9620307817596 
balance towards DEBITOR is now 9816640630200 
balance towards DEBITOR is now 10012973442804 
balance towards DEBITOR is now 10209306255408 
balance towards DEBITOR is now 10405639068012 
balance towards DEBITOR is now 10601971880616 
balance towards DEBITOR is now 10798304693220 
balance towards DEBITOR is now 10994637505824 
balance towards DEBITOR is now 11190970318428 
balance towards DEBITOR is now 11387303131032 
balance towards DEBITOR is now 11583635943636 
balance towards DEBITOR is now 11779968756240 
balance towards DEBITOR is now 11976301568844 
balance towards DEBITOR is now 12172634381448 
balance towards DEBITOR is now 12368967194052 
balance towards DEBITOR is now 12565300006656 
balance towards DEBITOR is now 12761632819260 
balance towards DEBITOR is now 12957965631864 
balance towards DEBITOR is now 13154298444468 
balance towards DEBITOR is now 13350631257072 
balance towards DEBITOR is now 13546964069676 
balance towards DEBITOR is now 13743296882280 
receiving cheque for 19829614073004 from DEBITOR 
[31mERROR[0m[01-22|12:07:21.222|github.com/ethersphere/swarm/p2p/protocols/protocol.go:248] dropping peer with DiscSubprotocolError  [31mpeer[0m=a13a5d5da4872560 [31mreason[0m="message handler: (msg code 1): processing and verifying received cheque: current balance is 13743296882280, received cheque would result in balance -6086317190724 which exceeds tolerance 3926656252094 and would cause debt"
balance towards DEBITOR is now 13939629694884 
balance towards DEBITOR is now 14135962507488 
balance towards DEBITOR is now 14332295320092 
balance towards DEBITOR is now 14528628132696 
balance towards DEBITOR is now 14724960945300 
balance towards DEBITOR is now 14921293757904 
balance towards DEBITOR is now 15117626570508 
...

this log shows how that:

1. first, the debitor updates its balance and sends the cheque
2. in the meantime, the creditor receives regular (non-cheque) messages and updates its balance accordingly
3. then, in the middle of these updates, the cheque is received and rejected due to being a debt cheque
4. finally, the creditor continues updating its balance as it keeps processing regular messages

[Eknir]

@mortelli , what is the status of this PR?

[mortelli]

@mortelli , what is the status of this PR?

there is no PR for this issue yet.

we still need to look into possibly changing this test so that it can consistently succeed.