Log reason whenever a child SA is freed. This makes it easier to

distinguish "valid" reasons to close an SA, such as rekeying,
from errors.

ok sthen@

5 files changed, 58 insertions, 11 deletions

diff --git a/sbin/iked/iked.h b/sbin/iked/iked.h
index 1d31cb16b3b..bc64f5b3a7b 100644
--- a/sbin/iked/iked.h
+++ b/sbin/iked/iked.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: iked.h,v 1.124 2019/11/11 15:10:39 tobhe Exp $	*/
+/*	$OpenBSD: iked.h,v 1.125 2019/11/13 12:24:40 tobhe Exp $	*/
 
 /*
  * Copyright (c) 2019 Tobias Heider <tobias.heider@stusta.de>
@@ -412,6 +412,7 @@ struct iked_sa {
 	struct timeval			 sa_timeused;
 
 	char				*sa_tag;
+	const char			*sa_reason;	/* reason for close */
 
 	struct iked_kex			 sa_kex;
 /* XXX compat defines until everything is converted */
@@ -820,6 +821,7 @@ int	 ikev2_childsa_delete(struct iked *, struct iked_sa *,
 	    uint8_t, uint64_t, uint64_t *, int);
 void	 ikev2_ikesa_recv_delete(struct iked *, struct iked_sa *);
 void	 ikev2_ike_sa_timeout(struct iked *env, void *);
