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

[Daan De Meyer]

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 at 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 at 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
>