ElementsProject / lightning

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

`listinvoices` and `listsendpays` crash the node #3082

Closed fiatjaf closed 5 years ago

fiatjaf commented 5 years ago

Issue and Steps to Reproduce

I always update my node to master. Today I realized I was on 0.7.0-something, so I updated with git pull and recompiled. For some reason I was still on 0.7.0 after that, but now listpayments didn't work, so I guess I was really updated (I don't know when that was removed). However running it crashed the daemon:

fiatjaf@lntxbot ~/lightning ((76860683…)) [2]> ~/lightning/cli/lightning-cli listsendpays                                                                                                                                                      
lightning-cli: reading response: socket closed       
Sep 22 02:35:01 lntxbot lightningd[1285]: lightningd: FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)                                                                                                                                           
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f886be send_backtrace                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]:         common/daemon.c:40                                                                                                                                                                            
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f88751 crashdump                                                                                                                                                                              
Sep 22 02:35:01 lntxbot lightningd[1285]:         common/daemon.c:53                                                                                                                                                                            
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x7f8327eecf1f ???                                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x7f8327f69578 ???                                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc4b70 memcpy                                                                                                                                                                                 
Sep 22 02:35:01 lntxbot lightningd[1285]:         /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc4b70 tal_dup_                                                                                                                                                                               
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/tal/tal.c:796                                                                                                                                                                       
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc2e81 tal_strdup_                                                                                                                                                                            
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/tal/str/str.c:18                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999faa680 wallet_stmt2payment                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         wallet/wallet.c:2167                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fae711 wallet_payment_list                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         wallet/wallet.c:2446                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f770d2 json_listsendpays                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/pay.c:989                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6cd6f parse_request                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/jsonrpc.c:650                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6d039 read_json                                                                                                                                                                              
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/jsonrpc.c:748                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fb9dee next_plan                                                                                                                                                                              
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:59                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fba2dd do_plan                                                                                                                                                                                
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:407                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fba30a io_ready                                                                                                                                                                               
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:417                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fbbae2 io_loop                                                                                                                                                                                
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/poll.c:445                                                                                                                                                                       
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6a96c io_loop_with_timers                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/io_loop_with_timers.c:24                                                                                                                                                           
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6e796 main                                                                                                                                                                                   
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/lightningd.c:835                                                                                                                                                                   
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x7f8327ecfb96 ???
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x7f8327f69578 ???                                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc4b70 memcpy                                                                                                                                                                                 
Sep 22 02:35:01 lntxbot lightningd[1285]:         /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc4b70 tal_dup_                                                                                                                                                                               
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/tal/tal.c:796                                                                                                                                                                       
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fc2e81 tal_strdup_                                                                                                                                                                            
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/tal/str/str.c:18                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999faa680 wallet_stmt2payment                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         wallet/wallet.c:2167                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fae711 wallet_payment_list                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         wallet/wallet.c:2446                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f770d2 json_listsendpays                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/pay.c:989                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6cd6f parse_request                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/jsonrpc.c:650                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6d039 read_json                                                                                                                                                                              
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/jsonrpc.c:748                                                                                                                                                                      
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fb9dee next_plan                                                                                                                                                                              
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:59                                                                                                                                                                          
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fba2dd do_plan                                                                                                                                                                                
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:407                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fba30a io_ready                                                                                                                                                                               
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/io.c:417                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999fbbae2 io_loop                                                                                                                                                                                
Sep 22 02:35:01 lntxbot lightningd[1285]:         ccan/ccan/io/poll.c:445                                                                                                                                                                       
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6a96c io_loop_with_timers                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/io_loop_with_timers.c:24                                                                                                                                                           
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f6e796 main                                                                                                                                                                                   
Sep 22 02:35:01 lntxbot lightningd[1285]:         lightningd/lightningd.c:835                                                                                                                                                                   
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x7f8327ecfb96 ???                                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0x562999f5d919 ???                                                                                                                                                                                    
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0                                                                                                                                                                                         
Sep 22 02:35:01 lntxbot lightningd[1285]: 0xffffffffffffffff ???
Sep 22 02:35:01 lntxbot lightningd[1285]:         ???:0
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: common/daemon.c:45 (send_backtrace) 0x562999f88706
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: common/daemon.c:53 (crashdump) 0x562999f88751
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: (null):0 ((null)) 0x7f8327eecf1f
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: (null):0 ((null)) 0x7f8327f69578
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34 (memcpy) 0x562999fc4b70
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/tal/tal.c:796 (tal_dup_) 0x562999fc4b70
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/tal/str/str.c:18 (tal_strdup_) 0x562999fc2e81
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: wallet/wallet.c:2167 (wallet_stmt2payment) 0x562999faa680
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: wallet/wallet.c:2446 (wallet_payment_list) 0x562999fae711
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: lightningd/pay.c:989 (json_listsendpays) 0x562999f770d2
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: lightningd/jsonrpc.c:650 (parse_request) 0x562999f6cd6f
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: lightningd/jsonrpc.c:748 (read_json) 0x562999f6d039
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x562999fb9dee
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x562999fba2dd
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x562999fba30a
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x562999fbbae2
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x562999f6a96c
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: lightningd/lightningd.c:835 (main) 0x562999f6e796
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: (null):0 ((null)) 0x7f8327ecfb96
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: (null):0 ((null)) 0x562999f5d919
Sep 22 02:35:01 lntxbot lightningd[1285]: 2019-09-22T02:35:01.725Z **BROKEN** lightningd(1285): backtrace: (null):0 ((null)) 0xffffffffffffffff
Sep 22 02:35:02 lntxbot lightningd[1285]: Log dumped in crash.log.20190922023501

