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@

8 files changed, 157 insertions, 136 deletions

diff --git a/usr.bin/ssh/Makefile.inc b/usr.bin/ssh/Makefile.inc
index 16f2c05e8d4..49d6405bf02 100644
--- a/usr.bin/ssh/Makefile.inc
+++ b/usr.bin/ssh/Makefile.inc
@@ -1,4 +1,4 @@
-#	$OpenBSD: Makefile.inc,v 1.84 2020/08/03 02:42:49 deraadt Exp $
+#	$OpenBSD: Makefile.inc,v 1.85 2020/10/16 13:24:45 djm Exp $
 
 .include <bsd.own.mk>
 
@@ -55,6 +55,8 @@ SRCS_BASE+=	ssherr.c
 SRCS_BASE+=	log.c
 SRCS_BASE+=	xmalloc.c
 SRCS_BASE+=	misc.c
+SRCS_BASE+=	addrmatch.c
+SRCS_BASE+=	match.c
 
 .if (${OPENSSL:L} == "yes")
 SRCS_KEX+=	dh.c
@@ -119,9 +121,6 @@ SRCS_PROT+=	monitor_fdpass.c
 SRCS_PROT+=	nchan.c
 SRCS_PROT+=	ttymodes.c
 
-SRCS_UTL+=	addrmatch.c
-SRCS_UTL+=	match.c
-
 .if (${OPENSSL:L} == "yes")
 SRCS_PKCS11+=		ssh-pkcs11.c
 SRCS_PKCS11_CLIENT+=	ssh-pkcs11-client.c
diff --git a/usr.bin/ssh/fatal.c b/usr.bin/ssh/fatal.c
index 52c8d586e98..d0478847066 100644
--- a/usr.bin/ssh/fatal.c
+++ b/usr.bin/ssh/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.
  *
@@ -32,12 +32,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/usr.bin/ssh/log.c b/usr.bin/ssh/log.c
index 5f5757fb16e..7be77b3b4dc 100644
--- a/usr.bin/ssh/log.c
+++ b/usr.bin/ssh/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
@@ -47,6 +47,7 @@
 #include <vis.h>
 
 #include "log.h"
+#include "match.h"
 
 static LogLevel log_level = SYSLOG_LEVEL_INFO;
 static int log_on_stderr = 1;
@@ -55,7 +56,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;
 
 /* textual representation of log-facilities/levels */
@@ -147,94 +149,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,...)
-{
-	va_list args;
-
-	va_start(args, fmt);
-	do_log(SYSLOG_LEVEL_FATAL, fmt, args);
-	va_end(args);
-	_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;
 }
 
 /*
@@ -361,18 +299,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)
 {
 	struct syslog_data sdata = SYSLOG_DATA_INIT;
 	char msgbuf[MSGBUFSIZ];
@@ -382,7 +311,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) {
@@ -430,7 +359,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",
@@ -443,3 +372,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/usr.bin/ssh/log.h b/usr.bin/ssh/log.h
index bd5c620e561..96c5ede100b 100644
--- a/usr.bin/ssh/log.h
+++ b/usr.bin/ssh/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>
@@ -45,36 +45,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/usr.bin/ssh/monitor.c b/usr.bin/ssh/monitor.c
index 98bef2909bb..85125f3ff60 100644
--- a/usr.bin/ssh/monitor.c
+++ b/usr.bin/ssh/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>
@@ -354,8 +354,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;
 
@@ -386,7 +386,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));
 
@@ -394,9 +397,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/usr.bin/ssh/monitor_wrap.c b/usr.bin/ssh/monitor_wrap.c
index a25efe9d61b..30a1217e39c 100644
--- a/usr.bin/ssh/monitor_wrap.c
+++ b/usr.bin/ssh/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>
@@ -78,7 +78,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;
@@ -92,6 +93,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/usr.bin/ssh/monitor_wrap.h b/usr.bin/ssh/monitor_wrap.h
index b6e99e34ff3..bbb6f978914 100644
--- a/usr.bin/ssh/monitor_wrap.h
+++ b/usr.bin/ssh/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/usr.bin/ssh/ssh-keyscan.c b/usr.bin/ssh/ssh-keyscan.c
index 108645a6a46..a362e397858 100644
--- a/usr.bin/ssh/ssh-keyscan.c
+++ b/usr.bin/ssh/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>.
  *
@@ -617,14 +617,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