Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

core: panic checking cancel order checksum #2964

Closed
buck54321 opened this issue Sep 8, 2024 · 7 comments · Fixed by #2977
Closed

core: panic checking cancel order checksum #2964

buck54321 opened this issue Sep 8, 2024 · 7 comments · Fixed by #2977
Assignees
@JoeGruffins

Comments

@buck54321
Copy link
Member

buck54321 commented Sep 8, 2024 •
edited
Loading 

panic: runtime error: invalid memory address or nil pointer dereference  
[signal SIGSEGV: segmentation violation code=0x1 addr=0xc8 pc=0xa70334]  
  
goroutine 1899759 [running]:  
decred.org/dcrdex/client/core.acceptCsum(0xc0012f6480, 0x1, {0xc0012f8bc0, 0x20, 0x20})  
        /home/user/code/gopath/pkg/mod/decred.org/[email protected]/client/core/core.go:8999 +0x94  
decred.org/dcrdex/client/core.processPreimageRequest(0xc0004b2800, 0xc000003080, 0x1bb6a, {0xae, 0x2f, 0x74, 0xcb, 0xb8, 0x1f, 0xd0, ...}, ...)  
        /home/user/code/gopath/pkg/mod/decred.org/[email protected]/client/core/core.go:8948 +0x253  
decred.org/dcrdex/client/core.handlePreimageRequest.func1()  
        /home/user/code/gopath/pkg/mod/decred.org/[email protected]/client/core/core.go:8925 +0x9f  
created by decred.org/dcrdex/client/core.handlePreimageRequest in goroutine 22  
        /home/user/code/gopath/pkg/mod/decred.org/[email protected]/client/core/core.go:8922 +0x3e5
@buck54321
Copy link
Member Author

buck54321 commented Sep 8, 2024 •
edited
Loading

The only way this can happen is if the tracker.cancel is set to nil somewhere between findOrder and acceptCsum in processPreimageRequest. tracker.cancel is set to nil on a couple of paths. Regardless of which it is, we probably need consider processPreimageRequest as a single operation under tracker.mtx.

@JoeGruffins
Copy link
Member

I can look into this if noone else is.

@JoeGruffins JoeGruffins mentioned this issue Sep 13, 2024
Closed
@JoeGruffins
Copy link
Member

We chatted on matrix and maybe the issue is more than just a panic. Its likely this panic occurred because preimage missed came as we were sending the preimage, so simply locking the trade mutex should fix that but there may be a bigger issue causing preimages to be missed. I have an example here using loadbot, where the server sent the preimage 20 seconds before we acknowledged it, and we missed it. This seems excessive on simnet, so it may be that we are waiting in core for some reason (til the end of the epoch?), or locked up, and missing sending preimages.

server:

2024-09-12 16:56:27.738 [DBG] SWAP: Received 'redemption' acknowledgement from user 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (taker) for match 40a1aac03488aa1e31f335c712c4afdd5671b6998e3f5de3cd7ef02ef230a4ff (MakerRedeemed)
2024-09-12 16:56:27.762 [TRC] MKT: balance check for eth - 0xB54564D481b7924C21133E9eaA2bfA535763Ed86: new qty = 100000000, new lots = 1, new redeems = 0
2024-09-12 16:56:27.808 [DBG] SWAP: processRedeem: sending 'redemption' request to counterparty 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (taker) for match ea8c0328c5b808f2e0950c760778dd945e06df7caa799de2d5621c7bb72ccf7d
2024-09-12 16:56:27.808 [TRC] MKT: (*DEXBalancer).CheckBalance: balance check for eth - 0xB54564D481b7924C21133E9eaA2bfA535763Ed86: total qty = 500000000, total lots = 1, total redeems = 0, redeemCosts = 0, required = 604700000, bal = 43316654740, fee bal = 0
2024-09-12 16:56:27.808 [TRC] MKT: Received order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f at 2024-09-12 07:56:27.808 +0000 UTC
2024-09-12 16:56:28.431 [DBG] SWAP: Deleting completed match 14d29a0c954f4eaba3b68b731da5ec00211519419d2d48eac2e237a999d38c1e
2024-09-12 16:56:28.431 [DBG] SWAP: Received 'redemption' acknowledgement from user 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (maker) for match 14d29a0c954f4eaba3b68b731da5ec00211519419d2d48eac2e237a999d38c1e (MatchComplete)
2024-09-12 16:56:28.985 [DBG] SWAP: handleRedeem: 'redeem' received from 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc for match a539e290a3cdf2f07287975b479bc3f8be08cff0d67166facc81a1d3243a027a, order 71be8c54213e64eb1c5204508a298e1df17570bf2b9d4743f53d84352c3431bc
2024-09-12 16:56:28.985 [DBG] SWAP: Allowing until 2024-09-12 07:57:28.985812257 +0000 UTC (59.999999529s) to locate redeem from taker (MakerRedeemed), match a539e290a3cdf2f07287975b479bc3f8be08cff0d67166facc81a1d3243a027a, tx 0xb3d9631c7b36ca723b93f9a8dc88d3180f9b6d92edefa7922c52e3aa3c458e89 (eth)
2024-09-12 16:56:28.987 [DBG] SWAP: processRedeem: valid redemption 0xb3d9631c7b36ca723b93f9a8dc88d3180f9b6d92edefa7922c52e3aa3c458e89 (eth) spending contract 0x32f880f2c2ab3c6d9972c122b0b1a15225165d10c13e74b8f9deadd1bc377e2a received at 2024-09-12 07:56:28.987 +0000 UTC from 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (taker) for match a539e290a3cdf2f07287975b479bc3f8be08cff0d67166facc81a1d3243a027a, swapStatus MakerRedeemed => MatchComplete

.....

2024-09-12 16:56:29.939 [DBG] SWAP: processRedeem: valid redemption 0xb107e3efa0b267f3f492bedb09fa54e44ab1f05eb9ce1814d99775787495b299 (eth) spending contract 0x406b5ec061e2077e37422c2388443f9dedc353b3d1b37ece0181f0265acef6cb received at 2024-09-12 07:56:29.939 +0000 UTC from 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (taker) for match 40a1aac03488aa1e31f335c712c4afdd5671b6998e3f5de3cd7ef02ef230a4ff, swapStatus MakerRedeemed => MatchComplete
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order 09dc5d4a78059ced9dd3fc812e16f618a793e8c00b85dda4903bc96cb9923ea3
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order 897ce4363095602a68db540fceb6948bc6c89bf90632204498d54e0cff3b0eaf
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order c55d66886f52c5902b60fdf50bb3eaa9dba714d443b73e4483b2f858e80d4261
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order d17801010c6bc3fbf9a77b24f98b0129f68a2883e9c87bec9fbdb0b0e53815cb
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order 704571424cf22d3370bbe459e420945d762383b895ee0cd7487a79ca479918d1
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order fee42b1686f818c9452ed7cac5ddb86b501b2773f9328edf1cc5d98be059f7b6
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:30.000 [TRC] MKT: Preimage request sent for order 05d41287d0525cd662f5eee2b44e57b9702721fe6691bd9d5de38f5984f8788c
2024-09-12 16:56:30.082 [DBG] AUTH: Match success for user 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc: strikes 60, bond tier 100 => tier 100
2024-09-12 16:56:30.082 [DBG] AUTH: Recorded order cb4261c71c79fc5abe7c102d1df2b68719cc839896105f9f5554f9ca15ddb44c that has finished processing: user=3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc, time=1726127790082, target=<nil>
2024-09-12 16:56:30.152 [DBG] SWAP: processRedeem: sending 'redemption' request to counterparty a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 (maker) for match 40a1aac03488aa1e31f335c712c4afdd5671b6998e3f5de3cd7ef02ef230a4ff

.......

