- djm@cvs.openbsd.org 2013/05/19 02:42:42

     [auth.h auth.c key.c monitor.c auth-rsa.c auth2.c auth1.c key.h]
     Standardise logging of supplemental information during userauth. Keys
     and ruser is now logged in the auth success/failure message alongside
     the local username, remote host/port and protocol in use. Certificates
     contents and CA are logged too.
     Pushing all logging onto a single line simplifies log analysis as it is
     no longer necessary to relate information scattered across multiple log
     entries. "I like it" markus@

9 files changed, 76 insertions, 45 deletions

diff --git a/ChangeLog b/ChangeLog
index c08e210be..d772486f5 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -26,6 +26,15 @@
      [auth2-pubkey.c]
      fix failure to recognise cert-authority keys if a key of a different type
      appeared in authorized_keys before it; ok markus@
+   - djm@cvs.openbsd.org 2013/05/19 02:42:42
+     [auth.h auth.c key.c monitor.c auth-rsa.c auth2.c auth1.c key.h]
+     Standardise logging of supplemental information during userauth. Keys
+     and ruser is now logged in the auth success/failure message alongside
+     the local username, remote host/port and protocol in use. Certificates
+     contents and CA are logged too.
+     Pushing all logging onto a single line simplifies log analysis as it is
+     no longer necessary to relate information scattered across multiple log
+     entries. "I like it" markus@
 
 20130529
   - (dtucker) [configure.ac openbsd-compat/bsd-misc.h] bz#2087: Add a null
diff --git a/auth-rsa.c b/auth-rsa.c
index 748eaae09..92f0ad75c 100644
--- a/auth-rsa.c
+++ b/auth-rsa.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: auth-rsa.c,v 1.82 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: auth-rsa.c,v 1.83 2013/05/19 02:42:42 djm Exp $ */
 /*
  * Author: Tatu Ylonen <ylo@cs.hut.fi>
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
@@ -164,7 +164,7 @@ static int
 rsa_key_allowed_in_file(struct passwd *pw, char *file,
     const BIGNUM *client_n, Key **rkey)
 {
-	char line[SSH_MAX_PUBKEY_BYTES];
+	char *fp, line[SSH_MAX_PUBKEY_BYTES];
 	int allowed = 0;
 	u_int bits;
 	FILE *f;
@@ -232,6 +232,11 @@ rsa_key_allowed_in_file(struct passwd *pw, char *file,
 			    "actual %d vs. announced %d.",
 			    file, linenum, BN_num_bits(key->rsa->n), bits);
 
+		fp = key_fingerprint(key, SSH_FP_MD5, SSH_FP_HEX);
+		debug("matching key found: file %s, line %lu %s %s",
+		    file, linenum, key_type(key), fp);
+		free(fp);
+
 		/* Never accept a revoked key */
 		if (auth_key_is_revoked(key))
 			break;
@@ -298,7 +303,6 @@ int
 auth_rsa(Authctxt *authctxt, BIGNUM *client_n)
 {
 	Key *key;
-	char *fp;
 	struct passwd *pw = authctxt->pw;
 
 	/* no user given */
@@ -328,11 +332,7 @@ auth_rsa(Authctxt *authctxt, BIGNUM *client_n)
 	 * options; this will be reset if the options cause the
 	 * authentication to be rejected.
 	 */
-	fp = key_fingerprint(key, SSH_FP_MD5, SSH_FP_HEX);
-	verbose("Found matching %s key: %s",
-	    key_type(key), fp);
-	free(fp);
-	key_free(key);
+	pubkey_auth_info(authctxt, key);
 
 	packet_send_debug("RSA authentication accepted.");
 	return (1);
diff --git a/auth.c b/auth.c
index ac126e6f3..9a36f1dac 100644
--- a/auth.c
+++ b/auth.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: auth.c,v 1.102 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: auth.c,v 1.103 2013/05/19 02:42:42 djm Exp $ */
 /*
  * Copyright (c) 2000 Markus Friedl.  All rights reserved.
  *
@@ -72,6 +72,7 @@
 #include "authfile.h"
 #include "monitor_wrap.h"
 #include "krl.h"
+#include "compat.h"
 
 /* import */
 extern ServerOptions options;
@@ -252,8 +253,25 @@ allowed_user(struct passwd * pw)
 }
 
 void
