iked(8): improve logging output

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

iked(8): improve logging output

Tobias Heider-2
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 -0000 1.121
+++ iked.h 9 Aug 2019 14:43:33 -0000
@@ -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.c 11 May 2019 16:30:23 -0000 1.171
+++ ikev2.c 9 Aug 2019 15:05:20 -0000
@@ -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->msg_peer, NULL, 0),
     print_host((struct sockaddr *)&msg->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 -0000 1.55
+++ ikev2_msg.c 9 Aug 2019 15:14:23 -0000
@@ -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->msg_local, NULL, 0),
-    print_host((struct sockaddr *)&msg->msg_peer, NULL, 0),
+    (flags & IKEV2_FLAG_RESPONSE) ? "res" : "req",
     betoh32(hdr->ike_msgid),
+    print_host((struct sockaddr *)&msg->msg_peer, NULL, 0),
+    print_host((struct sockaddr *)&msg->msg_local, NULL, 0),
     ibuf_length(buf), isnatt ? ", NAT-T" : "");
 
  if (isnatt) {
Index: ikev2_pld.c
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2_pld.c,v
retrieving revision 1.71
diff -u -p -u -r1.71 ikev2_pld.c
--- ikev2_pld.c 11 May 2019 16:30:23 -0000 1.71
+++ ikev2_pld.c 9 Aug 2019 15:08:33 -0000
@@ -1479,7 +1479,7 @@ ikev2_pld_delete(struct iked *env, struc
  }
  }
 
- log_warnx("%s: deleted %zu spis", __func__, found);
+ log_warnx("%s: deleted %zu spis", SPI_SA(sa, __func__), found);
  }
 
  if (found) {
Index: policy.c
===================================================================
RCS file: /mount/openbsd/cvs/src/sbin/iked/policy.c,v
retrieving revision 1.47
diff -u -p -u -r1.47 policy.c
--- policy.c 27 Nov 2017 18:39:35 -0000 1.47
+++ policy.c 9 Aug 2019 14:51:21 -0000
@@ -240,14 +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", __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'",
-    __func__, a, b,
+    SPI_SA(sa, __func__), a, b,
     print_host((struct sockaddr *)&sa->sa_peer.addr,
     NULL, 0),
     print_host((struct sockaddr *)&sa->sa_local.addr,

Reply | Threaded
Open this post in threaded view
|

Re: iked(8): improve logging output

Reyk Floeter-2
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 <[hidden email]>:
>
> 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 -0000    1.121
> +++ iked.h    9 Aug 2019 14:43:33 -0000
> @@ -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.c    11 May 2019 16:30:23 -0000    1.171
> +++ ikev2.c    9 Aug 2019 15:05:20 -0000
> @@ -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->msg_peer, NULL, 0),
>        print_host((struct sockaddr *)&msg->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 -0000    1.55
> +++ ikev2_msg.c    9 Aug 2019 15:14:23 -0000
> @@ -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->msg_local, NULL, 0),
> -        print_host((struct sockaddr *)&msg->msg_peer, NULL, 0),
> +        (flags & IKEV2_FLAG_RESPONSE) ? "res" : "req",
>        betoh32(hdr->ike_msgid),
> +        print_host((struct sockaddr *)&msg->msg_peer, NULL, 0),
> +        print_host((struct sockaddr *)&msg->msg_local, NULL, 0),
>        ibuf_length(buf), isnatt ? ", NAT-T" : "");
>
>    if (isnatt) {
> Index: ikev2_pld.c
> ===================================================================
> RCS file: /mount/openbsd/cvs/src/sbin/iked/ikev2_pld.c,v
> retrieving revision 1.71
> diff -u -p -u -r1.71 ikev2_pld.c
> --- ikev2_pld.c    11 May 2019 16:30:23 -0000    1.71
> +++ ikev2_pld.c    9 Aug 2019 15:08:33 -0000
> @@ -1479,7 +1479,7 @@ ikev2_pld_delete(struct iked *env, struc
>            }
>        }
>
> -        log_warnx("%s: deleted %zu spis", __func__, found);
> +        log_warnx("%s: deleted %zu spis", SPI_SA(sa, __func__), found);
>    }
>
>    if (found) {
> Index: policy.c
> ===================================================================
> RCS file: /mount/openbsd/cvs/src/sbin/iked/policy.c,v
> retrieving revision 1.47
> diff -u -p -u -r1.47 policy.c
> --- policy.c    27 Nov 2017 18:39:35 -0000    1.47
> +++ policy.c    9 Aug 2019 14:51:21 -0000
> @@ -240,14 +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", __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'",
> -                __func__, a, b,
> +                SPI_SA(sa, __func__), a, b,
>                print_host((struct sockaddr *)&sa->sa_peer.addr,
>                NULL, 0),
>                print_host((struct sockaddr *)&sa->sa_local.addr,
>

Reply | Threaded
Open this post in threaded view
|

Re: iked(8): improve logging output

Tobias Heider-2
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.