- djm@cvs.openbsd.org 2011/06/17 21:44:31

     [log.c log.h monitor.c monitor.h monitor_wrap.c monitor_wrap.h sshd.c]
     make the pre-auth privsep slave log via a socketpair shared with the
     monitor rather than /var/empty/dev/log; ok dtucker@ deraadt@ markus@

8 files changed, 197 insertions, 26 deletions

diff --git a/ChangeLog b/ChangeLog
index 5dae2a859..d41208092 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -9,6 +9,10 @@
      make sure key_parse_public/private_rsa1() no longer consumes its input
      buffer.  fixes ssh-add for passphrase-protected ssh1-keys;
      noted by naddy@; ok djm@
+   - djm@cvs.openbsd.org 2011/06/17 21:44:31
+     [log.c log.h monitor.c monitor.h monitor_wrap.c monitor_wrap.h sshd.c]
+     make the pre-auth privsep slave log via a socketpair shared with the
+     monitor rather than /var/empty/dev/log; ok dtucker@ deraadt@ markus@
 
 20110603
  - (dtucker) [README version.h contrib/caldera/openssh.spec
diff --git a/log.c b/log.c
index 4a8239b93..ad5a10b47 100644
--- a/log.c
+++ b/log.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: log.c,v 1.41 2008/06/10 04:50:25 dtucker Exp $ */
+/* $OpenBSD: log.c,v 1.42 2011/06/17 21:44:30 djm Exp $ */
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
@@ -56,6 +56,8 @@ static LogLevel log_level = SYSLOG_LEVEL_INFO;
 static int log_on_stderr = 1;
 static int log_facility = LOG_AUTH;
 static char *argv0;
+static log_handler_fn *log_handler;
+static void *log_handler_ctx;
 
 extern char *__progname;
 
@@ -260,6 +262,9 @@ log_init(char *av0, LogLevel level, SyslogFacility facility, int on_stderr)
                 exit(1);
         }
 
+        log_handler = NULL;
+        log_handler_ctx = NULL;
+
         log_on_stderr = on_stderr;
         if (on_stderr)
                 return;
@@ -327,6 +332,23 @@ log_init(char *av0, LogLevel level, SyslogFacility facility, int on_stderr)
 #define MSGBUFSIZ 1024
 
 void
+set_log_handler(log_handler_fn *handler, void *ctx)
+{
+        log_handler = handler;
+        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)
 {
 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT)
@@ -337,6 +359,7 @@ do_log(LogLevel level, const char *fmt, va_list args)
         char *txt = NULL;
         int pri = LOG_INFO;
         int saved_errno = errno;
+        log_handler_fn *tmp_handler;
 
         if (level > log_level)
                 return;
@@ -375,7 +398,7 @@ do_log(LogLevel level, const char *fmt, va_list args)
                 pri = LOG_ERR;
                 break;
         }
