Improve pkcs11_add_provider() logging: demote some excessively

verbose error()s to debug()s, include PKCS#11 provider name and slot
in log messages where possible.
bz#2610, based on patch from Jakub Jelen

1 files changed, 26 insertions, 15 deletions

diff --git a/usr.bin/ssh/ssh-pkcs11.c b/usr.bin/ssh/ssh-pkcs11.c
index d2e20edfd65..edbb343923a 100644
--- a/usr.bin/ssh/ssh-pkcs11.c
+++ b/usr.bin/ssh/ssh-pkcs11.c
@@ -1,4 +1,4 @@
-/* $OpenBSD: ssh-pkcs11.c,v 1.22 2016/02/12 00:20:30 djm Exp $ */
+/* $OpenBSD: ssh-pkcs11.c,v 1.23 2016/10/28 03:33:52 djm Exp $ */
 /*
  * Copyright (c) 2010 Markus Friedl.  All rights reserved.
  *
@@ -567,7 +567,8 @@ pkcs11_add_provider(char *provider_id, char *pin, struct sshkey ***keyp)
 
 	*keyp = NULL;
 	if (pkcs11_provider_lookup(provider_id) != NULL) {
-		error("provider already registered: %s", provider_id);
+		debug("%s: provider already registered: %s",
+		    __func__, provider_id);
 		goto fail;
 	}
 	/* open shared pkcs11-libarary */
@@ -584,23 +585,27 @@ pkcs11_add_provider(char *provider_id, char *pin, struct sshkey ***keyp)
 	p->handle = handle;
 	/* setup the pkcs11 callbacks */
 	if ((rv = (*getfunctionlist)(&f)) != CKR_OK) {
-		error("C_GetFunctionList failed: %lu", rv);
+		error("C_GetFunctionList for provider %s failed: %lu",
+		    provider_id, rv);
 		goto fail;
 	}
 	p->function_list = f;
 	if ((rv = f->C_Initialize(NULL)) != CKR_OK) {
-		error("C_Initialize failed: %lu", rv);
+		error("C_Initialize for provider %s failed: %lu",
+		    provider_id, rv);
 		goto fail;
 	}
 	need_finalize = 1;
 	if ((rv = f->C_GetInfo(&p->info)) != CKR_OK) {
-		error("C_GetInfo failed: %lu", rv);
+		error("C_GetInfo for provider %s failed: %lu",
+		    provider_id, rv);
 		goto fail;
 	}
 	rmspace(p->info.manufacturerID, sizeof(p->info.manufacturerID));
 	rmspace(p->info.libraryDescription, sizeof(p->info.libraryDescription));
-	debug("manufacturerID <%s> cryptokiVersion %d.%d"
+	debug("provider %s: manufacturerID <%s> cryptokiVersion %d.%d"
 	    " libraryDescription <%s> libraryVersion %d.%d",
+	    provider_id,
 	    p->info.manufacturerID,
 	    p->info.cryptokiVersion.major,
 	    p->info.cryptokiVersion.minor,
@@ -612,13 +617,15 @@ pkcs11_add_provider(char *provider_id, char *pin, struct sshkey ***keyp)
 		goto fail;
 	}
 	if (p->nslots == 0) {
-		error("no slots");
+		debug("%s: provider %s returned no slots", __func__,
+		    provider_id);
 		goto fail;
 	}
 	p->slotlist = xcalloc(p->nslots, sizeof(CK_SLOT_ID));
 	if ((rv = f->C_GetSlotList(CK_TRUE, p->slotlist, &p->nslots))
 	    != CKR_OK) {
-		error("C_GetSlotList failed: %lu", rv);
+		error("C_GetSlotList for provider %s failed: %lu",
+		    provider_id, rv);
 		goto fail;
 	}
 	p->slotinfo = xcalloc(p->nslots, sizeof(struct pkcs11_slotinfo));
@@ -628,20 +635,23 @@ pkcs11_add_provider(char *provider_id, char *pin, struct sshkey ***keyp)
 		token = &p->slotinfo[i].token;
 		if ((rv = f->C_GetTokenInfo(p->slotlist[i], token))
 		    != CKR_OK) {
-			error("C_GetTokenInfo failed: %lu", rv);
+			error("C_GetTokenInfo for provider %s slot %lu "
+			    "failed: %lu", provider_id, (unsigned long)i, rv);
 			continue;
 		}
 		if ((token->flags & CKF_TOKEN_INITIALIZED) == 0) {
-			debug2("%s: ignoring uninitialised token in slot %lu",
-			    __func__, (unsigned long)i);
+			debug2("%s: ignoring uninitialised token in "
+			    "provider %s slot %lu", __func__,
+			    provider_id, (unsigned long)i);
 			continue;
 		}
 		rmspace(token->label, sizeof(token->label));
 		rmspace(token->manufacturerID, sizeof(token->manufacturerID));
 		rmspace(token->model, sizeof(token->model));
 		rmspace(token->serialNumber, sizeof(token->serialNumber));
-		debug("label <%s> manufacturerID <%s> model <%s> serial <%s>"
-		    " flags 0x%lx",
+		debug("provider %s slot %lu: label <%s> manufacturerID <%s> "
+		    "model <%s> serial <%s> flags 0x%lx",
+		    provider_id, (unsigned long)i,
 		    token->label, token->manufacturerID, token->model,
 		    token->serialNumber, token->flags);
 		/* open session, login with pin and retrieve public keys */
@@ -653,11 +663,12 @@ pkcs11_add_provider(char *provider_id, char *pin, struct sshkey ***keyp)
 		p->refcount++;	/* add to provider list */
 		return (nkeys);
 	}
-	error("no keys");
+	debug("%s: provider %s returned no keys", __func__, provider_id);
 	/* don't add the provider, since it does not have any keys */
 fail:
 	if (need_finalize && (rv = f->C_Finalize(NULL)) != CKR_OK)
-		error("C_Finalize failed: %lu", rv);
+		error("C_Finalize for provider %s failed: %lu",
+		    provider_id, rv);
 	if (p) {
 		free(p->slotlist);
 		free(p->slotinfo);