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.

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

LTC/BTC swap failure - Taker's xud crashed #984

Closed
offerm opened this issue May 25, 2019 · 23 comments · Fixed by #1037
Closed

LTC/BTC swap failure - Taker's xud crashed #984

offerm opened this issue May 25, 2019 · 23 comments · Fixed by #1037

Comments

@offerm
Copy link
Contributor

offerm commented May 25, 2019

Failure to take an order.
Notes:

  1. no problem with sanity swaps.
  2. LTC and BTC have direct channels
  3. Error on make side atter receiving the first leg.
  4. XUD crashed on the taker side.

Taker issues a buy order:

xud@xud-test-2:/opt/xud$ xucli listorders
Trading pair: LTC/BTC
┌────────────────────────────────────────────────────┬────────────────────────────────────────────────────┐
│ Buy                                                │ Sell                                               │
├───────────────────┬───────────────────┬────────────┼───────────────────┬───────────────────┬────────────┤
│ Quantity          │ Price             │ Own Order  │ Quantity          │ Price             │ Own Order  │
├───────────────────┼───────────────────┼────────────┼───────────────────┼───────────────────┼────────────┤
│ 3.50000000        │ 0.0077            │            │ 2.50000000        │ 0.0079            │            │
├───────────────────┼───────────────────┼────────────┼───────────────────┼───────────────────┼────────────┤
│ 15.50000000       │ 0.0076            │            │ 13.00000000       │ 0.008             │            │
├───────────────────┼───────────────────┼────────────┼───────────────────┼───────────────────┼────────────┤
│ 18.00000000       │ 0.0075            │            │ 15.60000000       │ 0.0081            │            │
├───────────────────┼───────────────────┼────────────┼───────────────────┼───────────────────┼────────────┤
│ 21.25000000       │ 0.0074            │            │ 18.10000000       │ 0.0082            │            │
├───────────────────┼───────────────────┼────────────┼───────────────────┼───────────────────┼────────────┤
│ 24.00000000       │ 0.0073            │            │ 22.30000000       │ 0.0083            │            │
└───────────────────┴───────────────────┴────────────┴───────────────────┴───────────────────┴────────────┘
Trading pair: WETH/BTC
┌────────────────────────────────────────────────────┬────────────────────────────────────────────────────┐
│ Buy                                                │ Sell                                               │
├───────────────────┬───────────────────┬────────────┼───────────────────┬───────────────────┬────────────┤
│ Quantity          │ Price             │ Own Order  │ Quantity          │ Price             │ Own Order  │
└───────────────────┴───────────────────┴────────────┴───────────────────┴───────────────────┴────────────┘
xud@xud-test-2:/opt/xud$ xucli buy 0.1 LTC/BTC 0.0079 --stream

Response:

xud@xud-test-2:/opt/xud$ xucli buy 0.1 LTC/BTC 0.0079 --stream
failed to swap 0.1 LTC with peer order d96cfab0-7f2b-11e9-9040-7b281a4ac93a
events.js:174
      throw er; // Unhandled 'error' event
      ^
Error: 14 UNAVAILABLE: TCP Read failed
    at Object.exports.createStatusError (/opt/xud/node_modules/grpc/src/common.js:91:15)
    at ClientReadableStream._emitStatusIfDone (/opt/xud/node_modules/grpc/src/client.js:233:26)
    at ClientReadableStream._receiveStatus (/opt/xud/node_modules/grpc/src/client.js:211:8)
    at Object.onReceiveStatus (/opt/xud/node_modules/grpc/src/client_interceptors.js:1272:15)
    at InterceptingListener._callNext (/opt/xud/node_modules/grpc/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/opt/xud/node_modules/grpc/src/client_interceptors.js:618:8)
    at /opt/xud/node_modules/grpc/src/client_interceptors.js:1029:24
Emitted 'error' event at:
    at ClientReadableStream._emitStatusIfDone (/opt/xud/node_modules/grpc/src/client.js:234:12)
    at ClientReadableStream._receiveStatus (/opt/xud/node_modules/grpc/src/client.js:211:8)
    [... lines matching original stack trace ...]
    at /opt/xud/node_modules/grpc/src/client_interceptors.js:1029:24

Taker log:

25/05/2019 20:31:13.890 [ORDERBOOK] debug: reduced order d96cfab0-7f2b-11e9-9040-7b281a4ac93a by 10000000 quantity while matching order 0a41be00-7f2c-11e9-9a17-fb1c5525c06e
25/05/2019 20:31:13.892 [ORDERBOOK] debug: matched with peer 02b66438730d1fcdf4a4ae5d3d73e847a272f160fee2938e132b52cab0a0d9cfc6, executing swap on taker 0a41be00-7f2c-11e9-9a17-fb1c552
5c06e and maker d96cfab0-7f2b-11e9-9040-7b281a4ac93a for 10000000
25/05/2019 20:31:13.922 [LND] debug: BTC: got 1 route(s) to destination 02d693d951ce4fc116b2b5e22e8e4966dd3cf9ad7600b8de24190d6af429f260c0: 291915,,79000,320796811054874600,2500000000,
79000,,291915,79000000,,02d693d951ce4fc116b2b5e22e8e4966dd3cf9ad7600b8de24190d6af429f260c0,,79000000
25/05/2019 20:31:13.924 [SWAPS] debug: New deal: {"takerCltvDelta":576,"rHash":"81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603","orderId":"d96cfab0-7f2b-11e9-9040-7b2
81a4ac93a","pairId":"LTC/BTC","proposedQuantity":10000000,"rPreimage":"9e8e237ddb0804b9fca1673ccfa9fc33eb4de70392a56c38a21732e0f56e2efa","takerCurrency":"LTC","makerCurrency":"BTC","ta
kerAmount":10000000,"makerAmount":79000,"destination":"02d693d951ce4fc116b2b5e22e8e4966dd3cf9ad7600b8de24190d6af429f260c0","peerPubKey":"02b66438730d1fcdf4a4ae5d3d73e847a272f160fee2938
e132b52cab0a0d9cfc6","localId":"0a41be00-7f2c-11e9-9a17-fb1c5525c06e","price":0.0079,"isBuy":false,"phase":0,"state":0,"role":0,"createTime":1558816273923}
25/05/2019 20:31:13.926 [SWAPS] debug: Requesting deal: {"takerCltvDelta":576,"rHash":"81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603","orderId":"d96cfab0-7f2b-11e9-9
040-7b281a4ac93a","pairId":"LTC/BTC","proposedQuantity":10000000,"rPreimage":"9e8e237ddb0804b9fca1673ccfa9fc33eb4de70392a56c38a21732e0f56e2efa","takerCurrency":"LTC","makerCurrency":"B
TC","takerAmount":10000000,"makerAmount":79000,"destination":"02d693d951ce4fc116b2b5e22e8e4966dd3cf9ad7600b8de24190d6af429f260c0","peerPubKey":"02b66438730d1fcdf4a4ae5d3d73e847a272f160
fee2938e132b52cab0a0d9cfc6","localId":"0a41be00-7f2c-11e9-9a17-fb1c5525c06e","price":0.0079,"isBuy":false,"phase":0,"state":0,"role":0,"createTime":1558816273923}
25/05/2019 20:31:13.982 [P2P] debug: received swapAccepted from 02b66438730d1fcdf4a4ae5d3d73e847a272f160fee2938e132b52cab0a0d9cfc6: {"rHash":"81edc66eb9587c37596b629ef9d96a70ff1d0d9601
d6bfbdead409f071e24603","quantity":10000000,"makerCltvDelta":288}
25/05/2019 20:31:13.992 [LND] debug: LTC: added invoice of 10000000 for 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603
25/05/2019 20:31:14.447 [LND] error: BTC: sendPaymentSync failed with payment error: UnknownPaymentHash(amt=79000000 mSAT)
25/05/2019 20:31:14.450 [SWAPS] debug: deal 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603 failed due to SendPaymentFailure
25/05/2019 20:31:14.457 [ORDERBOOK] error: swap between orders d96cfab0-7f2b-11e9-9040-7b281a4ac93a & 0a41be00-7f2c-11e9-9a17-fb1c5525c06e failed due to SendPaymentFailure
**25/05/2019 20:31:25.563 [GLOBAL] info: config loaded**
25/05/2019 20:31:25.701 [DB] info: connected to database /home/xud/.xud/xud-simnet.db
25/05/2019 20:31:25.727 [RAIDEN] info: RaidenClient status: Disabled
25/05/2019 20:31:25.730 [LND] info: BTC: trying to verify connection to lnd at localhost:10002
25/05/2019 20:31:25.736 [LND] info: LTC: trying to verify connection to lnd at localhost:10001
25/05/2019 20:31:25.759 [LND] info: BTC: LndClient status: ConnectionVerified

Maker log:

25/05/2019 20:31:13.932 [P2P] debug: received swapRequest from 028599d05b18c0c3f8028915a17d603416f7276c822b6b2d20e71a3502bd0f9e0a: {"proposedQuantity":10000000,"pairId":"LTC/BTC","orde
rId":"d96cfab0-7f2b-11e9-9040-7b281a4ac93a","rHash":"81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603","takerCltvDelta":576}
25/05/2019 20:31:13.934 [ORDERBOOK] debug: added hold of 10000000 on order d96cfab0-7f2b-11e9-9040-7b281a4ac93a
25/05/2019 20:31:13.936 [SWAPS] debug: New deal: {"proposedQuantity":10000000,"pairId":"LTC/BTC","orderId":"d96cfab0-7f2b-11e9-9040-7b281a4ac93a","rHash":"81edc66eb9587c37596b629ef9d96
a70ff1d0d9601d6bfbdead409f071e24603","takerCltvDelta":576,"takerPubKey":"0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef","price":0.0079,"isBuy":false,"quantity":100
00000,"makerAmount":79000,"takerAmount":10000000,"makerCurrency":"BTC","takerCurrency":"LTC","destination":"0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef","peerPub
Key":"028599d05b18c0c3f8028915a17d603416f7276c822b6b2d20e71a3502bd0f9e0a","localId":"d96cfab0-7f2b-11e9-9040-7b281a4ac93a","phase":0,"state":0,"role":1,"createTime":1558816273935}
25/05/2019 20:31:13.942 [LND] debug: LTC: got 1 route(s) to destination 0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef: 14681,,10000000,12244161486979072,2500000000
0,10000000,,14681,10000000000,,0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef,,10000000000
25/05/2019 20:31:13.957 [SWAPS] debug: got block height of 14105
25/05/2019 20:31:13.957 [SWAPS] debug: total timelock of route = 576 makerCltvDelta = 288
25/05/2019 20:31:13.976 [LND] debug: BTC: added invoice of 79000 for 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603
25/05/2019 20:31:13.979 [SWAPS] debug: Sending swap response to peer 
25/05/2019 20:31:14.213 [SWAPS] debug: Executing maker code to resolve hash
25/05/2019 20:31:14.262 [LND] error: LTC: sendToRouteSync failed with payment error: unable to route payment to destination: UnknownNextPeer
25/05/2019 20:31:14.264 [SWAPS] debug: deal 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603 failed due to SendPaymentFailure
25/05/2019 20:31:14.268 [ORDERBOOK] debug: removed hold of 10000000 on order d96cfab0-7f2b-11e9-9040-7b281a4ac93a
25/05/2019 20:31:14.263 [LND] error: LTC: got exception from sendToRouteSync: {"paymentHash":"","paymentHashString":"81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603","
routesList":[{"totalTimeLock":14681,"totalFees":0,"totalAmt":10000000,"hopsList":[{"chanId":12244161486979072,"chanCapacity":25000000000,"amtToForward":10000000,"fee":0,"expiry":14681,
"amtToForwardMsat":10000000000,"feeMsat":0,"pubKey":"0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef"}],"totalFeesMsat":0,"totalAmtMsat":10000000000}]}
25/05/2019 20:31:14.269 [SWAPS] error: could not settle invoice: Error: Got exception from sendPaymentSync unable to route payment to destination: UnknownNextPeer
    at Swaps.<anonymous> (/opt/xud/dist/swaps/Swaps.js:504:27)
    at Generator.throw (<anonymous>)
    at rejected (/opt/xud/dist/swaps/Swaps.js:5:65)
25/05/2019 20:31:14.291 [LND] debug: BTC: canceled invoice for 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603
25/05/2019 20:31:14.292 [LND] debug: BTC: deleted invoice subscription for 81edc66eb9587c37596b629ef9d96a70ff1d0d9601d6bfbdead409f071e24603
25/05/2019 20:31:14.487 [P2P] info: Peer 028599d05b18c0c3f8028915a17d603416f7276c822b6b2d20e71a3502bd0f9e0a socket closed
25/05/2019 20:31:14.489 [ORDERBOOK] debug: removed all orders for peer 028599d05b18c0c3f8028915a17d603416f7276c822b6b2d20e71a3502bd0f9e0a
25/05/2019 20:31:25.832 [P2P] debug: Connected pre-handshake to peer 35.231.171.148:47512
@offerm offerm added P1 top priority simnet labels May 25, 2019
@offerm
Copy link
Contributor Author

offerm commented May 25, 2019

lndltc log shows this:

2019-05-25 21:12:19.206 [DBG] CRTR: Searching for path to 303237366535366535353235363032646335343536656535356332653238663230313636313038356263653766303036343430306564383366306331363765
386566, sending 10000000000 mSAT
2019-05-25 21:12:19.619 [DBG] CRTR: Mission Control returning prune view of 0 edges, 0 vertexes
2019-05-25 21:12:19.657 [ERR] HSWC: Link 14130:1:0 not found
2019-05-25 21:12:19.675 [ERR] CRTR: Attempt to send payment f6dddd3d379a74ca8825b703d8feb1e3d7aa21657e4bfd260bd35302f11ee6b1 failed: UnknownNextPeer
2019-05-25 21:12:19.676 [DBG] CRTR: Reporting edge 15536099300540416:0 failure to Mission Control

Links

{
    "channels": [
        {
            "active": true,
            "remote_pubkey": "0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef",
            "channel_point": "4523708e2f2ba5a2bb0031fe1ee591191afcdc52dc4fb201a4c78e96dfd0653f:1",
            "chan_id": "15536099300540417",
            "capacity": "225000000000",
            "local_balance": "112500000000",
            "remote_balance": "112499963800",
            "commit_fee": "36200",
            "commit_weight": "724",
            "fee_per_kw": "50000",
            "unsettled_balance": "0",
            "total_satoshis_sent": "4",
            "total_satoshis_received": "4",
            "num_updates": "16",
            "pending_htlcs": [
            ],
            "csv_delay": 4693,
            "private": false,
            "initiator": false,
            "chan_status_flags": "ChanStatusDefault"
        },
        {
            "active": true,
            "remote_pubkey": "03301fd51f87728426918f284174d7d8d324585106f190276f4546f85ed6de123e",
            "channel_point": "b2e367999259278cddd463a969bc0a9d4a2aef41cd162420830e19e739dad39f:1",
            "chan_id": "15536099300671489",
            "capacity": "225000000000",
            "local_balance": "112499963800",
            "remote_balance": "112500000000",
            "commit_fee": "36200",
            "commit_weight": "724",
            "fee_per_kw": "50000",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 4693,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault"
        }
    ]
}

xud-log:

25/05/2019 21:12:19.684 [ORDERBOOK] debug: removed hold of 10000000 on order a62bbc80-7f31-11e9-8de8-af3730640b6d
25/05/2019 21:12:19.680 [LND] error: LTC: got exception from sendToRouteSync: {"paymentHash":"","paymentHashString":"f6dddd3d379a74ca8825b703d8feb1e3d7aa21657e4bfd260bd35302f11ee6b1","
routesList":[{"totalTimeLock":15922,"totalFees":0,"totalAmt":10000000,"hopsList":[{"chanId":15536099300540416,"chanCapacity":225000000000,"amtToForward":10000000,"fee":0,"expiry":15922
,"amtToForwardMsat":10000000000,"feeMsat":0,"pubKey":"0276e56e5525602dc5456ee55c2e28f201661085bce7f0064400ed83f0c167e8ef"}],"totalFeesMsat":0,"totalAmtMsat":10000000000}]}
25/05/2019 21:12:19.686 [SWAPS] error: could not settle invoice: Error: Got exception from sendPaymentSync unable to route payment to destination: UnknownNextPeer
    at Swaps.<anonymous> (/opt/xud/dist/swaps/Swaps.js:504:27)
    at Generator.throw (<anonymous>)
    at rejected (/opt/xud/dist/swaps/Swaps.js:5:65)