Then I checked out the release 0.7.1 as I thought master was probably broken. But lightningd failed to start there, complaining about a move from database v107 to v104. So I went back to master again and now for some reason it was 0.7.2-something. Maybe this story is worthless and just a picture of my own confusion, but nonetheless it's told here.

Now listsendpays and listinvoices both give me errors (and the daemon crashes):

fiatjaf@lntxbot ~/lightning ((76860683…))> ~/lightning/cli/lightning-cli listinvoices                                                                                                                                                          
lightning-cli: reading response: socket closed
Sep 22 02:32:04 lntxbot lightningd[1008]: lightningd: FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)                                                                                                                                           
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6ed6be send_backtrace                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]:         common/daemon.c:40                                                                                                                                                                            
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6ed751 crashdump                                                                                                                                                                              
Sep 22 02:32:04 lntxbot lightningd[1008]:         common/daemon.c:53                                                                                                                                                                            
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x7f4305a01f1f ???                                                                                                                                                                                    
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0                                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x7f4305a7e578 ???                                                                                                                                                                                    
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0                                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c729b70 memcpy                                                                                                                                                                                 
Sep 22 02:32:04 lntxbot lightningd[1008]:         /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34                                                                                                                                      
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c729b70 tal_dup_                                                                                                                                                                               
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/tal/tal.c:796  
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c727e81 tal_strdup_
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/tal/str/str.c:18
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c70d53c wallet_stmt2invoice_details
Sep 22 02:32:04 lntxbot lightningd[1008]:         wallet/invoices.c:117
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c70de13 invoices_iterator_deref
Sep 22 02:32:04 lntxbot lightningd[1008]:         wallet/invoices.c:465
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c712a6b wallet_invoice_iterator_deref
Sep 22 02:32:04 lntxbot lightningd[1008]:         wallet/wallet.c:1925
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6cf6fc json_add_invoices
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/invoice.c:819
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6cf7af json_listinvoices
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/invoice.c:840
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6d1d6f parse_request
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/jsonrpc.c:650
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6d2039 read_json
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/jsonrpc.c:748
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c71edee next_plan
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/io/io.c:59
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c71f2dd do_plan
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/io/io.c:407
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c71f30a io_ready
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/io/io.c:417
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c720ae2 io_loop
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/io/poll.c:445
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6cf96c io_loop_with_timers
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/io_loop_with_timers.c:24
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6d3796 main
Sep 22 02:32:04 lntxbot lightningd[1008]:         lightningd/lightningd.c:835
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x7f43059e4b96 ???
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6c2919 ???
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0
Sep 22 02:32:04 lntxbot lightningd[1008]: 0xffffffffffffffff ???
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: common/daemon.c:45 (send_backtrace) 0x56181c6ed706
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: common/daemon.c:53 (crashdump) 0x56181c6ed751
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: (null):0 ((null)) 0x7f4305a01f1f
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: (null):0 ((null)) 0x7f4305a7e578
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34 (memcpy) 0x56181c729b70
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/tal/tal.c:796 (tal_dup_) 0x56181c729b70
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/tal/str/str.c:18 (tal_strdup_) 0x56181c727e81
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.569Z **BROKEN** lightningd(1008): backtrace: wallet/invoices.c:117 (wallet_stmt2invoice_details) 0x56181c70d53c
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.570Z **BROKEN** lightningd(1008): backtrace: wallet/invoices.c:465 (invoices_iterator_deref) 0x56181c70de13
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.570Z **BROKEN** lightningd(1008): backtrace: wallet/wallet.c:1925 (wallet_invoice_iterator_deref) 0x56181c712a6b
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.570Z **BROKEN** lightningd(1008): backtrace: lightningd/invoice.c:819 (json_add_invoices) 0x56181c6cf6fc
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: lightningd/invoice.c:840 (json_listinvoices) 0x56181c6cf7af
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: lightningd/jsonrpc.c:650 (parse_request) 0x56181c6d1d6f
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: lightningd/jsonrpc.c:748 (read_json) 0x56181c6d2039
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x56181c71edee
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x56181c71f2dd
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x56181c71f30a
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x56181c720ae2
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x56181c6cf96c
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: lightningd/lightningd.c:835 (main) 0x56181c6d3796
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: (null):0 ((null)) 0x7f43059e4b96
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: (null):0 ((null)) 0x56181c6c2919
Sep 22 02:32:04 lntxbot lightningd[1008]: 2019-09-22T02:32:04.572Z **BROKEN** lightningd(1008): backtrace: (null):0 ((null)) 0xffffffffffffffff
Sep 22 02:32:05 lntxbot lightningd[1008]: Log dumped in crash.log.20190922023204

