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.

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

Make plugins more talkative (log notifications plugin->lightningd) #2154

Merged
merged 2 commits into from Dec 13, 2018

Conversation

Projects
None yet
4 participants
@cdecker
Copy link
Member

cdecker commented Dec 8, 2018

Adds notification handling to lightningd so that we can start injecting logs into the main daemon output. Should make it easier to follow what happens in the plugins.

@cdecker cdecker added the plugin label Dec 8, 2018

@cdecker cdecker self-assigned this Dec 8, 2018

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from 6f5c119 to 335fde9 Dec 8, 2018

@cdecker cdecker requested a review from rustyrussell Dec 8, 2018

@renepickhardt
Copy link
Collaborator

renepickhardt left a comment

Was about to make general comments but due to line 290 and the fact that the logfiles does not see which plugin send the message I request a change. Will be helpful to grep for a plugin name

greeting = request['params']['options']['greeting']
plugin_log("Plugin helloworld.py initialized with greeting \"{}\"".format(greeting), "debug")

This comment has been minimized.

@renepickhardt

renepickhardt Dec 8, 2018

Collaborator

This allows the developer to depict a message via calling b plugin_log. This is very helpful and nice! For exceptions I will be able to catch them and push the error string to this method.

However if my third party libs use std.out I will still run into problems.

This comment has been minimized.

@conscott

conscott Dec 8, 2018

Collaborator

Agreed. For now, as a hacky workaround you can use context_lib to capture stdout during specific function calls to third party modules that use stdout.

Example:

import io
from contextlib import redirect_stdout
import third_party_module

# Redirect stdout to f only for duration of function call
f = io.StringIO()
with redirect_stdout(f):
    third_party_module.function_that_prints_to_std_out()

# Contains everything written to stdout
out = f.getvalue()

Although this doesn't seem like a viable solution long term.

This comment has been minimized.

@renepickhardt

renepickhardt Dec 8, 2018

Collaborator

well that might not be to bad. for exaple in flask I could do app.run in this case.
also I could regularly do plugin_log(f.getvalue()) to send the message to c-lightning) but yes I guess this is really just temporary.

This comment has been minimized.

@cdecker

cdecker Dec 9, 2018

Member

Working on a plugin class that monkey-patches stdout and stderr so we can start using these streams like we normally do, but prints result in log notifications instead.

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Note that stderr now goes to parent stderr: this is nice for simple debugging. Like when my plugins backtrace :)

This comment has been minimized.

@cdecker

cdecker Dec 10, 2018

Member

My small python Plugin library grabs stderr as well and turns things into log notifications. This has the advantage that it provides more context than just spurious writes to stderr. See the plugin-6 PR that I'll open in a few minutes.

}

/* We expect the request->cb to copy if needed */
request->response = plugin->buffer;

This comment has been minimized.

@renepickhardt

renepickhardt Dec 8, 2018

Collaborator

So the request message body is replied back in the response? This will not make the plugin display the responds or an I mistaking? I saw in line 290 you push the message to the clightning logfiles as I had expected it

This comment has been minimized.

@cdecker

cdecker Dec 9, 2018

Member

This was a refactor and not part of the notifications handling. This is when we receive a response to a call that we sent ourselves (and not a notification which doesn't have an ID). See the split in lines 389 - 432. The request struct contains all data that is related to this request-response cycle and will be used to dispatch the response to the caller (which might be internal or an external JSON-RPC call that we forwarded).

This is just moved into its own function from here:

/* We expect the request->cb to copy if needed */
request->response = plugin->buffer;
request->errortok = errortok;
request->resulttok = resulttok;
request->toks = toks;
request->cb(request, request->arg);

}

/* We strip the \" otherwise they'd be printed here. */
log_(plugin->log, level, "log: %.*s", json_tok_len(msgtok) - 2,

This comment has been minimized.

@renepickhardt

renepickhardt Dec 8, 2018

Collaborator

Would be great if there would not only be the message but also the name of the plugin written down to the log. Not sure what's the best way to achieve this.

I guess having the plugin send their name in the log message. However it would be great to fix the name and map it against registered plugins.

This comment has been minimized.

@cdecker

cdecker Dec 9, 2018

Member

plugin->log is a logger that is prefixed with the plugin's basename, so the complete line here reads

2018-12-09T12:42:59.072Z plugin-helloworld.py log: Plugin helloworld.py initialized with greeting \"World\"

Which I think is what you want.

This comment has been minimized.

@renepickhardt

renepickhardt Dec 9, 2018

Collaborator

When I Previously used plugin->log I did not see the plugin name. (maybe I was just blind) But maybe I set up my plugin incorrectly or did some other mistake. I will try to see if I can reconstruct this behavior. But it's great that it is already implemented!

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Was changed recently, in commit 111d6df

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Do we need 'log:' here? I guess we use this for other things, but confusion seems unlikely AFAICT.

This comment has been minimized.

@cdecker

cdecker Dec 10, 2018

Member

I was hoping to differentiate the entries lightningd writes about the plugin from the ones that the plugins inject themselves. But you're probably right, it's unlikely that a plugin would inject a log-line pretending to kill itself :-)

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from 335fde9 to 85b64cd Dec 9, 2018

@cdecker cdecker changed the title Make plugins more talkative (log notifications plugin -> lightningd Make plugins more talkative (log notifications plugin->lightningd) Dec 9, 2018

@rustyrussell
Copy link
Contributor

rustyrussell left a comment

Method of sending 'method=log' with no 'id' field seems fine; it's extensible to other notifications in future. Rebasing this should simplify it; most of those fields seem to have vanished.

Show resolved Hide resolved lightningd/plugin.c
/* We strip the \" otherwise they'd be printed here. */
log_(plugin->log, level, "log: %.*s", json_tok_len(msgtok) - 2,
json_tok_contents(plugin->buffer, msgtok) + 1);
}

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Ok, these accessors are specifically for the case where we want to add "". For cases like this, just use fields themselves, it.msgtok->end - msgtok->start, buffer + msgtok->start

This comment has been minimized.

@cdecker

cdecker Dec 10, 2018

Member

It just felt a bit safer to use the accessor, but you're right, if we use the accessor and then work around its quirks, it's probably best to just use the raw pointer access.

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

We should probably rename those helpers, they're damn misleading...

json_tok_fulltoken() and json_tok_fulltoken_len()?

}

/* We strip the \" otherwise they'd be printed here. */
log_(plugin->log, level, "log: %.*s", json_tok_len(msgtok) - 2,

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Do we need 'log:' here? I guess we use this for other things, but confusion seems unlikely AFAICT.

level = LOG_UNUSUAL;
else if (json_tok_streq(plugin->buffer, leveltok, "error"))
level = LOG_BROKEN;
else {

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Special-casing LOG_IO would be nice I think. We should also use that for comms with the plugin itself...

This comment has been minimized.

@cdecker

cdecker Dec 10, 2018

Member

Notice that this is just mapping incoming log notifications from the plugin. It does not handle LOG_IO which would be produced internally by lightningd and be passed directly to the logger that way.

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

But the plugin may want to do IO logging for other unrelated things...

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from 85b64cd to b0ca4fe Dec 10, 2018

@cdecker

This comment has been minimized.

Copy link
Member

cdecker commented Dec 10, 2018

Rebased on top of recent changes to the plugins.

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from b0ca4fe to 0b96382 Dec 10, 2018

@cdecker

This comment has been minimized.

Copy link
Member

cdecker commented Dec 10, 2018

Ready for round 2 :-)

Ping @renepickhardt and @rustyrussell

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from c76a324 to d6afd1f Dec 10, 2018

@rustyrussell
Copy link
Contributor

rustyrussell left a comment

OK, I think the parsing for 'method' etc should be inside the "oh, it has no id, I have to handle it myself" branch/function. It's both simpler and more optimal.

plugin_kill(plugin, "Received a JSON-RPC response for non-existent request");
return false;
if (idtok && (errortok || resulttok)) {
/* When a rpc call is made, the Server MUST reply with

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Remove all these checks, IMHO. It's none of our business what they send back and forth, as long as it's an object with matching id. That's minimal.

In fact, this patch seems entirely extraneous; the next patch should just touch the "!idtok" case....

This comment has been minimized.

@cdecker

cdecker Dec 11, 2018

Member

That might be true for passthrough RPC calls, but not all are passthrough, so we better make sure that they adhere to the JSON-RPC standard. We have getmanifest and init which are handled by us internally, and we can check either here, or in the callbacks, but this looked like a good place to do so.

Also we'll add more of the internally handled RPC calls, once we start moving the bitcoin connection to a plugin (bitcoind, neutrino, ...) so I'd like to keep them here.

This comment has been minimized.

@rustyrussell

rustyrussell Dec 12, 2018

Contributor

It's not just a layering violation, it's also slow for large objects; at least with 'id' it's likely to be at the front. Especially once you add looking for "params" and "method" in the next patch.

We really should be doing this only once we've identified that it's something we need to deal with. That's both minimal and clearer.

@@ -314,7 +363,7 @@ static struct io_plan *plugin_read_json(struct io_conn *conn UNUSED,
/* Read and process all messages from the connection */
do {
success = plugin_read_json_one(plugin);
} while (success);
} while (success && ! plugin->stop);

if (plugin->stop)
return io_close(plugin->stdout_conn);

This comment has been minimized.

@rustyrussell

rustyrussell Dec 10, 2018

Contributor

Good (unrelated) catch; but just check plugin->stop inside the loop, rather than doing so twice?

cdecker added some commits Dec 6, 2018

plugin: Split the parsing from the request handling in the plugin
This is a preparatory step for the next commit which adds notification
parsing as well.

Signed-off-by: Christian Decker <decker.christian@gmail.com>
plugin: Handle log notifications from plugins
Logs are parsed and injected into the main daemon's logs.

Signed-off-by: Christian Decker <decker.christian@gmail.com>

@cdecker cdecker force-pushed the cdecker:plugin-5 branch from 99e40e2 to 909ac60 Dec 12, 2018

@cdecker

This comment has been minimized.

Copy link
Member

cdecker commented Dec 12, 2018

Ok, rebased, squashed and removed the duplicate checking of method, params, errors and results from plugin_json_read_one, as suggested by @rustyrussell 😉

Addressed

@rustyrussell

This comment has been minimized.

Copy link
Contributor

rustyrussell commented Dec 13, 2018

Ack 909ac60

The JSON-RPC.org quotes are a bit verbose, but it's nice to have them somewhere people might read!

@rustyrussell rustyrussell merged commit a304db9 into ElementsProject:master Dec 13, 2018

2 checks passed

ackbot PR ack'd by rustyrussell
continuous-integration/travis-ci/pr The Travis CI build passed
Details
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment