utboundReservedAmount && outboundReservedAmount >= amount assertion was reached for removeorder/placeorder calls

[raladev]

Description

Got this case during arby testing with order placing-filling-replacing activity once, after that i tried several times but was not able to get it again. After the error i was able place orders and swap successfuly, so it does not lead to xud crash.

Depends on logs, it looks like race condition - removing/placing actions were triggered immidietly after swap finishing (check time).

Expected result

No such assertions

Log

07/01/2021 15:54:44.104 [P2P] debug: received swapRequest from 0254bf3688a3c8501bde20ab804bcfa8da346473ea53af993c5f85f2d118db833b (SpaceCrucial): {"proposedQuantity":10000,"pairId":"ETH/BTC","orderId":"81e1a270-5100-11eb-ae4b-0bd90f0bd209","rHash":"f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb","takerCltvDelta":40}
07/01/2021 15:54:44.113 [SWAPS] debug: trying to accept deal: {"quantity":10000,"localId":"arby-ETH/BTC-buy-order","price":0.03155743,"isBuy":true} from xudPubKey: 0254bf3688a3c8501bde20ab804bcfa8da346473ea53af993c5f85f2d118db833b
07/01/2021 15:54:44.114 [SWAPS] debug: New deal: {"rHash":"f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb","pairId":"ETH/BTC","proposedQuantity":10000,"orderId":"81e1a270-5100-11eb-ae4b-0bd90f0bd209","price":0.03155743,"isBuy":true,"quantity":10000,"makerAmount":10000,"takerAmount":316,"makerCurrency":"ETH","takerCurrency":"BTC","makerUnits":"100000000000000","takerUnits":"316","takerCltvDelta":40,"takerPubKey":"02d209407a9d31a9812816a250e94b3662b399f0dcde629af4d7193e0f4cd09fc4","destination":"02d209407a9d31a9812816a250e94b3662b399f0dcde629af4d7193e0f4cd09fc4","peerPubKey":"0254bf3688a3c8501bde20ab804bcfa8da346473ea53af993c5f85f2d118db833b","localId":"arby-ETH/BTC-buy-order","phase":0,"state":0,"role":1,"createTime":1610034884114}
07/01/2021 15:54:44.124 [LND-BTC] debug: found a route to 02d209407a9d31a9812816a250e94b3662b399f0dcde629af4d7193e0f4cd09fc4 for 316 units with finalCltvDelta 40: 279994,1,317,306353626312409088,500000000,316,1,279954,316000,1000,0252f366111259996a101c5a82c880e9c95c8278d7e668c40163c0db656161cbbf,true,307629059800629248,,316,,279954,316000,,02d209407a9d31a9812816a250e94b3662b399f0dcde629af4d7193e0f4cd09fc4,true,1000,317000
07/01/2021 15:54:44.128 [SWAPS] debug: got BTC block height of 279914
07/01/2021 15:54:44.129 [SWAPS] debug: found route to taker with total lock duration of 80 BTC blocks (~13h)
07/01/2021 15:54:44.131 [SWAPS] debug: calculated lock buffer for first leg: 6822 ETH blocks (~28h)
07/01/2021 15:54:44.131 [SWAPS] debug: lock delta for final hop to maker: 7022 ETH blocks (~29h)
07/01/2021 15:54:44.133 [SWAPS] debug: Setting SwapAccepted phase for deal f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb
07/01/2021 15:54:44.134 [SWAPS] debug: sending swap accepted packet: {"rHash":"f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb","makerCltvDelta":7022,"quantity":10000} to peer: 0254bf3688a3c8501bde20ab804bcfa8da346473ea53af993c5f85f2d118db833b
07/01/2021 15:54:46.272 [HTTP] debug: http server request json: {"aliceIdentifier":"vector5yw6vEx4VJPWMC4Vf48WSfY4bzgfJxAt4EGGFGT1o1mmQnRz35","bobIdentifier":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6","channelAddress":"0x02561e828d86673F4cF72650e06811A718119E6c","channelBalance":{"to":["0x53f9F268caC0961c18494c0514716801aebD4941","0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5"],"amount":["387596310000000000","30000000000000000000"]},"transfer":{"balance":{"to":["0x53f9F268caC0961c18494c0514716801aebD4941","0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5"],"amount":["100000000000000","0"]},"assetId":"0x0000000000000000000000000000000000000000","transferId":"0x077b2a74cd25ed74ccb3619604ae96b37ead7f482d294728da0a94b91f618f48","channelAddress":"0x02561e828d86673F4cF72650e06811A718119E6c","transferDefinition":"0xBd8B6d172aC46146F20DaFe63539c23F3120636A","transferEncodings":["tuple(bytes32 lockHash, uint256 expiry)","tuple(bytes32 preImage)"],"transferTimeout":"82080","initialStateHash":"0x5b20127d310b0792848d9eac270dec601afa25495acbf73a59737a367d45429f","transferState":{"expiry":"1715364874","lockHash":"0xf2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb"},"channelFactoryAddress":"0x09f37Ee0662E13e7d07e84CE77705E981Be79406","chainId":1337,"initiator":"0x53f9F268caC0961c18494c0514716801aebD4941","responder":"0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5","meta":{"senderIdentifier":"vector52DJtSLfAr8LTwbR3diRn8EDCPwrFfU1cLt9v1PTodz1D5fcF5","requireOnline":true,"routingId":"0x45895016f55ac153c4c2dd8c9cc5385a89149e5ab296bbf0cfeb79a02dbfaa49","path":[{"recipient":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6","recipientChainId":1337,"recipientAssetId":"0x0000000000000000000000000000000000000000"}]},"inDispute":false,"channelNonce":18,"initiatorIdentifier":"vector5yw6vEx4VJPWMC4Vf48WSfY4bzgfJxAt4EGGFGT1o1mmQnRz35","responderIdentifier":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6"},"conditionType":"HashlockTransfer","activeTransferIds":["0x077b2a74cd25ed74ccb3619604ae96b37ead7f482d294728da0a94b91f618f48"]}
07/01/2021 15:54:46.477 [CONNEXT] debug: accepting incoming transfer with rHash: f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb, units: 100000000000000, timelock 7022, currency ETH, and routingId 0x45895016f55ac153c4c2dd8c9cc5385a89149e5ab296bbf0cfeb79a02dbfaa49
07/01/2021 15:54:46.477 [SWAPS] debug: Executing maker code to resolve hash
07/01/2021 15:54:46.478 [SWAPS] debug: Setting SendingPayment phase for deal f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb
07/01/2021 15:54:46.497 [LND-BTC] debug: sending payment of 316 with hash f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb
07/01/2021 15:54:48.226 [CONNEXT] debug: new inbound capacity (collateral) for ETH of 38759631
07/01/2021 15:54:48.575 [SWAPS] info: Successfully executed swap f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb with peer 0254bf3688a3c8501bde20ab804bcfa8da346473ea53af993c5f85f2d118db833b (SpaceCrucial)
07/01/2021 15:54:48.579 [SWAPS] debug: Setting PreimageResolved phase for deal f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb
07/01/2021 15:54:48.580 [CONNEXT] debug: settling ETH invoice for f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb with preimage 105aa1912302afe823efe579ed534a3926d1a0e7e101e539d5f6f3a438b394fa
07/01/2021 15:54:48.637 [LND-BTC] debug: new channel maximum outbound capacity: 244999683
07/01/2021 15:54:48.637 [LND-BTC] debug: new channel total outbound capacity: 244999683
07/01/2021 15:54:48.669 [ORDERBOOK] error: error while removing order (81e1a270-5100-11eb-ae4b-0bd90f0bd209): AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert_1.default(outboundReservedAmount && outboundReservedAmount >= amount)

    at SwapClientManager.subtractOutboundReservedAmount (/app/dist/swaps/SwapClientManager.js:246:29)
    at OrderBook.onOrderRemoved (/app/dist/orderbook/OrderBook.js:1052:42)
    at OrderBook.emit (events.js:315:20)
    at OrderBook.removeOwnOrder (/app/dist/orderbook/OrderBook.js:809:22)
    at OrderBook.addOwnOrder (/app/dist/orderbook/OrderBook.js:614:22)
    at OrderBook.placeOrder (/app/dist/orderbook/OrderBook.js:546:30)
    at async GrpcService.placeOrderSync (/app/dist/grpc/GrpcService.js:820:32)
    at async Object.value (/app/dist/grpc/GrpcServer.js:125:13)
