We keep a history of logs internally, so we can drop them to disk on a
crash. This "black box recorder" was some of the first code I wrote
for CLN, but I can't remember the last time we use a crash log to
diagnose a problem.
We attempt to prune it to keep it under 10MB, but the complexity
and cost is rarely worth it: simplify it to use a ringbuffer.
Changelog-Changed: lightningd: logging is now more efficient internally (no more pruning, simple ringbuffer).
```
139993 DEBUG lightningd: fixup_scan: block 786151 with 1203 txs
===> 55388 DEBUG plugin-bcli: Log pruned 1001 entries (mem 10508118 -> 10298662)
33000 DEBUG gossipd: Unreasonable timestamp in 0102000a38ec41f9137a5a560dac6effbde059c12cb727344821cbdd4ef46964a4791a0f67cd997499a6062fc8b4284bf1b47a91541fd0e65129505f02e4d08542b16fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000d9d56000ba40001690fe262010100900000000000000001000003e8000001f30000000000989680
23515 DEBUG hsmd: Client: Received message 14 from client
22269 DEBUG 024b9a1fa8e006f1e3937f65f66c408e6da8e1ca728ea43222a7381df1cc449605-hsmd: Got WIRE_HSMD_ECDH_REQ
14409 DEBUG gossipd: Enqueueing update for announce 0102002f7e4b4deb19947c67292e70cb22f7fac837fa9ee6269393f3c513d0431d52672e7387625856c19299cfd584e1a3f39e0f98df13c99090df9f4d5cca8446776fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000e216b0008050001692e1c390101009000000000000003e800000000000013880000004526945a00
12534 DEBUG gossipd: Previously-rejected announce for 514127x248x1
10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Got it!
10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: ... , awaiting 1120
10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Sending master 1020
```
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
They're only exposed because of the notifications, but they are better
off with explicit parameters anyway.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Basically, `devtools/reduce-includes.sh */*.c`.
Build time from make clean (RUST=0) (includes building external libs):
Before:
real 0m38.944000-40.416000(40.1131+/-0.4)s
user 3m6.790000-17.159000(15.0571+/-2.8)s
sys 0m35.304000-37.336000(36.8942+/-0.57)s
After:
real 0m37.872000-39.974000(39.5466+/-0.59)s
user 3m1.211000-14.968000(12.4556+/-3.9)s
sys 0m35.008000-36.830000(36.4143+/-0.5)s
Build time after touch config.vars (RUST=0):
Before:
real 0m19.831000-21.862000(21.5528+/-0.58)s
user 2m15.361000-30.731000(28.4798+/-4.4)s
sys 0m21.056000-22.339000(22.0346+/-0.35)s
After:
real 0m18.384000-21.307000(20.8605+/-0.92)s
user 2m5.585000-26.843000(23.6017+/-6.7)s
sys 0m19.650000-22.003000(21.4943+/-0.69)s
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This speeds logging slightly, but most of the time is actually
spent in fflush() (which we need).
Result (10 runs, eatmydata):
FAILED tests/test_connection.py::test_bench - assert 24.086638-25.347475(24.6901+/-0.4) == 0
This is an 8% performance improvement (over the entire series), which is not bad.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
The updated API requires typed htables to explicitly state whether they
allow duplicates: for most cases we don't, but we've had issues in the
past.
This is a big patch, but mainly mechanical.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We ratelimited DEBUG messages, but that can be annoying and cause us to miss things.
We demoted the worst offenders in the last release, to TRACE level.
Now, only log trace if it's wanted, and never suppress DEBUG.
Changelog-Changed: Logging: we no longer suppress DEBUG messages from subdaemons.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Fixes: https://github.com/ElementsProject/lightning/issues/7917
Currently make a plugin that do reportings of logs on
a services like graphana is not possible. So this commit
include the possibility to write a plugin that do the report
of this analisys.
Changelog-Added: core: notify plugins when a log line is emitted.
Signed-off-by: Vincenzo Palazzo <vincenzopalazzodev@gmail.com>
We have various functions to convert to a string, rename them all so we can
count on fmt_X being the formatter for struct X, and make them all return
`char *`.
Sometimes they existed but were private, sometimes they had a
different name. Most take a pointer, but simple types pass by copy:
short_channel_id, amount_msat and amount_sat.
The following public functions changed:
1. psbt_to_b64 -> fmt_wally_psbt.
2. pubkey_to_hexstr -> fmt_pubkey.
3. short_channel_id_to_str -> fmt_short_channel_id (scid by copy now!)
4. fmt_signature -> fmt_secp256k1_ecdsa_signature
5. fmt_amount_sat/fmt_amount_msat pass copy not pointer, return non-const char *.
6. node_id_to_hexstr -> fmt_node_id
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
json_add_timeabs only printed in milliseconds and json_add_time outputs a string which is weird
Changelog-Changed: JSON-RPC time fields now have full nanosecond precision (i.e. 9 decimals not 3): `listfowards` `received_time` `resolved_time` `listpays`/`listsendpays` `created_at`.
In this case, the user's default was info, but they specifically asked for debug
from one plugin. Since there were no per-file filters, it set filtering to the
default level, info, and rejected it. Since it's been explicitly filtered in,
we need to pass it at this point.
Reported-by: @wtogami
Fixes: #6503
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Without this, only per-peer daemons were filtered correctly. For generic
daemons, we need to filter with the actual nodeid they use (if any).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: config: `log-level` filters now apply correctly to messages from `connectd`.
Rather than initializating the "print_level" field on first use, we can
do it in logging_options_parsed(), now we have a linked list of them.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
`struct log` becomes `struct logger`, and the member which points to the
`struct log_book` becomes `->log_book` not `->lr`.
Also, we don't need to keep the log_book in struct plugin, since it has
access to ld's log_book.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Previously, if these failed we always exited; once we have dymamic
configs this would be a (tiny) memory leak, so use tmpctx.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
listconfigs is convenient, but it doesn't handle multi-options well: it
outputs an object with duplicate fields in this case (e.g. log-file), nor
is it extensible to show more than raw values.
However, listconfigs doesn't do what other list commands do (use a
sub-object "configs") so we can put the new values under that.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: JSON-RPC: `listconfigs` now has `configs` subobject with more information about each config option.
We have hacky code to show some listconfigs values as literals; instead
explicitly encode the types.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This will be used for listconfig, which knows these should be presented
as arrays, not single values.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This adds:
1. ability to search for an option by name.
2. allowance to set our own bits when registering options.
3. show callbacks which can say "don't show", and variable length.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
The one to stderr is fine, the log one gets corrupted, like so:
```
2022-07-24T07:20:08.6250702Z lightningd-2 2022-07-24T06:49:19.494Z **BROKEN** lightningd: Plugin '????UH??SH??8H?}?H?u?H?U?H?M?H?M?H?E?H?????' returned an invalid response to the db_write hook: (F???U
```
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Rather than a generic "add member", provide two routines: one which
doesn't quote, and one which does.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We have them split over common/param.c, common/json.c,
common/json_helpers.c, common/json_tok.c and common/json_stream.c.
Change that to:
* common/json_parse (all the json_to_xxx routines)
* common/json_parse_simple (simplest the json parsing routines, for cli too)
* common/json_stream (all the json_add_xxx routines)
* common/json_param (all the param and param_xxx routines)
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
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.
That's useful for "tell me everything about this node" debugging.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Fixes: #5348
Changelog-Added: lightningd: `log-level=debug:<partial-nodeid>` supported to get debug-level logs for everything about a peer.
I've wanted this for a while: the ability to log to multiple places
at once.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Changed: lightningd: `log-file` option specified multiple times opens multiple log files.
And turn "" includes into full-path (which makes it easier to put
config.h first, and finds some cases check-includes.sh missed
previously).
config.h sets _GNU_SOURCE which really needs to be done before any
'#includes': we mainly got away with it with glibc, but other platforms
like Alpine may have stricter requirements.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Do proper refcounting on log prefixes; previously we kept them around,
which is fine, but the extra notleak() and backtrace in developer mode
could get quite heavy (I ended up with 1G of backtraces!). This is
mainly due to creating one on every JSONRPC command, and running
clboss.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: lightningd: remove slow memory leak in DEVELOPER builds.
Before:
Ten builds, laptop -j5, no ccache:
```
real 0m36.686000-38.956000(38.608+/-0.65)s
user 2m32.864000-42.253000(40.7545+/-2.7)s
sys 0m16.618000-18.316000(17.8531+/-0.48)s
```
Ten builds, laptop -j5, ccache (warm):
```
real 0m8.212000-8.577000(8.39989+/-0.13)s
user 0m12.731000-13.212000(12.9751+/-0.17)s
sys 0m3.697000-3.902000(3.83722+/-0.064)s
```
After:
Ten builds, laptop -j5, no ccache: 8% faster
```
real 0m33.802000-35.773000(35.468+/-0.54)s
user 2m19.073000-27.754000(26.2542+/-2.3)s
sys 0m15.784000-17.173000(16.7165+/-0.37)s
```
Ten builds, laptop -j5, ccache (warm): 1% faster
```
real 0m8.200000-8.485000(8.30138+/-0.097)s
user 0m12.485000-13.100000(12.7344+/-0.19)s
sys 0m3.702000-3.889000(3.78787+/-0.056)s
```
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Fixes: #4494
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: config: New option `log-timestamps` allow disabling of timestamp prefix in logs.
