We sometimes see a a closing balance with notification of 100/0

[lalexgap]

See https://github.com/statechannels/go-nitro/actions/runs/5034369990/jobs/9029151062

rpc_test.go:313: Received unexpected notification: {0xb5cf2bc6b41492c89ac8c38c714c18dd2b24903fce274092d51df7de183cb37f Closing {0x0000000000000000000000000000000000000000 0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94 0xAAA6628Ec44A8a742987EF3A114dDFE2D4F7aDCE 0 100}}

Occasionally our RPC test flickers and fails with the error above.

It looks like sometimes we get a Closing notification with a balance of 100/0 instead of the expected value of 99/1. I think this could be legitimate, since it's possible that Bob happens to receive the close objective before the voucher? However I think we should dig into this and figure out what exactly is happening.

Unfortunately I blew away the log files when rerunning the action.

[lalexgap]

Here's another example. Here are the log files.

[geoknee]

Here's another example. Here are the log files.

Thanks @lalexgap. I piped the logs through pino-pretty and trawled through. Summary output below, with most lines trimmed and ordering preserved:

[21:43:29.622] DEBUG <engine.go:683>: 0xBBB676  <  {"engine":"0xBBB676","message":"Constructing objective VirtualDefund-0xa1220ec1300a77856f72e63922ce7a269b0469c954dbd58c896c4b943518b0ed from message"}

[21:43:29.623] TRACE <engine.go:782>: 0xBBB676 0xBBB676 < 0xAAA662 {"engine":"0xBBB676","To":"0xBBB676","From":"0xAAA662","PayloadSummaries":[],"ProposalSummaries":[],"Payments":[{"ChannelId":"0xa1220ec1300a77856f72e63922ce7a269b0469c954dbd58c896c4b943518b0ed","Amount":1}],"RejectedObjectives":[],"message":"Received message"}

[21:43:29.623] TRACE:   <  {"client":"0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94","rpc":"server","scope":"","message":"Sending notification: {ID:0xa1220ec1300a77856f72e63922ce7a269b0469c954dbd58c896c4b943518b0ed Status:Closing Balance:{AssetAddress:0x0000000000000000000000000000000000000000 Payee:0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94 Payer:0xAAA6628Ec44A8a742987EF3A114dDFE2D4F7aDCE PaidSoFar:+0 RemainingFunds:+100}}"}
[21:43:29.623] TRACE:   <  {"client":"0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94","rpc":"server","scope":"","message":"Sending notification: {ID:0xa1220ec1300a77856f72e63922ce7a269b0469c954dbd58c896c4b943518b0ed Status:Closing Balance:{AssetAddress:0x0000000000000000000000000000000000000000 Payee:0xBBB676f9cFF8D242e9eaC39D063848807d3D1D94 Payer:0xAAA6628Ec44A8a742987EF3A114dDFE2D4F7aDCE PaidSoFar:+1 RemainingFunds:+99}}"}

It looks like:

• Bob gets a virtual defund message from Alice before receiving the voucher
• Bob goes through virtual defunding protocol, which involves asking Alice for the latest payment. A notification is triggered reflecting the lack of any vouchers received yet (the channel wasn't really updated, but that's how it works rn).
• Bob gets the final state from Alice, which implicitly includes an adjustment from the voucher*. AND/.OR the voucher is received and the channel is updated.
• Another notification is triggered and from this point on everyone seems to be "in sync".

I think overall the behaviour seems good and definitely in line with our protocols. So adjusting the test expectations seems very reasonable to me.

*There's an opportunity for a Byzantine Alice to trick Bob here, but she has no way of knowing that he didn't get the voucher yet. Depending on how it would be handled, a clever Byzantine Alice could try to trick Bob. But it's a very edge case unlikely to succeed. Moreover, Bob will probably not have delivered the service corresponding to that voucher... so it doesn't seem unfair for Alice to check out with the lower amount. I think in a realistic setting, Alice will wait until she has an indication that Bob received the payment before trying to defund the channel. With micropayments, we expect to rely on some microtrust (there's always a chance the payer or the payee misses out by 1 unit of exchange).