-        if (txt != NULL) {
+        if (txt != NULL && log_handler == NULL) {
                 snprintf(fmtbuf, sizeof(fmtbuf), "%s: %s", txt, fmt);
                 vsnprintf(msgbuf, sizeof(msgbuf), fmtbuf, args);
         } else {
@@ -383,7 +406,13 @@ do_log(LogLevel level, const char *fmt, va_list args)
         }
         strnvis(fmtbuf, msgbuf, sizeof(fmtbuf),
             log_on_stderr ? LOG_STDERR_VIS : LOG_SYSLOG_VIS);
-        if (log_on_stderr) {
+        if (log_handler != NULL) {
+                /* Avoid recursion */
+                tmp_handler = log_handler;
+                log_handler = NULL;
+                tmp_handler(level, fmtbuf, log_handler_ctx);
+                log_handler = tmp_handler;
+        } else if (log_on_stderr) {
                 snprintf(msgbuf, sizeof msgbuf, "%s\r\n", fmtbuf);
                 write(STDERR_FILENO, msgbuf, strlen(msgbuf));
         } else {
diff --git a/log.h b/log.h
index 650582791..1b8d2142b 100644
--- a/log.h
+++ b/log.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: log.h,v 1.17 2008/06/13 00:12:02 dtucker Exp $ */
+/* $OpenBSD: log.h,v 1.18 2011/06/17 21:44:30 djm Exp $ */
 
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
@@ -46,6 +46,8 @@ typedef enum {
         SYSLOG_LEVEL_NOT_SET = -1
 }       LogLevel;
 
+typedef void (log_handler_fn)(LogLevel, const char *, void *);
+
 void     log_init(char *, LogLevel, SyslogFacility, int);
 
 SyslogFacility  log_facility_number(char *);
@@ -64,6 +66,10 @@ 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));
 #endif
diff --git a/monitor.c b/monitor.c
index 2c9254182..bb8003c67 100644
--- a/monitor.c
+++ b/monitor.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor.c,v 1.113 2011/05/23 03:30:07 djm Exp $ */
+/* $OpenBSD: monitor.c,v 1.114 2011/06/17 21:44:30 djm Exp $ */
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
  * Copyright 2002 Markus Friedl <markus@openbsd.org>
@@ -44,6 +44,13 @@
 #include <stdlib.h>
 #include <string.h>
 #include <unistd.h>
+#ifdef HAVE_POLL_H
+#include <poll.h>
+#else
+# ifdef HAVE_SYS_POLL_H
+#  include <sys/poll.h>
+# endif
+#endif
 
 #ifdef SKEY
 #include <skey.h>
@@ -52,6 +59,7 @@
 #include <openssl/dh.h>
 
 #include "openbsd-compat/sys-queue.h"
+#include "atomicio.h"
 #include "xmalloc.h"
 #include "ssh.h"
 #include "key.h"
@@ -179,6 +187,8 @@ int mm_answer_audit_event(int, Buffer *);
 int mm_answer_audit_command(int, Buffer *);
 #endif
 
+static int monitor_read_log(struct monitor *);
+
 static Authctxt *authctxt;
 static BIGNUM *ssh1_challenge = NULL;   /* used for ssh1 rsa auth */
 
@@ -346,6 +356,10 @@ monitor_child_preauth(Authctxt *_authctxt, struct monitor *pmonitor)
 
         debug3("preauth child monitor started");
 
+        close(pmonitor->m_recvfd);
+        close(pmonitor->m_log_sendfd);
+        pmonitor->m_log_sendfd = pmonitor->m_recvfd = -1;
+
         authctxt = _authctxt;
         memset(authctxt, 0, sizeof(*authctxt));
 
@@ -405,6 +419,10 @@ monitor_child_preauth(Authctxt *_authctxt, struct monitor *pmonitor)
 #endif
         }
 
+        /* Drain any buffered messages from the child */
+        while (pmonitor->m_log_recvfd != -1 && monitor_read_log(pmonitor) == 0)
+                ;
+
         if (!authctxt->valid)
                 fatal("%s: authenticated invalid user", __func__);
         if (strcmp(auth_method, "unknown") == 0)
@@ -414,6 +432,10 @@ monitor_child_preauth(Authctxt *_authctxt, struct monitor *pmonitor)
             __func__, authctxt->user);
 
         mm_get_keystate(pmonitor);
+
+        close(pmonitor->m_sendfd);
+        close(pmonitor->m_log_recvfd);
+        pmonitor->m_sendfd = pmonitor->m_log_recvfd = -1;
 }
 
 static void
@@ -431,6 +453,9 @@ monitor_child_handler(int sig)
 void
 monitor_child_postauth(struct monitor *pmonitor)
 {
+        close(pmonitor->m_recvfd);
+        pmonitor->m_recvfd = -1;
+
         monitor_set_child_handler(pmonitor->m_pid);
         signal(SIGHUP, &monitor_child_handler);
         signal(SIGTERM, &monitor_child_handler);
@@ -454,6 +479,9 @@ monitor_child_postauth(struct monitor *pmonitor)
 
         for (;;)
                 monitor_read(pmonitor, mon_dispatch, NULL);
+
+        close(pmonitor->m_sendfd);
+        pmonitor->m_sendfd = -1;
 }
 
 void
@@ -465,6 +493,52 @@ monitor_sync(struct monitor *pmonitor)
         }
 }
 
+static int
+monitor_read_log(struct monitor *pmonitor)
+{
+        Buffer logmsg;
+        u_int len, level;
+        char *msg;
+
+        buffer_init(&logmsg);
+
+        /* Read length */
+        buffer_append_space(&logmsg, 4);
+        if (atomicio(read, pmonitor->m_log_recvfd,
+            buffer_ptr(&logmsg), buffer_len(&logmsg)) != buffer_len(&logmsg)) {
+                if (errno == EPIPE) {
+                        debug("%s: child log fd closed", __func__);
+                        close(pmonitor->m_log_recvfd);
+                        pmonitor->m_log_recvfd = -1;
+                        return -1;
+                }
+                fatal("%s: log fd read: %s", __func__, strerror(errno));
+        }
+        len = buffer_get_int(&logmsg);
+        if (len <= 4 || len > 8192)
+                fatal("%s: invalid log message length %u", __func__, len);
+
+        /* Read severity, message */
+        buffer_clear(&logmsg);
+        buffer_append_space(&logmsg, len);
+        if (atomicio(read, pmonitor->m_log_recvfd,
+            buffer_ptr(&logmsg), buffer_len(&logmsg)) != buffer_len(&logmsg))
+                fatal("%s: log fd read: %s", __func__, strerror(errno));
+
+        /* Log it */
+        level = buffer_get_int(&logmsg);
+        msg = buffer_get_string(&logmsg, NULL);
+        if (log_level_name(level) == NULL)
+                fatal("%s: invalid log level %u (corrupted message?)",
+                    __func__, level);
+        do_log2(level, "%s [preauth]", msg);
+
+        buffer_free(&logmsg);
+        xfree(msg);
+
+        return 0;
+}
+
 int
 monitor_read(struct monitor *pmonitor, struct mon_table *ent,
     struct mon_table **pent)
@@ -472,6 +546,27 @@ monitor_read(struct monitor *pmonitor, struct mon_table *ent,
         Buffer m;
         int ret;
         u_char type;
+        struct pollfd pfd[2];
+
+        for (;;) {
+                bzero(&pfd, sizeof(pfd));
+                pfd[0].fd = pmonitor->m_sendfd;
+                pfd[0].events = POLLIN;
+                pfd[1].fd = pmonitor->m_log_recvfd;
+                pfd[1].events = pfd[1].fd == -1 ? 0 : POLLIN;
+                if (poll(pfd, pfd[1].fd == -1 ? 1 : 2, -1) == -1)
+                        fatal("%s: poll: %s", __func__, strerror(errno));
+                if (pfd[1].revents) {
+                        /*
+                         * Drain all log messages before processing next
+                         * monitor request.
+                         */
+                        monitor_read_log(pmonitor);
+                        continue;
+                }
+                if (pfd[0].revents)
+                        break;  /* Continues below */
+        }
 
         buffer_init(&m);
 
@@ -1851,12 +1946,26 @@ mm_init_compression(struct mm_master *mm)
 } while (0)
 
 static void
-monitor_socketpair(int *pair)
+monitor_openfds(struct monitor *mon, int do_logfds)
 {
+        int pair[2];
+
         if (socketpair(AF_UNIX, SOCK_STREAM, 0, pair) == -1)
-                fatal("%s: socketpair", __func__);
+                fatal("%s: socketpair: %s", __func__, strerror(errno));
         FD_CLOSEONEXEC(pair[0]);
         FD_CLOSEONEXEC(pair[1]);
+        mon->m_recvfd = pair[0];
+        mon->m_sendfd = pair[1];
+
+        if (do_logfds) {
+                if (pipe(pair) == -1)
+                        fatal("%s: pipe: %s", __func__, strerror(errno));
+                FD_CLOSEONEXEC(pair[0]);
+                FD_CLOSEONEXEC(pair[1]);
+                mon->m_log_recvfd = pair[0];
+                mon->m_log_sendfd = pair[1];
+        } else
+                mon->m_log_recvfd = mon->m_log_sendfd = -1;
 }
 
 #define MM_MEMSIZE      65536
