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

Spurious WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS #3367

Closed
NicolasDorier opened this issue Dec 20, 2019 · 25 comments · Fixed by #3376
Closed

Spurious WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS #3367

NicolasDorier opened this issue Dec 20, 2019 · 25 comments · Fixed by #3376
Assignees

Comments

@NicolasDorier
Copy link
Collaborator

NicolasDorier commented Dec 20, 2019

The original report asked about us overpaying to the receiver, but that is AFeatureNotABug. This issue now tracks another problem: spurious incorrect_or_unknown_payment_details failure.

Issue and Steps to Reproduce

Do the below a few hundred times in an environment where miners are independent of the test suite (our test suite has block discovery tightly coupled to the test, i.e. blocks are only discovered if the test case says so):

  • Run two nodes and make a channel between them.
  • Make an invoice on one node and pay it on the other.

Above text by @ZmnSCPxj


Original report by @NicolasDorier

Issue and Steps to Reproduce

  1. Connect 2 nodes
  2. Create an invoice of 10_000 millisatoshi
  3. Pay the invoice
  4. msatoshi_received is 10_004 millisatoshi
@NicolasDorier
Copy link
Collaborator Author

NicolasDorier commented Dec 20, 2019

mmh it happened to one of my tests, and it seems it does not happen again. Is it some kind of wizard secret privacy feature?

Though another test failed with WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS... (which passed 5min ago...)

@NicolasDorier
Copy link
Collaborator Author

NicolasDorier commented Dec 20, 2019

There seems to have something strange on the payments. This randomly fails either with WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS or sometimes the amount paid is not exactly what is asked...

Can it be something that happen if you create two different invoice for the same amount in short period of time?

@NicolasDorier
Copy link
Collaborator Author

I will stop working on it, we are stuck on v0.7.3 for now.
I can't reliably reproduce, the same test are doing one of the above:

  1. Working fine
  2. Failing to pay WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS
  3. Paying but a slightly different amount

Let me know if you want me to test something.

@cdecker
Copy link
Member

cdecker commented Dec 20, 2019

The WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS error should not happen, that
is definitely an error. It'd usually mean that the recipient does not have an
invoice matching the payment_hash in the payment, and it can therefore not
be claimed.

Regarding the overpayment of invoices, that's on purpose to hide the actual
destination a bit better (if I were to forward a round number of something
that converted to USD would be a round number I could guess that the next hop
is very likely the destination). We compute a route to the destination and
then attach a shadow route that is then used to fuzz the amount that the
recipient receives and the CLTVs attached to the HTLC. If you don't want to
overpay you will have to modify the pay plugin in order not to add the
shadow route.

However the fuzzed amounts do respect the 0.5% fee allowance when computing
the route: we will never overpay more than invoice_amount * 0.5% - routing_fees (if no higher maxfeepercent was specified). So overpaying is
basically equivalent to taking a slightly longer route.

Can you provide instructions on how to reproduce the
WIRE_INCORRECT_OR_UNKKNOWN_PAYMENT_DETAILS issue? I'm struggling to see why
our integration tests (which cover the simple scenario you describe) would not
catch the random behavior.

@cdecker cdecker self-assigned this Dec 20, 2019
@NicolasDorier
Copy link
Collaborator Author

NicolasDorier commented Dec 20, 2019

I can probably send you the RPC logs between the two nodes one moment.

@NicolasDorier
Copy link
Collaborator Author

@cdecker so here are the RPC logs.

Scenario is:

B create two invoices.
A pays the first.
B ensures it is paid via waitinvoice.
A pays the second. <= Fails here... randomly
B ensure it is paid via waitinvoice.

(Source code is here)

I am copying here different logs:

  • The logs of the test
  • The logs of lightningd for A and B (there is probably some stuff from previous tests there)
  • The RPC logs of A and B

Logs of my test:

12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning (Customer): Server is up
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning (Merchant): Server is up
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Connecting channels...
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Channels connected
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: CanWaitListenInvoice
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Created invoice 3ptGLyQbMDXWZ84iksvuKpcTSm96
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Created invoice 4FsRefZvJdfXZmxDWTPaiqcgK5FD
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Paid invoice 3ptGLyQbMDXWZ84iksvuKpcTSm96
12/20/2019 11:55:44 AM +00:00 :Tests:   C-Lightning: Notification received for 3ptGLyQbMDXWZ84iksvuKpcTSm96

A RPC logs:

