WIP lightningd/plugin: add sync'd init for static plugins at startup and handle init errors

lightningd/plugin.c

@@ -31,6 +31,7 @@
  * willing to wait. Plugins shouldn't do any initialization in the
  * `getmanifest` call anyway, that's what `init `is for. */
 #define PLUGIN_MANIFEST_TIMEOUT 60
+#define PLUGIN_SYNC_INIT_TIMEOUT 10
 
 struct plugins *plugins_new(const tal_t *ctx, struct log_book *log_book,
 			    struct lightningd *ld)
@@ -801,6 +802,12 @@ static void plugin_manifest_timeout(struct plugin *plugin)
 	fatal("Can't recover from plugin failure, terminating.");
 }
 
+static void plugin_sync_init_timeout(struct plugin *plugin)
+{
+	log_broken(plugin->log, "The static plugin failed to respond to \"init\" in time, terminating.");
+	fatal("Can't recover from plugin failure, terminating.");
+}
+
 /**
  * Callback for the plugin_manifest request.
  */
@@ -830,6 +837,8 @@ static void plugin_manifest_cb(const char *buffer,
 	dynamictok = json_get_member(buffer, resulttok, "dynamic");
 	if (dynamictok && json_to_bool(buffer, dynamictok, &dynamic_plugin))
 		plugin->dynamic = dynamic_plugin;
+	else
+		plugin->dynamic = false;
 
 	if (!plugin_opts_add(plugin, buffer, resulttok) ||
 	    !plugin_rpcmethods_add(plugin, buffer, resulttok) ||
@@ -1017,15 +1026,52 @@ void plugins_init(struct plugins *plugins, const char *dev_plugin_debug)
 
 	if (plugins->pending_manifests > 0)
 		io_loop_with_timers(plugins->ld);
-	// There won't be io_loop anymore to wait for plugins
-	plugins->startup = false;
 }
 
 static void plugin_config_cb(const char *buffer,
 			     const jsmntok_t *toks,
 			     const jsmntok_t *idtok,
 			     struct plugin *plugin)
 {
+	const jsmntok_t *errortok;
+
+	/* An init-error from a static plugin during lightningd startup will crash
+	 * lightningd. An init-error outside startup will kill the (static or
+	 * dynamic) plugin only. */
+	errortok = json_get_member(buffer, toks, "error");
+	if (errortok && errortok->type != JSMN_STRING) {
+		if (!plugin->dynamic && plugin->plugins->startup)
+			fatal("init-error of static plugin at ld startup '%s':"
+				  " \"error\" result is not an object: %.*s", plugin->cmd,
+						    toks[0].end - toks[0].start,
+						    buffer + toks[0].start);
+
+		/* Any plugin that doesn't want to be started via RPC at run-time, can
+		 * return an init-error, so it is killed cleanly. */
+		plugin_kill(plugin,
+			    "\"error\" result is not an object: %.*s",
+			    toks[0].end - toks[0].start,
+			    buffer + toks[0].start);
+	}
+
+	/* TODO: add error code + message
+	 * TODO: check json `id` */
+	if (!plugin->dynamic  && plugin->plugins->startup) {
+		if (errortok)
+			fatal("init-error of static plugin at ld startup '%s'", plugin->cmd);
+		plugin->plugins->pending_sync_configs--;
+		tal_free(plugin->timeout_timer);
+
+		/* When all static plugins are initialized, break the io_loop in
+		 * plugins_config, which also unsets plugins->startup */
+		if (plugin->plugins->pending_sync_configs == 0)
+			io_break(plugin->plugins);
+	}
+
+	if (errortok) {
+		plugin_kill(plugin, "error initializing plugin");
+		return;
+	}
 	plugin->plugin_state = CONFIGURED;
 }
 
@@ -1061,17 +1107,36 @@ static void plugin_config(struct plugin *plugin)
 
 	jsonrpc_request_end(req);
 	plugin_request_send(plugin, req);
+
+	/* Wait for static plugin's `init` response during startup, so they can do
+	 * their thing or abort at an early stage */
+	if (!plugin->dynamic && plugin->plugins->startup) {
+		plugin->plugins->pending_sync_configs++;
+		/* FIXME assert plugin->timeout_timer == NULL here ? */
+		plugin->timeout_timer = new_reltimer(plugin->plugins->ld->timers,
+			      plugin, time_from_sec(PLUGIN_SYNC_INIT_TIMEOUT),
+			      plugin_sync_init_timeout, plugin);
+	}
 }
 
 void plugins_config(struct plugins *plugins)
 {
+	plugins->pending_sync_configs = 0;
+
 	struct plugin *p;
 	list_for_each(&plugins->plugins, p, list) {
 		if (p->plugin_state == UNCONFIGURED) {
 			p->plugin_state = CONFIGURING;
 			plugin_config(p);
 		}
 	}
+
+	/* Wait here for any static plugins to initialize, which implies startup.*/
+	if (plugins->pending_sync_configs > 0)
+		io_loop_with_timers(plugins->ld);
+
+	/* Close the startup window (if any) */
+	plugins->startup = false;
 }
 
 void json_add_opt_plugins(struct json_stream *response,

lightningd/plugin.h

@@ -29,7 +29,14 @@ struct plugin {
 
 	enum plugin_state plugin_state;
 
-	/* If this plugin can be restarted without restarting lightningd */
+	/* dynamic=True: plugin can be stopped/started via RPC at runtime and it
+	 * expects lightningd to be up-and-running during init.
+	 *
+	 * dynamic=False: when lightningd starts up, it will wait for the plugin's
+	 * init-result and will shutdown when that is an error. A static plugin
+	 * cannot be stopped but *can* be started via RPC. It should check the
+	 * `startup` field in its init call, which may return an error to kill the
+	 * plugin. Static plugins shouldn't make RPC calls during init. */
 	bool dynamic;
 	bool signal_startup;
 
@@ -50,7 +57,8 @@ struct plugin {
 	const char **methods;
 
 	/* Timer to add a timeout to some plugin RPC calls. Used to
-	 * guarantee that `getmanifest` doesn't block indefinitely. */
+	 * guarantee that `getmanifest` and some `init` (for non-dynamic plugins)
+	 * doesn't block indefinitely */
 	const struct oneshot *timeout_timer;
 
 	/* An array of subscribed topics */
@@ -65,6 +73,7 @@ struct plugin {
 struct plugins {
 	struct list_head plugins;
 	size_t pending_manifests;
+	size_t pending_sync_configs;
 	bool startup;
 
 	/* Currently pending requests by their request ID */

tests/plugins/static.py

@@ -12,14 +12,14 @@
 
 @plugin.init()
 def init(configuration, options, plugin):
-    plugin.log("Static plugin initialized.")
+    plugin.log("init startup={}".format(configuration['startup']))
 
 
-@plugin.method('hello')
+@plugin.method('world')
 def reject(plugin):
     """Mark a given node_id as reject for future connections.
     """
-    return "Hello, you cannot stop me without stopping lightningd"
+    return "World, you cannot stop me without stopping lightningd"
 
 
 plugin.run()

tests/plugins/static_2.py

@@ -0,0 +1,29 @@
+#!/usr/bin/env python3
+"""Simple plugin to test the dynamic behavior.
+
+A plugin started with dynamic to False cannot be controlled after lightningd
+has been started.
+"""
+
+from lightning import Plugin
+
+plugin = Plugin(dynamic=False)
+
+
+@plugin.init()
+def init(configuration, options, plugin):
+    plugin.log("init startup={}".format(configuration['startup']))
+
+    # we don't like to be started at run-time
+    if not configuration['startup']:
+        raise Exception
+
+
+@plugin.method('static_2')
+def reject(plugin):
+    """Mark a given node_id as reject for future connections.
+    """
+    return "World, you cannot stop me without stopping lightningd"
+
+
+plugin.run()

tests/test_plugin.py

@@ -108,51 +108,54 @@ def test_plugin_slowinit(node_factory):
 
 def test_plugin_command(node_factory):
     """Tests the 'plugin' RPC command"""
-    n = node_factory.get_node()
+    opts = {"plugin": os.path.join(os.getcwd(), "tests/plugins/static.py")}
+    l1 = node_factory.get_node(options=opts)
+
+    # Test that we cannot stop a plugin with 'dynamic' set to False in
+    # getmanifest
+    with pytest.raises(RpcError, match=r"plugin cannot be managed when lightningd is up"):
+        l1.rpc.plugin_stop(plugin="static.py")
+
+    # A static plugin started via RPC that returns an init-error is killed
+    l1.rpc.plugin_start(plugin=os.path.join(os.getcwd(), "tests/plugins/static_2.py"))
+    l1.daemon.wait_for_log(r"plugin-static_2.py Killing plugin: error initializing plugin")
 
     # Make sure that the 'hello' command from the helloworld.py plugin
     # is not available.
-    cmd = [hlp for hlp in n.rpc.help()["help"] if "hello" in hlp["command"]]
+    cmd = [hlp for hlp in l1.rpc.help()["help"] if "hello" in hlp["command"]]
     assert(len(cmd) == 0)
 
     # Add the 'contrib/plugins' test dir
     time.sleep(2)
-    n.rpc.plugin_startdir(directory=os.path.join(os.getcwd(), "contrib/plugins"))
-    n.daemon.wait_for_log(r"Plugin helloworld.py initialized")
+    l1.rpc.plugin_startdir(directory=os.path.join(os.getcwd(), "contrib/plugins"))
+    l1.daemon.wait_for_log(r"Plugin helloworld.py initialized")
     # Make sure that the 'hello' command from the helloworld.py plugin
     # is now available.
-    cmd = [hlp for hlp in n.rpc.help()["help"] if "hello" in hlp["command"]]
+    cmd = [hlp for hlp in l1.rpc.help()["help"] if "hello" in hlp["command"]]
     assert(len(cmd) == 1)
 
     # Make sure 'rescan' and 'list' controls dont crash
-    n.rpc.plugin_rescan()
-    n.rpc.plugin_list()
+    l1.rpc.plugin_rescan()
+    l1.rpc.plugin_list()
     time.sleep(1)
 
     # Make sure the plugin behaves normally after stop and restart
-    n.rpc.plugin_stop(plugin="helloworld.py")
-    n.daemon.wait_for_log(r"Killing plugin: helloworld.py")
+    l1.rpc.plugin_stop(plugin="helloworld.py")
+    l1.daemon.wait_for_log(r"Killing plugin: helloworld.py")
     time.sleep(1)
-    n.rpc.plugin_start(plugin=os.path.join(os.getcwd(), "contrib/plugins/helloworld.py"))
-    n.daemon.wait_for_log(r"Plugin helloworld.py initialized")
-    assert("Hello world" == n.rpc.call(method="hello"))
+    l1.rpc.plugin_start(plugin=os.path.join(os.getcwd(), "contrib/plugins/helloworld.py"))
+    l1.daemon.wait_for_log(r"Plugin helloworld.py initialized")
+    assert("Hello world" == l1.rpc.call(method="hello"))
 
     # Now stop the helloworld plugin
-    n.rpc.plugin_stop(plugin="helloworld.py")
-    n.daemon.wait_for_log(r"Killing plugin: helloworld.py")
+    l1.rpc.plugin_stop(plugin="helloworld.py")
+    l1.daemon.wait_for_log(r"Killing plugin: helloworld.py")
     time.sleep(1)
     # Make sure that the 'hello' command from the helloworld.py plugin
     # is not available anymore.
-    cmd = [hlp for hlp in n.rpc.help()["help"] if "hello" in hlp["command"]]
+    cmd = [hlp for hlp in l1.rpc.help()["help"] if "hello" in hlp["command"]]
     assert(len(cmd) == 0)
 
-    # Test that we cannot stop a plugin with 'dynamic' set to False in
-    # getmanifest
-    n.rpc.plugin_start(plugin=os.path.join(os.getcwd(), "tests/plugins/static.py"))
-    n.daemon.wait_for_log(r"Static plugin initialized.")
-    with pytest.raises(RpcError, match=r"plugin cannot be managed when lightningd is up"):
-        n.rpc.plugin_stop(plugin="static.py")
-
 
 def test_plugin_disable(node_factory):
     """--disable-plugin works"""