2024-09-12 16:56:49.852 [DBG] SWAP: processRedeem: valid redemption 0x8ad039742575bb9986d17edfbb22bae248acbaeec82588cc18dae20ebcd37862 (eth) spending contract 0x98ab47958f1b6790aa6d67180faf1791c9b6596ed5b1a21e4e07c58b8f8b5194 received at 2024-09-12 07:56:49.852 +0000 UTC from 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc (maker) for match 10da3a99e29c59ce04b9e95d8b0addb8db0a6313af457e388ffedecafca3f14e, swapStatus TakerSwapCast => MakerRedeemed
2024-09-12 16:56:49.897 [DBG] SWAP: processRedeem: sending 'redemption' request to counterparty a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 (taker) for match 676e4ed5f677ee7b2c5a56ce2044a94f19ac40bf43b89fef036cbda6ddd5b7c2
2024-09-12 16:56:49.920 [DBG] AUTH: Match success for user 3645d5d108374b082962498de9709a77f6d096c5792dcba0cabd78ef457f9fbc: strikes 60, bond tier 100 => tier 100
2024-09-12 16:56:49.920 [DBG] SWAP: processRedeem: sending 'redemption' request to counterparty a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 (taker) for match 10da3a99e29c59ce04b9e95d8b0addb8db0a6313af457e388ffedecafca3f14e
2024-09-12 16:56:50.000 [INF] MKT: Collected 4 valid order preimages, missed 4. Commit checksum: 3124dacdc26dfc59ca2da3f01cef96044fab2bbe10cc36e8cf1a31066bc808bb
2024-09-12 16:56:50.000 [INF] MKT: No preimage received for order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f from user a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7. Recording violation and revoking order.
2024-09-12 16:56:50.105 [DBG] AUTH: Recorded order b2bd87cd5024240460cb263b8dbb494d048341b772bcecad750564989e930801 that has finished processing: user=a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7, time=1726127810036, target=f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:50.105 [DBG] AUTH: RecordCancel: user a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 strikes 60, bond tier 100 => trading tier 100
2024-09-12 16:56:50.105 [DBG] AUTH: MissedPreimage: user a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 strikes 58, bond tier 100 => trading tier 100
2024-09-12 16:56:50.105 [INF] MKT: No preimage received for order 09dc5d4a78059ced9dd3fc812e16f618a793e8c00b85dda4903bc96cb9923ea3 from user a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7. Recording violation and revoking order.
2024-09-12 16:56:50.105 [INF] MKT: Sending a 'revoke_order' notification to a95e8b2833f023f812f203ea8c285a681d5e7a2d80cad88e3091582350a1b1f7 for order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:50.106 [TRC] MKT: balance check for eth - 0xB54564D481b7924C21133E9eaA2bfA535763Ed86: new qty = 200000000, new lots = 2, new redeems = 0

client

2024-09-12 16:56:28.076 [DBG] CORE:STACKER:1: notify: |POKE| (order) Order placed - Buying 0.400000000 ETH, rate = 0.0771 ({{{order|897ce4363095602a68db540fceb6948bc6c89bf90632204498d54e0cff3b0eaf}}}) - Order: 897ce4363095602a68db540fceb6948bc6c89bf90632204498d54e0cff3b0eaf
2024-09-12 16:56:28.112 [DBG] CORE:STACKER:1[btc]: Attempting to fund order for 0.01604 btc, maxFeeRate = 100, max swaps = 2
2024-09-12 16:56:28.131 [DBG] CORE:STACKER:1[btc]: Setting aside 0.10135549 BTC in 2 UTXOs to respect the 0.10003768 BTC reserved amount
2024-09-12 16:56:28.131 [INF] CORE:STACKER:1[btc]: Funding 0.01604 btc order with coins [de01741541e277f09a8e68eba4506d49134c7e3ed7aa7a7c696092a8c72a057c:1] worth 0.35650369
2024-09-12 16:56:28.147 [TRC] CORE:STACKER:1[eth]: Transaction 0xd79af77322324a442391911ab3aef644101533580126862d87c1a4a2a46104a2 generated for nonce 915
2024-09-12 16:56:28.148 [INF] CORE:STACKER:1: Broadcasted redeem transaction spending 1 contracts for order cd434fd5d3ffc6805414492cad57bcc659bbe2199778d77d272fa0162601fda1, paying to 0xd79af77322324a442391911ab3aef644101533580126862d87c1a4a2a46104a2 (eth)
2024-09-12 16:56:28.218 [DBG] CORE:STACKER:0: notify: |POKE| (order) Order placed - Selling 0.100000000 ETH, rate = 0.0795 ({{{order|f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f}}}) - Order: f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:28.335 [INF] CORE:STACKER:1: Match a539e290a3cdf2f07287975b479bc3f8be08cff0d67166facc81a1d3243a027a complete: buy 100000000 eth
2024-09-12 16:56:28.431 [INF] CORE:STACKER:1: runJob(redemption) completed in 693.687354ms
2024-09-12 16:56:28.431 [DBG] CORE:STACKER:1: Redeemable match 40a1aac03488aa1e31f335c712c4afdd5671b6998e3f5de3cd7ef02ef230a4ff for order cb4261c71c79fc5abe7c102d1df2b68719cc839896105f9f5554f9ca15ddb44c (Taker)