> 2019/12/20 11:55:44.579564  length=307 from=0 to=306
{"id":0,"method":"pay","params":["lnbcrt100n1pwledkqpp5v25q65mx8p5xkymf4up8al9dwzq9cag54jh6q0n42flkwzk6s8cqdqjfpjkcmr0ypmk7unvvscqp2sp52g8puehgty523sm62my5jtuaneyg0rugzzlxflf8tmxstkram7ws9qy9qsqdnpgwxuzl6ccnvgrk64lds578t6cmnhs4mq924gkuenftwx4x9dqzqpqrlha2z45fygtm5dp8va24p9tzr8fykfkp2kkhjczm8tekfcq7gerpy"]}< 2019/12/20 11:55:44.864215  length=720 from=0 to=719
{"jsonrpc":"2.0","id":0,"result":{"id":73,"payment_hash":"62a80d536638686b1369af027efcad70805c7514acafa03e75527f670ada81f0","destination":"0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520","msatoshi":10000,"amount_msat":"10000msat","msatoshi_sent":10000,"amount_sent_msat":"10000msat","created_at":1576842944,"status":"complete","payment_preimage":"dd3a8732be24223bfdb6394ed0d971f8accd256bb86093bfc0054aec40a596b7","bolt11":"lnbcrt100n1pwledkqpp5v25q65mx8p5xkymf4up8al9dwzq9cag54jh6q0n42flkwzk6s8cqdqjfpjkcmr0ypmk7unvvscqp2sp52g8puehgty523sm62my5jtuaneyg0rugzzlxflf8tmxstkram7ws9qy9qsqdnpgwxuzl6ccnvgrk64lds578t6cmnhs4mq924gkuenftwx4x9dqzqpqrlha2z45fygtm5dp8va24p9tzr8fykfkp2kkhjczm8tekfcq7gerpy"}}



> 2019/12/20 11:55:44.878969  length=307 from=0 to=306
{"id":0,"method":"pay","params":["lnbcrt100n1pwledkqpp5sjpdcx5820r53l2s2ydfmmstkm7hvkf565s0rl64cyjuglrpfwsqdqjfpjkcmr0ypmk7unvvscqp2sp5gajln08hamrgfdj45mem60z0atf9z4ut7awchpfmvk7qdaqwljcs9qy9qsqjvlev8tznpjdfz8mfe4205cdqsv44fjdrl9c04w89v7tvngd60gjudnlaafr08agc6gw3xajtpyln6nh8ey9ccq7hw9vq8z7ajj6cpsps3fv07"]}< 2019/12/20 11:55:45.403085  length=1003 from=0 to=1002
{"jsonrpc":"2.0","id":0,"error":{"code":203,"message":"failed: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS (reply from remote)","data":{"id":74,"payment_hash":"8482dc1a8753c748fd50511a9dee0bb6fd765934d520f1ff55c125c47c614ba0","destination":"0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520","msatoshi":10000,"amount_msat":"10000msat","msatoshi_sent":10000,"amount_sent_msat":"10000msat","created_at":1576842944,"status":"pending","bolt11":"lnbcrt100n1pwledkqpp5sjpdcx5820r53l2s2ydfmmstkm7hvkf565s0rl64cyjuglrpfwsqdqjfpjkcmr0ypmk7unvvscqp2sp5gajln08hamrgfdj45mem60z0atf9z4ut7awchpfmvk7qdaqwljcs9qy9qsqjvlev8tznpjdfz8mfe4205cdqsv44fjdrl9c04w89v7tvngd60gjudnlaafr08agc6gw3xajtpyln6nh8ey9ccq7hw9vq8z7ajj6cpsps3fv07","erring_index":1,"failcode":16399,"failcodename":"WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS","erring_node":"0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520","erring_channel":"124x2x0","erring_direction":0,"raw_message":"400f0000000000002710000000c1"}}}

Lightning logs for A