@offerm
Copy link
Contributor Author

offerm commented May 25, 2019

Interesting finding:

xud@xud-test-1:~$ xucli sell 0.1 LTC/BTC 0.00775 --stream
swapped 0.1 LTC with peer order 7e8fa1c0-7f34-11e9-9128-9deb3935a9ad
xud@xud-test-1:~$ 

looks like that if the first leg is LTC, it works well.

@kilrau kilrau added this to the 1.0.0 milestone May 27, 2019
@sangaman
Copy link
Collaborator

I'm stumped as to why the taker's xud crashed. Is this reproducible for you? It would also be very helpful to have the panic stack trace when it crashed if you can access it, that won't be in the actual log files though.

@kilrau kilrau added P2 mid priority and removed P1 top priority labels May 28, 2019
@ghost
Copy link

ghost commented May 28, 2019

Managed to reproduce the issue. Just like Offer said - direct channels, sanity checks pass, real swap fails. What is interesting is that I used the same xud nodes for non-direct channel swap and it succeeded without problems.

maker-command

➜  ./bin/xucli buy 0.00010000 LTC/BTC 0.1
no matches found
remaining 0.0001 LTC entered the order book as 3c436fc0-8175-11e9-a1ea-4b3b723703b3

maker-xud.log

[1] 28/05/2019 18:20:13.371 [RPC] debug: received call /xudrpc.Xud/PlaceOrderSync
[1] 28/05/2019 18:20:13.373 [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.1,"quantity":10000,"isBuy":true,"localId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","hold":0,"id":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","initialQuantity":10000,"createdAt":1559067613372}
[1] 28/05/2019 18:20:31.075 [P2P] debug: received swapRequest from 021ea6d67c850a0811b01c78c8117dca044b224601791a4186bf5748f667f73517: {"proposedQuantity":10000,"pairId":"LTC/BTC","orderId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","takerCltvDelta":144}
[1] 28/05/2019 18:20:31.076 [ORDERBOOK] debug: added hold of 10000 on order 3c436fc0-8175-11e9-a1ea-4b3b723703b3
[1] 28/05/2019 18:20:31.077 [SWAPS] debug: New deal: {"proposedQuantity":10000,"pairId":"LTC/BTC","orderId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","takerCltvDelta":144,"takerPubKey":"034c5266591bff232d1647f45bcf6bbc548d3d6f70b2992d28aba0afae067880ac","price":0.1,"isBuy":true,"quantity":10000,"makerAmount":10000,"takerAmount":1000,"makerCurrency":"LTC","takerCurrency":"BTC","destination":"034c5266591bff232d1647f45bcf6bbc548d3d6f70b2992d28aba0afae067880ac","peerPubKey":"021ea6d67c850a0811b01c78c8117dca044b224601791a4186bf5748f667f73517","localId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","phase":0,"state":0,"role":1,"createTime":1559067631076}
[1] 28/05/2019 18:20:31.083 [LND] debug: BTC: got 1 route(s) to destination 034c5266591bff232d1647f45bcf6bbc548d3d6f70b2992d28aba0afae067880ac: 1518916,,1000,1669900876870975500,2000000,1000,,1518916,1000000,,034c5266591bff232d1647f45bcf6bbc548d3d6f70b2992d28aba0afae067880ac,,1000000
[1] 28/05/2019 18:20:31.088 [SWAPS] debug: got block height of 1518772
[1] 28/05/2019 18:20:31.088 [SWAPS] debug: total timelock of route = 144 makerCltvDelta = 1152
[1] 28/05/2019 18:20:31.091 [LND] debug: LTC: added invoice of 10000 for 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a
[1] 28/05/2019 18:20:31.094 [SWAPS] debug: Sending swap response to peer
[1] 28/05/2019 18:20:31.222 [SWAPS] debug: Executing maker code to resolve hash
[1] 28/05/2019 18:20:31.259 [LND] error: BTC: sendToRouteSync failed with payment error: unable to route payment to destination: UnknownNextPeer
[1] 28/05/2019 18:20:31.260 [LND] error: BTC: got exception from sendToRouteSync: {"paymentHash":"","paymentHashString":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","routesList":[{"totalTimeLock":1518916,"totalFees":0,"totalAmt":1000,"hopsList":[{"chanId":1669900876870975500,"chanCapacity":2000000,"amtToForward":1000,"fee":0,"expiry":1518916,"amtToForwardMsat":1000000,"feeMsat":0,"pubKey":"034c5266591bff232d1647f45bcf6bbc548d3d6f70b2992d28aba0afae067880ac"}],"totalFeesMsat":0,"totalAmtMsat":1000000}]}
[1] 28/05/2019 18:20:31.261 [SWAPS] debug: deal 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a failed due to SendPaymentFailure
[1] 28/05/2019 18:20:31.263 [ORDERBOOK] debug: removed hold of 10000 on order 3c436fc0-8175-11e9-a1ea-4b3b723703b3
[1] 28/05/2019 18:20:31.263 [SWAPS] error: could not settle invoice: Error: Got exception from sendPaymentSync unable to route payment to destination: UnknownNextPeer
[1]     at Swaps.<anonymous> (/home/ar/xud/dist/swaps/Swaps.js:504:27)
[1]     at Generator.throw (<anonymous>)
[1]     at rejected (/home/ar/xud/dist/swaps/Swaps.js:5:65)
[1] 28/05/2019 18:20:31.268 [LND] debug: LTC: canceled invoice for 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a
[1] 28/05/2019 18:20:31.270 [LND] debug: LTC: deleted invoice subscription for 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a
[1] 28/05/2019 18:20:31.351 [P2P] info: Peer 021ea6d67c850a0811b01c78c8117dca044b224601791a4186bf5748f667f73517 socket closed
[1] 28/05/2019 18:20:31.352 [ORDERBOOK] debug: removed all orders for peer 021ea6d67c850a0811b01c78c8117dca044b224601791a4186bf5748f667f73517
[1] 28/05/2019 18:20:31.353 [P2P] debug: attempting to reconnect to a disconnected peer 021ea6d67c850a0811b01c78c8117dca044b224601791a4186bf5748f667f73517

taker-command

➜  ./bin/xucli sell 0.00010000 LTC/BTC 0.1
failed to swap 0.0001 LTC with peer order 3c436fc0-8175-11e9-a1ea-4b3b723703b3
remaining 0.0001 LTC entered the order book as 46cc9480-8175-11e9-8604-ade2bf0bcade

taker-xud.log

[1] 28/05/2019 18:20:13.323 [ORDERBOOK] debug: order added: {"id":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","pairId":"LTC/BTC","price":0.1,"quantity":10000,"isBuy":true,"peerPubKey":"03168c19fc21e6b48d74a94006eaa456114d48c7616e8351e2c81ee1f0cdd50293","createdAt":1559067613323,"initialQuantity":10000}
[1] 28/05/2019 18:20:26.708 [RPC] debug: received call /xudrpc.Xud/ListOrders
[1] 28/05/2019 18:20:31.048 [RPC] debug: received call /xudrpc.Xud/PlaceOrderSync
[1] 28/05/2019 18:20:31.049 [ORDERBOOK] debug: removed order 3c436fc0-8175-11e9-a1ea-4b3b723703b3 while matching order 46cc9480-8175-11e9-8604-ade2bf0bcade
[1] 28/05/2019 18:20:31.049 [ORDERBOOK] debug: matched with peer 03168c19fc21e6b48d74a94006eaa456114d48c7616e8351e2c81ee1f0cdd50293, executing swap on taker 46cc9480-8175-11e9-8604-ade2bf0bcade and maker 3c436fc0-8175-11e9-a1ea-4b3b723703b3 for 10000
[1] 28/05/2019 18:20:31.057 [LND] debug: LTC: got 1 route(s) to destination 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7: 1093216,,10000,1201359389856956400,16000000,10000,,1093216,10000000,,0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7,,10000000
[1] 28/05/2019 18:20:31.058 [SWAPS] debug: New deal: {"takerCltvDelta":144,"rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","orderId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","pairId":"LTC/BTC","proposedQuantity":10000,"rPreimage":"d8b5ae5b12696758389b86ccac4b4490390d947c206ce76a3c02a2fee02b8ce3","takerCurrency":"BTC","makerCurrency":"LTC","takerAmount":1000,"makerAmount":10000,"destination":"0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7","peerPubKey":"03168c19fc21e6b48d74a94006eaa456114d48c7616e8351e2c81ee1f0cdd50293","localId":"46cc9480-8175-11e9-8604-ade2bf0bcade","price":0.1,"isBuy":true,"phase":0,"state":0,"role":0,"createTime":1559067631057}
[1] 28/05/2019 18:20:31.059 [SWAPS] debug: Requesting deal: {"takerCltvDelta":144,"rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","orderId":"3c436fc0-8175-11e9-a1ea-4b3b723703b3","pairId":"LTC/BTC","proposedQuantity":10000,"rPreimage":"d8b5ae5b12696758389b86ccac4b4490390d947c206ce76a3c02a2fee02b8ce3","takerCurrency":"BTC","makerCurrency":"LTC","takerAmount":1000,"makerAmount":10000,"destination":"0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7","peerPubKey":"03168c19fc21e6b48d74a94006eaa456114d48c7616e8351e2c81ee1f0cdd50293","localId":"46cc9480-8175-11e9-8604-ade2bf0bcade","price":0.1,"isBuy":true,"phase":0,"state":0,"role":0,"createTime":1559067631057}
[1] 28/05/2019 18:20:31.080 [P2P] debug: received swapAccepted from 03168c19fc21e6b48d74a94006eaa456114d48c7616e8351e2c81ee1f0cdd50293: {"rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","quantity":10000,"makerCltvDelta":1152}
[1] 28/05/2019 18:20:31.085 [LND] debug: BTC: added invoice of 1000 for 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a
[1] 28/05/2019 18:20:31.321 [LND] error: LTC: sendPaymentSync failed with payment error: UnknownPaymentHash(amt=10000000 mSAT)
[1] 28/05/2019 18:20:31.322 [LND] error: LTC: got exception from sendPaymentSync: {"dest":"","destString":"0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7","amt":10000,"paymentHash":"","paymentHashString":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","paymentRequest":"","finalCltvDelta":1152,"outgoingChanId":0,"cltvLimit":0}
[1] 28/05/2019 18:20:31.323 [SWAPS] debug: deal 71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a failed due to SendPaymentFailure
[1] 28/05/2019 18:20:31.325 [SWAPS] debug: Sending swap error to peer: {"rHash":"71561cbae8c864c8f4fb80fd30ff4dce65362f0a2d4d5994bb07b262004fca4a","failureReason":"UnknownPaymentHash(amt=10000000 mSAT)"}
[1] 28/05/2019 18:20:31.326 [ORDERBOOK] error: swap between orders 3c436fc0-8175-11e9-a1ea-4b3b723703b3 & 46cc9480-8175-11e9-8604-ade2bf0bcade failed due to SendPaymentFailure
[1] 28/05/2019 18:20:31.326 [ORDERBOOK] warn: swap for 10000 failed during order matching due to SendPaymentFailure, will repeat matching routine for failed quantity
[1] 28/05/2019 18:20:31.327 [ORDERBOOK] debug: repeating matching routine for 46cc9480-8175-11e9-8604-ade2bf0bcade for failed quantity of 10000
[1] 28/05/2019 18:20:31.328 [ORDERBOOK] debug: order added: {"pairId":"LTC/BTC","price":0.1,"quantity":10000,"isBuy":false,"localId":"46cc9480-8175-11e9-8604-ade2bf0bcade","hold":0,"id":"46cc9480-8175-11e9-8604-ade2bf0bcade","initialQuantity":10000,"createdAt":1559067631048}
[1] { AssertionError: Assertion failed
[1]     at new goog.asserts.AssertionError (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:98:603)
[1]     at Object.goog.asserts.doAssertFailure_ (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:99:126)
[1]     at Object.goog.asserts.assert (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:99:385)
[1]     at jspb.BinaryWriter.writeUint32 (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:277:295)
[1]     at Function.proto.xudp2p.SwapFailedPacket.serializeBinaryToWriter (/home/ar/xud/dist/proto/xudp2p_pb.js:4673:12)
[1]     at proto.xudp2p.SwapFailedPacket.serializeBinary (/home/ar/xud/dist/proto/xudp2p_pb.js:4629:33)
[1]     at SwapFailedPacket.serialize (/home/ar/xud/dist/p2p/packets/types/SwapFailedPacket.js:29:24)
[1]     at SwapFailedPacket.Packet.toRaw (/home/ar/xud/dist/p2p/packets/Packet.js:51:37)
[1]     at Framer.<anonymous> (/home/ar/xud/dist/p2p/Framer.js:27:38)
[1]     at Generator.next (<anonymous>)
[1]     at /home/ar/xud/dist/p2p/Framer.js:7:71
[1]     at new Promise (<anonymous>)
[1]     at __awaiter (/home/ar/xud/dist/p2p/Framer.js:3:12)
[1]     at Framer.frame (/home/ar/xud/dist/p2p/Framer.js:26:49)
[1]     at Peer.<anonymous> (/home/ar/xud/dist/p2p/Peer.js:177:44)
[1]     at Generator.next (<anonymous>)
[1]     at /home/ar/xud/dist/p2p/Peer.js:7:71
[1]     at new Promise (<anonymous>)
[1]     at __awaiter (/home/ar/xud/dist/p2p/Peer.js:3:12)
[1]     at Peer.sendPacket (/home/ar/xud/dist/p2p/Peer.js:176:39)
[1]     at Swaps.<anonymous> (/home/ar/xud/dist/swaps/Swaps.js:70:24)
[1]     at Generator.next (<anonymous>)
[1]   message: 'Assertion failed',
[1]   reportErrorToServer: true,
[1]   messagePattern: 'Assertion failed' }
[1]
[1] /home/ar/xud/dist/bootstrap.js:13
[1]         throw err;
[1]         ^
[1] AssertionError: Assertion failed
[1]     at new goog.asserts.AssertionError (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:98:603)
[1]     at Object.goog.asserts.doAssertFailure_ (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:99:126)
[1]     at Object.goog.asserts.assert (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:99:385)
[1]     at jspb.BinaryWriter.writeUint32 (/home/ar/xud/node_modules/google-protobuf/google-protobuf.js:277:295)
[1]     at Function.proto.xudp2p.SwapFailedPacket.serializeBinaryToWriter (/home/ar/xud/dist/proto/xudp2p_pb.js:4673:12)
[1]     at proto.xudp2p.SwapFailedPacket.serializeBinary (/home/ar/xud/dist/proto/xudp2p_pb.js:4629:33)
[1]     at SwapFailedPacket.serialize (/home/ar/xud/dist/p2p/packets/types/SwapFailedPacket.js:29:24)
[1]     at SwapFailedPacket.Packet.toRaw (/home/ar/xud/dist/p2p/packets/Packet.js:51:37)
[1]     at Framer.<anonymous> (/home/ar/xud/dist/p2p/Framer.js:27:38)
[1]     at Generator.next (<anonymous>)
[1]     at /home/ar/xud/dist/p2p/Framer.js:7:71
[1]     at new Promise (<anonymous>)
[1]     at __awaiter (/home/ar/xud/dist/p2p/Framer.js:3:12)
[1]     at Framer.frame (/home/ar/xud/dist/p2p/Framer.js:26:49)
[1]     at Peer.<anonymous> (/home/ar/xud/dist/p2p/Peer.js:177:44)
[1]     at Generator.next (<anonymous>)
[1]     at /home/ar/xud/dist/p2p/Peer.js:7:71
[1]     at new Promise (<anonymous>)
[1]     at __awaiter (/home/ar/xud/dist/p2p/Peer.js:3:12)
[1]     at Peer.sendPacket (/home/ar/xud/dist/p2p/Peer.js:176:39)
[1]     at Swaps.<anonymous> (/home/ar/xud/dist/swaps/Swaps.js:70:24)
[1]     at Generator.next (<anonymous>)
[1] [nodemon] app crashed - waiting for file changes before starting...

@offerm offerm added P1 top priority and removed P2 mid priority labels May 29, 2019
@offerm
Copy link
Contributor Author

offerm commented May 29, 2019

@kilrau Adding P1 back again. I see this from time to time. Not sure you want to see it when you demo in Munich

@kilrau
Copy link
Contributor

kilrau commented May 29, 2019

Certainly not. @sangaman

@ghost
Copy link

ghost commented May 29, 2019

This issue can be divided into 2 parts:

  1. xud crashing when trying to send SwapFailedPacket - fixed in fix(swaps): prevent SwapFailurePacket crash #997

  2. direct channel LTC/BTC swap failing with UnknownPaymentHash message from lnd
    As mentioned by Offer above - a temporary workaround for this is to have maker initiate a sell order first.

@kilrau
Copy link
Contributor

kilrau commented May 29, 2019

Since 1. is fixed in #997, this issue is about fixing 2.

@offerm
Copy link
Contributor Author

offerm commented May 31, 2019

I have the same problem with sell orders of WETH/BTC.

The second leg is BTC and it fails with UnknownNextPeer.

This can be LND issue so we should try to reproduce with LND's command line (using send to route)

@offerm
Copy link
Contributor Author

offerm commented May 31, 2019

I have noticed some related issues on LND.
Upgrade to 0.61-beta did not solved it.

@kilrau kilrau assigned ghost Jun 4, 2019
@kilrau
Copy link
Contributor

kilrau commented Jun 4, 2019

We discussed on the call to just use sendpayment and get rid of sendtoroute. It allows to set cltv delta now. @erkarl

@offerm
Copy link
Contributor Author

offerm commented Jun 4, 2019 via email

@kilrau
Copy link
Contributor

kilrau commented Jun 5, 2019

Sure, please jump in with implementation details to review @erkarl

@offerm
Copy link
Contributor Author

offerm commented Jun 5, 2019

First, we have a problem that we don’t understand and not sure how to reproduce. Changing the payment api that we use due to this problem is just a guess. Probably not a good one.

I would not change this before we are live and before we have a good reason for it.

And, we should understand how we use cltv without the route.

Have a feeling that the reason for the problem has to do with the open htlcs that we have when we used sanity swaps. Maybe the number of open Htlc got to high?

@ghost
Copy link

ghost commented Jun 6, 2019

@offerm I'm able to reproduce the problem on my machines 100% of the time.

I did a quick proof of concept with sendPayment to make sure that the issue is related to sendToRoute. Turns out it doesn't solve the problem. Going to dig deeper...

@ghost
Copy link

ghost commented Jun 7, 2019

@offerm

Upon further inspection I discovered 2 problems.

lndrpc.SendToRouteSync is broken when we pass in a route that has only 1 hop. It will error with UnknownNextPeer message. I also tried on current lnd master v0.6.1-beta-228-gaa5156a1a985ef3e0b1e6ad48a081125a465870d where SendToRouteRequest.routes is deprecated in favor of SendToRouteRequest.route - same result. What is interesting is that I can only replicate the problem on testnet, but not on my local simnet.

The second problem I noticed on xud level was that we're not waiting for the hold invoice state to become OPEN and in case of low latency the taker can attempt to pay us "too fast" when accepting the deal, causing the payment to occasionally error with UnknownPaymentHash. This is the reason I mentioned yesterday that switching to lndrpc.SendPayment didn't work.

I suggest we move away from lndrpc.SendToRouteSync to using lndrpc.SendPayment and create an issue to lnd. We're already using it for sanity swaps. To address Offer's concern above - it also allows to specify the final_cltv_delta.

@kilrau
Copy link
Contributor

kilrau commented Jun 7, 2019

I suggest we move away from lndrpc.SendToRouteSync to using lndrpc.SendPayment and create an issue to lnd.

SGTM, please go ahead.

Not sure if v0.6.1-beta-228-gaa5156a1a985ef3e0b1e6ad48a081125a465870d includes the new error output of lightningnetwork/lnd#3113, but what exactly did it throw?

@offerm
Copy link
Contributor Author

offerm commented Jun 7, 2019 via email

@offerm
Copy link
Contributor Author

offerm commented Jun 7, 2019 via email

@ghost
Copy link

ghost commented Jun 7, 2019

@offerm

Can we find first what is the reason for the problem and why we don't see it [any more] on simnet?

That is a very good question that bothers me.

Also before we switch - how are we going to decide which value to provide as final_cltv_delta?

If we're the the taker we'll use deal.makerCltvDelta that the maker has set. In case of maker we'll use deal.takerCltvDelta set by the taker.

lnd logs for UnknownNextPeer

payer

2019-06-07 17:08:48.335 [TRC] CRTR: Attempting to send payment 601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187 (pid=10000), using route: (route.Route) amt=10000000 mSAT, fees=0 mSAT, tl=1106152, chans=1215313291925061632
2019-06-07 17:08:48.336 [TRC] HSWC: Committing fresh circuits: ([]channeldb.CircuitKey) (len=1 cap=1) {
 (channeldb.CircuitKey) (Chan ID=0:0:0, HTLC ID=10000)
}
2019-06-07 17:08:48.348 [ERR] HSWC: Link 1105321:1:0 not found
2019-06-07 17:08:48.348 [ERR] CRTR: Failed sending attempt 10000 for payment 601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187 to switch: UnknownNextPeer
2019-06-07 17:08:48.348 [TRC] CRTR: node=303238366238613835646362376164353732323263636264336338663031373232353237343533306262646132343335643162663838303033363138303761356137 reported failure when sending htlc
2019-06-07 17:08:48.348 [DBG] CRTR: Reporting channel 1215313291925061632 failure to Mission Control
2019-06-07 17:08:55.590 [INF] LTND: Received interrupt
2019-06-07 17:08:55.590 [INF] LTND: Shutting down...
2019-06-07 17:08:55.590 [INF] LTND: Gracefully shutting down.

payee

2019-06-07 17:08:48.189 [INF] INVC: New single invoice subscription client: id=0, hash=601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187
2019-06-07 17:08:48.469 [DBG] INVC: Invoice(601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187): canceling invoice
2019-06-07 17:08:48.470 [DBG] INVC: Invoice(601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187): canceled
2019-06-07 17:08:48.470 [INF] IRPC: Canceled invoice 601eb69afdfb01573bfcd1e869a611e277638493d701dfaf1e51ae06b460b187
2019-06-07 17:08:55.711 [INF] PEER: unable to read message from 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7@192.168.63.156:59598: EOF
2019-06-07 17:08:55.711 [INF] PEER: Disconnecting 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7@192.168.63.156:59598, reason: read handler closed
2019-06-07 17:08:55.711 [TRC] PEER: readHandler for peer 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7@192.168.63.156:59598 done
2019-06-07 17:08:55.711 [TRC] PEER: Update stream for ChannelID(4953eca7488aa8f3005ca4b25eb908ed70696b312da085786fdd94fb90a643af) exiting
2019-06-07 17:08:55.711 [TRC] PEER: writeHandler for peer 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7@192.168.63.156:59598 done
2019-06-07 17:08:55.812 [TRC] PEER: Update stream for gossiper exited
2019-06-07 17:08:55.912 [DBG] SRVR: Peer 0286b8a85dcb7ad57222ccbd3c8f017225274530bbda2435d1bf8800361807a5a7@192.168.63.156:59598 has been disconnected

@ghost
Copy link

ghost commented Jun 7, 2019

@offerm

Please also note that I had to use the following patch on xud level in order to produce the UnknownNextPeer error. This is due to fact that I upgraded to latest master lnd gaa5156a1a985ef3e0b1e6ad48a081125a465870d and cannot downgrade because of database migrations. The latest master doesn't support setRoutes so I had to specify a single route via setRoute.

Screen Shot 2019-06-07 at 20 25 44

@kilrau

Not sure if v0.6.1-beta-228-gaa5156a1a985ef3e0b1e6ad48a081125a465870d includes the new error output of lightningnetwork/lnd#3113, but what exactly did it throw?

Yes, includes it.

@offerm
Copy link
Contributor Author

offerm commented Jun 7, 2019 via email

@ghost
Copy link

ghost commented Jun 10, 2019

@offerm

Prior to executing the payment:

[DBG] DISC: Successfully sent ChannelUpdate message for channel=1105321:1:1 with peer=0301185776701afa4369f401f818049f66d24aa0ef3ccb5b64d307115ab906ab21 upon reconnection

Are you not able to reproduce the issue on testnet?

This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants