[pacman-dev,v2] alpm: Add better logging when a command fails to execute correctly

Message ID 20200523120444.82853-1-daan.j.demeyer@gmail.com
State New
Headers show
Series
  • [pacman-dev,v2] alpm: Add better logging when a command fails to execute correctly
Related show

Commit Message

Daan De Meyer May 23, 2020, 12:04 p.m. UTC
This makes debugging hook failures when running pacman less of a
hassle. Instead of a generic "command failed to execute correctly",
we now get the exact command and its arguments, as well as the exit
code of the command logged.

Signed-off-by: Daan De Meyer <daan.j.demeyer@gmail.com>
---

Updated strv_join failure handling. I'm also not entirely sure what to
do with the translations. Do I update all the separate files with the
updated message identifier? I can fix some of the translations but
the Arabic ones are impossible for me to fix.

 lib/libalpm/util.c | 45 ++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 44 insertions(+), 1 deletion(-)

Comments

Andrew Gregory May 23, 2020, 11:06 p.m. UTC | #1
On 05/23/20 at 02:04pm, Daan De Meyer wrote:
> This makes debugging hook failures when running pacman less of a
> hassle. Instead of a generic "command failed to execute correctly",
> we now get the exact command and its arguments, as well as the exit
> code of the command logged.
> 
> Signed-off-by: Daan De Meyer <daan.j.demeyer@gmail.com>
> ---
> 
> Updated strv_join failure handling. I'm also not entirely sure what to
> do with the translations. Do I update all the separate files with the
> updated message identifier? I can fix some of the translations but
> the Arabic ones are impossible for me to fix.

No, translations are done separately through transifex.

>  lib/libalpm/util.c | 45 ++++++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 44 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/libalpm/util.c b/lib/libalpm/util.c
> index ead03004..22ae48f6 100644
> --- a/lib/libalpm/util.c
> +++ b/lib/libalpm/util.c
> @@ -568,6 +568,42 @@ static void _alpm_reset_signals(void)
>  	}
>  }
>  
> +static char *strv_join(char *const *strv, const char *separator)
> +{
> +	char *const *i;
> +	char *r, *p;
> +	size_t size = 0;
> +
> +	if (!separator) {
> +		separator = " ";
> +	}
> +
> +	for (i = strv; *i; i++) {
> +		if (i != strv) {
> +			size += strlen(separator);
> +		}
> +
> +		size += strlen(*i);
> +	}
> +
> +	r = malloc(size + 1);
> +	if (r == NULL) {
> +		return NULL;
> +	}
> +
> +	p = r;
> +
> +	for (i = strv; *i; i++) {
> +		if (i != strv) {
> +			p = stpcpy(p, separator);
> +		}
> +
> +		p = stpcpy(p, *i);
> +	}
> +
> +	return r;
> +}

We already have an almost identical function in pacman/util.c.

