comms: expected other party to act

[JoeGruffins]

The problem seen here: https://github.com/decred/dcrdex/pull/1623#issuecomment-1137233243

@chappjc seems to know what's going on. Maybe client just isn't waiting long enough for a response? The trade completes alright apparently.

logs server: dcrdex.log client1: out3.txt client2 (the one trying to init again): out4.txt

[chappjc]

There's a lot to look at in your logs and I'm still scanning, but as an aside, be extra careful with your server and client lock time configs. There are a number of these around the time of that settlement sequence error:

[ERR] CORE: Order xxx, match yyy counter-party's swap expired before we could redeem (client / out4.txt)

And the server looks like you were recompiling with different lock times?

2022-05-25 21:37:29.118 [INF] MAIN: swap locktimes config: maker 40m0s, taker 20m0s

2022-05-25 22:16:37.151 [INF] MAIN: swap locktimes config: maker 1h0m0s, taker 30m0s

I can't really tell what clients were using at that time. I think we should add a log on startup for clients that is similar to server.

[chappjc]

Also it looks like those times were too short for BTC testnet at the time, which had very slow blocks and some reorgs:

2022-05-25 13:07:39.888 [DBG] CORE[btc]: tip change: 2227587 (000000000000002e34bab29fec6fe47052b6ee0c4195c598951a9316ec54a1d4) => 2227588 (000000000000000e122c9c6df2d1fbdca50ee5a294f9686daf5455967de4eff4)
2022-05-25 13:12:11.798 [DBG] CORE[btc]: tip change: 2227588 (000000000000000e122c9c6df2d1fbdca50ee5a294f9686daf5455967de4eff4) => 2227589 (000000000000002ffc29d1818fa6f051bf2688ebec54c1c56e5449f0e6122b7f)
2022-05-25 13:17:02.481 [DBG] CORE[btc]: tip change: 2227589 (000000000000002ffc29d1818fa6f051bf2688ebec54c1c56e5449f0e6122b7f) => 2227589 (000000000000002ffc29d1818fa6f051bf2688ebec54c1c56e5449f0e6122b7f)
2022-05-25 13:20:52.535 [DBG] CORE[btc]: tip change: 2227589 (000000000000002ffc29d1818fa6f051bf2688ebec54c1c56e5449f0e6122b7f) => 2227590 (000000000000001be2ece36b1371117e418687508e758a295884593e18eaed00)
2022-05-25 13:22:44.976 [DBG] CORE[btc]: tip change: 2227590 (000000000000001be2ece36b1371117e418687508e758a295884593e18eaed00) => 2227591 (00000000000000286aa91ab4bb1bf84ce92af6dc6dd613c1c6bee7d0c03e0739)
2022-05-25 13:34:18.038 [DBG] CORE[btc]: tip change: 2227591 (00000000000000286aa91ab4bb1bf84ce92af6dc6dd613c1c6bee7d0c03e0739) => 2227592 (0000000000000018dcea972abd737878b47533e03d4c49c6140c36d21857edc3)
2022-05-25 13:36:23.339 [DBG] CORE[btc]: tip change: 2227592 (0000000000000018dcea972abd737878b47533e03d4c49c6140c36d21857edc3) => 2227593 (0000000000000025880f17714b42c567a3ed54954cdf6e7a9c3cfaf9bc066b68)

[chappjc]

The non-blocking waiter #1623 just merged will help with this a lot, but there are still some strange things you hit.

[chappjc]

Regarding the strange things, first, error sending 'init' message: rpc error: error code 26: expected other party to act - Order is confusing to see logged because it's missing the errors.Is and match on the settlement sequence code. You should see Starting match status resolution for 'init' request SettlementSequenceError always, but you only see that sometimes.

Another issue is that there's no status resolution to fix it. In resolveConflictWithServerData it ends up hitting if srvStatus == match.Status and doing nothing because client and server do agree on status, but client keeps sending the init request because it still wants the auth.InitSig. There's no way get it because the initial request that succeeded server-side timed out client-side, and now server won't handle the request again. So client keeps trying and failing until the counter-party's turn comes and then the match proceeds without the InitSig. Ugh.

[JoeGruffins]

Oh yeah, I think I changed client locktimes a few times. And server I guess. I had it at 20/40 but bitcoin was going slow so switched to 30/60 and I think I saw the error there. Maybe I forgot to rebuild the client? I'm not sure.

[JoeGruffins]

The non-blocking waiter https://github.com/decred/dcrdex/pull/1623 just merged will help with this a lot, but there are still some strange things you hit.

This was testing on #1623

[chappjc]

Ruh roh

[JoeGruffins]

Perhaps due to compiling with different locktimes. Will test some more on testnet and close if I don't see again.

[JoeGruffins]

Have not seen again. Probably miss-matched locktimes.