search

ElementsProject / lightning

Core Lightning — Lightning Network implementation focusing on spec compliance and performance
Other
2.84k stars 901 forks source link

Can't pay invoice to Phoenix (ACINQ) custodial wallet with direct channel open to Phoenix node #4376

Closed tukac closed 3 years ago

tukac commented 3 years ago

Issue and Steps to Reproduce

Can't pay invoice to Phoenix wallet (Android, v. 1.4.6-21). I have direct channel open to Phoenix node (02e2670...).

Initiated via plugin RTL 0.10.0. Ends in lightningd crash.

2021-02-07T12:49:34.786Z INFO    plugin-plugin.js: pay initiated...
2021-02-07T12:49:34.786Z INFO    plugin-plugin.js: #%d --> %s
2021-02-07T12:49:34.786Z INFO    plugin-plugin.js: [\"lnbc123450n1psplctlpp5dvlnc8rz49at6vlua9km0zektmst8d6kgy34ntxlwtjxl88vj30qdqqxqyjw5q9qtzqqqqqq9qsqsp53wr5vk6g6sml882ntqn52jnf7p9czvfgl0zf8fncrlhkp50vf6psrzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcllmxd05mmyvgxsqqqqlgqqqqqeqqjqd7s2pee2pgmype3uztmp9twzldqacqh7m78k0n2xx0hvr7saeha9vhnrrvrteans2m0x2qsat33z6ax2fv5dd0mhyps8fwf9dc69z8cptn7838\",null,null,null,null,null,null,null]
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 570805x1483x0/1: enabled false, estimated capacity 25563193msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 570890x839x1/1: enabled false, estimated capacity 809020547msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 601291x1345x1/1: enabled false, estimated capacity 262980491msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633415x1637x1/1: enabled true, estimated capacity 4294967295msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633416x356x0/1: enabled true, estimated capacity 421547340msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633417x1650x1/1: enabled true, estimated capacity 3838900690msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633417x1683x1/1: enabled true, estimated capacity 1917505000msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633434x1732x0/1: enabled true, estimated capacity 417696801msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633434x1733x1/1: enabled false, estimated capacity 417017581msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633438x630x1/1: enabled true, estimated capacity 508833721msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 633441x1243x1/0: enabled true, estimated capacity 284005000msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 651175x980x0/1: enabled true, estimated capacity 45468544msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 656803x1621x1/0: enabled true, estimated capacity 2524383356msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 660621x989x0/1: enabled true, estimated capacity 1761333245msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 666560x1404x0/1: enabled true, estimated capacity 0msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 669301x639x1/1: enabled true, estimated capacity 4294967295msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 669408x1616x0/1: enabled true, estimated capacity 1917505000msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 669455x926x0/1: enabled true, estimated capacity 3897505000msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 669461x495x0/1: enabled true, estimated capacity 4294967295msat
2021-02-07T12:49:34.792Z DEBUG   plugin-pay: cmd 144 partid 0: Added a channel hint for 669530x870x0/1: enabled true, estimated capacity 4294967295msat
2021-02-07T12:49:34.793Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETCHANNELS_REPLY with 0 fds
2021-02-07T12:49:34.793Z DEBUG   plugin-pay: cmd 144 partid 0: After filtering routehints we're left with 1 usable hints
2021-02-07T12:49:34.793Z DEBUG   plugin-pay: cmd 144 partid 0: Asking gossipd whether 020685687d4191fa618f6fbd143ba59d5c65ea40905dee1a2989666be9bd918834 is reachable without routehints.
2021-02-07T12:49:34.793Z DEBUG   gossipd: Trying to find a route from (me) to 020685687d4191fa618f6fbd143ba59d5c65ea40905dee1a2989666be9bd918834 for 1000msat
2021-02-07T12:49:34.793Z INFO    gossipd: find_route: cannot find 020685687d4191fa618f6fbd143ba59d5c65ea40905dee1a2989666be9bd918834
2021-02-07T12:49:34.793Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETROUTE_REPLY with 0 fds
2021-02-07T12:49:34.793Z DEBUG   plugin-pay: cmd 144 partid 0: Using routehint 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f (16737899x15318417x34868) cltv_delta=144
2021-02-07T12:49:34.793Z DEBUG   plugin-pay: cmd 144 partid 0: The destination is not directly reachable excluding attempts without routehints
2021-02-07T12:49:34.793Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETCHANNELS_REPLY with 0 fds
2021-02-07T12:49:34.793Z INFO    plugin-pay: cmd 144 partid 0: Initial limit on max HTLCs: 15, Destination 020685687d4191fa618f6fbd143ba59d5c65ea40905dee1a2989666be9bd918834 has 1 channels, assuming 15 HTLCs per channel
2021-02-07T12:49:34.793Z INFO    plugin-pay: cmd 144 partid 1: Split into 2 sub-payments due to initial size (12345000msat > 10000000msat): new partid 2, new partid 3
pay: Could not load gossmap gossip_store: Invalid argument
2021-02-07T12:49:34.794Z INFO    plugin-pay: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.794Z **BROKEN** plugin-pay: Plugin marked as important, shutting down lightningd!
2021-02-07T12:49:34.794Z DEBUG   connectd: Shutting down
2021-02-07T12:49:34.794Z DEBUG   0395033b252c6f40e3756984162d68174e2bd8060a129c0d3462a9370471c6d28f-channeld-chan#954: Status closed, but not exited. Killing
2021-02-07T12:49:34.795Z DEBUG   031678745383bd273b4c3dbefc8ffbf4847d85c2f62d3407c0c980430b3257c403-channeld-chan#956: Status closed, but not exited. Killing
2021-02-07T12:49:34.795Z DEBUG   02004c625d622245606a1ea2c1c69cfb4516b703b47945a3647713c05fe4aaeb1c-channeld-chan#957: Status closed, but not exited. Killing
2021-02-07T12:49:34.796Z DEBUG   0227230b7b685f1742b944bfc5d79ddc8c5a90b68499775ee10895f87307d8d22e-channeld-chan#958: Status closed, but not exited. Killing
2021-02-07T12:49:34.796Z DEBUG   0390b5d4492dc2f5318e5233ab2cebf6d48914881a33ef6a9c6bcdbb433ad986d0-channeld-chan#968: Status closed, but not exited. Killing
2021-02-07T12:49:34.796Z DEBUG   0353325e099c2b657ca5c4bb975a20b0c3de1d2391dabe73f40484aac255628d22-channeld-chan#974: Status closed, but not exited. Killing
2021-02-07T12:49:34.797Z DEBUG   03d2a44997a0fb6deee0a31c389d9d6bcb6f929f1dd0ba67201d195f2b3c76087c-channeld-chan#975: Status closed, but not exited. Killing
2021-02-07T12:49:34.797Z DEBUG   02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b-channeld-chan#1136: Status closed, but not exited. Killing
2021-02-07T12:49:34.797Z DEBUG   03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6-channeld-chan#1215: Status closed, but not exited. Killing
2021-02-07T12:49:34.797Z DEBUG   021607cfce19a4c5e7e6e738663dfafbbbac262e4ff76c2c9b30dbeefc35c00643-channeld-chan#1298: Status closed, but not exited. Killing
2021-02-07T12:49:34.798Z DEBUG   02ed62b754205169637d8506ef4a3160019c69a0e80e5fac925800073841790f80-channeld-chan#1359: Status closed, but not exited. Killing
2021-02-07T12:49:34.798Z DEBUG   02e2670a2c2661a9eea13b7cfdcdd7f552f591b9ee60e5678b7abe77b7f9516f96-channeld-chan#1387: Status closed, but not exited. Killing
2021-02-07T12:49:34.799Z DEBUG   0242a4ae0c5bef18048fbecf995094b74bfb0f7391418d71ed394784373f41e4f3-channeld-chan#1391: Status closed, but not exited. Killing
2021-02-07T12:49:34.799Z DEBUG   03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-channeld-chan#1394: Status closed, but not exited. Killing
2021-02-07T12:49:34.799Z DEBUG   02a04446caa81636d60d63b066f2814cbd3a6b5c258e3172cbdded7a16e2cfff4c-channeld-chan#1396: Status closed, but not exited. Killing
2021-02-07T12:49:34.800Z DEBUG   02816caed43171d3c9854e3b0ab2cf0c42be086ff1bd4005acc2a5f7db70d83774-channeld-chan#1403: Status closed, but not exited. Killing
2021-02-07T12:49:34.800Z DEBUG   gossipd: Shutting down
2021-02-07T12:49:34.801Z DEBUG   hsmd: Shutting down
2021-02-07T12:49:34.801Z INFO    plugin-autoclean: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.801Z INFO    plugin-bcli: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.801Z INFO    plugin-keysend: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.801Z INFO    plugin-txprepare: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.802Z INFO    plugin-spenderp: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.802Z INFO    plugin-plugin.js: Killing plugin: Plugin exited before completing handshake.
2021-02-07T12:49:34.879Z DEBUG   plugin-manager: started(11102) /home/*/lightning/lightningd/../plugins/autoclean

getinfo output

{ "id": "*", "alias": "*", "color": "*", "num_peers": 20, "num_pending_channels": 0, "num_active_channels": 20, "num_inactive_channels": 0, "address": [ { "type": "ipv4", "address": "*", "port": 9737 } ], "binding": [ { "type": "ipv4", "address": "0.0.0.0", "port": 9737 } ], "version": "v0.9.3-54-g3a0b1c5", "blockheight": 669536, "network": "bitcoin", "msatoshi_fees_collected": 391915, "fees_collected_msat": "391915msat", "lightning-dir": "/home/*/.lightning/bitcoin" }

edit: lightning-cli pay bolt11 return: lightning-cli: reading response: socket closed

tukac commented 3 years ago

Pay plugin seems to create problem with direct channel payments. I have tried routing through my node to same final node and it works fine. But it fails on direct channel payment! Several different nodes/channels all behave same. I can't pay directly.

Example:

cli/lightning-cli pay lnbc5040u1pszqzsmpp5hd0v654e9227x6p5plv3ugfdgqqvzkncj4uh4hwq3g5dlg5lew5qdp58pjxzepnxumxvc34xasnxe3exuunjvtxxvmn2wpcxqurwctzv56qcqzpgxqzjcsp583j27x5zg7ftn8txcjqafe0qm383fd277ga8chdlv9km2rlk9j5s9qy9qsqzmlh8qry4x50rg7n9w4y924cy3c8nzdu8cc35ppxzc3l9em79my5ttnnym4paq86z2j3hk2uysgxfxzdv8m66tjemn9ajqpdcnt486qp0h32v5
lightning-cli: reading response: socket closed
2021-02-07T15:41:44.138Z DEBUG   0395033b252c6f40e3756984162d68174e2bd8060a129c0d3462a9370471c6d28f-gossipd: Bad gossip order: WIRE_CHANNEL_UPDATE before announcement 656961x2289x0/1
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 570805x1483x0/1: enabled false, estimated capacity 25563193msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 570890x839x1/1: enabled false, estimated capacity 809020547msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 601291x1345x1/1: enabled false, estimated capacity 262980491msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633415x1637x1/1: enabled true, estimated capacity 4294967295msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633416x356x0/1: enabled true, estimated capacity 421535340msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633417x1650x1/1: enabled true, estimated capacity 3838888690msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633417x1683x1/1: enabled true, estimated capacity 1917493000msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633434x1732x0/1: enabled true, estimated capacity 417684801msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633434x1733x1/1: enabled false, estimated capacity 417017581msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633438x630x1/1: enabled true, estimated capacity 1013827771msat
2021-02-07T15:41:45.344Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 633441x1243x1/0: enabled true, estimated capacity 283993000msat
2021-02-07T15:41:45.348Z DEBUG   plugin-pay: Log pruned 19338 entries (mem 10486971 -> 3076772)
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 651175x980x0/1: enabled true, estimated capacity 45468544msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 656803x1621x1/0: enabled true, estimated capacity 2019371356msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 660621x989x0/1: enabled true, estimated capacity 1761333245msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 666560x1404x0/1: enabled true, estimated capacity 49000487msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 669301x639x1/1: enabled true, estimated capacity 4294967295msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 669408x1616x0/1: enabled true, estimated capacity 1917493000msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 669455x926x0/1: enabled true, estimated capacity 3897493000msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 669461x495x0/1: enabled true, estimated capacity 4294967295msat
2021-02-07T15:41:45.350Z DEBUG   plugin-pay: cmd 82 partid 0: Added a channel hint for 669530x870x0/1: enabled true, estimated capacity 4294967295msat
2021-02-07T15:41:45.351Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETCHANNELS_REPLY with 0 fds
2021-02-07T15:41:45.358Z DEBUG   plugin-pay: cmd 82 partid 0: Adding shadow_route hop over channel 617924x2288x1: adding 6040msat in fees and 144 CLTV delta
2021-02-07T15:41:45.359Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETCHANNELS_REPLY with 0 fds
2021-02-07T15:41:45.359Z DEBUG   plugin-pay: cmd 82 partid 0: After filtering routehints we're left with 0 usable hints
2021-02-07T15:41:45.359Z DEBUG   plugin-pay: cmd 82 partid 0: Asking gossipd whether 033d8656219478701227199cbd6f670335c8d408a92ae88b962c49d4dc0e83e025 is reachable without routehints.
2021-02-07T15:41:45.378Z DEBUG   gossipd: Trying to find a route from (me) to 033d8656219478701227199cbd6f670335c8d408a92ae88b962c49d4dc0e83e025 for 1000msat
2021-02-07T15:41:45.378Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETROUTE_REPLY with 0 fds
2021-02-07T15:41:45.379Z DEBUG   plugin-pay: cmd 82 partid 0: Not using a routehint
2021-02-07T15:41:45.379Z DEBUG   plugin-pay: cmd 82 partid 0: The destination is directly reachable including attempts without routehints
2021-02-07T15:41:45.380Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GETCHANNELS_REPLY with 0 fds
2021-02-07T15:41:45.384Z INFO    plugin-pay: cmd 82 partid 0: Initial limit on max HTLCs: 3465, Destination 033d8656219478701227199cbd6f670335c8d408a92ae88b962c49d4dc0e83e025 has 231 channels, assuming 15 HTLCs per channel
2021-02-07T15:41:45.384Z INFO    plugin-pay: cmd 82 partid 1: Split into 4 sub-payments due to initial size (504000000msat > 160000000msat): new partid 2, new partid 3, new partid 4, new partid 5
pay: Could not load gossmap gossip_store: Invalid argument
2021-02-07T15:41:45.385Z INFO    plugin-pay: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.385Z **BROKEN** plugin-pay: Plugin marked as important, shutting down lightningd!
2021-02-07T15:41:45.385Z DEBUG   connectd: Shutting down
2021-02-07T15:41:45.385Z DEBUG   0395033b252c6f40e3756984162d68174e2bd8060a129c0d3462a9370471c6d28f-channeld-chan#954: Status closed, but not exited. Killing
2021-02-07T15:41:45.385Z DEBUG   031678745383bd273b4c3dbefc8ffbf4847d85c2f62d3407c0c980430b3257c403-channeld-chan#956: Status closed, but not exited. Killing
2021-02-07T15:41:45.386Z DEBUG   02004c625d622245606a1ea2c1c69cfb4516b703b47945a3647713c05fe4aaeb1c-channeld-chan#957: Status closed, but not exited. Killing
2021-02-07T15:41:45.386Z DEBUG   0227230b7b685f1742b944bfc5d79ddc8c5a90b68499775ee10895f87307d8d22e-channeld-chan#958: Status closed, but not exited. Killing
2021-02-07T15:41:45.386Z DEBUG   0390b5d4492dc2f5318e5233ab2cebf6d48914881a33ef6a9c6bcdbb433ad986d0-channeld-chan#968: Status closed, but not exited. Killing
2021-02-07T15:41:45.387Z DEBUG   0353325e099c2b657ca5c4bb975a20b0c3de1d2391dabe73f40484aac255628d22-channeld-chan#974: Status closed, but not exited. Killing
2021-02-07T15:41:45.387Z DEBUG   03d2a44997a0fb6deee0a31c389d9d6bcb6f929f1dd0ba67201d195f2b3c76087c-channeld-chan#975: Status closed, but not exited. Killing
2021-02-07T15:41:45.387Z DEBUG   02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b-channeld-chan#1136: Status closed, but not exited. Killing
2021-02-07T15:41:45.388Z DEBUG   03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6-channeld-chan#1215: Status closed, but not exited. Killing
2021-02-07T15:41:45.388Z DEBUG   021607cfce19a4c5e7e6e738663dfafbbbac262e4ff76c2c9b30dbeefc35c00643-channeld-chan#1298: Status closed, but not exited. Killing
2021-02-07T15:41:45.388Z DEBUG   02ed62b754205169637d8506ef4a3160019c69a0e80e5fac925800073841790f80-channeld-chan#1359: Status closed, but not exited. Killing
2021-02-07T15:41:45.388Z DEBUG   02e2670a2c2661a9eea13b7cfdcdd7f552f591b9ee60e5678b7abe77b7f9516f96-channeld-chan#1387: Status closed, but not exited. Killing
2021-02-07T15:41:45.389Z DEBUG   0242a4ae0c5bef18048fbecf995094b74bfb0f7391418d71ed394784373f41e4f3-channeld-chan#1391: Status closed, but not exited. Killing
2021-02-07T15:41:45.389Z DEBUG   03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-channeld-chan#1394: Status closed, but not exited. Killing
2021-02-07T15:41:45.389Z DEBUG   02a04446caa81636d60d63b066f2814cbd3a6b5c258e3172cbdded7a16e2cfff4c-channeld-chan#1396: Status closed, but not exited. Killing
2021-02-07T15:41:45.390Z DEBUG   02816caed43171d3c9854e3b0ab2cf0c42be086ff1bd4005acc2a5f7db70d83774-channeld-chan#1403: Status closed, but not exited. Killing
2021-02-07T15:41:45.390Z DEBUG   gossipd: Shutting down
2021-02-07T15:41:45.391Z DEBUG   hsmd: Shutting down
2021-02-07T15:41:45.391Z INFO    plugin-autoclean: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.391Z INFO    plugin-bcli: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.391Z INFO    plugin-keysend: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.391Z INFO    plugin-txprepare: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.391Z INFO    plugin-spenderp: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.391Z INFO    plugin-plugin.js: Killing plugin: Plugin exited before completing handshake.
2021-02-07T15:41:45.394Z INFO    plugin-rebalance.py: Killing plugin: Plugin exited before completing handshake.
cdecker commented 3 years ago

Assigned @rustyrussell as gossmap is his baby :-)

