| Message ID | 20220218093115.1006522-1-stijn@linux-ipv6.be |
|---|---|
| State | Superseded |
| Delegated to: | Stijn Tintel |
| Headers | show |
| Series | [RFC,ubus] cli: improve error logging for call command | expand |
On 18/02/2022 11:31, Stijn Tintel wrote: > When the ubus "call" command fails, ubus prints "Command failed: ...". > This is fine when the call command is executed interactively by the > user. However, when the call command is executed non-interactively, > these log messages leave the user completely clueless: > > netifd: wan6 (10841): Command failed: Unknown error > > procd: /etc/rc.d/S80umdns: Failed to parse message data > > These messages contain absolutely no info that explains where they come > from; it's not even clear they are coming from ubus. This makes tracking > down what's causing them virtually impossible. > > Improve this situation by printing the full ubus call to stderr when > stderr is not a TTY. > > Example of improved error message: > netifd: wan (2836): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan" } (Permission denied) > > While one might argue not to include the JSON message in the log, > excluding it will still not help to reproduce the failed command. > As we only print the full command when stderr is not a TTY, seeing this > error means we're doing a bad ubus call somewhere, which is a bug and > should be fixed. Printing the full command makes more sense than > printing half the command and still requiring us to figure out the exact > command that failed. > > Signed-off-by: Stijn Tintel <stijn@linux-ipv6.be> > --- > If anyone wants to argue this isn't useful: > https://forum.openwrt.org/search?q=%22Command%20failed%22 > --- > cli.c | 23 +++++++++++++++++++++-- > 1 file changed, 21 insertions(+), 2 deletions(-) > > diff --git a/cli.c b/cli.c > index 81591ec..bc14daf 100644 > --- a/cli.c > +++ b/cli.c > @@ -119,6 +119,19 @@ static void receive_event(struct ubus_context *ctx, struct ubus_event_handler *e > print_event(type, msg); > } > > +static void print_error(char *msg, char *cmd, int argc, char **argv, int err) > +{ > + int i; > + > + fprintf(stderr, "%s failed: ubus %s ", msg, cmd); > + for (i = 0; i < argc; i++) { > + fprintf(stderr, "%s ", argv[i]); > + } > + if (err) > + fprintf(stderr, "(%s)", ubus_strerror(err)); > + fprintf(stderr, "\n"); > +} > + > static int ubus_cli_list(struct ubus_context *ctx, int argc, char **argv) > { > const char *path = NULL; > @@ -143,7 +156,7 @@ static int ubus_cli_call(struct ubus_context *ctx, int argc, char **argv) > blob_buf_init(&b, 0); > if (argc == 3 && !blobmsg_add_json_from_string(&b, argv[2])) { > if (!simple_output) > - fprintf(stderr, "Failed to parse message data\n"); > + print_error("Parsing message data", "call", argc, argv, ret); Should have used 0 instead of ret here, but instead I will initialize ret to 0 at the start of the function. > return -1; > } > > @@ -151,7 +164,13 @@ static int ubus_cli_call(struct ubus_context *ctx, int argc, char **argv) > if (ret) > return ret; > > - return ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); > + ret = ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); > + if (ret && !simple_output && !isatty(fileno(stderr) == ENOTTY)) { > + print_error("Command", "call", argc, argv, ret); > + return -1; > + } > + > + return ret; > } > > struct cli_listen_data {
Stijn Tintel <stijn@linux-ipv6.be> [2022-02-18 11:31:15]: Hi, > These messages contain absolutely no info that explains where they come > from; it's not even clear they are coming from ubus. This makes tracking > down what's causing them virtually impossible. +1 > - return ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); > + ret = ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); > + if (ret && !simple_output && !isatty(fileno(stderr) == ENOTTY)) { can't you move that !simple and !isatty checks into common place like print_error() in order to simplify such common use cases? Other then that, feel free to add my Acked-by: Cheers, Petr
diff --git a/cli.c b/cli.c index 81591ec..bc14daf 100644 --- a/cli.c +++ b/cli.c @@ -119,6 +119,19 @@ static void receive_event(struct ubus_context *ctx, struct ubus_event_handler *e print_event(type, msg); } +static void print_error(char *msg, char *cmd, int argc, char **argv, int err) +{ + int i; + + fprintf(stderr, "%s failed: ubus %s ", msg, cmd); + for (i = 0; i < argc; i++) { + fprintf(stderr, "%s ", argv[i]); + } + if (err) + fprintf(stderr, "(%s)", ubus_strerror(err)); + fprintf(stderr, "\n"); +} + static int ubus_cli_list(struct ubus_context *ctx, int argc, char **argv) { const char *path = NULL; @@ -143,7 +156,7 @@ static int ubus_cli_call(struct ubus_context *ctx, int argc, char **argv) blob_buf_init(&b, 0); if (argc == 3 && !blobmsg_add_json_from_string(&b, argv[2])) { if (!simple_output) - fprintf(stderr, "Failed to parse message data\n"); + print_error("Parsing message data", "call", argc, argv, ret); return -1; } @@ -151,7 +164,13 @@ static int ubus_cli_call(struct ubus_context *ctx, int argc, char **argv) if (ret) return ret; - return ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); + ret = ubus_invoke(ctx, id, argv[1], b.head, receive_call_result_data, NULL, timeout * 1000); + if (ret && !simple_output && !isatty(fileno(stderr) == ENOTTY)) { + print_error("Command", "call", argc, argv, ret); + return -1; + } + + return ret; } struct cli_listen_data {
When the ubus "call" command fails, ubus prints "Command failed: ...". This is fine when the call command is executed interactively by the user. However, when the call command is executed non-interactively, these log messages leave the user completely clueless: netifd: wan6 (10841): Command failed: Unknown error procd: /etc/rc.d/S80umdns: Failed to parse message data These messages contain absolutely no info that explains where they come from; it's not even clear they are coming from ubus. This makes tracking down what's causing them virtually impossible. Improve this situation by printing the full ubus call to stderr when stderr is not a TTY. Example of improved error message: netifd: wan (2836): Command failed: ubus call network.interface notify_proto { "action": 0, "link-up": false, "keep": false, "interface": "wan" } (Permission denied) While one might argue not to include the JSON message in the log, excluding it will still not help to reproduce the failed command. As we only print the full command when stderr is not a TTY, seeing this error means we're doing a bad ubus call somewhere, which is a bug and should be fixed. Printing the full command makes more sense than printing half the command and still requiring us to figure out the exact command that failed. Signed-off-by: Stijn Tintel <stijn@linux-ipv6.be> --- If anyone wants to argue this isn't useful: https://forum.openwrt.org/search?q=%22Command%20failed%22 --- cli.c | 23 +++++++++++++++++++++-- 1 file changed, 21 insertions(+), 2 deletions(-)