treewide: fix flushing of messages to logs in some cases

... by setting FILE* properties and replace the explicit flushes.
Explicit flushing couldn't be well done e.g. for lua's error() function.
In particular, we had problems with journald not getting logs timely.

diff --git a/NEWS b/NEWS
index f8c216e437da8d17f4cd3479dd79b0bd6f51f480..3d69602298630955a302c9ac59c641a8eed2acca 100644 (file)
--- a/NEWS
+++ b/NEWS
@@ -14,6 +14,7 @@ Bugfixes
 - policy module: support '#' for separating port numbers, for consistency
 - fix startup on macOS+BSD when </dev/null and cqueues installed
 - policy.RPZ: log problems from zone-file level of parser as well (#453)
+- fix flushing of messages to logs in some cases (!781)
 
 Improvements
 ------------

diff --git a/daemon/main.c b/daemon/main.c
index 906b2f1ecb5fb8538f45c6cde48124a2c856a50c..30abf836831b29eeb4f103e08724d04c75efddc8 100644 (file)
--- a/daemon/main.c
+++ b/daemon/main.c
@@ -173,7 +173,6 @@ static void tty_process_input(uv_stream_t *stream, ssize_t nread, const uv_buf_t
                lua_settop(L, 0);
        }
 finish:
-       fflush(out);
        free(cmd);
        /* Close if redirected */
        if (stream_fd != STDIN_FILENO) {
@@ -420,6 +419,12 @@ static int run_worker(uv_loop_t *loop, struct engine *engine, fd_array_t *ipc_se
                return 1;
        }
 
+       if (setvbuf(stdout, NULL, _IONBF, 0) || setvbuf(stderr, NULL, _IONBF, 0)) {
+               kr_log_error("[system] failed to to set output buffering (ignored): %s\n",
+                               strerror(errno));
+               fflush(stderr);
+       }
+
        /* Control sockets or TTY */
        auto_free char *sock_file = NULL;
        uv_pipe_t pipe;
@@ -428,7 +433,6 @@ static int run_worker(uv_loop_t *loop, struct engine *engine, fd_array_t *ipc_se
        if (args->interactive) {
                if (!args->quiet)
                        printf("[system] interactive mode\n> ");
-               fflush(stdout);
                uv_pipe_open(&pipe, 0);
                uv_read_start((uv_stream_t*) &pipe, tty_alloc, tty_process_input);
        } else {

diff --git a/lib/utils.c b/lib/utils.c
index a3bf7ca96f94e925269424858479dc3a29ab8ed4..6e63f997177e2ca9efbf43d35ef58c8e36c9e18e 100644 (file)
--- a/lib/utils.c
+++ b/lib/utils.c
@@ -118,12 +118,11 @@ bool kr_verbose_set(bool status)
 
 void kr_log_verbose(const char *fmt, ...)
 {
-       if (kr_verbose_status) {
+       if (unlikely(kr_verbose_status)) {
                va_list args;
                va_start(args, fmt);
                vprintf(fmt, args);
                va_end(args);
-               fflush(stdout);
        }
 }
 
@@ -141,7 +140,6 @@ void kr_log_qverbose_impl(const struct kr_query *qry, const char *cls, const cha
        va_start(args, fmt);
        vprintf(fmt, args);
        va_end(args);
-       fflush(stdout);
 }
 
 bool kr_log_trace(const struct kr_query *query, const char *source, const char *fmt, ...)

diff --git a/lib/utils.h b/lib/utils.h
index a515a388013695fd6a1daa3f59d1569335a95316..8deef4efe7446d74a5629b2d307a2719fa355184 100644 (file)
--- a/lib/utils.h
+++ b/lib/utils.h
@@ -46,7 +46,7 @@ typedef void (*trace_callback_f)(struct kr_request *request);
 /** @brief Callback for request logging handler. */
 typedef void (*trace_log_f)(const struct kr_query *query, const char *source, const char *msg);
 
-#define kr_log_info(...) do { printf(__VA_ARGS__); fflush(stdout); } while(0)
+#define kr_log_info printf
 #define kr_log_error(...) fprintf(stderr, ## __VA_ARGS__)
 
 /* Always export these, but override direct calls by macros conditionally. */