+void	 ikev2_ike_sa_setreason(struct iked_sa *, char *);
 
 struct ibuf *
 	 ikev2_prfplus(struct iked_hash *, struct ibuf *, struct ibuf *,
diff --git a/sbin/iked/ikev2.c b/sbin/iked/ikev2.c
index 9ee4fc32972..feaf5d02fec 100644
--- a/sbin/iked/ikev2.c
+++ b/sbin/iked/ikev2.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ikev2.c,v 1.177 2019/11/11 15:10:39 tobhe Exp $	*/
+/*	$OpenBSD: ikev2.c,v 1.178 2019/11/13 12:24:40 tobhe Exp $	*/
 
 /*
  * Copyright (c) 2019 Tobias Heider <tobias.heider@stusta.de>
@@ -499,6 +499,7 @@ ikev2_recv(struct iked *env, struct iked_message *msg)
 		    (ibuf_length(msg->msg_data) != ibuf_length(sa->sa_1stmsg) ||
 		    memcmp(ibuf_data(msg->msg_data), ibuf_data(sa->sa_1stmsg),
 		    ibuf_length(sa->sa_1stmsg)) != 0)) {
+			ikev2_ike_sa_setreason(sa, NULL);
 			sa_free(env, sa);
 			msg->msg_sa = sa = NULL;
 			goto done;
@@ -515,6 +516,8 @@ ikev2_recv(struct iked *env, struct iked_message *msg)
 			if (r == -1) {
 				log_warn("%s: failed to retransmit a "
 				    "response", __func__);
+				ikev2_ike_sa_setreason(sa,
+				    "retransmitting response failed");
 				sa_free(env, sa);
 			}
 			return;
@@ -559,6 +562,7 @@ done:
 
 	if (sa != NULL && sa->sa_state == IKEV2_STATE_CLOSED) {
 		log_debug("%s: closing SA", __func__);
+		ikev2_ike_sa_setreason(sa, "closed");
 		sa_free(env, sa);
 	}
 }
@@ -814,8 +818,11 @@ ikev2_init_recv(struct iked *env, struct iked_message *msg,
 		    betoh64(hdr->ike_ispi), betoh64(hdr->ike_rspi), 1,
 		    NULL)) == NULL || sa != msg->msg_sa) {
 			log_debug("%s: invalid new SA", __func__);
-			if (sa)
+			if (sa) {
+				ikev2_ike_sa_setreason(sa, "invalid new SA");
 				sa_free(env, sa);
+				sa = NULL;
+			}
 		}
 		break;
 	case IKEV2_EXCHANGE_IKE_AUTH:
@@ -929,6 +936,7 @@ ikev2_init_ike_sa_timeout(struct iked *env, void *arg)
 	    print_spi(sa->sa_hdr.sh_ispi, 8),
 	    print_spi(sa->sa_hdr.sh_rspi, 8));
 
+	ikev2_ike_sa_setreason(sa, "SA_INIT timeout");
 	sa_free(env, sa);
 }
 
@@ -1104,6 +1112,7 @@ ikev2_init_ike_sa_peer(struct iked *env, struct iked_policy *pol,
  closeonly:
 	if (ret == -1) {
 		log_debug("%s: closing SA", __func__);
+		ikev2_ike_sa_setreason(sa, "failed to send SA_INIT");
 		sa_free(env, sa);
 	}
 
@@ -2367,11 +2376,13 @@ ikev2_resp_recv(struct iked *env, struct iked_message *msg,
 			if (msg->msg_error == 0)
 				msg->msg_error = IKEV2_N_NO_PROPOSAL_CHOSEN;
 			ikev2_send_init_error(env, msg);
+			ikev2_ike_sa_setreason(sa, "no proposal chosen");
 			sa_state(env, sa, IKEV2_STATE_CLOSED);
 			return;
 		}
 		if (ikev2_resp_ike_sa_init(env, msg) != 0) {
 			log_debug("%s: failed to send init response", __func__);
+			ikev2_ike_sa_setreason(sa, "SA_INIT reponse failed");
 			sa_state(env, sa, IKEV2_STATE_CLOSED);
 			return;
 		}
@@ -2379,6 +2390,7 @@ ikev2_resp_recv(struct iked *env, struct iked_message *msg,
 	case IKEV2_EXCHANGE_IKE_AUTH:
 		if (!sa_stateok(sa, IKEV2_STATE_SA_INIT)) {
 			log_debug("%s: state mismatch", __func__);
+			ikev2_ike_sa_setreason(sa, "state mismatch IKE_AUTH");
 			sa_state(env, sa, IKEV2_STATE_CLOSED);
 			return;
 		}
@@ -2390,6 +2402,7 @@ ikev2_resp_recv(struct iked *env, struct iked_message *msg,
 		if (ikev2_ike_auth_recv(env, sa, msg) != 0) {
 			log_debug("%s: failed to send auth response", __func__);
 			ikev2_send_error(env, sa, msg, hdr->ike_exchange);
+			ikev2_ike_sa_setreason(sa, "IKE_AUTH failed");
 			sa_state(env, sa, IKEV2_STATE_CLOSED);
 			return;
 		}
@@ -2570,6 +2583,7 @@ ikev2_send_auth_failed(struct iked *env, struct iked_sa *sa)
 	timer_set(env, &sa->sa_timer, ikev2_ike_sa_timeout, sa);
 	timer_add(env, &sa->sa_timer, IKED_IKE_SA_DELETE_TIMEOUT);
 	config_free_fragments(&sa->sa_fragments);
+	ikev2_ike_sa_setreason(sa, "authentication failed");
 
 	return (ret);
 }
@@ -3271,8 +3285,10 @@ ikev2_ike_sa_rekey(struct iked *env, void *arg)
 		nsa = NULL;
 	}
 done:
-	if (nsa)
+	if (nsa) {
+		ikev2_ike_sa_setreason(nsa, "failed to send CREATE_CHILD_SA");
 		sa_free(env, nsa);
+	}
 	ibuf_release(e);
 
 	if (ret == 0)
@@ -3349,8 +3365,12 @@ ikev2_init_create_child_sa(struct iked *env, struct iked_message *msg)
 		if ((nsa = sa_new(env, sa->sa_nexti->sa_hdr.sh_ispi,
 		    spi->spi, 1, NULL)) == NULL || nsa != sa->sa_nexti) {
 			log_debug("%s: invalid rekey SA", __func__);
-			if (nsa)
+			if (nsa) {
+				ikev2_ike_sa_setreason(nsa,
+				    "invalid SA for rekey");
 				sa_free(env, nsa);
+			}
+			ikev2_ike_sa_setreason(sa->sa_nexti, "invalid SA nexti");
 			sa_free(env, sa->sa_nexti);
 			sa->sa_nexti = NULL;
 			return (-1);
@@ -3394,6 +3414,8 @@ ikev2_init_create_child_sa(struct iked *env, struct iked_message *msg)
 			dsa->sa_fd = sa->sa_fd;
 			dsa->sa_natt = sa->sa_natt;
 			dsa->sa_udpencap = sa->sa_udpencap;
+			ikev2_ike_sa_setreason(dsa,
+			    "resolving simultaneous rekeying");
 			ikev2_ikesa_delete(env, dsa, dsa->sa_hdr.sh_initiator);
 		}
 		sa->sa_nexti = sa->sa_nextr = NULL;
@@ -3616,6 +3638,7 @@ ikev2_ikesa_enable(struct iked *env, struct iked_sa *sa, struct iked_sa *nsa)
 	if (sa->sa_state == IKEV2_STATE_ESTABLISHED)
 		ikev2_disable_timer(env, sa);
 
+	ikev2_ike_sa_setreason(sa, "SA rekeyed");
 	ikev2_ikesa_delete(env, sa, nsa->sa_hdr.sh_initiator);
 	return (0);
 }
@@ -3653,6 +3676,7 @@ done:
 	/* Remove IKE-SA after timeout, e.g. if we don't get a delete */
 	timer_set(env, &sa->sa_timer, ikev2_ike_sa_timeout, sa);
 	timer_add(env, &sa->sa_timer, IKED_IKE_SA_DELETE_TIMEOUT);
+	ikev2_ike_sa_setreason(sa, "deleting SA");
 }
 
 void