.....

2024-09-12 16:56:50.399 [DBG] CORE:STACKER:1: Received valid ack for 'redeem' request for match 823d8b5d9327552a73ab6f9534f64b48dbfca2afed2fb193d04d12805151257a)
2024-09-12 16:56:50.399 [TRC] CORE:STACKER:0: Received a courtesy redemption request for match 0dc42d05a78288d506eb84f0c7a7ba3ff13d1a85194a7da2d176ef4ee005f1af as maker
2024-09-12 16:56:50.400 [DBG] CORE:STACKER:0: Received preimage request for order 09dc5d4a78059ced9dd3fc812e16f618a793e8c00b85dda4903bc96cb9923ea3 with known commitment 0b986dea39584bb306ae14c20480800b84a2b93eb56d9e24a799a0589df7189c
2024-09-12 16:56:50.400 [DBG] CORE:STACKER:0: Received preimage request for order d17801010c6bc3fbf9a77b24f98b0129f68a2883e9c87bec9fbdb0b0e53815cb with known commitment af6aee63174a9d4877c34dcb24f78b78107adc5dd04456730b5d4c9831dfb280
2024-09-12 16:56:50.400 [DBG] CORE:STACKER:0: Received preimage request for order fee42b1686f818c9452ed7cac5ddb86b501b2773f9328edf1cc5d98be059f7b6 with known commitment c82f53b0be60a26254fcc65fa5482e3fd142674ac887b373ae6e5af969e75748
2024-09-12 16:56:50.400 [DBG] CORE:STACKER:0: Received preimage request for order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f with known commitment ce90dac90eb06df6bc2981e1f73a4c22f053bd791012370de1ce56c471577b01
2024-09-12 16:56:50.400 [INF] LOADBOT[STACKER:1]: Balance: eth = 45734753588 available, 1021800000 locked
2024-09-12 16:56:50.400 [DBG] CORE:STACKER:0: async processPreimageRequest for 09dc5d4a78059ced9dd3fc812e16f618a793e8c00b85dda4903bc96cb9923ea3 succeeded
2024-09-12 16:56:50.401 [DBG] CORE:STACKER:0: async processPreimageRequest for d17801010c6bc3fbf9a77b24f98b0129f68a2883e9c87bec9fbdb0b0e53815cb succeeded
2024-09-12 16:56:50.401 [DBG] CORE:STACKER:0: async processPreimageRequest for fee42b1686f818c9452ed7cac5ddb86b501b2773f9328edf1cc5d98be059f7b6 succeeded
2024-09-12 16:56:50.401 [ERR] CORE:STACKER:0[wss://127.0.0.1:17273/ws]: No handler found for response: {"type":2,"id":9163,"payload":{"result":null,"error":{"code":32,"message":"unknown response ID"}},"sig":""}
2024-09-12 16:56:50.401 [DBG] CORE:STACKER:0: async processPreimageRequest for f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f succeeded
2024-09-12 16:56:50.401 [TRC] CORE:STACKER:0: Received a courtesy redemption request for match 40a1aac03488aa1e31f335c712c4afdd5671b6998e3f5de3cd7ef02ef230a4ff as maker
2024-09-12 16:56:50.401 [ERR] CORE:STACKER:0[wss://127.0.0.1:17273/ws]: No handler found for response: {"type":2,"id":9166,"payload":{"result":null,"error":{"code":32,"message":"unknown response ID"}},"sig":""}
2024-09-12 16:56:50.401 [ERR] CORE:STACKER:0[wss://127.0.0.1:17273/ws]: No handler found for response: {"type":2,"id":9168,"payload":{"result":null,"error":{"code":32,"message":"unknown response ID"}},"sig":""}
2024-09-12 16:56:50.401 [ERR] CORE:STACKER:0[wss://127.0.0.1:17273/ws]: No handler found for response: {"type":2,"id":9169,"payload":{"result":null,"error":{"code":32,"message":"unknown response ID"}},"sig":""}
2024-09-12 16:56:50.402 [TRC] MANTLE:STACKER:0: book note received
2024-09-12 16:56:50.402 [TRC] MANTLE:STACKER:0: book note received

.......

2024-09-12 16:56:50.423 [DBG] CORE:STACKER:0: Waiting 2.2s to tick trade ffa35666ebe3463642562da9623f6c068fddfb5be5e79779acb8e64dec629a5c with 2 active matches
2024-09-12 16:56:50.423 [INF] CORE:STACKER:0: Notified of maker's redemption (eth: 0x8ad039742575bb9986d17edfbb22bae248acbaeec82588cc18dae20ebcd37862) and validated secret for order ffa35666ebe3463642562da9623f6c068fddfb5be5e79779acb8e64dec629a5c...
2024-09-12 16:56:50.424 [DBG] CORE:STACKER:0: Score changed at 127.0.0.1:17273. New score is 58 / 60, tier = 100, penalties = 0
2024-09-12 16:56:50.424 [WRN] CORE:STACKER:0: Revoking order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:50.426 [ERR] CORE:STACKER:0: notify: |ERROR| (order) Order revoked - Order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f on market eth_btc at 127.0.0.1:17273 has been revoked by the server - Order: f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f
2024-09-12 16:56:50.426 [CRT] MANTLE:STACKER:0: Error note received: {"type":"order","topic":"OrderRevoked","subject":"Order revoked","details":"Order f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f on market eth_btc at 127.0.0.1:17273 has been revoked by the server","severity":5,"stamp":1726127810425,"acked":false,"id":"576436861b68b60e","order":{"host":"127.0.0.1:17273","baseID":60,"baseSymbol":"eth","quoteID":0,"quoteSymbol":"btc","market":"eth_btc","type":1,"id":"f841b794e57b20c243bbb205e5b6c4c4b867efce004ec8d32094a4b91dc5f58f","stamp":1726127787808,"submitTime":1726127785880,"sig":"3044022052595870e35e733ce136683dca6258a496a9d3df081cf7df95e8e2af2fe4b29e022012295ffe0fd3225ed9a069ab51f64a01d6dd224217f52a4001ac35080be493bd","status":5,"epoch":115075185,"qty":100000000,"sell":true,"filled":0,"matches":null,"cancelling":false,"canceled":false,"feesPaid":{"swap":0,"redemption":0,"funding":0,"refund":0},"allFeesConfirmed":true,"fundingCoins":[{"id":"307842353435363444343831623739323443323131333345396561413262664135333537363345643836","stringID":"0xB54564D481b7924C21133E9eaA2bfA535763Ed86","assetID":60,"symbol":"eth"}],"lockedamt":0,"parentAssetLockedAmt":0,"redeemLockedAmt":0,"refundLockedAmt":0,"accelerationCoins":[],"rate":795000,"tif":1,"targetOrderID":"","readyToTick":true}}
2024-09-12 16:56:50.427 [DBG] CORE:STACKER:1[wss://127.0.0.1:17273/ws]: Sending close 1000 (normal) message.

@JoeGruffins
Copy link
Member

More logs for the same server and client, these preimages were sent and received in the middle of the others, so its more than strange that we waited somewhere for the previous preimages:

server

2024-09-12 16:56:44.756 [DBG] ASSET[btc]: New block 29f1121520ae84fd7ae5ec24c81851d9f2f2080eaa48aaef5cf5abf0b95cd62b (1120)
2024-09-12 16:56:44.756 [TRC] ASSET[btc]: Notifying 1 btc asset consumers of new block at height 1120
2024-09-12 16:56:44.757 [DBG] SWAP: Swap {txid = 77b674d29159d73111581dcdcbaf1fbf2d44736c0f4f82e6733c1db61180836f, vout = 0} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:44.757 [DBG] SWAP: Swap {txid = 8c8eacb7ca7f992146b5217b763d8090e7d35428278b75355f87486eb56d6f42, vout = 0} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:44.758 [DBG] SWAP: Swap {txid = 03fa7ea40cefc32d2940a1d21d75b4ae6fbb6714070bf0951873359b91be3ee6, vout = 0} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:44.759 [DBG] SWAP: Swap {txid = a4d1e9f2faa4c329ee83ce9198508cc1fd2aba99bd80b73a65ef9d6b957734eb, vout = 0} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:44.759 [DBG] SWAP: Swap {txid = 32ca54f67bb796559d6f160595dd58c4d4cb3a71a582cf62f8ab5decd106885f, vout = 0} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:44.760 [DBG] SWAP: Swap {txid = 03fa7ea40cefc32d2940a1d21d75b4ae6fbb6714070bf0951873359b91be3ee6, vout = 2} (btc) has reached 2 confirmations (1 required)
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order e4ded41dc81f69d98195da294bd6b2909d79e0c297ea1ded734e0cdbee21327f
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order b1ebe33f5c2c0896a0ebe38c19c168546e742ecab326c26acef695f8544852f7
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order f8e174f502dbb146dda13d8801bd4331f4522824be69d00ac7967a0e08f035f8
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order 8e61ade1a05ff441b437e503dd7fe50ce1bc6e2886b6ac4b2034dfdd205da443
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order 5e72f656767732993346c8ee819f4fed2188ad150a7fd602a06e592e98925bd6
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order bfd182e84faf4a5b22733a2591c72da8096764d1a6001c994a3a0ced79660725
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order 1cfe5c5e0edb5052ec4d0d99d731038d8825891df89523122727110404c0d419
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order f7a5d0b5e53611bb97b5e81de756a7594185307579df8e70f885eb9751a3bc5f
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order b2fb379262b699eeaed67c278e685a5d90b6be28bc2fa59c99ef1f9b91632b77
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order c8719e216924a0fbecc8947e856b6cd14126e94de69cbb04d8ee96a3d1eafb21
2024-09-12 16:56:45.000 [TRC] MKT: Preimage request sent for order 076af1ef4a2b5cedc4fe4df521684c506b5f2308e7535546e4e77cc449f68939
2024-09-12 16:56:45.001 [TRC] MKT: Good preimage received for order e4ded41dc81f69d98195da294bd6b2909d79e0c297ea1ded734e0cdbee21327f: 3aeb348da2c49eea1ee3f1e5f7754ff18471447e434c98eb4003d815cf3ccc56
2024-09-12 16:56:45.001 [TRC] MKT: Good preimage received for order 1cfe5c5e0edb5052ec4d0d99d731038d8825891df89523122727110404c0d419: 49fde01b7c6bc8e791f6205ed7a8bb8bad5968cee821a06bae432c3d86b1c695

client:

2024-09-12 16:56:44.992 [INF] CORE:STACKER:0: Match a2a9897604848ad2a7b781436c965fef99d484c4f44fa641cc18ce06c2a2bec3 complete: sell 100000000 eth
2024-09-12 16:56:44.992 [INF] LOADBOT[STACKER:1]: Balance: btc = 7763370813 available, 1291945289 locked
2024-09-12 16:56:45.000 [DBG] CORE:STACKER:1: Received preimage request for order e4ded41dc81f69d98195da294bd6b2909d79e0c297ea1ded734e0cdbee21327f with known commitment 125ccee82eb26a3d14ffcff5654b7fa47bc3eb39d9cc26c0aeade40fcdd18837
2024-09-12 16:56:45.000 [DBG] CORE:STACKER:1: Received preimage request for order b1ebe33f5c2c0896a0ebe38c19c168546e742ecab326c26acef695f8544852f7 with known commitment 175463a15d84a85cd38b31c0d27e2cfd405a084e5749f5cbd65d50294148ff7d
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order f8e174f502dbb146dda13d8801bd4331f4522824be69d00ac7967a0e08f035f8 with known commitment 60495cb2af079b58f39f5b015141a8ef462be9117d7bd22c75f8e9b635c9e34d
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order 8e61ade1a05ff441b437e503dd7fe50ce1bc6e2886b6ac4b2034dfdd205da443 with known commitment 7d73f380e295427ac4031587c9cf9097121a1cfa61ff592107deee9f3ad4aec3
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order 5e72f656767732993346c8ee819f4fed2188ad150a7fd602a06e592e98925bd6 with known commitment a6b33b8b2bc8bf1813dd4dfcee747d9e404956829ed4338a34ed04b506510129
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order bfd182e84faf4a5b22733a2591c72da8096764d1a6001c994a3a0ced79660725 with known commitment abedc25e69a6c866722cf75c2e44f116231b3cfda55ba9887d4d666afa26ffb3
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order f7a5d0b5e53611bb97b5e81de756a7594185307579df8e70f885eb9751a3bc5f with known commitment c532ca192f31e97b7e93ed401a044e1de7db12c3539766c538ad9a54cde4a82d
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order b2fb379262b699eeaed67c278e685a5d90b6be28bc2fa59c99ef1f9b91632b77 with known commitment d9225ebae8f11915d6d783a753d6a89d94e7bc097567ef0eb6c9dfa639d5807f
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: Received preimage request for order 076af1ef4a2b5cedc4fe4df521684c506b5f2308e7535546e4e77cc449f68939 with known commitment f198a55b0c250caddbf2bd5060e1e15b859b59ceaee42192a358ea6061866bfe
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for e4ded41dc81f69d98195da294bd6b2909d79e0c297ea1ded734e0cdbee21327f succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for b1ebe33f5c2c0896a0ebe38c19c168546e742ecab326c26acef695f8544852f7 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for f8e174f502dbb146dda13d8801bd4331f4522824be69d00ac7967a0e08f035f8 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for 8e61ade1a05ff441b437e503dd7fe50ce1bc6e2886b6ac4b2034dfdd205da443 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for bfd182e84faf4a5b22733a2591c72da8096764d1a6001c994a3a0ced79660725 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for 076af1ef4a2b5cedc4fe4df521684c506b5f2308e7535546e4e77cc449f68939 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for b2fb379262b699eeaed67c278e685a5d90b6be28bc2fa59c99ef1f9b91632b77 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for 5e72f656767732993346c8ee819f4fed2188ad150a7fd602a06e592e98925bd6 succeeded
2024-09-12 16:56:45.001 [DBG] CORE:STACKER:1: async processPreimageRequest for f7a5d0b5e53611bb97b5e81de756a7594185307579df8e70f885eb9751a3bc5f succeeded

@JoeGruffins
Copy link
Member

JoeGruffins commented Sep 16, 2024 •
edited
Loading

One more, client showed that some of the preimage requests from the batch that failed were received with only a slight delay

client

2024-09-12 16:56:33.812 [DBG] CORE:STACKER:0: Notifying DEX 127.0.0.1:17273 of our btc swap redemption 1f2d2ebd241ce0ae23a275d8177ef2378b6d88b83ab2d6ccec15c816940eaef2:0 for match 12106c02ed05946d2f395702620d03e84521c5b8b5fd6c656433e0f58ae0f72f
2024-09-12 16:56:33.812 [TRC] MANTLE:STACKER:1: book note received
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: Received preimage request for order 897ce4363095602a68db540fceb6948bc6c89bf90632204498d54e0cff3b0eaf with known commitment 243fe89972be077bf5a1e1e501fb190d57a34bffe2b406c5b5aaaf35c95ffafe
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: Received preimage request for order c55d66886f52c5902b60fdf50bb3eaa9dba714d443b73e4483b2f858e80d4261 with known commitment 76c4c7b8ee5f22b16291605421134b4a89a2e66abe928e687ceff1e6010e53fa
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: Received preimage request for order 704571424cf22d3370bbe459e420945d762383b895ee0cd7487a79ca479918d1 with known commitment b3b9ae4cc640d2813d3ad8aaebb34068f1c4c6c6d9b000941aa58aad3fd405ba
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: Received preimage request for order 05d41287d0525cd662f5eee2b44e57b9702721fe6691bd9d5de38f5984f8788c with known commitment ceead07ef1d2722ebfcb0d4f4e16777e3af7f13ca76ae146a1476a4e53855ebb
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:0: notify: |POKE| (order) Match complete - Redeemed 0.00759000 BTC on order {{{order|c9cea05a784685859cd150b65aacb39d808d5c2f6021c99e26b083367a7b3833}}} - Order: c9cea05a784685859cd150b65aacb39d808d5c2f6021c99e26b083367a7b3833
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:0: Slow tick: trade c9cea05a784685859cd150b65aacb39d808d5c2f6021c99e26b083367a7b3833 processed in 5.309334231s, blocked for 701ns
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: async processPreimageRequest for c55d66886f52c5902b60fdf50bb3eaa9dba714d443b73e4483b2f858e80d4261 succeeded
2024-09-12 16:56:33.812 [TRC] MANTLE:STACKER:1: book note received
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: async processPreimageRequest for 704571424cf22d3370bbe459e420945d762383b895ee0cd7487a79ca479918d1 succeeded
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: async processPreimageRequest for 897ce4363095602a68db540fceb6948bc6c89bf90632204498d54e0cff3b0eaf succeeded
2024-09-12 16:56:33.812 [DBG] CORE:STACKER:1: async processPreimageRequest for 05d41287d0525cd662f5eee2b44e57b9702721fe6691bd9d5de38f5984f8788c succeeded
2024-09-12 16:56:33.813 [INF] CORE:STACKER:1: Notified of maker's redemption (btc: d4f455e291c232f0c79e535ad87fcb6a6dd123d26e4dd597f1c1c3c12d79e62c:0) and validated secret for order 0a1fbbcd08bfaecbca85a0d1758a3e3c334bc23ccf7018d5fa0af78f30f671a8...
2024-09-12 16:56:34.002 [DBG] CORE:STACKER:1: Notifying DEX 127.0.0.1:17273 of our eth swap redemption 0x81542cc118a240c1dafc33ba3612eb23629a481c2f7fafff3a910e2ece27621c for match 7564df30a58c402857af25232b376bca1c4e475a9af875f242d3b16391b1fcaf

@JoeGruffins
Copy link
Member

Just noticing that it's STACKER:0 That seems to be stuck, thats why there are still notifications inbetween for STACKER:1

@JoeGruffins
Copy link
Member

JoeGruffins commented Sep 16, 2024 •
edited
Loading

Sorry to be so chatty here, it seems this is the most important log from client:

2024-09-12 16:56:49.920 [INF] CORE:STACKER:0: runJob(nomatch) completed in 11.210301633s
2024-09-12 16:56:49.920 [INF] CORE:STACKER:0: Standing order 68ccf7809fbd182e1832e5be964257582b19133c50a486b8b364af2037868bfb did not match and is now booked.
2024-09-12 16:56:49.920 [DBG] CORE:STACKER:1: Received valid ack for 'redeem' request for match 10da3a99e29c59ce04b9e95d8b0addb8db0a6313af457e388ffedecafca3f14e)
2024-09-12 16:56:50.036 [INF] CORE:STACKER:0: Standing order e0a576e20711ed31e3b1f8a34959058283baee4c6d7194dab97ec3444eda10e5 did not match and is now booked.
2024-09-12 16:56:50.105 [INF] LOADBOT[STACKER:0]: Balance: eth = 37101754740 available, 6214900000 locked
2024-09-12 16:56:50.174 [WRN] CORE:STACKER:0: Long delay since previous trade check (just resumed?): 36.662294212s. Skipping this check to allow reconnect.

@buck54321 buck54321 mentioned this issue Sep 17, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@JoeGruffins JoeGruffins

Labels
None yet
Projects
None yet
Milestone
No milestone
2 participants
@buck54321 @JoeGruffins