2019-12-20T11:55:45.098Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: revoke_and_ack LOCAL: remote_per_commit = 03882aa41a915baff740474fa7033c3d071a63aa43aa3e1e487dc6805635843fb0, old_remote_per_commit = 02d03ab148e7ab7b9fa323e71ad3df208f483a890beee8dbdf2a82aacfd78e7138
2019-12-20T11:55:45.100Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Trying commit
2019-12-20T11:55:45.100Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: SENT_ADD_HTLC->SENT_ADD_COMMIT
2019-12-20T11:55:45.100Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc added REMOTE: local 16776766919 remote 448081
2019-12-20T11:55:45.100Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: -> local 16776756919 remote 448081
2019-12-20T11:55:45.100Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: sending_commit: HTLC LOCAL 73 = SENT_ADD_COMMIT/RCVD_ADD_COMMIT
2019-12-20T11:55:45.101Z DEBUG hsmd: Client: Received message 19 from client
2019-12-20T11:55:45.101Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Creating commit_sig signature 147 304402200a5a218f979e20b9cf38edd0d3f97e35821e72e63f4590177e0e34475343a649022039691d4252c1882b03d9936aaa1a40638114fd38921d6d8c8c4813451d7838a501 for tx 02000000010f9a6dafe92b0997920e9aca36fdc3ed26eec523d1fcce40f36a50300dff4379000000000014811a8001e4f2ff0000000000160014bfb3548ca6906b5b4dea6a11c70284e33c9e1eaa79a81020 wscript 5221023bbdd30507b0156ef6a4143254f5c076af696afa1c87b77e7ccd3fabfb70f7082103c3df66b4703362620231a0fe6a72854d172e2dfaef438f19ace3daab28c49d4f52ae key 023bbdd30507b0156ef6a4143254f5c076af696afa1c87b77e7ccd3fabfb70f708
2019-12-20T11:55:45.102Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Telling master we're about to commit...
2019-12-20T11:55:45.102Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1020
2019-12-20T11:55:45.103Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 SENT_ADD_HTLC->SENT_ADD_COMMIT
2019-12-20T11:55:45.121Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1120
2019-12-20T11:55:45.121Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.122Z DEBUG lightningd: Payment part 0/0 status 0
2019-12-20T11:55:45.122Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending commit_sig with 0 htlc sigs
2019-12-20T11:55:45.123Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_out WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.146Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_in WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.146Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received revoke_and_ack
2019-12-20T11:55:45.147Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: SENT_ADD_COMMIT->RCVD_ADD_REVOCATION
2019-12-20T11:55:45.147Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: rcvd_revoke_and_ack: HTLC LOCAL 73 = RCVD_ADD_REVOCATION/SENT_ADD_REVOCATION
2019-12-20T11:55:45.148Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Commits outstanding after recv revoke_and_ack
2019-12-20T11:55:45.148Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: HTLC 73[LOCAL] => RCVD_ADD_REVOCATION
2019-12-20T11:55:45.148Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1022
2019-12-20T11:55:45.149Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: got revoke 146: 1 changed
2019-12-20T11:55:45.149Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 SENT_ADD_COMMIT->RCVD_ADD_REVOCATION
2019-12-20T11:55:45.179Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1122
2019-12-20T11:55:45.180Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.180Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: revoke_and_ack LOCAL: remote_per_commit = 035b7e08228d7450ba3081ac841701b21d10a49d30a7954d2eacf45a08526d31f7, old_remote_per_commit = 03882aa41a915baff740474fa7033c3d071a63aa43aa3e1e487dc6805635843fb0
2019-12-20T11:55:45.181Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Trying commit
2019-12-20T11:55:45.181Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Can't send commit: nothing to send
2019-12-20T11:55:45.182Z DEBUG hsmd: Client: Received message 18 from client
2019-12-20T11:55:45.182Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_in WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.182Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received commit
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: RCVD_ADD_REVOCATION->RCVD_ADD_ACK_COMMIT
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc added LOCAL: local 16776766919 remote 448081
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: -> local 16776756919 remote 448081
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: rcvd_commit: HTLC LOCAL 73 = RCVD_ADD_ACK_COMMIT/SENT_ADD_ACK_COMMIT
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Derived key 028d1de6e8557d825a5d201180f39e8ba6f311c61ec290b53c6a3b843c0148d632 from basepoint 034873dc2b3de277fbf40fd59cb28f40de0f168869cc4e2770c79a372e16f99c8d, point 02363d585da12c07815a2f45aa8524999b0bd2f7411637091534d5d2d332ebbc37
2019-12-20T11:55:45.183Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received commit_sig with 0 htlc sigs
2019-12-20T11:55:45.184Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending revoke_and_ack
2019-12-20T11:55:45.184Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: RCVD_ADD_ACK_COMMIT->SENT_ADD_ACK_REVOCATION
2019-12-20T11:55:45.184Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: sending_revoke_and_ack: HTLC LOCAL 73 = SENT_ADD_ACK_REVOCATION/RCVD_ADD_ACK_REVOCATION
2019-12-20T11:55:45.184Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1021
2019-12-20T11:55:45.187Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: got commitsig 147: feerate 4000, 0 added, 0 fulfilled, 0 failed, 1 changed
2019-12-20T11:55:45.187Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 RCVD_ADD_REVOCATION->RCVD_ADD_ACK_COMMIT
2019-12-20T11:55:45.187Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 RCVD_ADD_ACK_COMMIT->SENT_ADD_ACK_REVOCATION
2019-12-20T11:55:45.203Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1121
2019-12-20T11:55:45.204Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.208Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_out WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.223Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_in WIRE_UPDATE_FAIL_HTLC
2019-12-20T11:55:45.223Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: FAIL:: HTLC LOCAL 73 = RCVD_REMOVE_HTLC/SENT_REMOVE_HTLC
2019-12-20T11:55:45.233Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Trying commit
2019-12-20T11:55:45.233Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Can't send commit: nothing to send
2019-12-20T11:55:45.272Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_in WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.274Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received commit
2019-12-20T11:55:45.274Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: RCVD_REMOVE_HTLC->RCVD_REMOVE_COMMIT
2019-12-20T11:55:45.275Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc added LOCAL: local 16776756919 remote 448081
2019-12-20T11:55:45.277Z DEBUG hsmd: Client: Received message 18 from client
2019-12-20T11:55:45.277Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: -> local 16776766919 remote 448081
2019-12-20T11:55:45.278Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: rcvd_commit: HTLC LOCAL 73 = RCVD_REMOVE_COMMIT/SENT_REMOVE_COMMIT FAILED
2019-12-20T11:55:45.278Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Derived key 02e94af4e885fdb40f138c21c9fce25232aac6459b35e4709bcaf9b406cb6161fa from basepoint 034873dc2b3de277fbf40fd59cb28f40de0f168869cc4e2770c79a372e16f99c8d, point 0354dd7aa0da64fc636879b4bfb388420dde99b6801a30abf948b7a68f059e2c70
2019-12-20T11:55:45.278Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received commit_sig with 0 htlc sigs
2019-12-20T11:55:45.279Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending revoke_and_ack
2019-12-20T11:55:45.279Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: RCVD_REMOVE_COMMIT->SENT_REMOVE_REVOCATION
2019-12-20T11:55:45.280Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: sending_revoke_and_ack: HTLC LOCAL 73 = SENT_REMOVE_REVOCATION/RCVD_REMOVE_REVOCATION FAILED
2019-12-20T11:55:45.280Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: revoke_and_ack made pending: commit timer
2019-12-20T11:55:45.280Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1021
2019-12-20T11:55:45.281Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: got commitsig 148: feerate 4000, 0 added, 0 fulfilled, 1 failed, 0 changed
2019-12-20T11:55:45.281Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 SENT_ADD_ACK_REVOCATION->RCVD_REMOVE_COMMIT
2019-12-20T11:55:45.281Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: Our HTLC 73 failed (0)
2019-12-20T11:55:45.282Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 RCVD_REMOVE_COMMIT->SENT_REMOVE_REVOCATION
2019-12-20T11:55:45.308Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1121
2019-12-20T11:55:45.309Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.309Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_out WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.311Z DEBUG hsmd: Client: Received message 19 from client
2019-12-20T11:55:45.311Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Trying commit
2019-12-20T11:55:45.311Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: SENT_REMOVE_REVOCATION->SENT_REMOVE_ACK_COMMIT
2019-12-20T11:55:45.311Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc added REMOTE: local 16776756919 remote 448081
2019-12-20T11:55:45.312Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: -> local 16776766919 remote 448081
2019-12-20T11:55:45.312Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: sending_commit: HTLC LOCAL 73 = SENT_REMOVE_ACK_COMMIT/RCVD_REMOVE_ACK_COMMIT FAILED
2019-12-20T11:55:45.312Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Creating commit_sig signature 148 304402205feeb36bf7c242f1f382627a40b2fc77b26c8c8ad856aeec9cf871b55cb9ee4b02205505d07e8cf88839c7ac1c58b0c7bf71f785ea663f0cfd7522a2759fe9832afd01 for tx 02000000010f9a6dafe92b0997920e9aca36fdc3ed26eec523d1fcce40f36a50300dff4379000000000014811a8001eef2ff0000000000160014bfb3548ca6906b5b4dea6a11c70284e33c9e1eaa7ea81020 wscript 5221023bbdd30507b0156ef6a4143254f5c076af696afa1c87b77e7ccd3fabfb70f7082103c3df66b4703362620231a0fe6a72854d172e2dfaef438f19ace3daab28c49d4f52ae key 023bbdd30507b0156ef6a4143254f5c076af696afa1c87b77e7ccd3fabfb70f708
2019-12-20T11:55:45.313Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Telling master we're about to commit...
2019-12-20T11:55:45.313Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1020
2019-12-20T11:55:45.313Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 SENT_REMOVE_REVOCATION->SENT_REMOVE_ACK_COMMIT
2019-12-20T11:55:45.360Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1120
2019-12-20T11:55:45.360Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.360Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending commit_sig with 0 htlc sigs
2019-12-20T11:55:45.360Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_out WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.381Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: peer_in WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.381Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Received revoke_and_ack
2019-12-20T11:55:45.382Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: htlc 73: SENT_REMOVE_ACK_COMMIT->RCVD_REMOVE_ACK_REVOCATION
2019-12-20T11:55:45.382Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: rcvd_revoke_and_ack: HTLC LOCAL 73 = RCVD_REMOVE_ACK_REVOCATION/SENT_REMOVE_ACK_REVOCATION FAILED
2019-12-20T11:55:45.382Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: No commits outstanding after recv revoke_and_ack
2019-12-20T11:55:45.382Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: HTLC 73[LOCAL] => RCVD_REMOVE_ACK_REVOCATION
2019-12-20T11:55:45.382Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Sending master 1022
2019-12-20T11:55:45.383Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: got revoke 147: 1 changed
2019-12-20T11:55:45.383Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: HTLC out 73 SENT_REMOVE_ACK_COMMIT->RCVD_REMOVE_ACK_REVOCATION
2019-12-20T11:55:45.383Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: Removing out HTLC 73 state RCVD_REMOVE_ACK_REVOCATION REMOTEFAIL
2019-12-20T11:55:45.383Z INFO 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: htlc 73 failed from 0th node with code 0x400f (WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS)
2019-12-20T11:55:45.383Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-chan#1: failmsg: 400f0000000000002710000000c1
2019-12-20T11:55:45.401Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: ... , awaiting 1122
2019-12-20T11:55:45.402Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Got it!
2019-12-20T11:55:45.406Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: revoke_and_ack LOCAL: remote_per_commit = 02d6aa2309cd50639f6ef67bbdfd62e79ec85008c9c788cb0558b9cbaf160aa7f6, old_remote_per_commit = 035b7e08228d7450ba3081ac841701b21d10a49d30a7954d2eacf45a08526d31f7
2019-12-20T11:55:45.406Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Trying commit
2019-12-20T11:55:45.406Z DEBUG 0330d2b4ec7d7c724984e13b635276b68fb3074ee4a9e9ac148d66d0a0b3279520-channeld-chan#1: Can't send commit: nothing to send

B RPC logs

> 2019/12/20 11:55:44.473469  length=94 from=0 to=93
{"id":0,"method":"invoice","params":[10000,"3ptGLyQbMDXWZ84iksvuKpcTSm96","Hello world",3600]}< 2019/12/20 11:55:44.522415  length=527 from=0 to=526
{"jsonrpc":"2.0","id":0,"result":{"payment_hash":"62a80d536638686b1369af027efcad70805c7514acafa03e75527f670ada81f0","expires_at":1576846544,"bolt11":"lnbcrt100n1pwledkqpp5v25q65mx8p5xkymf4up8al9dwzq9cag54jh6q0n42flkwzk6s8cqdqjfpjkcmr0ypmk7unvvscqp2sp52g8puehgty523sm62my5jtuaneyg0rugzzlxflf8tmxstkram7ws9qy9qsqdnpgwxuzl6ccnvgrk64lds578t6cmnhs4mq924gkuenftwx4x9dqzqpqrlha2z45fygtm5dp8va24p9tzr8fykfkp2kkhjczm8tekfcq7gerpy","warning_capacity":"No channel with a peer that is not a dead end, has sufficient incoming capacity"} }

> 2019/12/20 11:55:44.527922  length=94 from=0 to=93
{"id":0,"method":"invoice","params":[10000,"4FsRefZvJdfXZmxDWTPaiqcgK5FD","Hello world",3600]}< 2019/12/20 11:55:44.574160  length=527 from=0 to=526
{"jsonrpc":"2.0","id":0,"result":{"payment_hash":"8482dc1a8753c748fd50511a9dee0bb6fd765934d520f1ff55c125c47c614ba0","expires_at":1576846544,"bolt11":"lnbcrt100n1pwledkqpp5sjpdcx5820r53l2s2ydfmmstkm7hvkf565s0rl64cyjuglrpfwsqdqjfpjkcmr0ypmk7unvvscqp2sp5gajln08hamrgfdj45mem60z0atf9z4ut7awchpfmvk7qdaqwljcs9qy9qsqjvlev8tznpjdfz8mfe4205cdqsv44fjdrl9c04w89v7tvngd60gjudnlaafr08agc6gw3xajtpyln6nh8ey9ccq7hw9vq8z7ajj6cpsps3fv07","warning_capacity":"No channel with a peer that is not a dead end, has sufficient incoming capacity"} }