@@ -3671,9 +3695,12 @@ ikev2_ikesa_recv_delete(struct iked *env, struct iked_sa *sa)
 			    SPI_SA(sa, __func__));
 			ikev2_ikesa_enable(env, sa, sa->sa_nextr);
 		}
+		ikev2_ike_sa_setreason(sa->sa_nexti,
+		    "received delete (simultaneous rekeying)");
 		sa_free(env, sa->sa_nexti);
 		sa->sa_nextr = sa->sa_nexti = NULL;
 	}
+	ikev2_ike_sa_setreason(sa, "received delete");
 	sa_state(env, sa, IKEV2_STATE_CLOSED);
 }
 
@@ -3953,11 +3980,20 @@ ikev2_resp_create_child_sa(struct iked *env, struct iked_message *msg)
 }
 
 void
+ikev2_ike_sa_setreason(struct iked_sa *sa, char *reason)
+{
+	/* allow update only if reason is reset to NULL */
+	if (reason == NULL || sa->sa_reason == NULL)
+		sa->sa_reason = reason;
+}
+
+void
 ikev2_ike_sa_timeout(struct iked *env, void *arg)
 {
 	struct iked_sa			*sa = arg;
 
 	log_debug("%s: closing SA", __func__);
+	ikev2_ike_sa_setreason(sa, "timeout");
 	sa_free(env, sa);
 }
 
@@ -3967,6 +4003,7 @@ ikev2_ike_sa_rekey_timeout(struct iked *env, void *arg)
 	struct iked_sa			*sa = arg;
 
 	log_debug("%s: closing SA", __func__);
+	ikev2_ike_sa_setreason(sa, "rekey timeout");
 	sa_free(env, sa);
 }
 
