sshd double-logging

[Darren Tucker]

Hi all.

As Corinna pointed out, there are some cases where sshd will log some
authentications twice when privsep=yes.

This can happen on any platform although it seems most obvious on the
ones that don't do post-auth privsep.  It also occurs when sshd logs
to stderr (eg running under daemontools) or when you have a /dev/log in
the privsep chroot.

The patch below attempts to solve this for the general case.  The idea
is that everything is logged by the monitor, except for "postponed"
authentications.  (The monitor never knows about the "postponed"
ones since the slave is just waiting for a response from the client.
I don't think it's worth another monitor call to log those.)

Index: auth.c
===================================================================
RCS file: /usr/local/src/security/openssh/cvs/openssh_cvs/auth.c,v
retrieving revision 1.101
diff -u -p -r1.101 auth.c
--- auth.c	31 Aug 2005 16:59:49 -0000	1.101
+++ auth.c	12 Feb 2006 00:24:03 -0000
@@ -231,6 +231,15 @@ auth_log(Authctxt *authctxt, int authent
 	void (*authlog) (const char *fmt,...) = verbose;
 	char *authmsg;
 
+#if 0
+	logit("authenticated %d method %s info '%s' postponed %d monitor %d",
+	    authenticated, method, info, authctxt->postponed, mm_is_monitor());
+#endif
+	authlog = logit; /* XXX for testing only */
+
+	if (use_privsep && !mm_is_monitor() && !authctxt->postponed)
+		return;
+
 	/* Raise logging level */
 	if (authenticated == 1 ||
 	    !authctxt->valid ||
Index: monitor.c
===================================================================
RCS file: /usr/local/src/security/openssh/cvs/openssh_cvs/monitor.c,v
retrieving revision 1.88
diff -u -p -r1.88 monitor.c
--- monitor.c	5 Nov 2005 04:07:05 -0000	1.88
+++ monitor.c	12 Feb 2006 00:17:03 -0000
@@ -188,7 +188,7 @@ struct mon_table mon_dispatch_proto20[] 
     {MONITOR_REQ_PAM_ACCOUNT, 0, mm_answer_pam_account},
     {MONITOR_REQ_PAM_INIT_CTX, MON_ISAUTH, mm_answer_pam_init_ctx},
     {MONITOR_REQ_PAM_QUERY, MON_ISAUTH, mm_answer_pam_query},
-    {MONITOR_REQ_PAM_RESPOND, MON_ISAUTH, mm_answer_pam_respond},
+    {MONITOR_REQ_PAM_RESPOND, MON_AUTH, mm_answer_pam_respond},
     {MONITOR_REQ_PAM_FREE_CTX, MON_ONCE|MON_AUTHDECIDE, mm_answer_pam_free_ctx},
 #endif
 #ifdef SSH_AUDIT_EVENTS
@@ -231,8 +231,8 @@ struct mon_table mon_dispatch_proto15[] 
     {MONITOR_REQ_SESSKEY, MON_ONCE, mm_answer_sesskey},
     {MONITOR_REQ_SESSID, MON_ONCE, mm_answer_sessid},
     {MONITOR_REQ_AUTHPASSWORD, MON_AUTH, mm_answer_authpassword},
-    {MONITOR_REQ_RSAKEYALLOWED, MON_ISAUTH, mm_answer_rsa_keyallowed},
-    {MONITOR_REQ_KEYALLOWED, MON_ISAUTH, mm_answer_keyallowed},
+    {MONITOR_REQ_RSAKEYALLOWED, MON_AUTH, mm_answer_rsa_keyallowed},
+    {MONITOR_REQ_KEYALLOWED, MON_AUTH, mm_answer_keyallowed},
     {MONITOR_REQ_RSACHALLENGE, MON_ONCE, mm_answer_rsa_challenge},
     {MONITOR_REQ_RSARESPONSE, MON_ONCE|MON_AUTHDECIDE, mm_answer_rsa_response},
 #ifdef BSD_AUTH
@@ -248,7 +248,7 @@ struct mon_table mon_dispatch_proto15[] 
     {MONITOR_REQ_PAM_ACCOUNT, 0, mm_answer_pam_account},
     {MONITOR_REQ_PAM_INIT_CTX, MON_ISAUTH, mm_answer_pam_init_ctx},
     {MONITOR_REQ_PAM_QUERY, MON_ISAUTH, mm_answer_pam_query},
-    {MONITOR_REQ_PAM_RESPOND, MON_ISAUTH, mm_answer_pam_respond},
+    {MONITOR_REQ_PAM_RESPOND, MON_AUTH, mm_answer_pam_respond},
     {MONITOR_REQ_PAM_FREE_CTX, MON_ONCE|MON_AUTHDECIDE, mm_answer_pam_free_ctx},
 #endif
 #ifdef SSH_AUDIT_EVENTS
@@ -921,7 +921,8 @@ mm_answer_pam_respond(int sock, Buffer *
 	buffer_clear(m);
 	buffer_put_int(m, ret);
 	mm_request_send(sock, MONITOR_ANS_PAM_RESPOND, m);
-	auth_method = "keyboard-interactive/pam";
+	auth_method = compat20 ? "keyboard-interactive/pam" :
+	    "challenge-response";
 	if (ret == 0)
 		sshpam_authok = sshpam_ctxt;
 	return (0);
@@ -980,17 +981,20 @@ mm_answer_keyallowed(int sock, Buffer *m
 		case MM_USERKEY:
 			allowed = options.pubkey_authentication &&
 			    user_key_allowed(authctxt->pw, key);
+			auth_method = "publickey";
 			break;
 		case MM_HOSTKEY:
 			allowed = options.hostbased_authentication &&
 			    hostbased_key_allowed(authctxt->pw,
 			    cuser, chost, key);
+			auth_method = "hostbased";
 			break;
 		case MM_RSAHOSTKEY:
 			key->type = KEY_RSA1; /* XXX */
 			allowed = options.rhosts_rsa_authentication &&
 			    auth_rhosts_rsa_key_allowed(authctxt->pw,
 			    cuser, chost, key);
+			auth_method = "rsa";
 			break;
 		default:
 			fatal("%s: unknown key type %d", __func__, type);
@@ -1010,6 +1014,9 @@ mm_answer_keyallowed(int sock, Buffer *m
 		key_blobtype = type;
 		hostbased_cuser = cuser;
 		hostbased_chost = chost;
+	} else {
+		/* Log failed attempt */
+		auth_log(authctxt, 0, auth_method, compat20 ? " ssh2" : "");
 	}
 
 	debug3("%s: key %p is %s",
@@ -1374,6 +1381,7 @@ mm_answer_rsa_keyallowed(int sock, Buffe
 
 	debug3("%s entering", __func__);
 
+	auth_method = "rsa";
 	if (options.rsa_authentication && authctxt->valid) {
 		if ((client_n = BN_new()) == NULL)
 			fatal("%s: BN_new", __func__);

-- 
Darren Tucker (dtucker at zip.com.au)
GPG key 8FF4FA69 / D9A3 86E9 7EEE AF4B B2D4  37C9 C982 80C7 8FF4 FA69
    Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.