@@ -1865,14 +1974,10 @@ struct monitor *
 monitor_init(void)
 {
         struct monitor *mon;
-        int pair[2];
 
         mon = xcalloc(1, sizeof(*mon));
 
-        monitor_socketpair(pair);
-
-        mon->m_recvfd = pair[0];
-        mon->m_sendfd = pair[1];
+        monitor_openfds(mon, 1);
 
         /* Used to share zlib space across processes */
         if (options.compression) {
@@ -1889,12 +1994,7 @@ monitor_init(void)
 void
 monitor_reinit(struct monitor *mon)
 {
-        int pair[2];
-
-        monitor_socketpair(pair);
-
-        mon->m_recvfd = pair[0];
-        mon->m_sendfd = pair[1];
+        monitor_openfds(mon, 0);
 }
 
 #ifdef GSSAPI
diff --git a/monitor.h b/monitor.h
index a8a2c0c19..5e7d552fb 100644
--- a/monitor.h
+++ b/monitor.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor.h,v 1.15 2008/11/04 08:22:13 djm Exp $ */
+/* $OpenBSD: monitor.h,v 1.16 2011/06/17 21:44:31 djm Exp $ */
 
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
@@ -72,6 +72,8 @@ struct mm_master;
 struct monitor {
         int                      m_recvfd;
         int                      m_sendfd;
+        int                      m_log_recvfd;
+        int                      m_log_sendfd;
         struct mm_master        *m_zback;
         struct mm_master        *m_zlib;
         struct Kex              **m_pkex;
diff --git a/monitor_wrap.c b/monitor_wrap.c
index 7a90b3ba3..1f60658e9 100644
--- a/monitor_wrap.c
+++ b/monitor_wrap.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor_wrap.c,v 1.72 2011/05/23 03:30:07 djm Exp $ */
+/* $OpenBSD: monitor_wrap.c,v 1.73 2011/06/17 21:44:31 djm Exp $ */
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
  * Copyright 2002 Markus Friedl <markus@openbsd.org>
@@ -88,6 +88,32 @@ extern struct monitor *pmonitor;
 extern Buffer loginmsg;
 extern ServerOptions options;
 
+void
+mm_log_handler(LogLevel level, const char *msg, void *ctx)
+{
+        Buffer log_msg;
+        struct monitor *mon = (struct monitor *)ctx;
+
+        if (mon->m_log_sendfd == -1)
+                fatal("%s: no log channel", __func__);
+
+        buffer_init(&log_msg);
+        /*
+         * Placeholder for packet length. Will be filled in with the actual
+         * packet length once the packet has been constucted. This saves
+         * fragile math.
+         */
+        buffer_put_int(&log_msg, 0);
+
+        buffer_put_int(&log_msg, level);
+        buffer_put_cstring(&log_msg, msg);
+        put_u32(buffer_ptr(&log_msg), buffer_len(&log_msg) - 4);
+        if (atomicio(vwrite, mon->m_log_sendfd, buffer_ptr(&log_msg),
+            buffer_len(&log_msg)) != buffer_len(&log_msg))
+                fatal("%s: write: %s", __func__, strerror(errno));
+        buffer_free(&log_msg);
+}
+
 int
 mm_is_monitor(void)
 {
diff --git a/monitor_wrap.h b/monitor_wrap.h
index de2d16f66..0c7f2e384 100644
--- a/monitor_wrap.h
+++ b/monitor_wrap.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor_wrap.h,v 1.22 2009/03/05 07:18:19 djm Exp $ */
+/* $OpenBSD: monitor_wrap.h,v 1.23 2011/06/17 21:44:31 djm Exp $ */
 
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
@@ -37,6 +37,7 @@ struct monitor;
 struct mm_master;
 struct Authctxt;
 
+void mm_log_handler(LogLevel, const char *, void *);
 int mm_is_monitor(void);
 DH *mm_choose_dh(int, int, int);
 int mm_key_sign(Key *, u_char **, u_int *, u_char *, u_int);
diff --git a/sshd.c b/sshd.c
index 50d0dede4..6e15522b3 100644
--- a/sshd.c
+++ b/sshd.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: sshd.c,v 1.382 2011/04/12 05:32:49 djm Exp $ */
+/* $OpenBSD: sshd.c,v 1.383 2011/06/17 21:44:31 djm Exp $ */
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
@@ -636,10 +636,8 @@ privsep_preauth(Authctxt *authctxt)
         } else if (pid != 0) {
                 debug2("Network child is on pid %ld", (long)pid);
 
-                close(pmonitor->m_recvfd);
                 pmonitor->m_pid = pid;
                 monitor_child_preauth(authctxt, pmonitor);
-                close(pmonitor->m_sendfd);
 
                 /* Sync memory */
                 monitor_sync(pmonitor);
@@ -651,8 +649,11 @@ privsep_preauth(Authctxt *authctxt)
                 return (1);
         } else {
                 /* child */
-
                 close(pmonitor->m_sendfd);
+                close(pmonitor->m_log_recvfd);
+
+                /* Arrange for logging to be sent to the monitor */
+                set_log_handler(mm_log_handler, pmonitor);
 
                 /* Demote the child */
                 if (getuid() == 0 || geteuid() == 0)
@@ -685,7 +686,6 @@ privsep_postauth(Authctxt *authctxt)
                 fatal("fork of unprivileged child failed");
         else if (pmonitor->m_pid != 0) {
                 verbose("User child is on pid %ld", (long)pmonitor->m_pid);
-                close(pmonitor->m_recvfd);
                 buffer_clear(&loginmsg);
                 monitor_child_postauth(pmonitor);
 
@@ -693,7 +693,10 @@ privsep_postauth(Authctxt *authctxt)
                 exit(0);
         }
 
+        /* child */
+
         close(pmonitor->m_sendfd);
+        pmonitor->m_sendfd = -1;
 
         /* Demote the private keys to public keys. */
         demote_sensitive_data();