> 2019/12/20 11:55:44.579894  length=57 from=0 to=56
{"id":0,"method":"waitanyinvoice","params":[99999999999]}< 2019/12/20 11:55:44.765728  length=735 from=0 to=734
{"jsonrpc":"2.0","id":0,"result":{"label":"3ptGLyQbMDXWZ84iksvuKpcTSm96","bolt11":"lnbcrt100n1pwledkqpp5v25q65mx8p5xkymf4up8al9dwzq9cag54jh6q0n42flkwzk6s8cqdqjfpjkcmr0ypmk7unvvscqp2sp52g8puehgty523sm62my5jtuaneyg0rugzzlxflf8tmxstkram7ws9qy9qsqdnpgwxuzl6ccnvgrk64lds578t6cmnhs4mq924gkuenftwx4x9dqzqpqrlha2z45fygtm5dp8va24p9tzr8fykfkp2kkhjczm8tekfcq7gerpy","payment_hash":"62a80d536638686b1369af027efcad70805c7514acafa03e75527f670ada81f0","msatoshi":10000,"amount_msat":"10000msat","status":"paid","pay_index":70,"msatoshi_received":10000,"amount_received_msat":"10000msat","paid_at":1576842944,"payment_preimage":"dd3a8732be24223bfdb6394ed0d971f8accd256bb86093bfc0054aec40a596b7","description":"Hello world","expires_at":1576846544} }

> 2019/12/20 11:55:44.878937  length=48 from=0 to=47
{"id":0,"method":"waitanyinvoice","params":[70]}

Lightnind logs for B

