Currently we print a log message whenever an SA state is changed. When the SA
is deleted we print something like "sa_state: ... -> CLOSED", without giving
any context why it was dropped.
This diff adds a mechanism to specify the reason why the SA was freed.
The old output looks like something is broken:
spi=0x175f15ff82672003: sa_state: AUTH_SUCCESS -> ESTABLISHED from
10.0.1.33:500 to 10.0.1.34:500 policy 'test'
spi=0x5e3d6af7b2ea15ed: ikev2_ikesa_recv_delete: received delete
spi=0x5e3d6af7b2ea15ed: sa_state: CLOSING -> CLOSED from 10.0.1.33:500 to
10.0.1.34:500 policy 'test'
With the diff it is clear that the SA was freed because it has been rekeyed:
spi=0x175f15ff82672003: sa_state: AUTH_SUCCESS -> ESTABLISHED from
10.0.1.34:500 to 10.0.1.33:500 policy 'test'
spi=0x5e3d6af7b2ea15ed: ikev2_ikesa_delete: sent delete, closing SA
spi=0x5e3d6af7b2ea15ed: sa_state: ESTABLISHED -> CLOSED from 10.0.1.34:500 to
10.0.1.33:500 policy 'test'
spi=0x5e3d6af7b2ea15ed: sa_free: SA rekeyed
It's pretty useful for debugging because it helps to find out what went wrong.
ok?
diff --git a/sbin/iked/iked.h b/sbin/iked/iked.h
index 1717723a08d..a9c71178f1e 100644
--- a/sbin/iked/iked.h
+++ b/sbin/iked/iked.h
@@ -412,6 +412,7 @@ struct iked_sa {
struct timeval sa_timeused;
char *sa_tag;
+ 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 f6148be352b..514cf40a268 100644
--- a/sbin/iked/ikev2.c
+++ b/sbin/iked/ikev2.c
@@ -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;
@@ -558,6 +561,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);
}
}
@@ -813,8 +817,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:
@@ -928,6 +935,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);
}
@@ -1103,6 +1111,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);
}
@@ -2366,11 +2375,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;
}
@@ -2378,6 +2389,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;
}
@@ -2389,6 +2401,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;
}
@@ -2569,6 +2582,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);
}
@@ -3270,8 +3284,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)
@@ -3348,8 +3364,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);
@@ -3393,6 +3413,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;
@@ -3615,6 +3637,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);
}
@@ -3652,6 +3675,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
@@ -3670,9 +3694,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);
}
@@ -3951,12 +3978,21 @@ ikev2_resp_create_child_sa(struct iked *env, struct
iked_message *msg)
return (-1);
}
+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);
}
@@ -3966,6 +4002,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 a0df12192d1..10aa3b3a10f 100644
--- a/sbin/iked/ikev2_msg.c
+++ b/sbin/iked/ikev2_msg.c
@@ -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..7ecf6927209 100644
--- a/sbin/iked/ikev2_pld.c
+++ b/sbin/iked/ikev2_pld.c
@@ -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 c4c41e3aabd..5e17bd0e4fb 100644
--- a/sbin/iked/policy.c
+++ b/sbin/iked/policy.c
@@ -379,6 +379,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);
}
@@ -389,9 +390,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) {
