[pulseaudio-discuss,v2,3/6] log: Print systemd journal API failure cause

Submitted by Ahmed S. Darwish on March 14, 2016, 6:17 a.m.

Details

Message ID 20160314061705.GA32237@darwish-pc
State New
Delegated to: Tanu Kaskinen
Headers show
Series "Bugfixes for PA 9.0" ( rev: 2 ) in PulseAudio

Not browsing as part of any series.

Commit Message

Ahmed S. Darwish March 14, 2016, 6:17 a.m.
Also in case of falling back to stderr, do not forget printing
the original log message.

Signed-off-by: Ahmed S. Darwish <darwish.07@gmail.com>
---

Notes:
       v2 changelog:

       - More correct log message
       - Print original failed log message after "Error writing
         logs to journal..", not before
       - In case of stderr transport, use pa_strempty() while
         printing the backtrace

       Moreover:

       - There's a bug in log.c: in case of journal failure the
         logging backend is not _permantently_ reset to syslog
         or stderr. Rather, the redirection happens only once.
         That's the topic of another patch

       - Here in my machine there's a bug either in PA or systemd
         itself where the sd journal log message "Detected that
         we are run from the build tree, fixing search path."
         __always__ fails. This only happens for that single
         message (!) That will also be the topic of another patch.

 src/pulsecore/log.c | 25 +++++++++++++++----------
 1 file changed, 15 insertions(+), 10 deletions(-)

Patch hide | download patch | download mbox

diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c
index 0c561e8..f6d8b71 100644
--- a/src/pulsecore/log.c
+++ b/src/pulsecore/log.c
@@ -363,7 +363,7 @@  static void log_syslog(pa_log_level_t level, char *t, char *timestamp, char *loc
     if ((local_t = pa_utf8_to_locale(t)))
         t = local_t;
 
-    syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
+    syslog(level_to_syslog[level], "%s%s%s%s", timestamp, pa_strempty(location), t, pa_strempty(bt));
     pa_xfree(local_t);
 }
 #endif
@@ -377,7 +377,7 @@  void pa_log_levelv_meta(
         va_list ap) {
 
     char *t, *n;
-    int saved_errno = errno;
+    int saved_errno = errno, ret;
     char *bt = NULL;
     pa_log_target_type_t _target;
     pa_log_level_t _maximum_level;
@@ -386,7 +386,7 @@  void pa_log_levelv_meta(
 
     /* We don't use dynamic memory allocation here to minimize the hit
      * in RT threads */
-    char text[16*1024], location[128], timestamp[32];
+    char text[16*1024], location[128], timestamp[32], logging_error[120];
 
     pa_assert(level < PA_LOG_LEVEL_MAX);
     pa_assert(format);
@@ -507,24 +507,29 @@  void pa_log_levelv_meta(
 
 #ifdef HAVE_SYSTEMD_JOURNAL
             case PA_LOG_JOURNAL:
-                if (sd_journal_send("MESSAGE=%s", t,
+                if ((ret = sd_journal_send("MESSAGE=%s", t,
                                 "PRIORITY=%i", level_to_journal[level],
                                 "CODE_FILE=%s", file,
                                 "CODE_FUNC=%s", func,
                                 "CODE_LINE=%d", line,
                                 "PULSE_BACKTRACE=%s", pa_strempty(bt),
-                                NULL) < 0) {
+                                NULL)) < 0) {
+                    pa_log_target new_target = { .file = NULL, };
+                    pa_snprintf(logging_error, sizeof(logging_error), "Error writing logs to journal. Reason: %s",
+                                pa_cstrerror(ret));
 #ifdef HAVE_SYSLOG_H
-                    pa_log_target new_target = { .type = PA_LOG_SYSLOG, .file = NULL };
+                    new_target.type = PA_LOG_SYSLOG;
 
-                    syslog(level_to_syslog[PA_LOG_ERROR], "%s%s%s", timestamp, __FILE__,
-                           "Error writing logs to the journal. Redirect log messages to syslog.");
+                    log_syslog(PA_LOG_ERROR, logging_error, timestamp, NULL, NULL);
+                    log_syslog(PA_LOG_ERROR, (char *)"Redirecting log messages to syslog.", timestamp, NULL, NULL);
                     log_syslog(level, t, timestamp, location, bt);
 #else
-                    pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
+                    new_target.type = PA_LOG_STDERR;
 
                     saved_errno = errno;
-                    fprintf(stderr, "%s\n", "Error writing logs to the journal. Redirect log messages to console.");
+                    fprintf(stderr, "** %s\n", logging_error);
+                    fprintf(stderr, "** %s\n", "Redirecting log messages to console.");
+                    fprintf(stderr, "%s%s%s%s\n", timestamp, location, t, pa_strempty(bt));
 #endif
                     pa_log_set_target(&new_target);
                 }

Comments

On Mon, 2016-03-14 at 08:17 +0200, Ahmed S. Darwish wrote:
> @@ -386,7 +386,7 @@ void pa_log_levelv_meta(
>  
>      /* We don't use dynamic memory allocation here to minimize the hit
>       * in RT threads */
> -    char text[16*1024], location[128], timestamp[32];
> +    char text[16*1024], location[128], timestamp[32], logging_error[120];
>  
>      pa_assert(level < PA_LOG_LEVEL_MAX);
>      pa_assert(format);
> @@ -507,24 +507,29 @@ void pa_log_levelv_meta(
>  
>  #ifdef HAVE_SYSTEMD_JOURNAL
>              case PA_LOG_JOURNAL:
> -                if (sd_journal_send("MESSAGE=%s", t,
> +                if ((ret = sd_journal_send("MESSAGE=%s", t,
>                                  "PRIORITY=%i", level_to_journal[level],
>                                  "CODE_FILE=%s", file,
>                                  "CODE_FUNC=%s", func,
>                                  "CODE_LINE=%d", line,
>                                  "PULSE_BACKTRACE=%s", pa_strempty(bt),
> -                                NULL) < 0) {
> +                                NULL)) < 0) {
> +                    pa_log_target new_target = { .file = NULL, };
> +                    pa_snprintf(logging_error, sizeof(logging_error), "Error writing logs to journal. Reason: %s",
> +                                pa_cstrerror(ret));
>  #ifdef HAVE_SYSLOG_H
> -                    pa_log_target new_target = { .type = PA_LOG_SYSLOG, .file = NULL };
> +                    new_target.type = PA_LOG_SYSLOG;
>  
> -                    syslog(level_to_syslog[PA_LOG_ERROR], "%s%s%s", timestamp, __FILE__,
> -                           "Error writing logs to the journal. Redirect log messages to syslog.");
> +                    log_syslog(PA_LOG_ERROR, logging_error, timestamp, NULL, NULL);
> +                    log_syslog(PA_LOG_ERROR, (char *)"Redirecting log messages to syslog.", timestamp, NULL, NULL);

I think it would be better to change the log_syslog() prototype than to
cast "const char *" to "char *" here. There's no good reason why
log_syslog() needs to take a mutable string.

Also, I think it makes sense to pass __FILE__ as the location instead
of NULL, like the previous code did.