search

ElementsProject / lightning

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

crash on logging #3205

Closed darosior closed 3 years ago

darosior commented 5 years ago 
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): FATAL SIGNAL 11 (version v0.7.2.1-571-g0985c6e)
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: common/daemon.c:46 (send_backtrace) 0x55f2518ff361
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: common/daemon.c:54 (crashdump) 0x55f2518ff3b1
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x7ff6143c883f
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x7ff614429206
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x7ff6143e29ee
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x7ff61440979f
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/str/str.c:66 (do_vfmt) 0x55f25195b4ac
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/str/str.c:92 (tal_vfmt_) 0x55f25195b592
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: lightningd/log.c:255 (logv) 0x55f2518d493a
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: lightningd/log.c:329 (log_) 0x55f2518d4d6f
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: lightningd/jsonrpc.c:147 (destroy_jcon) 0x55f2518cfc7d
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x55f25195c63e
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x55f25195cb2d
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/tal.c:407 (del_tree) 0x55f25195cb7f
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x55f25195ceb9
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/io/io.c:450 (io_close) 0x55f25194d061
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/io/io.c:401 (do_plan) 0x55f25194ce98
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x55f25194cf01
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x55f25194f0bb
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x55f2518cd5c1
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: lightningd/lightningd.c:859 (main) 0x55f2518d3aef
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x7ff6143b509a
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0x55f2518b9a59
2019-10-24T20:53:56.480Z **BROKEN** lightningd(29457): backtrace: (null):0 ((null)) 0xffffffffffffffff

Running master on 0985c6e219f6d3300853b640b5b29c15fb21358f

darosior commented 5 years ago

For more context it happened when testing the drain plugin, I was harassing a slow machine and the plugin logs quite a lot. I reported it but I think it's a really rare corner case.

cdecker commented 5 years ago

Sounds to me like there is an issue in the order things are freed.

whitslack commented 5 years ago

I just hit this crash. Here's what I did:

  1. I was running listpays with no arguments, but it was taking an unreasonably long time.
  2. I ran a second (concurrent) listpays with a bolt11 argument. It also hanged.
  3. I observed in ps that the pay plugin's process had crashed and was listed as <defunct>.
  4. Linux kernel log contains: 
    [Fri Nov  1 14:07:52 2019] pay[3111]: segfault at 0 ip 0000000000000000 sp 00007fff4657ce48 error 14 in pay[555eca34d000+4c000]
[Fri Nov  1 14:07:52 2019] Code: Bad RIP value.
  5. C-Lightning crashed entirely, with the following backtrace in its log: 
    2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): FATAL SIGNAL 11 (version 0.7.3)
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: common/daemon.c:54 (crashdump) 0x563a2cf184f6
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: /var/tmp/portage/sys-libs/glibc-2.29-r6/work/glibc-2.29/signal/../sysdeps/unix/sysv/linux/x86_64/sigaction.c:0 ((null)) 0x7f647ffddabf
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: ../sysdeps/x86_64/multiarch/../strlen.S:120 ((null)) 0x7f6480044b86
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: /var/tmp/portage/sys-libs/glibc-2.29-r6/work/glibc-2.29/stdio-common/vfprintf-internal.c:1645 (__vfprintf_internal) 0x7f648000f37d
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: /var/tmp/portage/sys-libs/glibc-2.29-r6/work/glibc-2.29/libio/vsnprintf.c:114 (__vsnprintf_internal) 0x7f648002273b
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: /usr/include/bits/stdio2.h:80 (vsnprintf) 0x563a2cf67509
2019-11-01T18:09:16.536Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/str/str.c:66 (do_vfmt) 0x563a2cf67509
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/str/str.c:92 (tal_vfmt_) 0x563a2cf6777f
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: lightningd/log.c:255 (logv) 0x563a2cef883a
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: lightningd/log.c:329 (log_) 0x563a2cef85cf
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: lightningd/jsonrpc.c:147 (destroy_jcon) 0x563a2cef5323
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x563a2cf6827c
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x563a2cf682c8
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/tal.c:407 (del_tree) 0x563a2cf68370
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x563a2cf68dc7
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/tal/tal.c:469 (tal_free) 0x563a2cf68dc7
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x563a2cf59f2b
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x563a2cef351e
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: lightningd/lightningd.c:859 (main) 0x563a2cee39f8
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: ../csu/libc-start.c:308 (__libc_start_main) 0x7f647ffc8eaa
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: (null):0 ((null)) 0x563a2cee43b9
2019-11-01T18:09:16.537Z **BROKEN** lightningd(3109): backtrace: (null):0 ((null)) 0xffffffffffffffff
darosior commented 5 years ago

Hmmm we should not accept multiple calls for the same plugin method. Maybe it was the same for me with drain

darosior commented 3 years ago

Have not erncounetered this for a year. Closing.

jsarenik commented 3 years ago

@darosior it's still open

darosior commented 3 years ago

Lol thanks