tukac commented 3 years ago

During every initiation:

2021-02-07T16:48:50.342Z BROKEN gossipd: gossip_store_compact: bad version 2021-02-07T16:48:50.342Z UNUSUAL gossipd: Gossip store version 0 not 9: removing 2021-02-07T16:48:50.342Z DEBUG gossipd: total store load time: 0 msec 2021-02-07T16:48:50.342Z DEBUG gossipd: gossip_store: Read 0/0/0/0 cannounce/cupdate/nannounce/cdelete from store (0 deleted) in 1 bytes 2021-02-07T16:48:50.342Z DEBUG gossipd: seeker: state = STARTING_UP New seeker

cdecker commented 3 years ago

That's very interesting indeed, so it throws away the gossip_store at each startup? Does it do that even without pay attempts between restarts?

tukac commented 3 years ago

Yes, every startup and without any activity in between.

cdecker commented 3 years ago

Can you attach the gossip_store file, before starting the node? That'd allow us to try and find the corruption, and hopefully also solve the crash (which I think might be related).

tukac commented 3 years ago

Sure. edit: file removed by me, will re-post if needed

whitslack commented 3 years ago

so it throws away the gossip_store at each startup?

My node has been doing this forever. I assumed the gossip just wasn't meant to carry over between runs.

rustyrussell commented 3 years ago

Is this MacOS too? @whitslack has this issue there (see https://github.com/ElementsProject/lightning/issues/4288).

whitslack commented 3 years ago

@rustyrussell: I don't run any Bitcoin stuff on my Mac, only on Linux.

rustyrussell commented 3 years ago

@whitslack Oh wow, you're seeing this on Linux? Damn, OK. Can you test https://github.com/ElementsProject/lightning/pull/4440 by any chance?

whitslack commented 3 years ago

@rustyrussell: I'm running my C-Lightning data dir on F2FS atop dmcrypt atop mdraid (RAID1) atop 2× SATA SSDs.

Can you test #4440 by any chance?

I'm not keen to introduce an assertion that I'm reasonably certain will fail and take down my whole C-Lightning node at some odd hour of the night. I could edit your patch locally to log a BROKEN instead, though that wouldn't give us a stack trace. Is there any convenient way in the C-Lightning code base to log a stack trace without aborting execution?

whitslack commented 3 years ago

@rustyrussell: I believe I have found the problem. In the gossip_store_new function in gossipd/gossip_store.c, in the case of version mismatch, the gossip store file is truncated to zero length via ftruncate, and then a new version byte is written via write, but the file position is not reset to zero after the truncation, so the new version byte is actually written at offset 1, meaning that the kernel zero-fills the byte at offset 0 when extending the file length from 0 to 2.

Here's a very sloppy, minimal demonstrator:

#include <fcntl.h>
#include <unistd.h>

int main() {
    unsigned char byte;
    int fd = open("test.dat", O_RDWR);
    read(fd, &byte, sizeof byte);
    ftruncate(fd, 0);
    byte = 1;
    write(fd, &byte, sizeof byte);
    return 0;
}
$ rm -f test.dat
$ truncate --size=1 test.dat
$ hexdump -C test.dat
00000000  00                                                |.|
00000001
$ gcc -o test test.c
$ ./test
$ hexdump -C test.dat
00000000  00 01                                             |..|
00000002

You should add a call to lseek(gs->fd, 0, SEEK_SET) before writing the new version byte to the truncated file.

rustyrussell commented 3 years ago

You should add a call to lseek(gs->fd, 0, SEEK_SET) before writing the new version byte to the truncated file.

Any chance you can send me your shipping address?

whitslack commented 3 years ago

Any chance you can send me your shipping address?

@rustyrussell: 😆 If you're trying to say thanks, the words are enough. I should be thanking you for all the work you do toward bootstrapping the Lightning future. Thanks!

rustyrussell commented 3 years ago

Any chance you can send me your shipping address?

@rustyrussell: laughing If you're trying to say thanks, the words are enough. I should be thanking you for all the work you do toward bootstrapping the Lightning future. Thanks!

But I got marketing to open the Emergency Supply of Jade wallets to ship one to you! Without an address I'm just gonna have to pretend you're me neighbor and have it shipped to me... :thinking:

whitslack commented 3 years ago

Without an address I'm just gonna have to pretend you're me neighbor and have it shipped to me...

Go for it. I prefer diceware for my cold storage. Can't beat the trustworthiness of an ultra low-tech entropy source.