Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log filtering by node id. #5349

Merged
merged 9 commits into from
Jul 9, 2022
Merged

Log filtering by node id. #5349

merged 9 commits into from
Jul 9, 2022

Commits on Jul 8, 2022

  1. update-mocks: handle missing deprecated_apis. 

    This expands update-mocks to be able to handle (simple!) missing
symbols which are not functions.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    37f0775 View commit details
    Browse the repository at this point in the history

  2. options: let log-level subsystem filter also cover nodeid. 

    That's useful for "tell me everything about this node" debugging.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Fixes: ElementsProject#5348
Changelog-Added: lightningd: `log-level=debug:<partial-nodeid>` supported to get debug-level logs for everything about a peer.
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    963cbeb View commit details
    Browse the repository at this point in the history

  3. pytest: fix flake in test_option_upfront_shutdown_script 

    Looking at the CI logs, it seems like it took over 5 seconds, so
the unilateral close occurred instead of the expected rejection
of the WIRE_SHUTDOWN reply.  Make it bulletproof.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    acaed0d View commit details
    Browse the repository at this point in the history

  4. pytest: restore prefix to logging. 

    Since we now log directly, we don't prepend the prefix ourselves, making it really
hard to tell *which* lightningd the log applies to!

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    4674266 View commit details
    Browse the repository at this point in the history

  5. options: print empty options properly. 

    Noticed by log-prefix default (""), which causes bad JSON:

```
    Malformed JSON reply '{"jsonrpc":"2.0","id":0,"result":{...
    "log-prefix":,"log-file":"log"} }
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    b73daa1 View commit details
    Browse the repository at this point in the history

  6. lightningd: make log-prefix actually prepend all log messages as expe… 

    …cted.

It actually only sets the prefix for the lightningd core log messages;
the other logs have their own prefix.

Make it a real, process-wide prefix which actually goes in front of the timestamp.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: options: `log-prefix` now correctly prefixes *all* log messages.
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    c520c03 View commit details
    Browse the repository at this point in the history

  7. lightningd: mark subd->conn notleak() properly in transition. 

    Since subd is temporarily unreferenced, and our leak detection goes up
to the highest unreferenced parent, it complains about openingd->conn.

The correct fix is to catch this where we detach the subd:

```
DEBUG:root:{
  "id": 1,
  "result": {
    "leaks": [
      {
        "value": "0x556e0445d8f8",
        "label": "ccan/ccan/io/io.c:91:struct io_conn",
        "backtrace": [
          "ccan/ccan/tal/tal.c:442 (tal_alloc_)",
          "ccan/ccan/io/io.c:91 (io_new_conn_)",
          "lightningd/subd.c:774 (new_subd)",
          "lightningd/subd.c:828 (new_channel_subd_)",
          "lightningd/opening_control.c:872 (peer_start_openingd)",
          "lightningd/peer_control.c:1311 (peer_active)",
          "lightningd/connect_control.c:458 (connectd_msg)",
          "lightningd/subd.c:557 (sd_msg_read)",
          "lightningd/subd.c:357 (read_fds)",
          "ccan/ccan/io/io.c:59 (next_plan)",
          "ccan/ccan/io/io.c:407 (do_plan)",
          "ccan/ccan/io/io.c:417 (io_ready)",
          "ccan/ccan/io/poll.c:453 (io_loop)",
          "lightningd/io_loop_with_timers.c:22 (io_loop_with_timers)",
          "lightningd/lightningd.c:1182 (main)",
          "../csu/libc-start.c:308 (__libc_start_main)"
        ],
        "parents": [
          "lightningd/lightningd.c:107:struct lightningd"
        ]
      }
    ]
  }
}
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    499aa75 View commit details
    Browse the repository at this point in the history

  8. pytest: fix test_gossip_no_backtalk flake. 

    Because we expire cache every flush, in DEVELOPER mode that can happen in
just over a second.  If gossipd takes a while to process the gossip,
this can mean we actually forget we received it from the peer.

Easiest fix is to run this test in non-DEVELOPER mode.

```       # With DEVELOPER, this is long enough for gossip flush.
        time.sleep(2)
>       assert not l3.daemon.is_in_log(r'\[OUT\] 0100')
E       AssertionError: assert not '2022-06-30T06:00:31.031Z 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: [OUT] 0100294834e94aa2407ace65373c84c2a8056d67a6778c22bd43f03a9000d8a01f075c3996ab6c88951bd9805adbfde78292022d7514ffcec37d5e466ef5ebd235c87ffa8a8567904502cd65ae913dbb8014509f442a6e37b00fd59fa3a06811a4965f45df1612d3a32b2566001430cfec4346cc021bd0a1bf6a87417dbc29e0715f16c4f9dc5a01bff07368ba8f54cf9813c3fc8f9f8b8c8005da2a18021f322a9a168af8f82d9deba49ced51bb26a9abc001bbad314a15baccc87c685e9302533c2e86a7b9dfe90bd4cb6be5c2da375be8c4a535a63cacff0544957a34ca865fdb61f9198d19dfd990a0fcbf8de39fa2c0fc54435c16e74df2b49fe3b6e905d599000006226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f0000670000010001022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d590266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c0351802e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5702324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b'
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    701b6f8 View commit details
    Browse the repository at this point in the history

  9. channeld: fix uninitializes scid alias for dual-funding. 

    Caused a crash in CI, reproduced under valgrind by calling
any_channel_by_scid from io_poll_lightningd:

```
==2422524== Conditional jump or move depends on uninitialised value(s)
==2422524==    at 0x12C98D: any_channel_by_scid (channel.c:606)
==2422524==    by 0x14FF75: io_poll_lightningd (lightningd.c:682)
==2422524==    by 0x225FDE: io_loop (poll.c:420)
==2422524==    by 0x14A914: io_loop_with_timers (io_loop_with_timers.c:22)
==2422524==    by 0x150C4E: main (lightningd.c:1193)
==2422524==  Uninitialised value was created by a heap allocation
==2422524==    at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==2422524==    by 0x234F61: allocate (tal.c:250)
==2422524==    by 0x235522: tal_alloc_ (tal.c:428)
==2422524==    by 0x12B500: new_unsaved_channel (channel.c:203)
==2422524==    by 0x13B77A: json_openchannel_init (dual_open_control.c:2610)
==2422524==    by 0x14C78D: command_exec (jsonrpc.c:630)
==2422524==    by 0x14CD9F: rpc_command_hook_final (jsonrpc.c:765)
==2422524==    by 0x181DDA: plugin_hook_call_ (plugin_hook.c:278)
==2422524==    by 0x14D198: plugin_hook_call_rpc_command (jsonrpc.c:853)
==2422524==    by 0x14D6A0: parse_request (jsonrpc.c:957)
==2422524==    by 0x14DAFE: read_json (jsonrpc.c:1054)
==2422524==    by 0x2231C8: next_plan (io.c:59)
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
    @rustyrussell
    rustyrussell committed Jul 8, 2022
    Configuration menu
    Copy the full SHA
    81a7699 View commit details
    Browse the repository at this point in the history