Spurious WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS

[NicolasDorier]

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]

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]

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]

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]

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.

[NicolasDorier]

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

[NicolasDorier]

@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]

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]

@ZmnSCPxj sqlite, will bring better log.

[ZmnSCPxj]

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

[NicolasDorier]

@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]

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]

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.