07/01/2021 15:54:48.670 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 2: The expression evaluated to a falsy value:

  assert_1.default(outboundReservedAmount && outboundReservedAmount >= amount)

07/01/2021 15:54:48.838 [LND-BTC] debug: new channel inbound capacity: 244991267
07/01/2021 15:54:48.839 [LND-BTC] debug: new channel total inbound capacity: 244991267
07/01/2021 15:54:49.481 [HTTP] debug: http server request json: {"aliceIdentifier":"vector5yw6vEx4VJPWMC4Vf48WSfY4bzgfJxAt4EGGFGT1o1mmQnRz35","bobIdentifier":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6","channelAddress":"0x02561e828d86673F4cF72650e06811A718119E6c","channelBalance":{"to":["0x53f9F268caC0961c18494c0514716801aebD4941","0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5"],"amount":["387596310000000000","30000100000000000000"]},"transfer":{"inDispute":false,"channelFactoryAddress":"0x09f37Ee0662E13e7d07e84CE77705E981Be79406","assetId":"0x0000000000000000000000000000000000000000","chainId":1337,"channelAddress":"0x02561e828d86673F4cF72650e06811A718119E6c","balance":{"amount":["100000000000000","0"],"to":["0x53f9F268caC0961c18494c0514716801aebD4941","0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5"]},"initiator":"0x53f9F268caC0961c18494c0514716801aebD4941","responder":"0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5","initialStateHash":"0x5b20127d310b0792848d9eac270dec601afa25495acbf73a59737a367d45429f","transferDefinition":"0xBd8B6d172aC46146F20DaFe63539c23F3120636A","initiatorIdentifier":"vector5yw6vEx4VJPWMC4Vf48WSfY4bzgfJxAt4EGGFGT1o1mmQnRz35","responderIdentifier":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6","channelNonce":18,"transferEncodings":["tuple(bytes32 lockHash, uint256 expiry)","tuple(bytes32 preImage)"],"transferId":"0x077b2a74cd25ed74ccb3619604ae96b37ead7f482d294728da0a94b91f618f48","transferState":{"expiry":"1715364874","lockHash":"0xf2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb","balance":{"to":["0x53f9F268caC0961c18494c0514716801aebD4941","0xcFAca7462c148DD5FdAfD7d2a07003463B7B05D5"],"amount":["0","100000000000000"]}},"transferTimeout":"82080","meta":{"senderIdentifier":"vector52DJtSLfAr8LTwbR3diRn8EDCPwrFfU1cLt9v1PTodz1D5fcF5","requireOnline":true,"routingId":"0x45895016f55ac153c4c2dd8c9cc5385a89149e5ab296bbf0cfeb79a02dbfaa49","path":[{"recipient":"vector8Rp4HgURsHgSoFGxRkaKdEQy1FSwbp64qE8AW73Y6bWfAS1ru6","recipientChainId":1337,"recipientAssetId":"0x0000000000000000000000000000000000000000"}]},"transferResolver":{"preImage":"0x105aa1912302afe823efe579ed534a3926d1a0e7e101e539d5f6f3a438b394fa"}},"conditionType":"HashlockTransfer","activeTransferIds":[]}
07/01/2021 15:54:49.708 [SWAPS] debug: Setting PaymentReceived phase for deal f2581f7cce0721be89a65f2a36ddcf2cf640f9625d3d9c58b9a1f84e205569eb - preimage is 105aa1912302afe823efe579ed534a3926d1a0e7e101e539d5f6f3a438b394fa
07/01/2021 15:54:55.700 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-ETH/BTC-buy-order could not be found
07/01/2021 15:56:01.317 [P2P] debug: Connection attempt #8 to 02964fa7a19351fb5de586f1d72bbebae2a1de7d4b638eaacb85a3e84812c10b27@zroxqzaaxeh2hz5piz7q4fqvagkxrt7bxqh2lpmoemf3xdq3sppm76id.onion:28885 failed: Socks5 proxy rejected connection - HostUnreachable. retrying in 640 sec...