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.
The tal overhead of 5 pointers, the linked list node is 2; and we also
tal'd the string. That's 96 bytes per entry.
Use a simple array instead, though it means more work on deletion
since each log_entry is no longer a tal object.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
1. Don't prune the last 10%.
2. Be more aggressive on pruning IO and DEBUG.
3. Account for skipped entries correctly across multiple prunes.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This allows finegrained logging control of particular subdaemons or
subsystems.
To do this, we defer setting the logging levels for each log object
until after early argument parsing (since e.g. "bitcoind" log object
is created early).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-changed: Options: log-level can now specify different levels for different subsystems.
1. Printed form is always "[<nodeid>-]<prefix>: <string>"
2. "jcon fd %i" becomes "jsonrpc #%i".
3. "jsonrpc" log is only used once, and is removed.
4. "database" log prefix is use for db accesses.
5. "lightningd(%i)" becomes simply "lightningd" without the pid.
6. The "lightningd_" prefix is stripped from subd log prefixes, and pid removed.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-changed: Logging: formatting made uniform: [NODEID-]SUBSYSTEM: MESSAGE
Changelog-removed: `lightning_` prefixes removed from subdaemon names, including in listpeers `owner` field.
We had a separate logbook for each peer, and copy log entries above
the printable log level into the master logbook. This didn't always
work well, since we didn't dump it on crash for example.
Keep a single global logbook instead, and remove this infrastructure.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Simply better encapsulation. We still need to expose log_entry, since the
notification hook uses it though.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
A log can have a default node_id, which can be overridden on a per-entry
basis. This changes the format of logging, so some tests need rework.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
I was wondering why TAGS was missing some functions, and finally
tracked it down: PRINTF_FMT() confuses etags if it's at the start
of a function, and it ignores the rest of the file.
So we put PRINTF_FMT at the end, but that doesn't work for
*definitions*, only *declarations*. So we remove it from definitions
and add gratuitous declarations in the few static places.1
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
"result" should always be an object (so that we can add new fields),
so make that implicit in json_stream_success.
This makes our primitives well-formed: we previously used NULL as our
fieldname when calling the first json_object_start, which is a hack
since we're actually in an object and the fieldname is 'result' (which
was already written by json_object_start).
There were only two cases which didn't do this:
1. dev-memdump returned an array. No API guarantees on this.
2. shutdown returned a string.
I temporarily made shutdown return an empty object, which shouldn't
break anything, but I want to fix that later anyway.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
- Related Changes for `warning` notification
Add a `bool` type parameter in `log_()` and `lov()`, this `bool` flag
indicates if we should call `warning` notifier.
1) The process of copying `log_book` of every peer to the `log_book` of
`ld` is usually included in `log_()` and `lov()`, and it may lead to
repeated `warning` notification. So a `bool`, which explicitly indicates
if the `warning` notification is disabled during this call, is necessary
.
2) The `LOG_INFO` and `LOG_DEBUG` level don't need to call
warning, so set that `bool` paramater as `FALSE` for these log level and
only set it as `TRUE` for `LOG_UNUAUSL`/`LOG_BROKEN`. As for `LOG_IO`,
it use `log_io()` to log, so we needn't think about notifier for it.
This notification bases on `LOG_BROKEN` and `LOG_UNUSUAL` level log.
--Introduction
A notification for topic `warning` is sent every time a new `BROKEN`/
`UNUSUAL` level(in plugins, we use `error`/`warn`) log generated, which
means an unusual/borken thing happens, such as channel failed,
message resolving failed...
```json
{
"warning": {
"level": "warn",
"time": "1559743608.565342521",
"source": "lightningd(17652): 0821f80652fb840239df8dc99205792bba2e559a05469915804c08420230e23c7c chan #7854:",
"log": "Peer permanent failure in CHANNELD_NORMAL: lightning_channeld: sent ERROR bad reestablish dataloss msg"
}
}
```
1. `level` is `warn` or `error`:
`warn` means something seems bad happened and it's under control, but
we'd better check it;
`error` means something extremely bad is out of control, and it may lead
to crash;
2. `time` is the second since epoch;
3. `source`, in fact, is the `prefix` of the log_entry. It means where
the event happened, it may have the following forms:
`<node_id> chan #<db_id_of_channel>:`, `lightningd(<lightningd_pid>):`,
`plugin-<plugin_name>:`, `<daemon_name>(<daemon_pid>):`, `jsonrpc:`,
`jcon fd <error_fd_to_jsonrpc>:`, `plugin-manager`;
4. `log` is the context of the original log entry.
--Note:
1. The main code uses `UNUSUAL`/`BROKEN`, and plugin module uses `warn`
/`error`, considering the consistency with plugin, warning choose `warn`
/`error`. But users who use c-lightning with plugins may want to
`getlog` with specified level when receive warning. It's the duty for
plugin dev to turn `warn`/`error` into `UNUSUAL`/`BROKEN` and present it
to the users, or pass it directly to `getlog`;
2. About time, `json_log()` in `log` module uses the Relative Time, from
the time when `log_book` inited to the time when this event happend.
But I consider the `UNUSUAL`/`BROKEN` event is rare, and it is very
likely to happen after running for a long time, so for users, they will
pay more attention to Absolute Time.
-- Related Change
1. Remove the definitions of `log`, `log_book`, `log_entry` from `log.c`
to `log.h`, then they can be used in warning declaration and definition.
2. Remove `void json_add_time(struct json_stream *result, const char
*fieldname, struct timespec ts)` from `log.c` to `json.c`, and add
related declaration in `json.h`. Now the notification function in
`notification.c` can call it.
2. Add a pointer to `struct lightningd` in `struct log_book`. This may
affect the independence of the `log` module, but storing a pointer to
`ld` is more direct;
A new string field is added to the command structure and is specified at the creation of each native command, and in the JSON created by 'json_add_help_command()'.
Adding a giant IO message simply causes it to be pruned immediately,
so truncate it if it's more than 1/64 the max size.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This will make the logger write 4 newlines to re-attached logfiles.
The newlines wont appear on logfiles that are just created.
Additionally the server prints 50 '-' dashes before printing his
startup message, which also help increase readability on logfile.
This was inspired by the way Bitcoin Core handles logfiles.
Usually, this means they return 'command_param_failed()' if param()
fails, and changing 'command_success(); return;' to 'return
command_success()'.
Occasionally, it's more complex: there's a command_its_complicated()
for the case where we can't exactly determine what the status is,
but it should be considered a last resort.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Handers of a specific form are both designed to be used as callbacks
for param(), and also dispose of the command if something goes wrong.
Make them return the 'struct command_result *' from command_failed(),
or NULL.
Renaming them just makes sense: json_tok_XXX is used for non-command-freeing
parsers too.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
These are only supposed to be used when you want the token contents including
surrounding "". We should use this when reporting errors, but usually
we just want to access the tok members directly.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
json_escaped.[ch], param.[ch] and jsonrpc_errors.h move from lightningd/
to common/. Tests moved too.
We add a new 'common/json_tok.[ch]' for the common parameter parsing
routines which a plugin might want, taking them out of
lightningd/json.c (which now only contains the lightningd-specific
ones).
The rest is mainly fixing up includes.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This (will) avoid the plugin having to walk back from the params object
as it currently does.
No code changes; I removed UNUSED and UNNEEDED labels from the other
parameters though (as *every* json_rpc callback needs to call param()
these days, they're *always* used).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Such an API is required for when we stream it directly. Almost all our
handlers fit this pattern already, or nearly do.
We remove new_json_result() in favor of explicit json_stream_success()
and json_stream_fail(), but still allowing command_fail() if you just
want a simple all-in-one fail wrapper.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
