Hi,
here's another improvement for iked logging.
The diff adds a new print when a new flow is enabled and when a new pair
of child SAs is loaded into the kernel:
0xf172af722de8de1a: recv IKE_AUTH res 1 peer 10.0.1.34:500 local 10.0.1.33:500,
516 bytes, policy 'test'
spi=0xf172af722de8de1a: ikev2_childsa_enable: loaded SPIs: 0x83525a6e,
0xc8e0fe46
spi=0xf172af722de8de1a: ikev2_childsa_enable: loaded flows:
ESP-10.0.1.33/32=10.3.1.34/32(0)
This is useful to find the matching child SAs with 'ipsecctl -sa', especially
when there is more than one pair of active SAs.
FLOWS:
flow esp in from 10.3.1.34 to 10.0.1.33 peer 10.0.1.34 srcid IPV4/10.0.1.33
dstid IPV4/10.0.1.34 type use
flow esp out from 10.0.1.33 to 10.3.1.34 peer 10.0.1.34 srcid IPV4/10.0.1.33
dstid IPV4/10.0.1.34 type require
flow esp out from ::/0 to ::/0 type deny
SAD:
esp tunnel from 10.0.1.33 to 10.0.1.34 spi 0x83525a6e auth hmac-sha2-256 enc
aes-256
esp tunnel from 10.0.1.34 to 10.0.1.33 spi 0xc8e0fe46 auth hmac-sha2-256 enc
aes-256
esp tunnel from 10.0.1.34 to 10.0.1.33 spi 0x56291c85 auth hmac-sha2-256 enc
aes-256
esp tunnel from 10.0.1.33 to 10.0.1.34 spi 0xc8167d59 auth hmac-sha2-256 enc
aes-256
I also added SPI_SA in one case I missed before and lowered the
log priority of the SA state change to debug now that we have the
'loaded flows' and 'sa_free reason' prints.
ok?
Index: iked.h
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/iked.h,v
retrieving revision 1.125
diff -u -p -r1.125 iked.h
--- iked.h 13 Nov 2019 12:24:40 -0000 1.125
+++ iked.h 15 Nov 2019 16:00:56 -0000
@@ -1033,6 +1033,8 @@ struct ibuf *
int ibuf_prepend(struct ibuf *, void *, size_t);
void *ibuf_advance(struct ibuf *, size_t);
void ibuf_zero(struct ibuf *);
+int ibuf_strcat(struct ibuf **, const char *);
+int ibuf_strlen(struct ibuf *);
/* log.c */
void log_init(int, int);
Index: ikev2.c
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2.c,v
retrieving revision 1.178
diff -u -p -r1.178 ikev2.c
--- ikev2.c 13 Nov 2019 12:24:40 -0000 1.178
+++ ikev2.c 15 Nov 2019 16:00:57 -0000
@@ -5561,6 +5561,9 @@ ikev2_childsa_enable(struct iked *env, s
struct iked_childsa *csa, *ocsa;
struct iked_flow *flow, *oflow;
int peer_changed, reload;
+ struct ibuf *spibuf = NULL;
+ struct ibuf *flowbuf = NULL;
+ char *buf;
if (sa->sa_ipcomp && sa->sa_cpi_in && sa->sa_cpi_out &&
ikev2_ipcomp_enable(env, sa) == -1)
@@ -5591,6 +5594,12 @@ ikev2_childsa_enable(struct iked *env, s
log_debug("%s: loaded CHILD SA spi %s", __func__,
print_spi(csa->csa_spi.spi, csa->csa_spi.spi_size));
+
+ /* append SPI to log buffer */
+ if (ibuf_strlen(spibuf))
+ ibuf_strcat(&spibuf, ", ");
+ ibuf_strcat(&spibuf, print_spi(csa->csa_spi.spi,
+ csa->csa_spi.spi_size));
}
peer_changed = (memcmp(&sa->sa_peer_loaded, &sa->sa_peer,
@@ -5633,6 +5642,22 @@ ikev2_childsa_enable(struct iked *env, s
log_debug("%s: %sloaded flow %p", __func__,
reload ? "re" : "", flow);
+
+ /* append flow to log buffer */
+ if (flow->flow_dir == IPSP_DIRECTION_OUT &&
+ asprintf(&buf, "%s-%s/%d=%s/%d(%u)%s",
+ print_map(flow->flow_saproto, ikev2_saproto_map),
+ print_host((struct sockaddr *)&flow->flow_src.addr, NULL,
0),
+ flow->flow_src.addr_mask,
+ print_host((struct sockaddr *)&flow->flow_dst.addr, NULL,
0),
+ flow->flow_dst.addr_mask,
+ flow->flow_ipproto,
+ reload ? "-R" : "") != -1) {
+ if (ibuf_strlen(flowbuf))
+ ibuf_strcat(&flowbuf, ", ");
+ ibuf_strcat(&flowbuf, buf);
+ free(buf);
+ }
}
/* remember the current address for ikev2_update_sa_addresses() */
@@ -5644,6 +5669,14 @@ ikev2_childsa_enable(struct iked *env, s
NULL, 0));
}
+ if (ibuf_strlen(spibuf))
+ log_info("%s: loaded SPIs: %.*s", SPI_SA(sa, __func__),
+ ibuf_strlen(spibuf), ibuf_data(spibuf));
+ if (ibuf_strlen(flowbuf))
+ log_info("%s: loaded flows: %.*s", SPI_SA(sa, __func__),
+ ibuf_strlen(flowbuf), ibuf_data(flowbuf));
+ ibuf_release(spibuf);
+ ibuf_release(flowbuf);
return (0);
}
Index: imsg_util.c
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/imsg_util.c,v
retrieving revision 1.11
diff -u -p -r1.11 imsg_util.c
--- imsg_util.c 20 Jan 2017 14:10:05 -0000 1.11
+++ imsg_util.c 15 Nov 2019 16:00:57 -0000
@@ -198,3 +198,27 @@ ibuf_prepend(struct ibuf *buf, void *dat
return (0);
}
+
+int
+ibuf_strcat(struct ibuf **buf, const char *s)
+{
+ size_t slen;
+
+ if (buf == NULL)
+ return (-1);
+ slen = strlen(s);
+ if (*buf == NULL) {
+ if ((*buf = ibuf_new(s, slen)) == NULL)
+ return (-1);
+ return (0);
+ }
+ return (ibuf_add(*buf, s, slen));
+}
+
+int
+ibuf_strlen(struct ibuf *buf)
+{
+ if (ibuf_length(buf) > INT_MAX)
+ return (INT_MAX);
+ return ((int)ibuf_length(buf));
+}
Index: policy.c
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/policy.c,v
retrieving revision 1.49
diff -u -p -r1.49 policy.c
--- policy.c 13 Nov 2019 12:24:40 -0000 1.49
+++ policy.c 15 Nov 2019 16:00:57 -0000
@@ -240,13 +240,14 @@ sa_state(struct iked *env, struct iked_s
sa->sa_state = state;
if (ostate != IKEV2_STATE_INIT &&
!sa_stateok(sa, state)) {
- log_debug("%s: cannot switch: %s -> %s", SPI_SA(sa, __func__),
a, b);
+ log_debug("%s: cannot switch: %s -> %s",
+ SPI_SA(sa, __func__), a, b);
sa->sa_state = ostate;
} else if (ostate != sa->sa_state) {
switch (state) {
case IKEV2_STATE_ESTABLISHED:
case IKEV2_STATE_CLOSED:
- log_info("%s: %s -> %s from %s to %s policy '%s'",
+ log_debug("%s: %s -> %s from %s to %s policy '%s'",
SPI_SA(sa, __func__), a, b,
print_host((struct sockaddr *)&sa->sa_peer.addr,
NULL, 0),
@@ -256,7 +257,8 @@ sa_state(struct iked *env, struct iked_s
"<unknown>");
break;
default:
- log_debug("%s: %s -> %s", __func__, a, b);
+ log_debug("%s: %s -> %s",
+ SPI_SA(sa, __func__), a, b);
break;
}
}