+auth_info(Authctxt *authctxt, const char *fmt, ...)
+{
+	va_list ap;
+        int i;
+
+	free(authctxt->info);
+	authctxt->info = NULL;
+
+	va_start(ap, fmt);
+	i = vasprintf(&authctxt->info, fmt, ap);
+	va_end(ap);
+
+	if (i < 0 || authctxt->info == NULL)
+		fatal("vasprintf failed");
+}
+
+void
 auth_log(Authctxt *authctxt, int authenticated, int partial,
-    const char *method, const char *submethod, const char *info)
+    const char *method, const char *submethod)
 {
 	void (*authlog) (const char *fmt,...) = verbose;
 	char *authmsg;
@@ -275,7 +293,7 @@ auth_log(Authctxt *authctxt, int authenticated, int partial,
 	else
 		authmsg = authenticated ? "Accepted" : "Failed";
 
-	authlog("%s %s%s%s for %s%.100s from %.200s port %d%s",
+	authlog("%s %s%s%s for %s%.100s from %.200s port %d %s%s%s",
 	    authmsg,
 	    method,
 	    submethod != NULL ? "/" : "", submethod == NULL ? "" : submethod,
@@ -283,7 +301,11 @@ auth_log(Authctxt *authctxt, int authenticated, int partial,
 	    authctxt->user,
 	    get_remote_ipaddr(),
 	    get_remote_port(),
-	    info);
+	    compat20 ? "ssh2" : "ssh1",
+	    authctxt->info != NULL ? ": " : "",
+	    authctxt->info != NULL ? authctxt->info : "");
+	free(authctxt->info);
+	authctxt->info = NULL;
 
 #ifdef CUSTOM_FAILED_LOGIN
 	if (authenticated == 0 && !authctxt->postponed &&
diff --git a/auth.h b/auth.h
index 7ff59f1ba..a406e1393 100644
--- a/auth.h
+++ b/auth.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: auth.h,v 1.73 2013/03/07 19:27:25 markus Exp $ */
+/* $OpenBSD: auth.h,v 1.74 2013/05/19 02:42:42 djm Exp $ */
 
 /*
  * Copyright (c) 2000 Markus Friedl.  All rights reserved.
@@ -60,6 +60,7 @@ struct Authctxt {
 	struct passwd	*pw;		/* set if 'valid' */
 	char		*style;
 	void		*kbdintctxt;
+	char		*info;		/* Extra info for next auth_log */
 	void		*jpake_ctx;
 #ifdef BSD_AUTH
 	auth_session_t	*as;
@@ -121,6 +122,7 @@ int	 auth_rsa_key_allowed(struct passwd *, BIGNUM *, Key **);
 int	 auth_rhosts_rsa_key_allowed(struct passwd *, char *, char *, Key *);
 int	 hostbased_key_allowed(struct passwd *, const char *, char *, Key *);
 int	 user_key_allowed(struct passwd *, Key *);
+void	 pubkey_auth_info(Authctxt *, const Key *);
 
 struct stat;
 int	 auth_secure_path(const char *, struct stat *, const char *, uid_t,
@@ -148,8 +150,10 @@ void disable_forwarding(void);
 void	do_authentication(Authctxt *);
 void	do_authentication2(Authctxt *);
 
-void	auth_log(Authctxt *, int, int, const char *, const char *,
-    const char *);
+void	auth_info(Authctxt *authctxt, const char *, ...)
+	    __attribute__((__format__ (printf, 2, 3)))
+	    __attribute__((__nonnull__ (2)));
+void	auth_log(Authctxt *, int, int, const char *, const char *);
 void	userauth_finish(Authctxt *, int, const char *, const char *);
 int	auth_root_allowed(const char *);
 
diff --git a/auth1.c b/auth1.c
index 238b3c9c3..3518fb1c6 100644
--- a/auth1.c
+++ b/auth1.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: auth1.c,v 1.78 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: auth1.c,v 1.79 2013/05/19 02:42:42 djm Exp $ */
 /*
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
  *                    All rights reserved
@@ -45,11 +45,11 @@
 extern ServerOptions options;
 extern Buffer loginmsg;
 
-static int auth1_process_password(Authctxt *, char *, size_t);
-static int auth1_process_rsa(Authctxt *, char *, size_t);
-static int auth1_process_rhosts_rsa(Authctxt *, char *, size_t);
-static int auth1_process_tis_challenge(Authctxt *, char *, size_t);
-static int auth1_process_tis_response(Authctxt *, char *, size_t);
+static int auth1_process_password(Authctxt *);
+static int auth1_process_rsa(Authctxt *);
+static int auth1_process_rhosts_rsa(Authctxt *);
+static int auth1_process_tis_challenge(Authctxt *);
+static int auth1_process_tis_response(Authctxt *);
 
 static char *client_user = NULL;    /* Used to fill in remote user for PAM */
 
@@ -57,7 +57,7 @@ struct AuthMethod1 {
 	int type;
 	char *name;
 	int *enabled;
-	int (*method)(Authctxt *, char *, size_t);
++	int (*method)(Authctxt *);
 };
 
 const struct AuthMethod1 auth1_methods[] = {
@@ -112,7 +112,7 @@ get_authname(int type)
 
 /*ARGSUSED*/
 static int
-auth1_process_password(Authctxt *authctxt, char *info, size_t infolen)
+auth1_process_password(Authctxt *authctxt)
 {
 	int authenticated = 0;
 	char *password;
@@ -137,7 +137,7 @@ auth1_process_password(Authctxt *authctxt, char *info, size_t infolen)
 
 /*ARGSUSED*/
 static int
-auth1_process_rsa(Authctxt *authctxt, char *info, size_t infolen)
+auth1_process_rsa(Authctxt *authctxt)
 {
 	int authenticated = 0;
 	BIGNUM *n;
@@ -155,7 +155,7 @@ auth1_process_rsa(Authctxt *authctxt, char *info, size_t infolen)
 
 /*ARGSUSED*/
 static int
-auth1_process_rhosts_rsa(Authctxt *authctxt, char *info, size_t infolen)
+auth1_process_rhosts_rsa(Authctxt *authctxt)
 {
 	int keybits, authenticated = 0;
 	u_int bits;
@@ -187,14 +187,14 @@ auth1_process_rhosts_rsa(Authctxt *authctxt, char *info, size_t infolen)
 	    client_host_key);
 	key_free(client_host_key);
 
-	snprintf(info, infolen, " ruser %.100s", client_user);
+	auth_info(authctxt, "ruser %.100s", client_user);
 
 	return (authenticated);
 }
 
 /*ARGSUSED*/
 static int
-auth1_process_tis_challenge(Authctxt *authctxt, char *info, size_t infolen)
+auth1_process_tis_challenge(Authctxt *authctxt)
 {
 	char *challenge;
 
@@ -213,7 +213,7 @@ auth1_process_tis_challenge(Authctxt *authctxt, char *info, size_t infolen)
 
 /*ARGSUSED*/
 static int
-auth1_process_tis_response(Authctxt *authctxt, char *info, size_t infolen)
+auth1_process_tis_response(Authctxt *authctxt)
 {
 	int authenticated = 0;
 	char *response;
@@ -236,7 +236,6 @@ static void
 do_authloop(Authctxt *authctxt)
 {
 	int authenticated = 0;
-	char info[1024];
 	int prev = 0, type = 0;
 	const struct AuthMethod1 *meth;
 
@@ -254,7 +253,7 @@ do_authloop(Authctxt *authctxt)
 #endif
 		{
 			auth_log(authctxt, 1, 0, "without authentication",
-			    NULL, "");
+			    NULL);
 			return;
 		}
 	}
@@ -268,7 +267,6 @@ do_authloop(Authctxt *authctxt)
 		/* default to fail */
 		authenticated = 0;
 
-		info[0] = '\0';
 
 		/* Get a packet from the client. */
 		prev = type;
@@ -298,7 +296,7 @@ do_authloop(Authctxt *authctxt)
 			goto skip;
 		}
 
-		authenticated = meth->method(authctxt, info, sizeof(info));
+		authenticated = meth->method(authctxt);
 		if (authenticated == -1)
 			continue; /* "postponed" */
 
@@ -353,8 +351,7 @@ do_authloop(Authctxt *authctxt)
 
  skip:
 		/* Log before sending the reply */
-		auth_log(authctxt, authenticated, 0, get_authname(type),
-		    NULL, info);
+		auth_log(authctxt, authenticated, 0, get_authname(type), NULL);
 
 		free(client_user);
 		client_user = NULL;
diff --git a/auth2.c b/auth2.c
index 5f136ce09..f0cab8cc0 100644
--- a/auth2.c
+++ b/auth2.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: auth2.c,v 1.128 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: auth2.c,v 1.129 2013/05/19 02:42:42 djm Exp $ */
 /*
  * Copyright (c) 2000 Markus Friedl.  All rights reserved.
  *
@@ -326,7 +326,7 @@ userauth_finish(Authctxt *authctxt, int authenticated, const char *method,
 	}
 
 	/* Log before sending the reply */
-	auth_log(authctxt, authenticated, partial, method, submethod, " ssh2");
+	auth_log(authctxt, authenticated, partial, method, submethod);
 
 	if (authctxt->postponed)
 		return;
diff --git a/key.c b/key.c
index 8183ec90e..55ee78998 100644
--- a/key.c
+++ b/key.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: key.c,v 1.103 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: key.c,v 1.104 2013/05/19 02:42:42 djm Exp $ */
 /*
  * read_bignum():
  * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
@@ -569,7 +569,7 @@ key_fingerprint_randomart(u_char *dgst_raw, u_int dgst_raw_len, const Key *k)
 }
 
 char *
-key_fingerprint(Key *k, enum fp_type dgst_type, enum fp_rep dgst_rep)
+key_fingerprint(const Key *k, enum fp_type dgst_type, enum fp_rep dgst_rep)
 {
 	char *retval = NULL;
 	u_char *dgst_raw;
diff --git a/key.h b/key.h
index f2e058e9e..17358ae1f 100644
--- a/key.h
+++ b/key.h
@@ -1,4 +1,4 @@
-/* $OpenBSD: key.h,v 1.36 2013/04/19 01:06:50 djm Exp $ */
+/* $OpenBSD: key.h,v 1.37 2013/05/19 02:42:42 djm Exp $ */
 
 /*
  * Copyright (c) 2000, 2001 Markus Friedl.  All rights reserved.
@@ -95,7 +95,7 @@ void		 key_free(Key *);
 Key		*key_demote(const Key *);
 int		 key_equal_public(const Key *, const Key *);
 int		 key_equal(const Key *, const Key *);
-char		*key_fingerprint(Key *, enum fp_type, enum fp_rep);
+char		*key_fingerprint(const Key *, enum fp_type, enum fp_rep);
 u_char		*key_fingerprint_raw(const Key *, enum fp_type, u_int *);
 const char	*key_type(const Key *);
 const char	*key_cert_type(const Key *);
diff --git a/monitor.c b/monitor.c
index 132f60df9..6acb20259 100644
--- a/monitor.c
+++ b/monitor.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: monitor.c,v 1.124 2013/05/17 00:13:13 djm Exp $ */
+/* $OpenBSD: monitor.c,v 1.125 2013/05/19 02:42:42 djm Exp $ */
 /*
  * Copyright 2002 Niels Provos <provos@citi.umich.edu>
  * Copyright 2002 Markus Friedl <markus@openbsd.org>
@@ -422,8 +422,7 @@ monitor_child_preauth(Authctxt *_authctxt, struct monitor *pmonitor)
 		}
 		if (ent->flags & (MON_AUTHDECIDE|MON_ALOG)) {
 			auth_log(authctxt, authenticated, partial,
-			    auth_method, auth_submethod,
-			    compat20 ? " ssh2" : "");
+			    auth_method, auth_submethod);
 			if (!authenticated)
 				authctxt->failures++;
 		}
@@ -1168,6 +1167,7 @@ mm_answer_keyallowed(int sock, Buffer *m)
 		case MM_USERKEY:
 			allowed = options.pubkey_authentication &&
 			    user_key_allowed(authctxt->pw, key);
+			pubkey_auth_info(authctxt, key);
 			auth_method = "publickey";
 			if (options.pubkey_authentication && allowed != 1)
 				auth_clear_options();
@@ -1207,8 +1207,7 @@ mm_answer_keyallowed(int sock, Buffer *m)
 		hostbased_chost = chost;
 	} else {
 		/* Log failed attempt */
-		auth_log(authctxt, 0, 0, auth_method, NULL,
-		    compat20 ? " ssh2" : "");
+		auth_log(authctxt, 0, 0, auth_method, NULL);
 		free(blob);
 		free(cuser);
 		free(chost);