- 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);