concurrent virtual-fund objectives can fail

[andrewgordstewart]

This CI run attempts to run three concurrent virtualfund objectives, and fails. It passes locally!

Locally, I can make the same test pass with 5 concurrent objectives, but not 6. This suggests there is some timing component that realizes a bug in the virtualfund protocol.

[andrewgordstewart]

➜  artifacts-2 grep "0xAAA662" virtualfund_benchmark_test.log | grep complete
0xAAA662: 22:03:00.834859 engine.go:104: Objective DirectFunding-0xd0b4844ba688dbf5824dfc49b47f85a097dd64662d3a20e9825f249098448b6b is complete & returned to API
0xAAA662: 22:03:00.835222 engine.go:104: Objective DirectFunding-0xd0b4844ba688dbf5824dfc49b47f85a097dd64662d3a20e9825f249098448b6b is complete & returned to API
0xAAA662: 22:03:00.914325 engine.go:104: Objective VirtualFund-0x4529700e188de529c65ae0ec34085b2b4891bad70a9e2a811665e10eb6cf3627 is complete & returned to API
0xAAA662: 22:03:00.915600 engine.go:104: Objective VirtualFund-0xf28b746007c27a95953404e1cd8fab75abb8c4a6b605eb47739e719a8cd083e2 is complete & returned to API
0xAAA662: 22:03:00.923297 engine.go:104: Objective VirtualFund-0xc25d9f877cb2d4e481cc62c9011dc83541f3e1f696d3e7c506983082d79117fa is complete & returned to API
➜  artifacts-2 grep "0xB" virtualfund_benchmark_test.log | grep complete
0xBBB676: 22:03:00.841397 engine.go:104: Objective DirectFunding-0xf8bdc5ec5852f01a9e6616c482f42b91e3320cc656410c324d9ae93ab8f34973 is complete & returned to API
0xBBB676: 22:03:00.919545 engine.go:104: Objective VirtualFund-0x4529700e188de529c65ae0ec34085b2b4891bad70a9e2a811665e10eb6cf3627 is complete & returned to API
0xBBB676: 22:03:00.920642 engine.go:104: Objective VirtualFund-0xf28b746007c27a95953404e1cd8fab75abb8c4a6b605eb47739e719a8cd083e2 is complete & returned to API
0xBBB676: 22:03:00.921939 engine.go:104: Objective VirtualFund-0xc25d9f877cb2d4e481cc62c9011dc83541f3e1f696d3e7c506983082d79117fa is complete & returned to API

This points to an issue in waitTimeForCompletedObjectiveIds, so I removed the use of it here.

Unfortunately, if I run with n=6 locally, Alice and Bob have a different view of how many objectives completed:

➜  go-nitro git:(ags/benchmark) ✗ grep "is complete" artifacts/virtualfund_benchmark_test.log | grep '0xB' | wc -l
       6
➜  go-nitro git:(ags/benchmark) ✗ grep "is complete" artifacts/virtualfund_benchmark_test.log | grep '0xA' | wc -l
       7

[andrewgordstewart]

➜  go-nitro git:(ags/benchmark) ✗ grep "0xB" artifacts/virtualfund_benchmark_test.log | grep VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe
...
0xBBB676: 15:27:09.570007 engine.go:119: Handling inbound message {to:0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94 objectiveId:VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe signedStates:[{turnNum:0 channelId:0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe}]}
0xBBB676: 15:27:09.570711 engine.go:247: Objective VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe is WaitingForCompleteFunding

➜  go-nitro git:(ags/benchmark) ✗ grep "0xA" artifacts/virtualfund_benchmark_test.log | grep VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe
...
0xAAA662: 15:27:09.567163 engine.go:119: Handling inbound message {to:0xAAA6628Ec44A8a742987EF3A114dDFE2D4F7aDCE objectiveId:VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe signedStates:[{turnNum:0 channelId:0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe}]}
0xAAA662: 15:27:09.568090 engine.go:247: Objective VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe is WaitingForNothing
0xAAA662: 15:27:09.568105 engine.go:104: Objective VirtualFund-0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe is complete & returned to API

It looks like Alice's client is satisfied with 0x28beb1a9fcbec6cadc35c14b8020a2a23d2cf96b687a1f690573f332bb641afe after receiving a preFS state from someone (Bob, I believe?)

[lalexgap]

This might be due to the ledger funding issue we identified at standup.

Bob/Irene could end up ignoring the ledger proposal if they receive proposals out of order.

[lalexgap]

I'm fairly certain this is the same issue as #366 (which has more discussion) so I'm closing in favour of that.