Some other basic commands work well. However the daemon it's crashing and restarting by itself every minute or so for no reason:

Sep 22 02:25:42 lntxbot lightningd[804]: 2019/09/22 02:25:42 plugin-jqmethods Initialized jqmethods plugin.                                                                                                                                     
Sep 22 02:30:01 lntxbot lightningd[804]: lightningd: FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)                                                                                                                                            
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a0c6be send_backtrace                                                                                                                                                                          
Sep 22 02:30:01 lntxbot lightningd[804]:         common/daemon.c:40                                                                                                                                                                             
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a0c751 crashdump                                                                                                                                                                               
Sep 22 02:30:01 lntxbot lightningd[804]:         common/daemon.c:53    
Sep 22 02:30:01 lntxbot lightningd[804]: 0x7f1654d30f1f ???                                                                                                                                                                            Sep 22 02:30:01 lntxbot lightningd[804]:         ???:0                                                                                                                                                                                          
Sep 22 02:30:01 lntxbot lightningd[804]: 0x7f1654dad578 ???                                                                                                                                                                                     
Sep 22 02:30:01 lntxbot lightningd[804]:         ???:0                                                                                                                                                                                          
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a48b70 memcpy                                                                                                                                                                                  
Sep 22 02:30:01 lntxbot lightningd[804]:         /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34                                                                                                                                       
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a48b70 tal_dup_                                                                                                                                                                                
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/tal/tal.c:796                                                                                                                                                                        
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a46e81 tal_strdup_                                                                                                                                                                             
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/tal/str/str.c:18                                                                                                                                                                     
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a2e680 wallet_stmt2payment                                                                                                                                                                     
Sep 22 02:30:01 lntxbot lightningd[804]:         wallet/wallet.c:2167                                                                                                                                                                           
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a32711 wallet_payment_list                                                                                                                                                                     
Sep 22 02:30:01 lntxbot lightningd[804]:         wallet/wallet.c:2446                                                                                                                                                                           
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039fb0d2 json_listsendpays                                                                                                                                                                       
Sep 22 02:30:01 lntxbot lightningd[804]:         lightningd/pay.c:989                                                                                                                                                                           
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039f0d6f parse_request
Sep 22 02:30:01 lntxbot lightningd[804]:         lightningd/jsonrpc.c:650
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039f1039 read_json
Sep 22 02:30:01 lntxbot lightningd[804]:         lightningd/jsonrpc.c:748
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a3ddee next_plan
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/io/io.c:59
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a3e2dd do_plan
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/io/io.c:407
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a3e30a io_ready
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/io/io.c:417
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b03a3fae2 io_loop
Sep 22 02:30:01 lntxbot lightningd[804]:         ccan/ccan/io/poll.c:445
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039ee96c io_loop_with_timers
Sep 22 02:30:01 lntxbot lightningd[804]:         lightningd/io_loop_with_timers.c:24
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039f2796 main
Sep 22 02:30:01 lntxbot lightningd[804]:         lightningd/lightningd.c:835
Sep 22 02:30:01 lntxbot lightningd[804]: 0x7f1654d13b96 ???
Sep 22 02:30:01 lntxbot lightningd[804]:         ???:0
Sep 22 02:30:01 lntxbot lightningd[804]: 0x561b039e1919 ???
Sep 22 02:30:01 lntxbot lightningd[804]:         ???:0
Sep 22 02:30:01 lntxbot lightningd[804]: 0xffffffffffffffff ???
Sep 22 02:30:01 lntxbot lightningd[804]:         ???:0
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): FATAL SIGNAL 11 (version v0.7.2.1-255-g7686068)
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: common/daemon.c:45 (send_backtrace) 0x561b03a0c706
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: common/daemon.c:53 (crashdump) 0x561b03a0c751
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: (null):0 ((null)) 0x7f1654d30f1f
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: (null):0 ((null)) 0x7f1654dad578
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34 (memcpy) 0x561b03a48b70
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: ccan/ccan/tal/tal.c:796 (tal_dup_) 0x561b03a48b70
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: ccan/ccan/tal/str/str.c:18 (tal_strdup_) 0x561b03a46e81
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: wallet/wallet.c:2167 (wallet_stmt2payment) 0x561b03a2e680
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: wallet/wallet.c:2446 (wallet_payment_list) 0x561b03a32711
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.488Z **BROKEN** lightningd(804): backtrace: lightningd/pay.c:989 (json_listsendpays) 0x561b039fb0d2
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: lightningd/jsonrpc.c:650 (parse_request) 0x561b039f0d6f
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: lightningd/jsonrpc.c:748 (read_json) 0x561b039f1039
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x561b03a3ddee
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x561b03a3e2dd
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x561b03a3e30a
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x561b03a3fae2
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x561b039ee96c
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: lightningd/lightningd.c:835 (main) 0x561b039f2796
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: (null):0 ((null)) 0x7f1654d13b96
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: (null):0 ((null)) 0x561b039e1919
Sep 22 02:30:01 lntxbot lightningd[804]: 2019-09-22T02:30:01.489Z **BROKEN** lightningd(804): backtrace: (null):0 ((null)) 0xffffffffffffffff
Sep 22 02:30:01 lntxbot lightningd[804]: Log dumped in crash.log.20190922023001

