upstream: revised log infrastructure for OpenSSH

log functions receive function, filename and line number of caller.
We can use this to selectively enable logging via pattern-lists.

ok markus@

OpenBSD-Commit-ID: 51a472610cbe37834ce6ce4a3f0e0b1ccc95a349

diff --git a/fatal.c b/fatal.c
index 5e5aa3fe18dfd229c6427d02c638584cfbf2514f..3ecd510f1dcff3f098bbe25e9260dd952c407bc2 100644 (file)
--- a/fatal.c
+++ b/fatal.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: fatal.c,v 1.7 2006/08/03 03:34:42 deraadt Exp $ */
+/* $OpenBSD: fatal.c,v 1.8 2020/10/16 13:24:45 djm Exp $ */
 /*
  * Copyright (c) 2002 Markus Friedl.  All rights reserved.
  *
@@ -34,12 +34,12 @@
 /* Fatal messages.  This function never returns. */
 
 void
-fatal(const char *fmt,...)
+sshfatal(const char *file, const char *func, int line, const char *fmt, ...)
 {
        va_list args;
 
        va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_FATAL, fmt, args);
+       ssh_log(file, func, line, SYSLOG_LEVEL_FATAL, fmt, args);
        va_end(args);
        cleanup_exit(255);
 }

diff --git a/log.c b/log.c
index 6b1a7a31417b5d70c5b800d26d828f05510ea65b..159c306deb878e6b4f87782a3529a98704165a7e 100644 (file)
--- a/log.c
+++ b/log.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: log.c,v 1.52 2020/07/03 06:46:41 djm Exp $ */
+/* $OpenBSD: log.c,v 1.53 2020/10/16 13:24:45 djm Exp $ */
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
@@ -51,6 +51,7 @@
 #endif
 
 #include "log.h"
+#include "match.h"
 
 static LogLevel log_level = SYSLOG_LEVEL_INFO;
 static int log_on_stderr = 1;
@@ -59,6 +60,8 @@ static int log_facility = LOG_AUTH;
 static char *argv0;
 static log_handler_fn *log_handler;
 static void *log_handler_ctx;
+static char **log_verbose;
+static size_t nlog_verbose;
 
 extern char *__progname;
 
@@ -157,96 +160,30 @@ log_level_name(LogLevel level)
        return NULL;
 }
 
-/* Error messages that should be logged. */
-
-void
-error(const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_ERROR, fmt, args);
-       va_end(args);
-}
-
-void
-sigdie(const char *fmt,...)
-{
-#ifdef DO_LOG_SAFE_IN_SIGHAND
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_FATAL, fmt, args);
-       va_end(args);
-#endif
-       _exit(1);
-}
-
-void
-logdie(const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_INFO, fmt, args);
-       va_end(args);
-       cleanup_exit(255);
-}
-
-/* Log this message (information that usually should go to the log). */
-
-void
-logit(const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_INFO, fmt, args);
-       va_end(args);
-}
-
-/* More detailed messages (information that does not need to go to the log). */
-
-void
-verbose(const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_VERBOSE, fmt, args);
-       va_end(args);
-}
-
-/* Debugging messages that should not be logged during normal operation. */
-
-void
-debug(const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_DEBUG1, fmt, args);
-       va_end(args);
-}
-
 void
-debug2(const char *fmt,...)
+log_verbose_add(const char *s)
 {
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_DEBUG2, fmt, args);
-       va_end(args);
+       char **tmp;
+
+       /* Ignore failures here */
+       if ((tmp = recallocarray(log_verbose, nlog_verbose, nlog_verbose + 1,
+           sizeof(*log_verbose))) != NULL) {
+               log_verbose = tmp;
+               if ((log_verbose[nlog_verbose] = strdup(s)) != NULL)
+                       nlog_verbose++;
+       }
 }
 
 void
-debug3(const char *fmt,...)
+log_verbose_reset(void)
 {
-       va_list args;
+       size_t i;
 
-       va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_DEBUG3, fmt, args);
-       va_end(args);
+       for (i = 0; i < nlog_verbose; i++)
+               free(log_verbose[i]);
+       free(log_verbose);
+       log_verbose = NULL;
+       nlog_verbose = 0;
 }
 
 /*
@@ -395,18 +332,9 @@ set_log_handler(log_handler_fn *handler, void *ctx)
        log_handler_ctx = ctx;
 }
 
-void
-do_log2(LogLevel level, const char *fmt,...)
-{
-       va_list args;
-
-       va_start(args, fmt);
-       do_log(level, fmt, args);
-       va_end(args);
-}
-
-void
-do_log(LogLevel level, const char *fmt, va_list args)
+static void
+do_log(const char *file, const char *func, int line, LogLevel level,
+    int force, const char *fmt, va_list args)
 {
 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT)
        struct syslog_data sdata = SYSLOG_DATA_INIT;
@@ -418,7 +346,7 @@ do_log(LogLevel level, const char *fmt, va_list args)
        int saved_errno = errno;
        log_handler_fn *tmp_handler;
 
-       if (level > log_level)
+       if (!force && level > log_level)
                return;
 
        switch (level) {
@@ -467,7 +395,7 @@ do_log(LogLevel level, const char *fmt, va_list args)
                /* Avoid recursion */
                tmp_handler = log_handler;
                log_handler = NULL;
