Re: iked(8): improve logging output
On Wed, Sep 25, 2019 at 10:45:50PM +0200, Tobias Heider wrote:
> ok?
>
> @@ -4084,8 +4094,8 @@ ikev2_send_informational(struct iked *en
> case IKEV2_N_NO_PROPOSAL_CHOSEN:
> break;
> default:
> - log_debug("%s: unsupported notification %s", __func__,
> - print_map(msg->msg_error, ikev2_n_map));
> + log_info("%s: unsupported notification %s", SPI_SA(sa,
> + __func__), print_map(msg->msg_error, ikev2_n_map));
> goto done;
> }
>
Are you sure that sa != NULL? A few lines below this is checked.
if (sa != NULL && msg->msg_e) {
> @@ -4510,20 +4525,22 @@ ikev2_sa_responder_dh(struct iked_kex *k
> if (kex->kex_dhgroup == NULL) {
> if ((xform = config_findtransform(proposals,
> IKEV2_XFORMTYPE_DH, proto)) == NULL) {
> - log_debug("%s: did not find dh transform", __func__);
> + log_info("%s: did not find dh transform",
> + SPI_SA(msg->msg_sa, __func__));
> return (-1);
> }
> if ((kex->kex_dhgroup =
> group_get(xform->xform_id)) == NULL) {
> - log_debug("%s: invalid dh %d", __func__,
> - xform->xform_id);
> + log_debug("%s: invalid dh %d",
> + SPI_SA(msg->msg_sa, __func__), xform->xform_id);
> return (-1);
> }
> }
>
> /* Look for dhgroup mismatch during an IKE SA negotiation */
> if (msg->msg_dhgroup != kex->kex_dhgroup->id) {
> - log_debug("%s: want dh %s, KE has %s", __func__,
> + log_info("%s: want dh %s, KE has %s",
> + SPI_SA(msg->msg_sa, __func__),
> print_map(kex->kex_dhgroup->id, ikev2_xformdh_map),
> print_map(msg->msg_dhgroup, ikev2_xformdh_map));
> msg->msg_error = IKEV2_N_INVALID_KE_PAYLOAD;
Would it make sense to put struct iked_sa *sa = msg->msg_sa;
into ikev2_sa_responder_dh() like in all other functions?
otherwise OK bluhm@
iked(8): improve logging output
A recent commit added the macro SPI_SA which is used to prepend log lines with
"spi=0x.." as seen in the message receive and send output.
This diff updates the rest of the ikev2.c file to use the new macro.
Because I was already fiddling with logging I changed some log_debugs to
log_info. Most of them were error messages that should not require verbose
to see them.
ok?
Index: ikev2.c
===
RCS file: /cvs/src/sbin/iked/ikev2.c,v
retrieving revision 1.175
diff -u -p -u -r1.175 ikev2.c
--- ikev2.c 29 Aug 2019 14:56:23 - 1.175
+++ ikev2.c 25 Sep 2019 20:39:08 -
@@ -275,7 +275,8 @@ ikev2_dispatch_cert(int fd, struct privs
log_debug("%s: peer certificate is valid", __func__);
sa_stateflags(sa, IKED_REQ_CERTVALID);
} else {
- log_warnx("%s: peer certificate is invalid", __func__);
+ log_warnx("%s: peer certificate is invalid",
+ SPI_SA(sa, __func__));
ikev2_send_auth_failed(env, sa);
break;
}
@@ -332,7 +333,8 @@ ikev2_dispatch_cert(int fd, struct privs
break;
}
if (sa_stateok(sa, IKEV2_STATE_VALID)) {
- log_warnx("%s: ignoring AUTH in state %s", __func__,
+ log_warnx("%s: ignoring AUTH in state %s",
+ SPI_SA(sa, __func__),
print_map(sa->sa_state, ikev2_state_map));
break;
}
@@ -371,7 +373,7 @@ ikev2_ikesa_info(uint64_t spi, const cha
{
static char buf[1024];
const char *spistr;
-
+
spistr = print_spi(spi, 8);
if (msg)
snprintf(buf, sizeof(buf), "spi=%s: %s", spistr, msg);
@@ -698,7 +700,7 @@ ikev2_ike_auth_recv(struct iked *env, st
if (ikev2_ike_auth_compatible(sa,
ikeauth.auth_method, msg->msg_auth.id_type) < 0) {
log_warnx("%s: unexpected auth method %s, was "
- "expecting %s", __func__,
+ "expecting %s", SPI_SA(sa, __func__),
print_map(msg->msg_auth.id_type, ikev2_auth_map),
print_map(ikeauth.auth_method, ikev2_auth_map));
return (-1);
@@ -884,7 +886,8 @@ ikev2_init_recv(struct iked *env, struct
if (ikev2_init_ike_sa_peer(env, pol,
>pol_peer, msg) != 0)
log_warnx("%s: failed to initiate a "
- "IKE_SA_INIT exchange", __func__);
+ "IKE_SA_INIT exchange", SPI_SA(sa,
+ __func__));
break;
}
(void)ikev2_init_auth(env, msg);
@@ -979,7 +982,7 @@ ikev2_init_ike_sa_peer(struct iked *env,
/* Pick peer's DH group if asked */
if (pol->pol_peerdh > 0 && sa->sa_dhgroup == NULL &&
(sa->sa_dhgroup = group_get(pol->pol_peerdh)) == NULL) {
- log_warnx("%s: invalid peer DH group %u", __func__,
+ log_warnx("%s: invalid peer DH group %u", SPI_SA(sa, __func__),
pol->pol_peerdh);
goto closeonly;
}
@@ -2350,7 +2353,8 @@ ikev2_resp_recv(struct iked *env, struct
}
if (ikev2_pld_parse(env, hdr, msg, msg->msg_offset) != 0) {
- log_debug("%s: failed to parse message", __func__);
+ log_info("%s: failed to parse message",
+ SPI_SA(msg->msg_sa, __func__));
return;
}
@@ -2373,7 +2377,8 @@ ikev2_resp_recv(struct iked *env, struct
switch (hdr->ike_exchange) {
case IKEV2_EXCHANGE_IKE_SA_INIT:
if (ikev2_sa_responder(env, sa, NULL, msg) != 0) {
- log_debug("%s: failed to get IKE SA keys", __func__);
+ log_info("%s: failed to negotiate IKE SA",
+ SPI_SA(sa, __func__));
if (msg->msg_error == 0)
msg->msg_error = IKEV2_N_NO_PROPOSAL_CHOSEN;
ikev2_send_init_error(env, msg);
@@ -2605,6 +2610,8 @@ ikev2_add_error(struct iked *env, struct
default:
return (-1);
}
+ log_info("%s: %s", SPI_SA(msg->msg_sa, __func__),
+ print_map(msg->msg_error, ikev2_n_map));
len = sizeof(*n);
if ((ptr = ibuf_advance(buf, len)) == NULL)
return (-1);
@@ -3373,8 +3380,8 @@ ikev2_init_create_child_sa(struct iked *
* Resolve simultaneous IKE SA rekeying by
* deleting the SA with the lowest NONCE.
*/
-
Re: iked(8): improve logging output
On Fri, Aug 09, 2019 at 05:42:30PM +0200, Reyk Floeter wrote: > Hi, > > I agree that __func__ should be removed from anything except log_debug() > messages. > > I think you should prepend the term sa or spi to explain what the hex numbers > mean. > > otherwise OK reyk Thanks! Added with "spi=" prepended to the spi values.
Re: iked(8): improve logging output
Hi,
I agree that __func__ should be removed from anything except log_debug()
messages.
I think you should prepend the term sa or spi to explain what the hex numbers
mean.
otherwise OK reyk
> Am 09.08.2019 um 17:31 schrieb Tobias Heider :
>
> The current log output is not as helpful as i would like it to be, so here's
> a diff to make it better. This unifies the syntax of the send and recv output,
> uses the same terms as the configuration (peer and local instead of to and
> from)
> and prepends the SAs SPI to each line to make it easier to spot which message
> belongs to which flow.
>
> Example old:
> ikev2_msg_send: IKE_SA_INIT request from 0.0.0.0:500 to 10.0.1.23:500 msgid
> 0, 510 bytes
> ikev2_recv: IKE_SA_INIT response from responder 10.0.1.23:500 to
> 10.0.1.24:500 policy 'test' id 0, 446 bytes
> ikev2_msg_send: IKE_AUTH request from 10.0.1.24:500 to 10.0.1.23:500 msgid 1,
> 272 bytes
> ikev2_recv: IKE_AUTH response from responder 10.0.1.23:500 to 10.0.1.24:500
> policy 'test' id 1, 240 bytes
> sa_state: VALID -> ESTABLISHED from 10.0.1.23:500 to 10.0.1.24:500 policy
> 'test'
>
> Example new:
> 0x5003cf5b45df23ae: recv IKE_SA_INIT req 0 peer 10.0.1.24:500 local
> 10.0.1.23:500, 510 bytes, policy 'test'
> 0x5003cf5b45df23ae: send IKE_SA_INIT res 0 peer 10.0.1.24:500 local
> 10.0.1.23:500, 446 bytes
> 0x5003cf5b45df23ae: recv IKE_AUTH req 1 peer 10.0.1.24:500 local
> 10.0.1.23:500, 272 bytes, policy 'test'
> 0x5003cf5b45df23ae: send IKE_AUTH res 1 peer 10.0.1.24:500 local
> 10.0.1.23:500, 240 bytes
> 0x5003cf5b45df23ae: sa_state: VALID -> ESTABLISHED from 10.0.1.24:500 to
> 10.0.1.23:500 policy 'test'
>
> Ok?
>
> Index: iked.h
> ===
> RCS file: /mount/openbsd/cvs/src/sbin/iked/iked.h,v
> retrieving revision 1.121
> diff -u -p -u -r1.121 iked.h
> --- iked.h11 May 2019 16:30:23 -1.121
> +++ iked.h9 Aug 2019 14:43:33 -
> @@ -843,6 +843,11 @@ int ikev2_rekey_sa(struct iked *, struc
> int ikev2_drop_sa(struct iked *, struct iked_spi *);
> int ikev2_print_id(struct iked_id *, char *, size_t);
>
> +const char*ikev2_ikesa_info(uint64_t, const char *msg);
> +#define SPI_IH(hdr) ikev2_ikesa_info(betoh64((hdr)->ike_ispi), NULL)
> +#define SPI_SH(sh, f)ikev2_ikesa_info((sh)->sh_ispi, (f))
> +#define SPI_SA(sa, f)SPI_SH(&(sa)->sa_hdr, (f))
> +
> /* ikev2_msg.c */
> void ikev2_msg_cb(int, short, void *);
> struct ibuf *
> Index: ikev2.c
> ===
> RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2.c,v
> retrieving revision 1.171
> diff -u -p -u -r1.171 ikev2.c
> --- ikev2.c11 May 2019 16:30:23 -1.171
> +++ ikev2.c9 Aug 2019 15:05:20 -
> @@ -366,6 +366,20 @@ ikev2_dispatch_cert(int fd, struct privs
>return (0);
> }
>
> +const char *
> +ikev2_ikesa_info(uint64_t spi, const char *msg)
> +{
> +static char buf[1024];
> +const char *spistr;
> +
> +spistr = print_spi(spi, 8);
> +if (msg)
> +snprintf(buf, sizeof(buf), "%s: %s", spistr, msg);
> +else
> +snprintf(buf, sizeof(buf), "%s: ", spistr);
> +return buf;
> +}
> +
> struct iked_sa *
> ikev2_getimsgdata(struct iked *env, struct imsg *imsg, struct iked_sahdr *sh,
> uint8_t *type, uint8_t **buf, size_t *size)
> @@ -423,14 +437,15 @@ ikev2_recv(struct iked *env, struct iked
>if (policy_lookup(env, msg) != 0)
>return;
>
> -log_info("%s: %s %s from %s %s to %s policy '%s' id %u, %ld bytes",
> -__func__, print_map(hdr->ike_exchange, ikev2_exchange_map),
> -msg->msg_response ? "response" : "request",
> -initiator ? "responder" : "initiator",
> +log_info("%srecv %s %s %u peer %s local %s, %ld bytes, policy '%s'",
> +SPI_IH(hdr),
> +print_map(hdr->ike_exchange, ikev2_exchange_map),
> +msg->msg_response ? "res" : "req",
> +msg->msg_msgid,
>print_host((struct sockaddr *)>msg_peer, NULL, 0),
>print_host((struct sockaddr *)>msg_local, NULL, 0),
> -msg->msg_policy->pol_name, msg->msg_msgid,
> -ibuf_length(msg->msg_data));
> +ibuf_length(msg->msg_data),
> +msg->msg_policy->pol_name);
>log_debug("%s: ispi %s rspi %s", __func__,
>print_spi(betoh64(hdr->ike_ispi), 8),
>print_spi(betoh64(hdr->ike_rspi), 8));
> Index: ikev2_msg.c
> ===
> RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2_msg.c,v
> retrieving revision 1.55
> diff -u -p -u -r1.55 ikev2_msg.c
> --- ikev2_msg.c11 May 2019 16:30:23 -1.55
> +++ ikev2_msg.c9 Aug 2019 15:14:23 -
> @@ -319,12 +319,13 @@ ikev2_msg_send(struct iked *env, struct
>
>exchange = hdr->ike_exchange;
>flags = hdr->ike_flags;
> -log_info("%s: %s %s from %s to %s msgid %u, %ld bytes%s", __func__,
> +log_info("%ssend %s %s %u peer %s local %s, %ld
iked(8): improve logging output
The current log output is not as helpful as i would like it to be, so here's
a diff to make it better. This unifies the syntax of the send and recv output,
uses the same terms as the configuration (peer and local instead of to and from)
and prepends the SAs SPI to each line to make it easier to spot which message
belongs to which flow.
Example old:
ikev2_msg_send: IKE_SA_INIT request from 0.0.0.0:500 to 10.0.1.23:500 msgid 0,
510 bytes
ikev2_recv: IKE_SA_INIT response from responder 10.0.1.23:500 to 10.0.1.24:500
policy 'test' id 0, 446 bytes
ikev2_msg_send: IKE_AUTH request from 10.0.1.24:500 to 10.0.1.23:500 msgid 1,
272 bytes
ikev2_recv: IKE_AUTH response from responder 10.0.1.23:500 to 10.0.1.24:500
policy 'test' id 1, 240 bytes
sa_state: VALID -> ESTABLISHED from 10.0.1.23:500 to 10.0.1.24:500 policy 'test'
Example new:
0x5003cf5b45df23ae: recv IKE_SA_INIT req 0 peer 10.0.1.24:500 local
10.0.1.23:500, 510 bytes, policy 'test'
0x5003cf5b45df23ae: send IKE_SA_INIT res 0 peer 10.0.1.24:500 local
10.0.1.23:500, 446 bytes
0x5003cf5b45df23ae: recv IKE_AUTH req 1 peer 10.0.1.24:500 local 10.0.1.23:500,
272 bytes, policy 'test'
0x5003cf5b45df23ae: send IKE_AUTH res 1 peer 10.0.1.24:500 local 10.0.1.23:500,
240 bytes
0x5003cf5b45df23ae: sa_state: VALID -> ESTABLISHED from 10.0.1.24:500 to
10.0.1.23:500 policy 'test'
Ok?
Index: iked.h
===
RCS file: /mount/openbsd/cvs/src/sbin/iked/iked.h,v
retrieving revision 1.121
diff -u -p -u -r1.121 iked.h
--- iked.h 11 May 2019 16:30:23 - 1.121
+++ iked.h 9 Aug 2019 14:43:33 -
@@ -843,6 +843,11 @@ int ikev2_rekey_sa(struct iked *, struc
int ikev2_drop_sa(struct iked *, struct iked_spi *);
int ikev2_print_id(struct iked_id *, char *, size_t);
+const char *ikev2_ikesa_info(uint64_t, const char *msg);
+#define SPI_IH(hdr) ikev2_ikesa_info(betoh64((hdr)->ike_ispi), NULL)
+#define SPI_SH(sh, f)ikev2_ikesa_info((sh)->sh_ispi, (f))
+#define SPI_SA(sa, f)SPI_SH(&(sa)->sa_hdr, (f))
+
/* ikev2_msg.c */
voidikev2_msg_cb(int, short, void *);
struct ibuf *
Index: ikev2.c
===
RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2.c,v
retrieving revision 1.171
diff -u -p -u -r1.171 ikev2.c
--- ikev2.c 11 May 2019 16:30:23 - 1.171
+++ ikev2.c 9 Aug 2019 15:05:20 -
@@ -366,6 +366,20 @@ ikev2_dispatch_cert(int fd, struct privs
return (0);
}
+const char *
+ikev2_ikesa_info(uint64_t spi, const char *msg)
+{
+ static char buf[1024];
+ const char *spistr;
+
+ spistr = print_spi(spi, 8);
+ if (msg)
+ snprintf(buf, sizeof(buf), "%s: %s", spistr, msg);
+ else
+ snprintf(buf, sizeof(buf), "%s: ", spistr);
+ return buf;
+}
+
struct iked_sa *
ikev2_getimsgdata(struct iked *env, struct imsg *imsg, struct iked_sahdr *sh,
uint8_t *type, uint8_t **buf, size_t *size)
@@ -423,14 +437,15 @@ ikev2_recv(struct iked *env, struct iked
if (policy_lookup(env, msg) != 0)
return;
- log_info("%s: %s %s from %s %s to %s policy '%s' id %u, %ld bytes",
- __func__, print_map(hdr->ike_exchange, ikev2_exchange_map),
- msg->msg_response ? "response" : "request",
- initiator ? "responder" : "initiator",
+ log_info("%srecv %s %s %u peer %s local %s, %ld bytes, policy '%s'",
+ SPI_IH(hdr),
+ print_map(hdr->ike_exchange, ikev2_exchange_map),
+ msg->msg_response ? "res" : "req",
+ msg->msg_msgid,
print_host((struct sockaddr *)>msg_peer, NULL, 0),
print_host((struct sockaddr *)>msg_local, NULL, 0),
- msg->msg_policy->pol_name, msg->msg_msgid,
- ibuf_length(msg->msg_data));
+ ibuf_length(msg->msg_data),
+ msg->msg_policy->pol_name);
log_debug("%s: ispi %s rspi %s", __func__,
print_spi(betoh64(hdr->ike_ispi), 8),
print_spi(betoh64(hdr->ike_rspi), 8));
Index: ikev2_msg.c
===
RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2_msg.c,v
retrieving revision 1.55
diff -u -p -u -r1.55 ikev2_msg.c
--- ikev2_msg.c 11 May 2019 16:30:23 - 1.55
+++ ikev2_msg.c 9 Aug 2019 15:14:23 -
@@ -319,12 +319,13 @@ ikev2_msg_send(struct iked *env, struct
exchange = hdr->ike_exchange;
flags = hdr->ike_flags;
- log_info("%s: %s %s from %s to %s msgid %u, %ld bytes%s", __func__,
+ log_info("%ssend %s %s %u peer %s local %s, %ld bytes%s",
+ SPI_IH(hdr),
print_map(exchange, ikev2_exchange_map),
- (flags & IKEV2_FLAG_RESPONSE) ? "response" : "request",
- print_host((struct sockaddr *)>msg_local, NULL, 0),
- print_host((struct sockaddr *)>msg_peer, NULL, 0),
+ (flags & IKEV2_FLAG_RESPONSE) ? "res"