Is it crashing due to lack of memory? It cannot be. This is a very small machine, but it has only lightningd and lntxbot running, and both use few memory and there were no big changes, but maybe, who knows, i don't understand these crash dumps.

free -mh                                                                                                                                                                                         
              total        used        free      shared  buff/cache   available                                                                                                                                                                 
Mem:           985M        356M         85M         47M        543M        446M                                                                                                                                                                 
Swap:          511M        232M        279M      

getinfo output

{
  "id": "02c16cca44562b590dd279c942200bdccfd4f990c3a69fad620c10ef2f8228eaff",
  "alias": "telegram.me/lntxbot",
  "color": "296683",
  "num_peers": 47,
  "num_pending_channels": 1,
  "num_active_channels": 46,
  "num_inactive_channels": 0,
  "address": [],
  "binding": [
    {
      "type": "ipv4",
      "address": "0.0.0.0",
      "port": 9736
    },
    {
      "type": "ipv6",
      "address": "::",
      "port": 9735
    }
  ],
  "version": "v0.7.2.1-255-g7686068",
  "blockheight": 596012,
  "network": "bitcoin",
  "msatoshi_fees_collected": 118995,
  "fees_collected_msat": "118995msat"
}
fiatjaf commented 5 years ago

Apparently the continuous crashes are related to calls to listsendpays too. But I don't get it. lntxbot doesn't call listsendpays ever.

