Attachment 3323 Details for Bug 3063 – more kex debugging

[patch] more kex debugging

kexdebug.diff (text/plain), 8.03 KB, created by Damien Miller on 2019-09-05 16:09:38 AEST

(hide)

Description:

Filename:

MIME Type:

Creator: Damien Miller

Created: 2019-09-05 16:09:38 AEST

Size: 8.03 KB

patch

obsolete

>diff --git a/kex.c b/kex.c
>index 374b827..ff79014 100644
>--- a/kex.c
>+++ b/kex.c
>@@ -334,18 +334,25 @@ kex_buf2prop(struct sshbuf *raw, int *first_kex_follows, char ***propp)
> 		r = SSH_ERR_ALLOC_FAIL;
> 		goto out;
> 	}
>-	if ((r = sshbuf_consume(b, KEX_COOKIE_LEN)) != 0) /* skip cookie */
>+	if ((r = sshbuf_consume(b, KEX_COOKIE_LEN)) != 0) { /* skip cookie */
>+		error("%s: consume cookie: %s", __func__, ssh_err(r));
> 		goto out;
>+	}
> 	/* extract kex init proposal strings */
> 	for (i = 0; i < PROPOSAL_MAX; i++) {
>-		if ((r = sshbuf_get_cstring(b, &(proposal[i]), NULL)) != 0)
>+		if ((r = sshbuf_get_cstring(b, &(proposal[i]), NULL)) != 0) {
>+			error("%s: parse proposal %u: %s", __func__,
>+			    i, ssh_err(r));
> 			goto out;
>+		}
> 		debug2("%s: %s", proposal_names[i], proposal[i]);
> 	}
> 	/* first kex follows / reserved */
> 	if ((r = sshbuf_get_u8(b, &v)) != 0 ||	/* first_kex_follows */
>-	    (r = sshbuf_get_u32(b, &i)) != 0)	/* reserved */
>+	    (r = sshbuf_get_u32(b, &i)) != 0) {	/* reserved */
>+		error("%s: parse: %s", __func__, ssh_err(r));
> 		goto out;
>+	}
> 	if (first_kex_follows != NULL)
> 		*first_kex_follows = v;
> 	debug2("first_kex_follows %d ", v);
>@@ -398,6 +405,7 @@ kex_send_ext_info(struct ssh *ssh)
> 	int r;
> 	char *algs;
> 
>+	debug("Sending SSH2_MSG_EXT_INFO");
> 	if ((algs = sshkey_alg_list(0, 1, 1, ',')) == NULL)
> 		return SSH_ERR_ALLOC_FAIL;
> 	/* XXX filter algs list by allowed pubkey/hostbased types */
>@@ -405,8 +413,10 @@ kex_send_ext_info(struct ssh *ssh)
> 	    (r = sshpkt_put_u32(ssh, 1)) != 0 ||
> 	    (r = sshpkt_put_cstring(ssh, "server-sig-algs")) != 0 ||
> 	    (r = sshpkt_put_cstring(ssh, algs)) != 0 ||
>-	    (r = sshpkt_send(ssh)) != 0)
>+	    (r = sshpkt_send(ssh)) != 0) {
>+		error("%s: compose: %s", __func__, ssh_err(r));
> 		goto out;
>+	}
> 	/* success */
> 	r = 0;
>  out:
>@@ -424,11 +434,11 @@ kex_send_newkeys(struct ssh *ssh)
> 	    (r = sshpkt_send(ssh)) != 0)
> 		return r;
> 	debug("SSH2_MSG_NEWKEYS sent");
>-	debug("expecting SSH2_MSG_NEWKEYS");
> 	ssh_dispatch_set(ssh, SSH2_MSG_NEWKEYS, &kex_input_newkeys);
>-	if (ssh->kex->ext_info_c)
>+	if (ssh->kex->ext_info_c && (ssh->kex->flags & KEX_INITIAL) != 0)
> 		if ((r = kex_send_ext_info(ssh)) != 0)
> 			return r;
>+	debug("expecting SSH2_MSG_NEWKEYS");
> 	return 0;
> }
> 
>@@ -500,23 +510,32 @@ kex_send_kexinit(struct ssh *ssh)
> 	struct kex *kex = ssh->kex;
> 	int r;
> 
>-	if (kex == NULL)
>+	if (kex == NULL) {
>+		error("%s: no hex", __func__);
> 		return SSH_ERR_INTERNAL_ERROR;
>+	}
> 	if (kex->flags & KEX_INIT_SENT)
> 		return 0;
> 	kex->done = 0;
> 
> 	/* generate a random cookie */
>-	if (sshbuf_len(kex->my) < KEX_COOKIE_LEN)
>+	if (sshbuf_len(kex->my) < KEX_COOKIE_LEN) {
>+		error("%s: bad kex length: %zu < %d", __func__,
>+		    sshbuf_len(kex->my), KEX_COOKIE_LEN);
> 		return SSH_ERR_INVALID_FORMAT;
>-	if ((cookie = sshbuf_mutable_ptr(kex->my)) == NULL)
>+	}
>+	if ((cookie = sshbuf_mutable_ptr(kex->my)) == NULL) {
>+		error("%s: buffer error", __func__);
> 		return SSH_ERR_INTERNAL_ERROR;
>+	}
> 	arc4random_buf(cookie, KEX_COOKIE_LEN);
> 
> 	if ((r = sshpkt_start(ssh, SSH2_MSG_KEXINIT)) != 0 ||
> 	    (r = sshpkt_putb(ssh, kex->my)) != 0 ||
>-	    (r = sshpkt_send(ssh)) != 0)
>+	    (r = sshpkt_send(ssh)) != 0) {
>+		error("%s: compose reply: %s", __func__, ssh_err(r));
> 		return r;
>+	}
> 	debug("SSH2_MSG_KEXINIT sent");
> 	kex->flags |= KEX_INIT_SENT;
> 	return 0;
>@@ -533,21 +552,28 @@ kex_input_kexinit(int type, u_int32_t seq, struct ssh *ssh)
> 	int r;
> 
> 	debug("SSH2_MSG_KEXINIT received");
>-	if (kex == NULL)
>-		return SSH_ERR_INVALID_ARGUMENT;
>-
>+	if (kex == NULL) {
>+		error("%s: no hex", __func__);
>+		return SSH_ERR_INTERNAL_ERROR;
>+	}
> 	ssh_dispatch_set(ssh, SSH2_MSG_KEXINIT, NULL);
> 	ptr = sshpkt_ptr(ssh, &dlen);
> 	if ((r = sshbuf_put(kex->peer, ptr, dlen)) != 0)
> 		return r;
> 
> 	/* discard packet */
>-	for (i = 0; i < KEX_COOKIE_LEN; i++)
>-		if ((r = sshpkt_get_u8(ssh, NULL)) != 0)
>+	for (i = 0; i < KEX_COOKIE_LEN; i++) {
>+		if ((r = sshpkt_get_u8(ssh, NULL)) != 0) {
>+			error("%s: discard cookie: %s", __func__, ssh_err(r));
> 			return r;
>-	for (i = 0; i < PROPOSAL_MAX; i++)
>-		if ((r = sshpkt_get_string(ssh, NULL, NULL)) != 0)
>+		}
>+	}
>+	for (i = 0; i < PROPOSAL_MAX; i++) {
>+		if ((r = sshpkt_get_string(ssh, NULL, NULL)) != 0) {
>+			error("%s: discard proposal: %s", __func__, ssh_err(r));
> 			return r;
>+		}
>+	}
> 	/*
> 	 * XXX RFC4253 sec 7: "each side MAY guess" - currently no supported
> 	 * KEX method has the server move first, but a server might be using
>@@ -572,6 +598,7 @@ kex_input_kexinit(int type, u_int32_t seq, struct ssh *ssh)
> 	if (kex->kex_type < KEX_MAX && kex->kex[kex->kex_type] != NULL)
> 		return (kex->kex[kex->kex_type])(ssh);
> 
>+	error("%s: unknown kex type %u", __func__, kex->kex_type);
> 	return SSH_ERR_INTERNAL_ERROR;
> }
> 
>@@ -705,6 +732,7 @@ choose_enc(struct sshenc *enc, char *client, char *server)
> 	if (name == NULL)
> 		return SSH_ERR_NO_CIPHER_ALG_MATCH;
> 	if ((enc->cipher = cipher_by_name(name)) == NULL) {
>+		error("%s: unsupported cipher %s", __func__, name);
> 		free(name);
> 		return SSH_ERR_INTERNAL_ERROR;
> 	}
>@@ -726,6 +754,7 @@ choose_mac(struct ssh *ssh, struct sshmac *mac, char *client, char *server)
> 	if (name == NULL)
> 		return SSH_ERR_NO_MAC_ALG_MATCH;
> 	if (mac_setup(mac, name) < 0) {
>+		error("%s: unsupported MAC %s", __func__, name);
> 		free(name);
> 		return SSH_ERR_INTERNAL_ERROR;
> 	}
>@@ -749,6 +778,7 @@ choose_comp(struct sshcomp *comp, char *client, char *server)
> 	} else if (strcmp(name, "none") == 0) {
> 		comp->type = COMP_NONE;
> 	} else {
>+		error("%s: unsupported compression scheme %s", __func__, name);
> 		free(name);
> 		return SSH_ERR_INTERNAL_ERROR;
> 	}
>@@ -766,8 +796,10 @@ choose_kex(struct kex *k, char *client, char *server)
> 	debug("kex: algorithm: %s", k->name ? k->name : "(no match)");
> 	if (k->name == NULL)
> 		return SSH_ERR_NO_KEX_ALG_MATCH;
>-	if ((kexalg = kex_alg_by_name(k->name)) == NULL)
>+	if ((kexalg = kex_alg_by_name(k->name)) == NULL) {
>+		error("%s: unsupported KEX method %s", __func__, k->name);
> 		return SSH_ERR_INTERNAL_ERROR;
>+	}
> 	k->kex_type = kexalg->type;
> 	k->hash_alg = kexalg->hash_alg;
> 	k->ec_nid = kexalg->ec_nid;
>@@ -784,8 +816,11 @@ choose_hostkeyalg(struct kex *k, char *client, char *server)
> 	if (k->hostkey_alg == NULL)
> 		return SSH_ERR_NO_HOSTKEY_ALG_MATCH;
> 	k->hostkey_type = sshkey_type_from_name(k->hostkey_alg);
>-	if (k->hostkey_type == KEY_UNSPEC)
>+	if (k->hostkey_type == KEY_UNSPEC) {
>+		error("%s: unsupported hostkey algorithm %s", __func__,
>+		    k->hostkey_alg);
> 		return SSH_ERR_INTERNAL_ERROR;
>+	}
> 	k->hostkey_nid = sshkey_ecdsa_nid_from_name(k->hostkey_alg);
> 	return 0;
> }
>@@ -954,6 +989,7 @@ derive_key(struct ssh *ssh, int id, u_int need, u_char *hash, u_int hashlen,
> 	    kex->session_id_len) != 0 ||
> 	    ssh_digest_final(hashctx, digest, mdsz) != 0) {
> 		r = SSH_ERR_LIBCRYPTO_ERROR;
>+		error("%s: KEX hash failed", __func__);
> 		goto out;
> 	}
> 	ssh_digest_free(hashctx);
>@@ -970,6 +1006,7 @@ derive_key(struct ssh *ssh, int id, u_int need, u_char *hash, u_int hashlen,
> 		    ssh_digest_update(hashctx, hash, hashlen) != 0 ||
> 		    ssh_digest_update(hashctx, digest, have) != 0 ||
> 		    ssh_digest_final(hashctx, digest + have, mdsz) != 0) {
>+			error("%s: KDF failed", __func__);
> 			r = SSH_ERR_LIBCRYPTO_ERROR;
> 			goto out;
> 		}
>@@ -1033,8 +1070,10 @@ kex_load_hostkey(struct ssh *ssh, struct sshkey **prvp, struct sshkey **pubp)
> 	*pubp = NULL;
> 	*prvp = NULL;
> 	if (kex->load_host_public_key == NULL ||
>-	    kex->load_host_private_key == NULL)
>+	    kex->load_host_private_key == NULL) {
>+		error("%s: missing hostkey loader", __func__);
> 		return SSH_ERR_INVALID_ARGUMENT;
>+	}
> 	*pubp = kex->load_host_public_key(kex->hostkey_type,
> 	    kex->hostkey_nid, ssh);
> 	*prvp = kex->load_host_private_key(kex->hostkey_type,
>@@ -1049,8 +1088,10 @@ kex_verify_host_key(struct ssh *ssh, struct sshkey *server_host_key)
> {
> 	struct kex *kex = ssh->kex;
> 
>-	if (kex->verify_host_key == NULL)
>+	if (kex->verify_host_key == NULL) {
>+		error("%s: missing hostkey verifier", __func__);
> 		return SSH_ERR_INVALID_ARGUMENT;
>+	}
> 	if (server_host_key->type != kex->hostkey_type ||
> 	    (kex->hostkey_type == KEY_ECDSA &&
> 	    server_host_key->ecdsa_nid != kex->hostkey_nid))

Flags:

dtucker: ok+

Actions: View | Diff

Attachments on bug 3063: 3317 | 3320 | 3321 | 3322 | 3323 | 3324 | 3325 | 3326