apps/lib/http_server.{c,h}: clean up logging and move it to log.{c,h}

Reviewed-by: Tomas Mraz <tomas@openssl.org>
Reviewed-by: Dmitry Belyavskiy <beldmit@gmail.com>
Reviewed-by: David von Oheimb <david.von.oheimb@siemens.com>
(Merged from https://github.com/openssl/openssl/pull/18434)

5 files changed, 182 insertions, 119 deletions

diff --git a/apps/include/http_server.h b/apps/include/http_server.h
index e80e29d8c5..4811e6be40 100644
--- a/apps/include/http_server.h
+++ b/apps/include/http_server.h
@@ -11,6 +11,7 @@
 # define OSSL_HTTP_SERVER_H
 
 # include "apps.h"
+# include "log.h"
 
 # ifndef HAVE_FORK
 #  if defined(OPENSSL_SYS_VMS) || defined(OPENSSL_SYS_WINDOWS)
@@ -31,37 +32,10 @@
 #  define HTTP_DAEMON
 #  include <sys/types.h>
 #  include <sys/wait.h>
-#  include <syslog.h>
 #  include <signal.h>
 #  define MAXERRLEN 1000 /* limit error text sent to syslog to 1000 bytes */
 # endif
 
-# undef LOG_TRACE
-# undef LOG_DEBUG
-# undef LOG_INFO
-# undef LOG_WARNING
-# undef LOG_ERR
-# define LOG_TRACE     8
-# define LOG_DEBUG     7
-# define LOG_INFO      6
-# define LOG_WARNING   4
-# define LOG_ERR       3
-
-/*-
- * Output a message using the trace API with the given category
- * if the category is >= 0 and tracing is enabled.
- * Log the message to syslog if multi-threaded HTTP_DAEMON, else to bio_err
- * if the verbosity is sufficient for the given level of severity.
- * category: trace category as defined in trace.h, or -1
- * prog: the name of the current app, or NULL
- * level: the severity of the message, e.g., LOG_ERR
- * fmt: message format, which should not include a trailing newline
- * ...: potential extra parameters like with printf()
- * returns nothing
- */
-void trace_log_message(int category,
-                       const char *prog, int level, const char *fmt, ...);
-
 # ifndef OPENSSL_NO_SOCK
 /*-
  * Initialize an HTTP server, setting up its listening BIO
diff --git a/apps/include/log.h b/apps/include/log.h
new file mode 100644
index 0000000000..1b8b58d41a
--- /dev/null
+++ b/apps/include/log.h
@@ -0,0 +1,50 @@
+/*
+ * Copyright 1995-2022 The OpenSSL Project Authors. All Rights Reserved.
+ *
+ * Licensed under the Apache License 2.0 (the "License").  You may not use
+ * this file except in compliance with the License.  You can obtain a copy
+ * in the file LICENSE in the source distribution or at
+ * https://www.openssl.org/source/license.html
+ */
+
+#ifndef OSSL_APPS_LOG_H
+# define OSSL_APPS_LOG_H
+
+# include <openssl/bio.h>
+# if !defined(OPENSSL_SYS_VMS) && !defined(OPENSSL_SYS_WINDOWS) \
+    && !defined(OPENSSL_NO_SOCK) && !defined(OPENSSL_NO_POSIX_IO)
+#  include <syslog.h>
+# else
+#  define LOG_EMERG   0
+#  define LOG_ALERT   1
+#  define LOG_CRIT    2
+#  define LOG_ERR     3
+#  define LOG_WARNING 4
+#  define LOG_NOTICE  5
+#  define LOG_INFO    6
+#  define LOG_DEBUG   7
+# endif
+
+# undef LOG_TRACE
+# define LOG_TRACE (LOG_DEBUG + 1)
+
+int log_set_verbosity(const char *prog, int level);
+int log_get_verbosity(void);
+
+/*-
+ * Output a message using the trace API with the given category
+ * if the category is >= 0 and tracing is enabled.
+ * Log the message to syslog if multi-threaded HTTP_DAEMON, else to bio_err
+ * if the verbosity is sufficient for the given level of severity.
+ * Yet cannot do both types of output in strict ANSI mode.
+ * category: trace category as defined in trace.h, or -1
+ * prog: the name of the current app, or NULL
+ * level: the severity of the message, e.g., LOG_ERR
+ * fmt: message format, which should not include a trailing newline
+ * ...: potential extra parameters like with printf()
+ * returns nothing
+ */
+void trace_log_message(int category,
+                       const char *prog, int level, const char *fmt, ...);
+
+#endif /* OSSL_APPS_LOG_H */
diff --git a/apps/lib/build.info b/apps/lib/build.info
index 727d924745..f0df608734 100644
--- a/apps/lib/build.info
+++ b/apps/lib/build.info
@@ -8,7 +8,7 @@ IF[{- $config{target} =~ /^vms-/ -}]
 ENDIF
 
 # Source for libapps
-$LIBAPPSSRC=apps.c apps_ui.c opt.c fmt.c s_cb.c s_socket.c app_rand.c \
+$LIBAPPSSRC=apps.c apps_ui.c log.c opt.c fmt.c s_cb.c s_socket.c app_rand.c \
         columns.c app_params.c names.c app_provider.c app_x509.c http_server.c \
         engine.c engine_loader.c app_libctx.c apps_opt_printf.c
 
diff --git a/apps/lib/http_server.c b/apps/lib/http_server.c
index 4b18e8fea4..3f9f884c69 100644
--- a/apps/lib/http_server.c
+++ b/apps/lib/http_server.c
@@ -24,6 +24,7 @@
 #include <openssl/trace.h>
 #include <openssl/rand.h>
 #include "s_apps.h"
+#include "log.h"
 
 #if defined(__TANDEM)
 # if defined(OPENSSL_TANDEM_FLOSS)
@@ -31,84 +32,25 @@
 # endif
 #endif
 
-static int verbosity = LOG_INFO;
-
 #define HTTP_PREFIX "HTTP/"
 #define HTTP_VERSION_PATT "1." /* allow 1.x */
 #define HTTP_PREFIX_VERSION HTTP_PREFIX""HTTP_VERSION_PATT
 #define HTTP_1_0 HTTP_PREFIX_VERSION"0" /* "HTTP/1.0" */
 #define HTTP_VERSION_STR " "HTTP_PREFIX_VERSION
 
-#ifdef HTTP_DAEMON
-
-int n_responders = 0; /* run multiple responder processes, set by ocsp.c */
-int acfd = (int) INVALID_SOCKET;
-
-static int print_syslog(const char *str, size_t len, void *levPtr)
-{
-    int level = *(int *)levPtr;
-    int ilen = len > MAXERRLEN ? MAXERRLEN : len;
-
-    syslog(level, "%.*s", ilen, str);
-
-    return ilen;
-}
-#endif
-
-static void log_with_prefix(const char *prog, const char *fmt, va_list ap)
-{
-    char prefix[80];
-    BIO *bio, *pre = BIO_new(BIO_f_prefix());
-
-    (void)snprintf(prefix, sizeof(prefix), "%s: ", prog);
-    (void)BIO_set_prefix(pre, prefix);
-    bio = BIO_push(pre, bio_err);
-    (void)BIO_vprintf(bio, fmt, ap);
-    (void)BIO_printf(bio, "\n");
-    (void)BIO_flush(bio);
-    (void)BIO_pop(pre);
-    BIO_free(pre);
-}
-
-void trace_log_message(int category,
-                       const char *prog, int level, const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if (category >= 0 && OSSL_trace_enabled(category)) {
-        va_list ap_copy;
-        BIO *out = OSSL_trace_begin(category);
-
-        va_copy(ap_copy, ap);
-        (void)BIO_vprintf(out, fmt, ap_copy);
-        (void)BIO_printf(out, "\n");
-        va_end(ap_copy);
-        OSSL_trace_end(category, out);
-    }
-    if (verbosity < level) {
-        va_end(ap);
-        return;
-    }
-#ifdef HTTP_DAEMON
-    if (n_responders != 0) {
-        vsyslog(level, fmt, ap);
-        if (level <= LOG_ERR)
-            ERR_print_errors_cb(print_syslog, &level);
-    } else
-#endif
-    log_with_prefix(prog, fmt, ap);
-    va_end(ap);
-}
-
 #define log_HTTP(prog, level, text) \
     trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, "%s", text)
 #define log_HTTP1(prog, level, fmt, arg) \
     trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, fmt, arg)
 #define log_HTTP2(prog, level, fmt, arg1, arg2) \
     trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, fmt, arg1, arg2)
+#define log_HTTP3(prog, level, fmt, a1, a2, a3)                        \
+    trace_log_message(OSSL_TRACE_CATEGORY_HTTP, prog, level, fmt, a1, a2, a3)
 
 #ifdef HTTP_DAEMON
+int n_responders = 0; /* run multiple responder processes, set by ocsp.c */
+int acfd = (int)INVALID_SOCKET;
+
 void socket_timeout(int signum)
 {
     if (acfd != (int)INVALID_SOCKET)
@@ -149,8 +91,9 @@ void spawn_loop(const char *prog)
     openlog(prog, LOG_PID, LOG_DAEMON);
 
     if (setpgid(0, 0)) {
-        syslog(LOG_ERR, "fatal: error detaching from parent process group: %s",
-               strerror(errno));
+        log_HTTP1(prog, LOG_ERR,
+                  "fatal: error detaching from parent process group: %s",
+                  strerror(errno));
         exit(1);
     }
     kidpids = app_malloc(n_responders * sizeof(*kidpids), "child PID array");
@@ -177,27 +120,33 @@ void spawn_loop(const char *prog)
                     }
                 }
                 if (i >= n_responders) {
-                    syslog(LOG_ERR, "fatal: internal error: "
-                           "no matching child slot for pid: %ld",
-                           (long)fpid);
+                    log_HTTP1(prog, LOG_ERR, "fatal: internal error: "
+                              "no matching child slot for pid: %ld",
+                              (long)fpid);
                     killall(1, kidpids);
                 }
                 if (status != 0) {
-                    if (WIFEXITED(status))
-                        syslog(LOG_WARNING, "child process: %ld, exit status: %d",
-                               (long)fpid, WEXITSTATUS(status));
-                    else if (WIFSIGNALED(status))
-                        syslog(LOG_WARNING, "child process: %ld, term signal %d%s",
-                               (long)fpid, WTERMSIG(status),
+                    if (WIFEXITED(status)) {
+                        log_HTTP2(prog, LOG_WARNING,
+                                  "child process: %ld, exit status: %d",
+                                  (long)fpid, WEXITSTATUS(status));
+                    } else if (WIFSIGNALED(status)) {
+                        char *dumped = "";
+
 # ifdef WCOREDUMP
-                               WCOREDUMP(status) ? " (core dumped)" :
+                        if (WCOREDUMP(status))
+                            dumped = " (core dumped)";
 # endif
-                               "");
+                        log_HTTP3(prog, LOG_WARNING,
+                                  "child process: %ld, term signal %d%s",
+                                  (long)fpid, WTERMSIG(status), dumped);
+                    }
                     ossl_sleep(1000);
                 }
                 break;
             } else if (errno != EINTR) {
-                syslog(LOG_ERR, "fatal: waitpid(): %s", strerror(errno));
+                log_HTTP1(prog, LOG_ERR,
+                          "fatal: waitpid(): %s", strerror(errno));
                 killall(1, kidpids);
             }
         }
