1. Create a plugin: ./lightning/tests/plugins/pretend_badlog.py
This plugin subscribes 'warning' notification and log the payload of
'warning';
2. Add a new test: tests/test_plugin.py::test_warning_notification
This test runs the plugin-pretend_badlog.py and check if 'warning'
notification can be normal triggered and subscribed.
- 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;
We currently set TIMEOUT and PYTEST_PAR in our Travis instance directly,
which is a bit unhelpful. In particular, parallelism should be increased
when DEVELOPER isn't set since we spend 60 seconds waiting for gossip in
many cases.
If this doesn't stop timeouts, I'll have to mark more tests SLOW_MACHINE :(
331.24s call tests/test_connection.py::test_opening_tiny_channel
245.45s call tests/test_gossip.py::test_gossip_store_load_complex
215.35s call tests/test_invoices.py::test_invoice_routeboost
194.04s call tests/test_plugin.py::test_htlc_accepted_hook_forward_restart
182.62s call tests/test_plugin.py::test_htlc_accepted_hook_fail
182.02s call tests/test_plugin.py::test_htlc_accepted_hook_resolve
182.01s call tests/test_pay.py::test_pay_limits
159.10s call tests/test_gossip.py::test_gossip_notices_close
153.94s call tests/test_connection.py::test_peerinfo
121.62s call tests/test_invoices.py::test_invoice_preimage
121.46s call tests/test_gossip.py::test_gossipwith
120.76s call tests/test_pay.py::test_setchannelfee_all
120.61s call tests/test_connection.py::test_second_channel
120.42s call tests/test_closing.py::test_closing_id
120.39s call tests/test_gossip.py::test_gossip_addresses
120.39s call tests/test_gossip.py::test_gossip_weirdalias
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We reserve inputs when we're going to send a transaction, but we don't
unreserve them if we crash. This is most graphically demonstrated by
the txprepare case, which makes it easier to trigger.
Instead, we should query bitcoind to see whether the tx made it out or
not, as we would do manually with dev-rescan-outputs.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We fail this at the moment, since we rely on shutdown to do the cleanups
for us.
(Also had to fix the unclean shutdown path: the caller checks the rc unless
mayfail is set, and of course it's not zero since we just SIGTERM'd it).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This allows you to prepare a tx, then release or discard it later.
Shares almost all the code with json_withdraw (which is now technically
superfluous).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We currently allocate utxos off cmd, but the next commit will persist a
wtx beyond the command which created it, breaking that assumption.
In general, a struct member should be owned by the struct itself, and
a tal context should be an explicit arg, not implicit.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We generally want to do as much validation as possible inside
parameter parsing, as that means the 'check' command detects more
erroneous uses. In this case, we can try to interpret the destination
address as soon as we encounter it.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
As a side-effect, we now only add txfilters for addresses we actually
expose, rather than always filtering for both p2sh and native segwit.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
It would always return bech32; fix that, and don't bother printing
it if they use the (new) 'all' parameter.
This API was introduced in 3e67c09d5e,
which means it wasn't in a release so no CHANGELOG entry necessary.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
(Or, if we crashed before we got to write out the channel_update).
It's a corner case, but one reported by @darosior and reproduced
on my test node (both with bad gossip_store due to previous iterations
of this patchset!).
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Triggered by a previous variant of this PR, but a goo1d idea to simply
discard the store in general when we get a duplicate entry.
We crash trying to delete old ones, which means writing to the store.
But they should have already been deleted.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This clarifies things a fair bit: we simply add and remove from the
gossip_store directly.
Before this series: (--disable-developer, -Og)
store_load_msec:20669-20902(20822.2+/-82)
vsz_kb:439704-439712(439706+/-3.2)
listnodes_sec:0.890000-1.000000(0.92+/-0.04)
listchannels_sec:11.960000-13.380000(12.576+/-0.49)
routing_sec:3.070000-5.970000(4.814+/-1.2)
peer_write_all_sec:28.490000-30.580000(29.532+/-0.78)
After: (--disable-developer, -Og)
store_load_msec:19722-20124(19921.6+/-1.4e+02)
vsz_kb:288320
listnodes_sec:0.860000-0.980000(0.912+/-0.056)
listchannels_sec:10.790000-12.260000(11.65+/-0.5)
routing_sec:2.540000-4.950000(4.262+/-0.88)
peer_write_all_sec:17.570000-19.500000(18.048+/-0.73)
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We have a problem: if we get halfway through writing the compacted store
and run out of disk space, we've already changed half the indexes.
This changes it so we do nothing until writing is finished: then we
iterate through and update indexes. It also weans us off broadcast
ordering, which we can now eliminated.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We didn't count some records before, so we could compare the two counters.
This is much simpler, and avoids reliance on bs.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
This means we intercept the peer's gossip_timestamp_filter request
in the per-peer subdaemon itself. The rest of the semantics are fairly
simple however.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We need the timestamp for channel_announcement, but this is simplified
because MCP always follows the channel_announcement by a channel_update.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
(We don't increment the gossip_store version, since there are only a
few commits since the last time we did this).
This lets the reader simply filter messages; this is especially nice since
the channel_announcement timestamp is *derived*, not in the actual message.
This also creates a 'struct gossip_hdr' which makes the code a bit
clearer.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Keeping the uintmap ordering all the broadcastable messages is expensive:
130MB for the million-channels project. But now we delete obsolete entries
from the store, we can have the per-peer daemons simply read that sequentially
and stream the gossip itself.
This is the most primitive version, where all gossip is streamed;
successive patches will bring back proper handling of timestamp filtering
and initial_routing_sync.
We add a gossip_state field to track what's happening with our gossip
streaming: it's initialized in gossipd, and currently always set, but
once we handle timestamps the per-peer daemon may do it when the first
filter is sent.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We used to generate this in the caller, then save it in case we needed
to retry. We're about to change the message we send to lightningd, so
we'll need to regenerate it every time; just hand all the extra args
into peer_connected() and we can generate the `connect_peer_connected`
msg there.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
1diff --git a/connectd/connectd.c b/connectd/connectd.c
index 94fe50b56..459c9ac63 100644
There's a corner case where otherwise a reader could see the header and
not the body of a message. It could handle that in various ways,
but simplest (and most efficient) is to avoid it happening.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
They already send *us* gossip messages, so they have to be distinct anyway.
Why make us both do extra work?
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Encapsulating the peer state was a win for lightningd; not surprisingly,
it's even more of a win for the other daemons, especially as we want
to add a little gossip information.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We ask gossipd for the channel_update for the outgoing channel; any other
messages it sends us get queued for later processing.
But this is overzealous: we can shunt those msgs to the peer while
we're waiting. This fixes a nasty case where we have to handle
WIRE_GOSSIPD_NEW_STORE_FD messages by queuing the fd for later.
This then means that WIRE_GOSSIPD_NEW_STORE_FD can be handled
internally inside handle_gossip_msg(), since it's always dealt with
the same, simplifying all callers.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We use the high bit of the length field: this way we can still check
that the checksums are valid on deleted fields.
Once this is done, serially reading the gossip_store file will result
in a complete, ordered, minimal gossip broadcast. Also, the horrible
corner case where we might try to delete things from the store during
load time is completely gone: we only load non-deleted things.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
We're about to bump version again, and the code to upgrade it was
quite hairy (and buggy!). It's not worthwhile for such a
poorly-tested path: I will just add code to limit how much incoming
gossip we get to avoid flooding when we upgrade, however.
I also use a modern gossip_store version in our test_gossip_store_load
test, instead of relying on the upgrade path.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
They're really gossipd-internal, and we don't want per-peer daemons
to confuse them with normal updates.
I don't bump the gossip_store version; that's coming with another update
anyway.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Since we have more or less given up on the separation between response
callback and deserialization we can also just have the individual parts
returned.
Signed-off-by: Christian Decker <decker.christian@gmail.com>
Suggested-by: Rusty Russell <@rustyrussell>
It disables the error when attempting to do a state transition from
`RCVD_ADD_ACK_REVOCATION` to `RCVD_ADD_ACK_REVOCATION` which was done before
getting to this point.
Signed-off-by: Christian Decker <decker.christian@gmail.com>