2019-12-20T11:55:45.222Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Got it!
2019-12-20T11:55:45.222Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: revoke_and_ack REMOTE: remote_per_commit = 0354dd7aa0da64fc636879b4bfb388420dde99b6801a30abf948b7a68f059e2c70, old_remote_per_commit = 02363d585da12c07815a2f45aa8524999b0bd2f7411637091534d5d2d332ebbc37
2019-12-20T11:55:45.222Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Now dealing with deferred WIRE_CHANNEL_FAIL_HTLC
2019-12-20T11:55:45.222Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: FAIL:: HTLC REMOTE 73 = SENT_REMOVE_HTLC/RCVD_REMOVE_HTLC
2019-12-20T11:55:45.222Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: peer_out WIRE_UPDATE_FAIL_HTLC
2019-12-20T11:55:45.223Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Trying commit
2019-12-20T11:55:45.223Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc 73: SENT_REMOVE_HTLC->SENT_REMOVE_COMMIT
2019-12-20T11:55:45.223Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc added REMOTE: local 448081 remote 16776756919
2019-12-20T11:55:45.223Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: -> local 448081 remote 16776766919
2019-12-20T11:55:45.223Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: sending_commit: HTLC REMOTE 73 = SENT_REMOVE_COMMIT/RCVD_REMOVE_COMMIT FAILCODE:16399
2019-12-20T11:55:45.224Z DEBUG hsmd: Client: Received message 19 from client
2019-12-20T11:55:45.224Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Creating commit_sig signature 148 304402207044c75a4122d300998b39a3bd9461137240c2e4d8f6bc67a8fdb0c9c648016902201f730f453150de777c4647e61ddef3e81d9a99d277bf2863ad14f5864be9f55901 for tx 02000000010f9a6dafe92b0997920e9aca36fdc3ed26eec523d1fcce40f36a50300dff4379000000000014811a8001eef2ff000000000022002075c8317de879f87d44395f7f65e067dd84f61f11ebde413614cbf74033c7904f7ea81020 wscript 5221023bbdd30507b0156ef6a4143254f5c076af696afa1c87b77e7ccd3fabfb70f7082103c3df66b4703362620231a0fe6a72854d172e2dfaef438f19ace3daab28c49d4f52ae key 03c3df66b4703362620231a0fe6a72854d172e2dfaef438f19ace3daab28c49d4f
2019-12-20T11:55:45.225Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Telling master we're about to commit...
2019-12-20T11:55:45.225Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Sending master 1020
2019-12-20T11:55:45.225Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: HTLC in 73 SENT_REMOVE_HTLC->SENT_REMOVE_COMMIT
2019-12-20T11:55:45.244Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: ... , awaiting 1120
2019-12-20T11:55:45.245Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Got it!
2019-12-20T11:55:45.245Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Sending commit_sig with 0 htlc sigs
2019-12-20T11:55:45.245Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: peer_out WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: peer_in WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Received revoke_and_ack
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc 73: SENT_REMOVE_COMMIT->RCVD_REMOVE_REVOCATION
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: rcvd_revoke_and_ack: HTLC REMOTE 73 = RCVD_REMOVE_REVOCATION/SENT_REMOVE_REVOCATION FAILCODE:16399
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Commits outstanding after recv revoke_and_ack
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: HTLC 73[REMOTE] => RCVD_REMOVE_REVOCATION
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Sending master 1022
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: got revoke 147: 1 changed
2019-12-20T11:55:45.309Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: HTLC in 73 SENT_REMOVE_COMMIT->RCVD_REMOVE_REVOCATION
2019-12-20T11:55:45.338Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: ... , awaiting 1122
2019-12-20T11:55:45.339Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Got it!
2019-12-20T11:55:45.339Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: revoke_and_ack REMOTE: remote_per_commit = 0375df4790979d5f7de4a975b554a5fd81e44cc833d92358d829a0dd137e464d21, old_remote_per_commit = 0354dd7aa0da64fc636879b4bfb388420dde99b6801a30abf948b7a68f059e2c70
2019-12-20T11:55:45.339Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Trying commit
2019-12-20T11:55:45.339Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Can't send commit: nothing to send
2019-12-20T11:55:45.360Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: peer_in WIRE_COMMITMENT_SIGNED
2019-12-20T11:55:45.361Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Received commit
2019-12-20T11:55:45.361Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc 73: RCVD_REMOVE_REVOCATION->RCVD_REMOVE_ACK_COMMIT
2019-12-20T11:55:45.363Z DEBUG hsmd: Client: Received message 18 from client
2019-12-20T11:55:45.363Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc added LOCAL: local 448081 remote 16776756919
2019-12-20T11:55:45.364Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: -> local 448081 remote 16776766919
2019-12-20T11:55:45.364Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: rcvd_commit: HTLC REMOTE 73 = RCVD_REMOVE_ACK_COMMIT/SENT_REMOVE_ACK_COMMIT FAILCODE:16399
2019-12-20T11:55:45.364Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Feerates are 4000/4000
2019-12-20T11:55:45.364Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: We need 170668sat at feerate 4000 for 0 untrimmed htlcs: we have 16776766919msat/16776766919msat
2019-12-20T11:55:45.365Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Derived key 021d28008ef5ea621fd972e13e82a198a87ade5dba3872ec21b74a6f9665b93dff from basepoint 02d858a432bb9ccb301f1fc35fa81256bed5c6ce9a5f468fe50885842691506729, point 035b7e08228d7450ba3081ac841701b21d10a49d30a7954d2eacf45a08526d31f7
2019-12-20T11:55:45.365Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Received commit_sig with 0 htlc sigs
2019-12-20T11:55:45.365Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Sending revoke_and_ack
2019-12-20T11:55:45.366Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: htlc 73: RCVD_REMOVE_ACK_COMMIT->SENT_REMOVE_ACK_REVOCATION
2019-12-20T11:55:45.366Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: sending_revoke_and_ack: HTLC REMOTE 73 = SENT_REMOVE_ACK_REVOCATION/RCVD_REMOVE_ACK_REVOCATION FAILCODE:16399
2019-12-20T11:55:45.366Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Sending master 1021
2019-12-20T11:55:45.366Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: got commitsig 148: feerate 4000, 0 added, 0 fulfilled, 0 failed, 1 changed
2019-12-20T11:55:45.366Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: HTLC in 73 RCVD_REMOVE_REVOCATION->RCVD_REMOVE_ACK_COMMIT
2019-12-20T11:55:45.367Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: HTLC in 73 RCVD_REMOVE_ACK_COMMIT->SENT_REMOVE_ACK_REVOCATION
2019-12-20T11:55:45.367Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-chan#1: Removing in HTLC 73 state SENT_REMOVE_ACK_REVOCATION WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS
2019-12-20T11:55:45.381Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: ... , awaiting 1121
2019-12-20T11:55:45.381Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: Got it!
2019-12-20T11:55:45.381Z DEBUG 02b1386441a8ee3addc0549806c2a2a865d47eb391029c2168edd1c7497c8ab9b1-channeld-chan#1: peer_out WIRE_REVOKE_AND_ACK
2019-12-20T11:55:45.615Z DEBUG jsonrpc#27: Abandoning command waitanyinvoice
2019-12-20T11:55:46.072Z UNUSUAL lightningd: Unable to estimate CONSERVATIVE/2 fee
2019-12-20T11:55:46.086Z UNUSUAL lightningd: Unable to estimate ECONOMICAL/4 fee