>  /** Execute a command with arguments in a chroot.
>   * @param handle the context handle
>   * @param cmd command to execute
> @@ -745,7 +781,14 @@ int _alpm_run_chroot(alpm_handle_t *handle, const char *cmd, char *const argv[],
>  		if(WIFEXITED(status)) {
>  			_alpm_log(handle, ALPM_LOG_DEBUG, "call to waitpid succeeded\n");
>  			if(WEXITSTATUS(status) != 0) {
> -				_alpm_log(handle, ALPM_LOG_ERROR, _("command failed to execute correctly\n"));
> +				char *argv_str = strv_join(argv, NULL);
> +				if (argv_str) {
> +					_alpm_log(handle, ALPM_LOG_ERROR,
> +							_("command \"%s\" failed to execute correctly: %i\n"),
> +							argv_str, WEXITSTATUS(status));

I doubt that the exit status is generally going to be useful to the
user, nor is it clear from the error message that that's even what is
being printed.

> +					free(argv_str);
> +				}

I don't know that this is the right approach.  This is going to give
pretty useless, and probably confusing, output for scriptlets.  Hooks
and scripts should really be printing appropriate error messages when
they fail, so that our error message should really only matter in the
rare occasions where the command fails to execute at all.  I would be
more inclined to point the user at the actual hook or script that
failed.

> +
>  				retval = 1;
>  			}
>  		} else if(WIFSIGNALED(status) != 0) {
> -- 
> 2.26.2
Daan De Meyer May 24, 2020, 3:06 p.m. UTC | #2
You have a point, maybe I'm not solving the right problem. To give a little
more context, While playing with systemd's mkosi (
https://github.com/systemd/mkosi), systemd's systemd-tmpfiles pacman hook
has been consistently failing with "error: command failed to execute
correctly". However, when looking at pacman's logs with `journalctl
_COMM=pacman` (mkosi has pacman log to syslog), there was absolutely no
further information on the failure. I've looked at systemd's source code
now and if stderr is not a tty, it logs separately to another medium
(syslog, journal, ...). To get the actual error from systemd-tmpfiles, I
first hacked this patch into pacman to know which command was actually
failing and even then I had to modify the file descriptor dupping to
directly have systemd inherit the pacman stderr fd before I could actually
get the error from systemd-tmpfiles.

So maybe, instead of this patch, we should force systemd-tmpfiles to output
to the console instead by setting the SYSTEMD_LOG_TARGET environment
variable in the corresponding pacman hook. On the other hand,
systemd-tmpfiles is a CLI tool so maybe it should be outputting to the
console even if it is not a tty. I'll open an issue with systemd as well to
discuss this. It's not intuitive that spawning a systemd CLI tool as a
child process with input redirected to pipes would suddenly cause the
logging output to go somewhere else.


On Sun, 24 May 2020 at 01:06, Andrew Gregory <andrew.gregory.8@gmail.com>
wrote:

> On 05/23/20 at 02:04pm, Daan De Meyer wrote:
> > This makes debugging hook failures when running pacman less of a
> > hassle. Instead of a generic "command failed to execute correctly",
> > we now get the exact command and its arguments, as well as the exit
> > code of the command logged.
> >
> > Signed-off-by: Daan De Meyer <daan.j.demeyer@gmail.com>
> > ---
> >
> > Updated strv_join failure handling. I'm also not entirely sure what to
> > do with the translations. Do I update all the separate files with the
> > updated message identifier? I can fix some of the translations but
> > the Arabic ones are impossible for me to fix.
>
> No, translations are done separately through transifex.
>
> >  lib/libalpm/util.c | 45 ++++++++++++++++++++++++++++++++++++++++++++-
> >  1 file changed, 44 insertions(+), 1 deletion(-)
> >
> > diff --git a/lib/libalpm/util.c b/lib/libalpm/util.c
> > index ead03004..22ae48f6 100644
> > --- a/lib/libalpm/util.c
> > +++ b/lib/libalpm/util.c
> > @@ -568,6 +568,42 @@ static void _alpm_reset_signals(void)
> >       }
> >  }
> >
> > +static char *strv_join(char *const *strv, const char *separator)
> > +{
> > +     char *const *i;
> > +     char *r, *p;
> > +     size_t size = 0;
> > +
> > +     if (!separator) {
> > +             separator = " ";
> > +     }
> > +
> > +     for (i = strv; *i; i++) {
> > +             if (i != strv) {
> > +                     size += strlen(separator);
> > +             }
> > +
> > +             size += strlen(*i);
> > +     }
> > +
> > +     r = malloc(size + 1);
> > +     if (r == NULL) {
> > +             return NULL;
> > +     }
> > +
> > +     p = r;
> > +
> > +     for (i = strv; *i; i++) {
> > +             if (i != strv) {
> > +                     p = stpcpy(p, separator);
> > +             }
> > +
> > +             p = stpcpy(p, *i);
> > +     }
> > +
> > +     return r;
> > +}
>
> We already have an almost identical function in pacman/util.c.
>
> >  /** Execute a command with arguments in a chroot.
> >   * @param handle the context handle
> >   * @param cmd command to execute
> > @@ -745,7 +781,14 @@ int _alpm_run_chroot(alpm_handle_t *handle, const
> char *cmd, char *const argv[],
> >               if(WIFEXITED(status)) {
> >                       _alpm_log(handle, ALPM_LOG_DEBUG, "call to waitpid
> succeeded\n");
> >                       if(WEXITSTATUS(status) != 0) {
> > -                             _alpm_log(handle, ALPM_LOG_ERROR,
> _("command failed to execute correctly\n"));
> > +                             char *argv_str = strv_join(argv, NULL);
> > +                             if (argv_str) {
> > +                                     _alpm_log(handle, ALPM_LOG_ERROR,
> > +                                                     _("command \"%s\"
> failed to execute correctly: %i\n"),
> > +                                                     argv_str,
> WEXITSTATUS(status));
>
> I doubt that the exit status is generally going to be useful to the
> user, nor is it clear from the error message that that's even what is
> being printed.
>
> > +                                     free(argv_str);
> > +                             }
>
> I don't know that this is the right approach.  This is going to give
> pretty useless, and probably confusing, output for scriptlets.  Hooks
> and scripts should really be printing appropriate error messages when
> they fail, so that our error message should really only matter in the
> rare occasions where the command fails to execute at all.  I would be
> more inclined to point the user at the actual hook or script that
> failed.
>
> > +
> >                               retval = 1;
> >                       }
> >               } else if(WIFSIGNALED(status) != 0) {
> > --
> > 2.26.2
>

Patch

diff --git a/lib/libalpm/util.c b/lib/libalpm/util.c
index ead03004..22ae48f6 100644
--- a/lib/libalpm/util.c
+++ b/lib/libalpm/util.c
@@ -568,6 +568,42 @@  static void _alpm_reset_signals(void)
 	}
 }
 
+static char *strv_join(char *const *strv, const char *separator)
+{
+	char *const *i;
+	char *r, *p;
+	size_t size = 0;
+
+	if (!separator) {
+		separator = " ";
+	}
+
+	for (i = strv; *i; i++) {
+		if (i != strv) {
+			size += strlen(separator);
+		}
+
+		size += strlen(*i);
+	}
+
+	r = malloc(size + 1);
+	if (r == NULL) {
+		return NULL;
+	}
+
+	p = r;
+
+	for (i = strv; *i; i++) {
+		if (i != strv) {
+			p = stpcpy(p, separator);
+		}
+
+		p = stpcpy(p, *i);
+	}
+
+	return r;
+}
+
 /** Execute a command with arguments in a chroot.
  * @param handle the context handle
  * @param cmd command to execute
@@ -745,7 +781,14 @@  int _alpm_run_chroot(alpm_handle_t *handle, const char *cmd, char *const argv[],
 		if(WIFEXITED(status)) {
 			_alpm_log(handle, ALPM_LOG_DEBUG, "call to waitpid succeeded\n");
 			if(WEXITSTATUS(status) != 0) {
-				_alpm_log(handle, ALPM_LOG_ERROR, _("command failed to execute correctly\n"));
+				char *argv_str = strv_join(argv, NULL);
+				if (argv_str) {
+					_alpm_log(handle, ALPM_LOG_ERROR,
+							_("command \"%s\" failed to execute correctly: %i\n"),
+							argv_str, WEXITSTATUS(status));
+					free(argv_str);
+				}
+
 				retval = 1;
 			}
 		} else if(WIFSIGNALED(status) != 0) {