fiatjaf commented 5 years ago

I've deleted the pay plugin from the plugins folder as it was the only thing I could find that could be calling listsendpays, the the node stopped crashing continuously. I don't understand why is that, as lntxbot doesn't call pay ever either, but anyway, now the problem is narrowed down to the node crashing on listinvoices and listsendpays as shown in the stack dumps above. Most other commands work fine, including invoice (and receiving payments) and decodepay, getroute, sendpay etc.

fiatjaf commented 5 years ago

Dear reader, please ignore all of the above and focus on the following part, as it is the error common to all errors:

Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6ed6be send_backtrace                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]:         common/daemon.c:40                                                                                                                                                                            
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c6ed751 crashdump                                                                                                                                                                              
Sep 22 02:32:04 lntxbot lightningd[1008]:         common/daemon.c:53                                                                                                                                                                            
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x7f4305a01f1f ???                                                                                                                                                                                    
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0                                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x7f4305a7e578 ???                                                                                                                                                                                    
Sep 22 02:32:04 lntxbot lightningd[1008]:         ???:0                                                                                                                                                                                         
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c729b70 memcpy                                                                                                                                                                                 
Sep 22 02:32:04 lntxbot lightningd[1008]:         /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34                                                                                                                                      
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c729b70 tal_dup_                                                                                                                                                                               
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/tal/tal.c:796  
Sep 22 02:32:04 lntxbot lightningd[1008]: 0x56181c727e81 tal_strdup_
Sep 22 02:32:04 lntxbot lightningd[1008]:         ccan/ccan/tal/str/str.c:18
ZmnSCPxj commented 5 years ago

tal_strdup_ is very reliable code, but naively reads whatever pointer is passed in. The error is in its callers, wallet_stmt2invoice_details and wallet_stmt2payment. This makes me suspect the recent changes regarding database abstraction, simply because that is the newest part of the codebase. In particular we used to use the term stmt to mean a SQL statement currently being queried, and the stmt2whatever functions convert from the SQL statement results to whatever type.

rustyrussell commented 5 years ago

@ZmnSCPxj nailed it.

Looks like a four-char typo in wallet/db.c:

diff --git a/wallet/db.c b/wallet/db.c
index 2e741ab1f..7e6cee8a2 100644
--- a/wallet/db.c
+++ b/wallet/db.c
@@ -567,7 +567,7 @@ const void *db_column_blob(struct db_stmt *stmt, int col)

 const unsigned char *db_column_text(struct db_stmt *stmt, int col)
 {
-   return stmt->db->config->column_blob_fn(stmt, col);
+   return stmt->db->config->column_text_fn(stmt, col);
 }

 size_t db_count_changes(struct db_stmt *stmt)

Does changing blob to text there fix it?