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 <tobias.hei...@stusta.de>:
>
> 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,
>