-               tmp_handler(level, fmtbuf, log_handler_ctx);
+               tmp_handler(file, func, line, level, fmtbuf, log_handler_ctx);
                log_handler = tmp_handler;
        } else if (log_on_stderr) {
                snprintf(msgbuf, sizeof msgbuf, "%.*s\r\n",
@@ -486,3 +414,64 @@ do_log(LogLevel level, const char *fmt, va_list args)
        }
        errno = saved_errno;
 }
+
+void
+sshlog(const char *file, const char *func, int line, int showfunc,
+    LogLevel level, const char *fmt, ...)
+{
+       va_list args;
+
+       va_start(args, fmt);
+       sshlogv(file, func, line, showfunc, level, fmt, args);
+       va_end(args);
+}
+
+void
+sshlogdie(const char *file, const char *func, int line, const char *fmt, ...)
+{
+       va_list args;
+
+       va_start(args, fmt);
+       sshlogv(file, func, line, 0, SYSLOG_LEVEL_INFO, fmt, args);
+       va_end(args);
+       cleanup_exit(255);
+}
+
+void
+sshsigdie(const char *file, const char *func, int line, const char *fmt, ...)
+{
+       va_list args;
+
+       va_start(args, fmt);
+       sshlogv(file, func, line, 0, SYSLOG_LEVEL_FATAL, fmt, args);
+       va_end(args);
+       _exit(1);
+}
+
+void
+sshlogv(const char *file, const char *func, int line, int showfunc,
+    LogLevel level, const char *fmt, va_list args)
+{
+       char tag[128], fmt2[MSGBUFSIZ + 128];
+       int forced = 0;
+       const char *cp;
+       size_t i;
+
+       snprintf(tag, sizeof(tag), "%.48s:%.48s():%d",
+           (cp = strrchr(file, '/')) == NULL ? file : cp + 1, func, line);
+       for (i = 0; i < nlog_verbose; i++) {
+               if (match_pattern_list(tag, log_verbose[i], 0) == 1) {
+                       forced = 1;
+                       break;
+               }
+       }
+
+       if (log_handler == NULL && forced)
+               snprintf(fmt2, sizeof(fmt2), "%s: %s", tag, fmt);
+       else if (showfunc)
+               snprintf(fmt2, sizeof(fmt2), "%s: %s", func, fmt);
+       else
+               strlcpy(fmt2, fmt, sizeof(fmt2));
+
+       do_log(file, func, line, level, forced, fmt2, args);
+}

diff --git a/log.h b/log.h
index 78cda287dd6cfd2bdfb31fdc25d81430ca511e18..b1ab7c7e0b70861d96ad16060d69807d22f848f0 100644 (file)
--- a/log.h
+++ b/log.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: log.h,v 1.24 2019/09/06 04:53:27 djm Exp $ */
+/* $OpenBSD: log.h,v 1.25 2020/10/16 13:24:45 djm Exp $ */
 
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
@@ -48,36 +48,57 @@ typedef enum {
        SYSLOG_LEVEL_NOT_SET = -1
 }       LogLevel;
 
-typedef void (log_handler_fn)(LogLevel, const char *, void *);
+typedef void (log_handler_fn)(const char *, const char *, int, LogLevel,
+    const char *, void *);
 
 void     log_init(char *, LogLevel, SyslogFacility, int);
 LogLevel log_level_get(void);
 int      log_change_level(LogLevel);
 int      log_is_on_stderr(void);
 void     log_redirect_stderr_to(const char *);
+void    log_verbose_add(const char *);
+void    log_verbose_reset(void);
 
 SyslogFacility log_facility_number(char *);
 const char *   log_facility_name(SyslogFacility);
 LogLevel       log_level_number(char *);
 const char *   log_level_name(LogLevel);
 
-void     fatal(const char *, ...) __attribute__((noreturn))
-    __attribute__((format(printf, 1, 2)));
-void     error(const char *, ...) __attribute__((format(printf, 1, 2)));
-void     sigdie(const char *, ...)  __attribute__((noreturn))
-    __attribute__((format(printf, 1, 2)));
-void     logdie(const char *, ...) __attribute__((noreturn))
-    __attribute__((format(printf, 1, 2)));
-void     logit(const char *, ...) __attribute__((format(printf, 1, 2)));
-void     verbose(const char *, ...) __attribute__((format(printf, 1, 2)));
-void     debug(const char *, ...) __attribute__((format(printf, 1, 2)));
-void     debug2(const char *, ...) __attribute__((format(printf, 1, 2)));
-void     debug3(const char *, ...) __attribute__((format(printf, 1, 2)));
-
-
 void    set_log_handler(log_handler_fn *, void *);
-void    do_log2(LogLevel, const char *, ...)
-    __attribute__((format(printf, 2, 3)));
-void    do_log(LogLevel, const char *, va_list);
 void    cleanup_exit(int) __attribute__((noreturn));
+
+void    sshlog(const char *, const char *, int, int,
+    LogLevel, const char *, ...) __attribute__((format(printf, 6, 7)));
+void    sshlogv(const char *, const char *, int, int,
+    LogLevel, const char *, va_list);
+void    sshsigdie(const char *, const char *, int, const char *, ...)
+    __attribute__((noreturn)) __attribute__((format(printf, 4, 5)));
+void    sshlogdie(const char *, const char *, int, const char *, ...)
+    __attribute__((noreturn)) __attribute__((format(printf, 4, 5)));
+void    sshfatal(const char *, const char *, int, const char *, ...)
+    __attribute__((noreturn)) __attribute__((format(printf, 4, 5)));
+
+#define ssh_nlog(level, ...)   sshlog(__FILE__, __func__, __LINE__, 0, level, __VA_ARGS__)
+#define ssh_debug3(...)                sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_DEBUG3, __VA_ARGS__)
+#define ssh_debug2(...)                sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_DEBUG2, __VA_ARGS__)
+#define ssh_debug(...)         sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_DEBUG1, __VA_ARGS__)
+#define ssh_verbose(...)       sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_VERBOSE, __VA_ARGS__)
+#define ssh_log(...)           sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_INFO, __VA_ARGS__)
+#define ssh_error(...)         sshlog(__FILE__, __func__, __LINE__, 0, SYSLOG_LEVEL_ERROR, __VA_ARGS__)
+#define ssh_fatal(...)         sshfatal(__FILE__, __func__, __LINE__, __VA_ARGS__)
+#define ssh_logdie(...)                sshlogdie(__FILE__, __func__, __LINE__, __VA_ARGS__)
+#define ssh_sigdie(...)                sshsigdie(__FILE__, __func__, __LINE__, __VA_ARGS__)
+
+#define debug  ssh_debug
+#define debug1 ssh_debug1
+#define debug2 ssh_debug2
+#define debug3 ssh_debug3
+#define error  ssh_error
+#define logit  ssh_log
+#define verbose        ssh_verbose
+#define fatal  ssh_fatal
+#define logdie ssh_logdie
+#define sigdie ssh_sigdie
+#define do_log2        ssh_nlog
+
 #endif

diff --git a/monitor.c b/monitor.c
index 4cf79dfc98cd6b79e60cfc5c057457cf2497c171..9f22f0681488cb105fac7c5c10b947bbb581968a 100644 (file)
--- a/monitor.c
+++ b/monitor.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor.c,v 1.214 2020/08/27 01:07:09 djm Exp $ */
+/* $OpenBSD: monitor.c,v 1.215 2020/10/16 13:24:45 djm Exp $ */
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
  * Copyright 2002 Markus Friedl <markus@openbsd.org>