@ZmnSCPxj
Copy link
Contributor

Not paying the exact amount is actually part of the shadow routes feature, which is necessary for privacy, thus not a bug. Suggest changing this issue to be the spurious failure of paying a second invoice.

The lightning logs seem incomplete -- the logs for B do not include the event where it received the update_add_htlc message it seems, and the logs for A do not include the first payment event, at least not entirely. I also checked and the BOLT11 fed into RPC of A are the bolt11 coming from the RPC of B, so that is definitely something strange.

Can you try inserting listinvoices after each invoice command, and after the first waitanyinvoice? Also, are you using the postgresql or the sqlite backend?

@NicolasDorier
Copy link
Collaborator Author

@ZmnSCPxj sqlite, will bring better log.

@NicolasDorier NicolasDorier changed the title [Bug] 0.8.0: Note paying exact amount of the invoice [Bug] 0.8.0: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS Dec 23, 2019
@ZmnSCPxj
Copy link
Contributor

Okay, so not likely to be a strange interaction with postgresql.

@NicolasDorier
Copy link
Collaborator Author

@ZmnSCPxj here are 100% of the logs. I needed to execute the tests several time before reproducing it.

A-rpc.txt
B-rpc.txt
A-B-DebugLogs.txt

@ZmnSCPxj
Copy link
Contributor

Got it:

^[[33mlightningd_dest_1  |^[[0m 2019-12-23T08:26:37.360Z DEBUG 023a9360296c43825921a0eeb56e1b723a3bbcec0d1ea4a4c0115318bcf54aa785-chan#1: Expiry cltv too soon 166 < 157 + 10

in the past, this had its own error, final_expiry_too_soon, and, if i remember correctly, was special-cased by pay in order to allow it to retry.

The most common reason for the final payee rejecting the incoming CLTV is that a block was found randomly between the pay command sending out a payment, to the receiver receiving it.

  1. pay sends out payment.
  2. Miners find a new block.
  3. Receiver receives the payment.

Since pay uses the current blockheight to compute the final CLTV, by the time the receiver receives it it is too close in the future and it fails.

This seems to suggest to me that we need to spend one or two blocks in our maxdelay budget to give some leeway on a block or two getting discovered. Unfortunately the new incorrect_or_unknown_payment_details covers too many cases for us to just retry it.

A more sophisticated solution:

  • Before pay sends out the payment, record the blockheight.
  • When pay receives the incorrect_or_unknown_payment_details, see if the current blockheight is different from the original blockheight we sent at.
    • If so, update it to the now-current blockheight re-send it with the same route (which should "reset" the final CLTV to consider the new blockheight).

@NicolasDorier
Copy link
Collaborator Author

I am a bit surprised. I am not mining any block between the time I create the invoice and the time I pay for it.

@NicolasDorier
Copy link
Collaborator Author

What should I do? Should I release 0.8 as is because this is normally a scenario happening rarely in real situation or wait a patch?

@ZmnSCPxj
Copy link
Contributor

incorrect_or_unknown_payment_details gives the following raw failure format:

  1. type: PERM|15 (incorrect_or_unknown_payment_details)
  2. data:
  • [u64:htlc_msat]
  • [u32:height]

The height parameter is supposed to be how we learn this particular failure. Unfortunately, sendpay doe not propagate the above properly; all that pay gets is a raw_message, a string of hex bytes that are the raw failure, which we have to parse separately to get the height coming from the final recipient. I suppose my above proposal is easier to implement for now.

@ZmnSCPxj
Copy link
Contributor

Lemme make a patch for now. How long does it take for you to verify that it does not happen again?

I am not mining any block between the time I create the invoice and the time I pay for it.

The issue is mining a block between the time you start paying and the time that the receiver gets an HTLC in an irrevocably committed state, which takes a few milliseconds of time and some message turnarounds. Do you not have an automatic miner model in the background of your test env? Because if not this is indeed a strange error to have (though there is still a need to fix this particular error where a block is mined between pay starting and the receiver receiving it), but that is what I can see in your logs.

@NicolasDorier
Copy link
Collaborator Author

@ZmnSCPxj I can verify easily if I have the patch

@NicolasDorier
Copy link
Collaborator Author

I don't have a miner but I noticed that when by test start I have a process to make sure there is a channel between payer and payee. This process may mine a block.

If I repeat my test without this part, I don't seem to reproduce the bug.

@ZmnSCPxj
Copy link
Contributor

Okay, so it is possible that the background process is indeed possibly mining a block between when pay sends out and the receiver gets it. If you can make this reliable, or at least occur more often, then that would be good.

Am making a patch, hopefully it works, unfortunately it has been a while since I have seen the code and there have been many changes, not sure if the code I am hacking is still in the same shape as I saw them before.

@ZmnSCPxj
Copy link
Contributor

ZmnSCPxj commented Dec 23, 2019

I have a branch here: https://github.com/ZmnSCPxj/lightning/tree/blockheight-disagreement

Untested as of now, though it is compiling successfully. Here is travis for my copy: https://travis-ci.org/ZmnSCPxj/lightning/builds/628688151

Unfortunately hardware resources I need will be in use elsewhere, can you @NicolasDorier check the status in a while?

@cdecker cdecker changed the title [Bug] 0.8.0: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS [Bug] 0.8.0: Not paying exact amount of the invoice Dec 23, 2019
@cdecker cdecker changed the title [Bug] 0.8.0: Not paying exact amount of the invoice Not paying exact amount of the invoice Dec 23, 2019
@cdecker
Copy link
Member

cdecker commented Dec 23, 2019

I think I know what is happening here: you set up the network by opening
channels and mining blocks to confirm then. Then you likely stop mining and
start testing the channels. Problem is that some nodes may not have seen all
the blocks yet, causing intermittent errors.

Let's say you sync nodes on blockheight 100, the nodes have some funds and now
start opening channels. Then you generate a couple of blocks, the nodes see
them, activate the channel (sending funding_locked), let's say at height
102, the you generate a couple more blocks (maybe to get the channels the 6
confirmations required for gossip), let's say height 106, but don't wait for
the nodes to sync.

The situation is as follow:

  • Node A thinks we are at height 102, and constructs the route accordingly
    (final CLTV at height 111).
  • Node B is also at height 102, so the payment succeeds since A included a
    sufficient margin.

This is the case where the payment goes through. Then B polls bitcoind
learns about the blocks that were mined, but it hadn't seen yet, leading to
the following situation:

  • Node A things we are at height 102, and still constructs the route with a
    final CLTV of 111.
  • Node B has caught up with bitcoind and is at height 106, but the CLTV
    given by A is now not sufficiently far in the future (only 5 instead of the
    expected 9), thus the payment fails.

This explains why you are not generating blocks while sending payments but
still getting intermittent failures even after a first successful payment.

The trick here is to give all nodes sufficient time to catch up with the
blockchain. Notice that this is specific to regtest and testnet where it
is possible to have a lot of blocks be mined between polls, and specifically
more blocks than the recipient has configured as slack.

@NicolasDorier
Copy link
Collaborator Author

@cdecker it is possible, though I generate normally only 2 blocks and never had issue before.

@NicolasDorier
Copy link
Collaborator Author

@ZmnSCPxj it seems travis not happy.

@ZmnSCPxj
Copy link
Contributor

Regardless, it seems to me a blockheight disagreement with the receiver is still possible on a real non-regtest non-testnet, e.g. mainnet.

We use cltv_final configuration in invoice command:

info->b11->min_final_cltv_expiry = cmd->ld->config.cltv_final;

The check is based on the same cltv_final:

/* BOLT #4:
*
* - if the `cltv_expiry` value is unreasonably near the present:
* - MUST fail the HTLC.
* - MUST return an `incorrect_or_unknown_payment_details` error.
*/
if (get_block_height(ld->topology) + ld->config.cltv_final
> hin->cltv_expiry) {
log_debug(hin->key.channel->log,
"Expiry cltv too soon %u < %u + %u",
hin->cltv_expiry,
get_block_height(ld->topology),
ld->config.cltv_final);
failcode = WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS;
goto fail;
}

For reference the default cltv_final on mainnet is:

.cltv_final = 10,

Thus it is still possible on an edge case on a mainnet network. This becomes unlikely if you have any shadow route at all (which gives additional budget to the final CLTV). But in the test case there is no possible shadow route due to it being just two nodes. Further, even in mainnet you still have a chance that pay will select a shadow route length of 0 regardless, so we still do need to handle this edge case.

Unfortunately for my patch, it does not work since it is not possible to mix synchronous commands to asynchronous commands arising from the plugin, so I have to do a more drastic modification to get the current block height from lightningd. This will take some time, especially due to other precommitments of underlying processing hardware on my side.

@ZmnSCPxj ZmnSCPxj changed the title Not paying exact amount of the invoice Spurious WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS Dec 23, 2019
@ZmnSCPxj
Copy link
Contributor

ZmnSCPxj commented Dec 23, 2019

@cdecker : xref: #638 (comment)

In the past, this case had its own failure code, final_expiry_too_soon. This failure code was 17, i.e. a non-PERM, non-NODE error (the BOLT spec as of lightning/bolts@6729755 claims it is PERM | 17 but this is factually incorrect, as reading that commit diff shows). This meant that pay would retry this case. Since this case is now folded into a PERM | 18 failure code, pay will no longer retry it (it is a permanent error, so pay assumes there is no point in retrying. because permanent).

However this specific sub-case (blockheight disagreement) is in fact a non-permanent error! So we should specially identify and handle this case.

Thus this is a real regression, caused by a BOLT spec change, which folded a non-PERM error into a PERM error. We have to reidentify this non-PERM error by other means, and retry the payment again instead when we detect it. It is fortuitous that @NicolasDorier was able to generate a test case that sometimes tickles it, as we expect this to be a very rare (but real!) bug in handling, and one which did not exist prior to merging final_epiry_too_soon into incorrect_or_unknown_payment_details.

@NicolasDorier
Copy link
Collaborator Author

I will then keep off the update to 0.8 until there is a patch I can test, let me know when you have something I can test.

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