@@ -216,7 +165,7 @@ void spawn_loop(const char *prog)
             if (termsig)
                 _exit(0);
             if (RAND_poll() <= 0) {
-                syslog(LOG_ERR, "fatal: RAND_poll() failed");
+                log_HTTP(prog, LOG_ERR, "fatal: RAND_poll() failed");
                 _exit(1);
             }
             return;
@@ -229,7 +178,8 @@ void spawn_loop(const char *prog)
                 }
             }
             if (i >= n_responders) {
-                syslog(LOG_ERR, "fatal: internal error: no free child slots");
+                log_HTTP(prog, LOG_ERR,
+                         "fatal: internal error: no free child slots");
                 killall(1, kidpids);
             }
             break;
@@ -237,7 +187,7 @@ void spawn_loop(const char *prog)
     }
 
     /* The loop above can only break on termsig */
-    syslog(LOG_INFO, "terminating on signal: %d", termsig);
+    log_HTTP1(prog, LOG_INFO, "terminating on signal: %d", termsig);
     killall(0, kidpids);
 }
 #endif
@@ -249,14 +199,8 @@ BIO *http_server_init(const char *prog, const char *port, int verb)
     int asock;
     int port_num;
 
-    if (verb >= 0) {
-        if (verb > LOG_TRACE) {
-            log_HTTP1(prog, LOG_ERR,
-                      "Logging verbosity level %d too high", verb);
-            return NULL;
-        }
-        verbosity = verb;
-    }
+    if (verb >= 0 && !log_set_verbosity(prog, verb))
+        return NULL;
     bufbio = BIO_new(BIO_f_buffer());
     if (bufbio == NULL)
         goto err;
