From 192e534d32a1fb6e36c0817d3241a5f15e088461 Mon Sep 17 00:00:00 2001
From: djm <djm@openbsd.org>
Date: Fri, 14 Sep 2018 04:17:12 +0000
Subject: [PATCH] Use consistent format in debug log for keys readied, offered
 and received during public key authentication.

This makes it a little easier to see what is going on, as each message
now contains the key filename, its type and fingerprint, and whether
the key is hosted in an agent or a token.
---
 usr.bin/ssh/sshconnect2.c | 73 +++++++++++++++++++++++++--------------
 1 file changed, 47 insertions(+), 26 deletions(-)

diff --git a/usr.bin/ssh/sshconnect2.c b/usr.bin/ssh/sshconnect2.c
index 957a04b692c..206b711bcb0 100644
--- a/usr.bin/ssh/sshconnect2.c
+++ b/usr.bin/ssh/sshconnect2.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: sshconnect2.c,v 1.284 2018/08/13 02:41:05 djm Exp $ */
+/* $OpenBSD: sshconnect2.c,v 1.285 2018/09/14 04:17:12 djm Exp $ */
 /*
  * Copyright (c) 2000 Markus Friedl.  All rights reserved.
  * Copyright (c) 2008 Damien Miller.  All rights reserved.
@@ -573,6 +573,27 @@ input_userauth_failure(int type, u_int32_t seq, struct ssh *ssh)
 	return 0;
 }
 
+/*
+ * Format an identity for logging including filename, key type, fingerprint
+ * and location (agent, etc.). Caller must free.
+ */
+static char *
+format_identity(Identity *id)
+{
+	char *fp, *ret = NULL;
+
+	if ((fp = sshkey_fingerprint(id->key, options.fingerprint_hash,
+	    SSH_FP_DEFAULT)) == NULL)
+		fatal("%s: sshkey_fingerprint failed", __func__);
+	xasprintf(&ret, "%s %s %s%s%s%s",
+	    id->filename, sshkey_type(id->key), fp,
+	    id->userprovided ? ", explicit" : "",
+	    (id->key->flags & SSHKEY_FLAG_EXT) ? ", token" : "",
+	    id->agent_fd != -1 ? ", agent" : "");
+	free(fp);
+	return ret;
+}
+
 /* ARGSUSED */
 int
 input_userauth_pk_ok(int type, u_int32_t seq, struct ssh *ssh)
@@ -580,9 +601,9 @@ input_userauth_pk_ok(int type, u_int32_t seq, struct ssh *ssh)
 	Authctxt *authctxt = ssh->authctxt;
 	struct sshkey *key = NULL;
 	Identity *id = NULL;
-	int pktype, sent = 0;
+	int pktype, found = 0, sent = 0;
 	size_t blen;
-	char *pkalg = NULL, *fp;
+	char *pkalg = NULL, *fp = NULL, *ident = NULL;
 	u_char *pkblob = NULL;
 	int r;
 
@@ -594,10 +615,8 @@ input_userauth_pk_ok(int type, u_int32_t seq, struct ssh *ssh)
 	    (r = sshpkt_get_end(ssh)) != 0)
 		goto done;
 
-	debug("Server accepts key: pkalg %s blen %zu", pkalg, blen);
-
 	if ((pktype = sshkey_type_from_name(pkalg)) == KEY_UNSPEC) {
-		debug("unknown pkalg %s", pkalg);
+		debug("%s: server sent unknown pkalg %s", __func__, pkalg);
 		goto done;
 	}
 	if ((r = sshkey_from_blob(pkblob, blen, &key)) != 0) {
@@ -610,11 +629,6 @@ input_userauth_pk_ok(int type, u_int32_t seq, struct ssh *ssh)
 		    key->type, pktype);
 		goto done;
 	}
-	if ((fp = sshkey_fingerprint(key, options.fingerprint_hash,
-	    SSH_FP_DEFAULT)) == NULL)
-		goto done;
-	debug2("input_userauth_pk_ok: fp %s", fp);
-	free(fp);
 
 	/*
 	 * search keys in the reverse order, because last candidate has been
@@ -623,13 +637,25 @@ input_userauth_pk_ok(int type, u_int32_t seq, struct ssh *ssh)
 	 */
 	TAILQ_FOREACH_REVERSE(id, &authctxt->keys, idlist, next) {
 		if (sshkey_equal(key, id->key)) {
-			sent = sign_and_send_pubkey(ssh, authctxt, id);
+			found = 1;
 			break;
 		}
 	}
+	if (!found || id == NULL) {
+		fp = sshkey_fingerprint(key, options.fingerprint_hash,
+		    SSH_FP_DEFAULT);
+		error("%s: server replied with unknown key: %s %s", __func__,
+		    sshkey_type(key), fp == NULL ? "<ERROR>" : fp);
+		goto done;
+	}
+	ident = format_identity(id);
+	debug("Server accepts key: %s", ident);
+	sent = sign_and_send_pubkey(ssh, authctxt, id);
 	r = 0;
  done:
 	sshkey_free(key);
+	free(ident);
+	free(fp);
 	free(pkalg);
 	free(pkblob);
 
@@ -1450,6 +1476,7 @@ pubkey_prepare(Authctxt *authctxt)
 	int agent_fd = -1, i, r, found;
 	size_t j;
 	struct ssh_identitylist *idlist;
+	char *ident;
 
 	TAILQ_INIT(&agent);	/* keys from the agent */
 	TAILQ_INIT(&files);	/* keys from the config file */
@@ -1566,10 +1593,11 @@ pubkey_prepare(Authctxt *authctxt)
 			memset(id, 0, sizeof(*id));
 			continue;
 		}
-		debug2("key: %s (%p)%s%s", id->filename, id->key,
-		    id->userprovided ? ", explicit" : "",
-		    id->agent_fd != -1 ? ", agent" : "");
+		ident = format_identity(id);
+		debug("Will attempt key: %s", ident);
+		free(ident);
 	}
+	debug2("%s: done", __func__);
 }
 
 static void
@@ -1617,7 +1645,7 @@ userauth_pubkey(Authctxt *authctxt)
 	struct ssh *ssh = active_state; /* XXX */
 	Identity *id;
 	int sent = 0;
-	char *fp;
+	char *ident;
 
 	while ((id = TAILQ_FIRST(&authctxt->keys))) {
 		if (id->tried++)
@@ -1632,16 +1660,9 @@ userauth_pubkey(Authctxt *authctxt)
 		 */
 		if (id->key != NULL) {
 			if (try_identity(id)) {
-				if ((fp = sshkey_fingerprint(id->key,
-				    options.fingerprint_hash,
-				    SSH_FP_DEFAULT)) == NULL) {
-					error("%s: sshkey_fingerprint failed",
-					    __func__);
-					return 0;
-				}
-				debug("Offering public key: %s %s %s",
-				    sshkey_type(id->key), fp, id->filename);
-				free(fp);
+				ident = format_identity(id);
+				debug("Offering public key: %s", ident);
+				free(ident);
 				sent = send_pubkey_test(ssh, authctxt, id);
 			}
 		} else {
-- 
2.20.1