[pacman-dev] [PATCH v2] alpm: Add better logging when a command fails to execute correctly
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(-) 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) { -- 2.26.2
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
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
participants (2)
-
Andrew Gregory
-
Daan De Meyer