@@ -380,7 +324,7 @@ int http_server_get_asn1_req(const ASN1_ITEM *it, ASN1_VALUE **preq,
     if (((end = strchr(reqbuf, '\r')) != NULL && end[1] == '\n')
             || (end = strchr(reqbuf, '\n')) != NULL)
         *end = '\0';
-    if (verbosity < LOG_TRACE)
+    if (log_get_verbosity() < LOG_TRACE)
         trace_log_message(-1, prog, LOG_INFO,
                           "Received request, 1st line: %s", reqbuf);
     log_HTTP(prog, LOG_TRACE, "Received request header:");
@@ -571,7 +515,7 @@ int http_server_send_asn1_resp(const char *prog, BIO *cbio, int keep_alive,
 
     if (ret < 0 || (size_t)ret >= sizeof(buf))
         return 0;
-    if (verbosity < LOG_TRACE && (p = strchr(buf, '\r')) != NULL)
+    if (log_get_verbosity() < LOG_TRACE && (p = strchr(buf, '\r')) != NULL)
         trace_log_message(-1, prog, LOG_INFO,
                           "Sending response, 1st line: %.*s", (int)(p - buf),
                           buf);
diff --git a/apps/lib/log.c b/apps/lib/log.c
new file mode 100644
index 0000000000..94a91949ea
--- /dev/null
+++ b/apps/lib/log.c
@@ -0,0 +1,95 @@
+/*
+ * Copyright 2020-2022 The OpenSSL Project Authors. All Rights Reserved.
+ *
+ * Licensed under the Apache License 2.0 (the "License").  You may not use
+ * this file except in compliance with the License.  You can obtain a copy
+ * in the file LICENSE in the source distribution or at
+ * https://www.openssl.org/source/license.html
+ */
+
+#include <openssl/trace.h>
+#include "apps.h"
+#include "log.h"
+
+static int verbosity = LOG_INFO;
+
+int log_set_verbosity(const char *prog, int level)
+{
+    if (level < LOG_EMERG || level > LOG_TRACE) {
+        trace_log_message(-1, prog, LOG_ERR,
+                          "Invalid verbosity level %d", level);
+        return 0;
+    }
+    verbosity = level;
+    return 1;
+}
+
+int log_get_verbosity(void)
+{
+    return verbosity;
+}
+
+#ifdef HTTP_DAEMON
+static int print_syslog(const char *str, size_t len, void *levPtr)
+{
+    int level = *(int *)levPtr;
+    int ilen = len > MAXERRLEN ? MAXERRLEN : len;
+
+    syslog(level, "%.*s", ilen, str);
+
+    return ilen;
+}
+#endif
+
+static void log_with_prefix(const char *prog, const char *fmt, va_list ap)
+{
+    char prefix[80];
+    BIO *bio, *pre = BIO_new(BIO_f_prefix());
+
+    (void)snprintf(prefix, sizeof(prefix), "%s: ", prog);
+    (void)BIO_set_prefix(pre, prefix);
+    bio = BIO_push(pre, bio_err);
+    (void)BIO_vprintf(bio, fmt, ap);
+    (void)BIO_printf(bio, "\n");
+    (void)BIO_flush(bio);
+    (void)BIO_pop(pre);
+    BIO_free(pre);
+}
+
+void trace_log_message(int category,
+                       const char *prog, int level, const char *fmt, ...)
+{
+    va_list ap;
+    va_start(ap, fmt);
+#ifdef __STRICT_ANSI__ /* unfortuantely, ANSI does not define va_copy */
+    if (verbosity >= level)
+        category = -1; /* disabling trace output in addition to logging */
+#endif
+    if (category >= 0 && OSSL_trace_enabled(category)) {
+        BIO *out = OSSL_trace_begin(category);
+#ifndef __STRICT_ANSI__
+        va_list ap_copy;
+
+        va_copy(ap_copy, ap);
+        (void)BIO_vprintf(out, fmt, ap_copy);
+        va_end(ap_copy);
+#else
+        (void)BIO_vprintf(out, fmt, ap);
+#endif
+        (void)BIO_printf(out, "\n");
+        OSSL_trace_end(category, out);
+    }
+    if (verbosity < level) {
+        va_end(ap);
+        return;
+    }
+#ifdef HTTP_DAEMON
+    if (n_responders != 0) {
+        vsyslog(level, fmt, ap);
+        if (level <= LOG_ERR)
+            ERR_print_errors_cb(print_syslog, &level);
+    } else
+#endif
+    log_with_prefix(prog, fmt, ap);
+    va_end(ap);
+}