diff --git a/sbin/iked/ikev2_msg.c b/sbin/iked/ikev2_msg.c
index d1ee03ac29e..d8e005eeb11 100644
--- a/sbin/iked/ikev2_msg.c
+++ b/sbin/iked/ikev2_msg.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ikev2_msg.c,v 1.57 2019/11/11 15:10:39 tobhe Exp $	*/
+/*	$OpenBSD: ikev2_msg.c,v 1.58 2019/11/13 12:24:40 tobhe Exp $	*/
 
 /*
  * Copyright (c) 2019 Tobias Heider <tobias.heider@stusta.de>
@@ -1214,6 +1214,7 @@ ikev2_msg_retransmit_timeout(struct iked *env, void *arg)
 		    (struct sockaddr *)&msg->msg_local,
 		    msg->msg_locallen) == -1) {
 			log_warn("%s: sendtofrom", __func__);
+			ikev2_ike_sa_setreason(sa, "retransmit failed");
 			sa_free(env, sa);
 			return;
 		}
@@ -1223,6 +1224,7 @@ ikev2_msg_retransmit_timeout(struct iked *env, void *arg)
 	} else {
 		log_debug("%s: retransmit limit reached for msgid %u",
 		    __func__, msg->msg_msgid);
+		ikev2_ike_sa_setreason(sa, "retransmit limit reached");
 		sa_free(env, sa);
 	}
 }
diff --git a/sbin/iked/ikev2_pld.c b/sbin/iked/ikev2_pld.c
index 40cfac9fd33..e92bd3be2a7 100644
--- a/sbin/iked/ikev2_pld.c
+++ b/sbin/iked/ikev2_pld.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: ikev2_pld.c,v 1.74 2019/08/24 13:09:38 tobhe Exp $	*/
+/*	$OpenBSD: ikev2_pld.c,v 1.75 2019/11/13 12:24:40 tobhe Exp $	*/
 
 /*
  * Copyright (c) 2019 Tobias Heider <tobias.heider@stusta.de>
@@ -1062,6 +1062,8 @@ ikev2_pld_notify(struct iked *env, struct ikev2_payload *pld,
 			}
 		}
 		log_debug("%s: AUTHENTICATION_FAILED, closing SA", __func__);
+		ikev2_ike_sa_setreason(msg->msg_sa,
+		    "authentication failed notification from peer");
 		sa_state(env, msg->msg_sa, IKEV2_STATE_CLOSED);
 		msg->msg_sa = NULL;
 		break;
diff --git a/sbin/iked/policy.c b/sbin/iked/policy.c
index 82794000d00..24f7a009d86 100644
--- a/sbin/iked/policy.c
+++ b/sbin/iked/policy.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: policy.c,v 1.48 2019/08/12 07:40:45 tobhe Exp $	*/
+/*	$OpenBSD: policy.c,v 1.49 2019/11/13 12:24:40 tobhe Exp $	*/
 
 /*
  * Copyright (c) 2010-2013 Reyk Floeter <reyk@openbsd.org>
@@ -377,6 +377,7 @@ sa_new(struct iked *env, uint64_t ispi, uint64_t rspi,
 	if (!ibuf_length(localid->id_buf) && pol != NULL &&
 	    ikev2_policy2id(&pol->pol_localid, localid, 1) != 0) {
 		log_debug("%s: failed to get local id", __func__);
+		ikev2_ike_sa_setreason(sa, "failed to get local id");
 		sa_free(env, sa);
 		return (NULL);
 	}
@@ -387,9 +388,12 @@ sa_new(struct iked *env, uint64_t ispi, uint64_t rspi,
 void
 sa_free(struct iked *env, struct iked_sa *sa)
 {
-	log_debug("%s: ispi %s rspi %s", __func__,
-	    print_spi(sa->sa_hdr.sh_ispi, 8),
-	    print_spi(sa->sa_hdr.sh_rspi, 8));
+	if (sa->sa_reason)
+		log_info("%s: %s", SPI_SA(sa, __func__), sa->sa_reason);
+	else
+		log_debug("%s: ispi %s rspi %s", SPI_SA(sa, __func__),
+		    print_spi(sa->sa_hdr.sh_ispi, 8),
+		    print_spi(sa->sa_hdr.sh_rspi, 8));
 
 	/* IKE rekeying running? */
 	if (sa->sa_nexti) {