@@ -420,8 +420,8 @@ static int
 monitor_read_log(struct monitor *pmonitor)
 {
        struct sshbuf *logmsg;
-       u_int len, level;
-       char *msg;
+       u_int len, level, line;
+       char *msg, *file, *func;
        u_char *p;
        int r;
 
@@ -452,7 +452,10 @@ monitor_read_log(struct monitor *pmonitor)
                fatal("%s: reserve: %s", __func__, ssh_err(r));
        if (atomicio(read, pmonitor->m_log_recvfd, p, len) != len)
                fatal("%s: log fd read: %s", __func__, strerror(errno));
-       if ((r = sshbuf_get_u32(logmsg, &level)) != 0 ||
+       if ((r = sshbuf_get_cstring(logmsg, &file, NULL)) != 0 ||
+           (r = sshbuf_get_cstring(logmsg, &func, NULL)) != 0 ||
+           (r = sshbuf_get_u32(logmsg, &line)) != 0 ||
+           (r = sshbuf_get_u32(logmsg, &level)) != 0 ||
            (r = sshbuf_get_cstring(logmsg, &msg, NULL)) != 0)
                fatal("%s: decode: %s", __func__, ssh_err(r));
 
@@ -460,9 +463,11 @@ monitor_read_log(struct monitor *pmonitor)
        if (log_level_name(level) == NULL)
                fatal("%s: invalid log level %u (corrupted message?)",
                    __func__, level);
-       do_log2(level, "%s [preauth]", msg);
+       sshlog(file, func, line, 0, level, "%s [preauth]", msg);
 
        sshbuf_free(logmsg);
+       free(file);
+       free(func);
        free(msg);
 
        return 0;

diff --git a/monitor_wrap.c b/monitor_wrap.c
index 5e38d83eb05257c68412f656fae0a7b7ad097591..c18ee1819dadd851621dc9e375b7daecbfe6cddd 100644 (file)
--- a/monitor_wrap.c
+++ b/monitor_wrap.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor_wrap.c,v 1.118 2020/08/27 01:06:18 djm Exp $ */
+/* $OpenBSD: monitor_wrap.c,v 1.119 2020/10/16 13:24:45 djm Exp $ */
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
  * Copyright 2002 Markus Friedl <markus@openbsd.org>
@@ -82,7 +82,8 @@ extern struct sshbuf *loginmsg;
 extern ServerOptions options;
 
 void
-mm_log_handler(LogLevel level, const char *msg, void *ctx)
+mm_log_handler(const char *file, const char *func, int line,
+    LogLevel level, const char *msg, void *ctx)
 {
        struct sshbuf *log_msg;
        struct monitor *mon = (struct monitor *)ctx;
@@ -96,6 +97,9 @@ mm_log_handler(LogLevel level, const char *msg, void *ctx)
                fatal("%s: sshbuf_new failed", __func__);
 
        if ((r = sshbuf_put_u32(log_msg, 0)) != 0 || /* length; filled below */
+           (r = sshbuf_put_cstring(log_msg, file)) != 0 ||
+           (r = sshbuf_put_cstring(log_msg, func)) != 0 ||
+           (r = sshbuf_put_u32(log_msg, (u_int)line)) != 0 ||
            (r = sshbuf_put_u32(log_msg, level)) != 0 ||
            (r = sshbuf_put_cstring(log_msg, msg)) != 0)
                fatal("%s: buffer error: %s", __func__, ssh_err(r));

diff --git a/monitor_wrap.h b/monitor_wrap.h
index 0db38c20657f0f782d6b02942df7a72b9791f6b6..8507f1c11ef876213d86a5c3448d5ae31101efe3 100644 (file)
--- a/monitor_wrap.h
+++ b/monitor_wrap.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor_wrap.h,v 1.45 2020/08/27 01:06:18 djm Exp $ */
+/* $OpenBSD: monitor_wrap.h,v 1.46 2020/10/16 13:24:45 djm Exp $ */
 
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
@@ -40,7 +40,8 @@ struct sshkey;
 struct sshauthopt;
 struct sshkey_sig_details;
 
-void mm_log_handler(LogLevel, const char *, void *);
+void mm_log_handler(const char *, const char *, int, LogLevel,
+    const char *, void *);
 int mm_is_monitor(void);
 #ifdef WITH_OPENSSL
 DH *mm_choose_dh(int, int, int);

diff --git a/ssh-keyscan.c b/ssh-keyscan.c
index ca190428a78b662f2b0f4cf5239e639b6514d920..ac7bfcd188cc69bdebf035de730756c14f6eb18e 100644 (file)
--- a/ssh-keyscan.c
+++ b/ssh-keyscan.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: ssh-keyscan.c,v 1.132 2020/08/12 01:23:45 cheloha Exp $ */
+/* $OpenBSD: ssh-keyscan.c,v 1.133 2020/10/16 13:24:45 djm Exp $ */
 /*
  * Copyright 1995, 1996 by David Mazieres <dm@lcs.mit.edu>.
  *
@@ -635,14 +635,15 @@ do_host(char *host)
 }
 
 void
-fatal(const char *fmt,...)
+sshfatal(const char *file, const char *func, int line,
+    const char *fmt, ...)
 {
        va_list args;
 
        va_start(args, fmt);
-       do_log(SYSLOG_LEVEL_FATAL, fmt, args);
+       ssh_log(file, func, line, SYSLOG_LEVEL_FATAL, fmt, args);
        va_end(args);
-       exit(255);
+       cleanup_exit(255);
 }
 
 static void