From 8ebcb7a99d7b73a1ee5874780b4efdc69d32c82f Mon Sep 17 00:00:00 2001 From: Filip Tehlar Date: Sun, 20 Oct 2019 10:38:13 +0000 Subject: [PATCH] ikev2: better logging Type: refactor Change-Id: Iedcb24684c54f4d78583ab3aa3db1097e73df248 Signed-off-by: Filip Tehlar --- src/plugins/ikev2/ikev2.c | 210 +++++++++++++++++--------------------- src/plugins/ikev2/ikev2_cli.c | 36 +++++++ src/plugins/ikev2/ikev2_crypto.c | 16 +-- src/plugins/ikev2/ikev2_payload.c | 62 ++--------- src/plugins/ikev2/ikev2_priv.h | 180 ++++++++++++++++++++++++++++++-- 5 files changed, 317 insertions(+), 187 deletions(-) diff --git a/src/plugins/ikev2/ikev2.c b/src/plugins/ikev2/ikev2.c index 03448b939f2..ee0b11ea4b0 100644 --- a/src/plugins/ikev2/ikev2.c +++ b/src/plugins/ikev2/ikev2.c @@ -37,7 +37,7 @@ static int ikev2_delete_tunnel_interface (vnet_main_t * vnm, #define ikev2_set_state(sa, v) do { \ (sa)->state = v; \ - clib_warning("sa state changed to " #v); \ + ikev2_elog_sa_state("ispi %lx SA state changed to " #v, sa->ispi); \ } while(0); typedef struct @@ -171,9 +171,6 @@ ikev2_select_proposal (ikev2_sa_proposal_t * proposals, } } - clib_warning ("bitmap is %x mandatory is %x optional is %x", - bitmap, mandatory_bitmap, optional_bitmap); - if ((bitmap & mandatory_bitmap) == mandatory_bitmap && (bitmap & ~optional_bitmap) == 0) { @@ -346,8 +343,6 @@ ikev2_generate_sa_init_data (ikev2_sa_t * sa) if (!t) { - clib_warning ("unknown dh data group %u (data len %u)", sa->dh_group, - vec_len (sa->i_dh_data)); sa->dh_group = IKEV2_TRANSFORM_DH_TYPE_NONE; return; } @@ -421,8 +416,6 @@ ikev2_complete_sa_data (ikev2_sa_t * sa, ikev2_sa_t * sai) if (!t) { - clib_warning ("unknown dh data group %u (data len %u)", sa->dh_group, - vec_len (sa->i_dh_data)); sa->dh_group = IKEV2_TRANSFORM_DH_TYPE_NONE; return; } @@ -596,13 +589,10 @@ ikev2_process_sa_init_req (vlib_main_t * vm, ikev2_sa_t * sa, u32 len = clib_net_to_host_u32 (ike->length); u8 payload = ike->nextpayload; - clib_warning ("ispi %lx rspi %lx nextpayload %x version %x " - "exchange %x flags %x msgid %x length %u", - clib_net_to_host_u64 (ike->ispi), - clib_net_to_host_u64 (ike->rspi), - payload, ike->version, - ike->exchange, ike->flags, - clib_net_to_host_u32 (ike->msgid), len); + ikev2_elog_exchange ("ispi %lx rspi %lx IKE_INIT request received " + "from %d.%d.%d.%d", + clib_net_to_host_u64 (ike->ispi), + clib_net_to_host_u64 (ike->rspi), sa->iaddr.as_u32); sa->ispi = clib_net_to_host_u64 (ike->ispi); @@ -646,8 +636,8 @@ ikev2_process_sa_init_req (vlib_main_t * vm, ikev2_sa_t * sa, } else { - clib_warning ("unknown payload %u flags %x length %u", payload, - ikep->flags, plen); + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { ikev2_set_state (sa, IKEV2_STATE_NOTIFY_AND_DELETE); @@ -671,17 +661,13 @@ ikev2_process_sa_init_resp (vlib_main_t * vm, ikev2_sa_t * sa, u32 len = clib_net_to_host_u32 (ike->length); u8 payload = ike->nextpayload; - clib_warning ("ispi %lx rspi %lx nextpayload %x version %x " - "exchange %x flags %x msgid %x length %u", - clib_net_to_host_u64 (ike->ispi), - clib_net_to_host_u64 (ike->rspi), - payload, ike->version, - ike->exchange, ike->flags, - clib_net_to_host_u32 (ike->msgid), len); - sa->ispi = clib_net_to_host_u64 (ike->ispi); sa->rspi = clib_net_to_host_u64 (ike->rspi); + ikev2_elog_exchange ("ispi %lx rspi %lx IKE_INIT response received " + "from %d.%d.%d.%d", sa->ispi, sa->rspi, + sa->raddr.as_u32); + /* store whole IKE payload - needed for PSK auth */ vec_free (sa->last_sa_init_res_packet_data); vec_add (sa->last_sa_init_res_packet_data, ike, len); @@ -728,8 +714,8 @@ ikev2_process_sa_init_resp (vlib_main_t * vm, ikev2_sa_t * sa, } else { - clib_warning ("unknown payload %u flags %x length %u", payload, - ikep->flags, plen); + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { ikev2_set_state (sa, IKEV2_STATE_NOTIFY_AND_DELETE); @@ -767,13 +753,12 @@ ikev2_decrypt_sk_payload (ikev2_sa_t * sa, ike_header_t * ike, u8 * payload) if (*payload == IKEV2_PAYLOAD_SK) { - clib_warning ("received IKEv2 payload SK, len %u", plen - 4); last_payload = *payload; } else { - clib_warning ("unknown payload %u flags %x length %u", payload, - ikep->flags, plen); + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + *payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { sa->unsupported_cp = *payload; @@ -787,7 +772,7 @@ ikev2_decrypt_sk_payload (ikev2_sa_t * sa, ike_header_t * ike, u8 * payload) if (last_payload != IKEV2_PAYLOAD_SK) { - clib_warning ("Last payload must be SK"); + ikev2_elog_error ("Last payload must be SK"); return 0; } @@ -799,7 +784,7 @@ ikev2_decrypt_sk_payload (ikev2_sa_t * sa, ike_header_t * ike, u8 * payload) if (memcmp (hmac, &ikep->payload[plen], tr_integ->key_trunc)) { - clib_warning ("message integrity check failed"); + ikev2_elog_error ("message integrity check failed"); vec_free (hmac); return 0; } @@ -845,6 +830,9 @@ ikev2_initial_contact_cleanup (ikev2_sa_t * sa) vec_free (delete); sa->initial_contact = 0; + + km->log_level = IKEV2_LOG_ERROR; + km->log_class = vlib_log_register_class ("ikev2", 0); } static void @@ -852,20 +840,16 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) { ikev2_child_sa_t *first_child_sa; int p = 0; - u32 len = clib_net_to_host_u32 (ike->length); u8 payload = ike->nextpayload; u8 *plaintext = 0; - ike_payload_header_t *ikep; u32 plen; - clib_warning ("ispi %lx rspi %lx nextpayload %x version %x " - "exchange %x flags %x msgid %x length %u", - clib_net_to_host_u64 (ike->ispi), - clib_net_to_host_u64 (ike->rspi), - payload, ike->version, - ike->exchange, ike->flags, - clib_net_to_host_u32 (ike->msgid), len); + ikev2_elog_exchange ("ispi %lx rspi %lx EXCHANGE_IKE_AUTH received " + "from %d.%d.%d.%d", clib_host_to_net_u64 (ike->ispi), + clib_host_to_net_u64 (ike->rspi), + sa->is_initiator ? sa->raddr.as_u32 : sa-> + iaddr.as_u32); ikev2_calc_keys (sa); @@ -902,7 +886,6 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) if (payload == IKEV2_PAYLOAD_SA) /* 33 */ { - clib_warning ("received payload SA, len %u", plen - sizeof (*ikep)); if (sa->is_initiator) { ikev2_sa_free_proposal_vector (&first_child_sa->r_proposals); @@ -921,9 +904,6 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) sa->i_id.type = id->id_type; vec_free (sa->i_id.data); vec_add (sa->i_id.data, id->payload, plen - sizeof (*id)); - - clib_warning ("received payload IDi, len %u id_type %u", - plen - sizeof (*id), id->id_type); } else if (payload == IKEV2_PAYLOAD_IDR) /* 36 */ { @@ -932,9 +912,6 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) sa->r_id.type = id->id_type; vec_free (sa->r_id.data); vec_add (sa->r_id.data, id->payload, plen - sizeof (*id)); - - clib_warning ("received payload IDr len %u id_type %u", - plen - sizeof (*id), id->id_type); } else if (payload == IKEV2_PAYLOAD_AUTH) /* 39 */ { @@ -952,9 +929,6 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) vec_free (sa->i_auth.data); vec_add (sa->i_auth.data, a->payload, plen - sizeof (*a)); } - - clib_warning ("received payload AUTH, len %u auth_type %u", - plen - sizeof (*a), a->auth_method); } else if (payload == IKEV2_PAYLOAD_NOTIFY) /* 41 */ { @@ -971,25 +945,18 @@ ikev2_process_auth_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) } else if (payload == IKEV2_PAYLOAD_TSI) /* 44 */ { - clib_warning ("received payload TSi, len %u", - plen - sizeof (*ikep)); - vec_free (first_child_sa->tsi); first_child_sa->tsi = ikev2_parse_ts_payload (ikep); } else if (payload == IKEV2_PAYLOAD_TSR) /* 45 */ { - clib_warning ("received payload TSr, len %u", - plen - sizeof (*ikep)); - vec_free (first_child_sa->tsr); first_child_sa->tsr = ikev2_parse_ts_payload (ikep); } else { - clib_warning ("unknown payload %u flags %x length %u data %u", - payload, ikep->flags, plen - 4, - format_hex_bytes, ikep->payload, plen - 4); + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { @@ -1012,20 +979,14 @@ ikev2_process_informational_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) { int p = 0; - u32 len = clib_net_to_host_u32 (ike->length); u8 payload = ike->nextpayload; u8 *plaintext = 0; - ike_payload_header_t *ikep; u32 plen; - clib_warning ("ispi %lx rspi %lx nextpayload %x version %x " - "exchange %x flags %x msgid %x length %u", - clib_net_to_host_u64 (ike->ispi), - clib_net_to_host_u64 (ike->rspi), - payload, ike->version, - ike->exchange, ike->flags, - clib_net_to_host_u32 (ike->msgid), len); + ikev2_elog_exchange ("ispi %lx rspi %lx INFORMATIONAL received " + "from %d.%d.%d.%d", clib_host_to_net_u64 (ike->ispi), + clib_host_to_net_u64 (ike->rspi), sa->iaddr.as_u32); plaintext = ikev2_decrypt_sk_payload (sa, ike, &payload); @@ -1059,10 +1020,8 @@ ikev2_process_informational_req (vlib_main_t * vm, ikev2_sa_t * sa, } else { - clib_warning ("unknown payload %u flags %x length %u data %u", - payload, ikep->flags, plen - 4, - format_hex_bytes, ikep->payload, plen - 4); - + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { sa->unsupported_cp = payload; @@ -1083,7 +1042,6 @@ ikev2_process_create_child_sa_req (vlib_main_t * vm, ikev2_sa_t * sa, ike_header_t * ike) { int p = 0; - u32 len = clib_net_to_host_u32 (ike->length); u8 payload = ike->nextpayload; u8 *plaintext = 0; u8 rekeying = 0; @@ -1097,13 +1055,9 @@ ikev2_process_create_child_sa_req (vlib_main_t * vm, ikev2_sa_t * sa, ikev2_sa_proposal_t *proposal = 0; ikev2_child_sa_t *child_sa; - clib_warning ("ispi %lx rspi %lx nextpayload %x version %x " - "exchange %x flags %x msgid %x length %u", - clib_net_to_host_u64 (ike->ispi), - clib_net_to_host_u64 (ike->rspi), - payload, ike->version, - ike->exchange, ike->flags, - clib_net_to_host_u32 (ike->msgid), len); + ikev2_elog_exchange ("ispi %lx rspi %lx CREATE_CHILD_SA received " + "from %d.%d.%d.%d", clib_host_to_net_u64 (ike->ispi), + clib_host_to_net_u64 (ike->rspi), sa->raddr.as_u32); plaintext = ikev2_decrypt_sk_payload (sa, ike, &payload); @@ -1154,10 +1108,8 @@ ikev2_process_create_child_sa_req (vlib_main_t * vm, ikev2_sa_t * sa, } else { - clib_warning ("unknown payload %u flags %x length %u data %u", - payload, ikep->flags, plen - 4, - format_hex_bytes, ikep->payload, plen - 4); - + ikev2_elog_uint (IKEV2_LOG_ERROR, "Unknown payload! type=%d", + payload); if (ikep->flags & IKEV2_PAYLOAD_FLAG_CRITICAL) { sa->unsupported_cp = payload; @@ -1194,7 +1146,8 @@ ikev2_process_create_child_sa_req (vlib_main_t * vm, ikev2_sa_t * sa, child_sa = ikev2_sa_get_child (sa, n->spi, n->protocol_id, 1); if (!child_sa) { - clib_warning ("child SA spi %lx not found", n->spi); + ikev2_elog_uint (IKEV2_LOG_ERROR, "child SA spi %lx not found", + n->spi); goto cleanup_and_exit; } vec_add2 (sa->rekey, rekey, 1); @@ -1356,8 +1309,9 @@ ikev2_sa_auth (ikev2_sa_t * sa) if (!(sa->i_auth.method == IKEV2_AUTH_METHOD_SHARED_KEY_MIC || sa->i_auth.method == IKEV2_AUTH_METHOD_RSA_SIG)) { - clib_warning ("unsupported authentication method %u", - sa->i_auth.method); + ikev2_elog_uint (IKEV2_LOG_ERROR, + "unsupported authentication method %u", + sa->i_auth.method); ikev2_set_state (sa, IKEV2_STATE_AUTH_FAILED); return; } @@ -1457,6 +1411,8 @@ ikev2_sa_auth (ikev2_sa_t * sa) } else { + ikev2_elog_uint (IKEV2_LOG_ERROR, "authentication failed, no matching " + "profile found! ispi %lx", sa->ispi); ikev2_set_state (sa, IKEV2_STATE_AUTH_FAILED); } vec_free (psk); @@ -1478,8 +1434,9 @@ ikev2_sa_auth_init (ikev2_sa_t * sa) if (!(sa->i_auth.method == IKEV2_AUTH_METHOD_SHARED_KEY_MIC || sa->i_auth.method == IKEV2_AUTH_METHOD_RSA_SIG)) { - clib_warning ("unsupported authentication method %u", - sa->i_auth.method); + ikev2_elog_uint (IKEV2_LOG_ERROR, + "unsupported authentication method %u", + sa->i_auth.method); ikev2_set_state (sa, IKEV2_STATE_AUTH_FAILED); return; } @@ -1558,9 +1515,9 @@ ikev2_add_tunnel_from_main (ikev2_add_ipsec_tunnel_args_t * a) if (rv) { - clib_warning ("installing ipip tunnel failed! loc:%U rem:%U", - format_ip4_address, &a->local_ip, - format_ip4_address, &a->remote_ip); + ikev2_elog_peers (IKEV2_LOG_ERROR, "installing ipip tunnel failed! " + "loc:%d.%d.%d.%d rem:%d.%d.%d.%d", + a->local_ip.ip4.as_u32, a->remote_ip.ip4.as_u32); return; } @@ -1771,10 +1728,10 @@ ikev2_create_tunnel_interface (vnet_main_t * vnm, } if (thread_index & 0xffffffc0) - clib_warning ("error: thread index exceeds max range 0x3f!"); + ikev2_elog_error ("error: thread index exceeds max range 0x3f!"); if (child_index & 0xfffff000 || sa_index & 0xfffff000) - clib_warning ("error: sa/child index exceeds max range 0xfff!"); + ikev2_elog_error ("error: sa/child index exceeds max range 0xfff!"); child->local_sa_id = a.local_sa_id = @@ -2174,17 +2131,21 @@ ikev2_retransmit_sa_init (ike_header_t * ike, ike->length = tmp->length; clib_memcpy_fast(ike->payload, tmp->payload, clib_net_to_host_u32(tmp->length) - sizeof(*ike)); - clib_warning("IKE_SA_INIT retransmit from %U to %U", - format_ip4_address, &raddr, - format_ip4_address, &iaddr); + ikev2_elog_uint_peers (IKEV2_LOG_DEBUG, + "ispi %lx IKE_SA_INIT retransmit " + "from %d.%d.%d.%d to %d.%d.%d.%d", + ike->ispi, + raddr.as_u32, iaddr.as_u32); return 1; } /* else ignore req */ else { - clib_warning("IKE_SA_INIT ignore from %U to %U", - format_ip4_address, &raddr, - format_ip4_address, &iaddr); + ikev2_elog_uint_peers (IKEV2_LOG_DEBUG, + "ispi %lx IKE_SA_INIT ignore " + "from %d.%d.%d.%d to %d.%d.%d.%d", + ike->ispi, + raddr.as_u32, iaddr.as_u32); return -1; } } @@ -2226,21 +2187,17 @@ ikev2_retransmit_resp (ikev2_sa_t * sa, ike_header_t * ike) ike->length = tmp->length; clib_memcpy_fast (ike->payload, tmp->payload, clib_net_to_host_u32 (tmp->length) - sizeof (*ike)); - clib_warning ("IKE msgid %u retransmit from %U to %U", - msg_id, - format_ip4_address, &sa->raddr, - format_ip4_address, &sa->iaddr); + ikev2_elog_uint_peers (IKEV2_LOG_DEBUG, "IKE retransmit msgid %d", + msg_id, sa->raddr.as_u32, sa->iaddr.as_u32); return 1; } /* old req ignore */ else { - clib_warning ("IKE msgid %u req ignore from %U to %U", - msg_id, - format_ip4_address, &sa->raddr, - format_ip4_address, &sa->iaddr); - return -1; + ikev2_elog_uint_peers (IKEV2_LOG_DEBUG, "IKE req ignore msgid %d", + msg_id, sa->raddr.as_u32, sa->iaddr.as_u32); } + return -1; } @@ -2583,10 +2540,11 @@ ikev2_node_fn (vlib_main_t * vm, } else { - clib_warning ("IKEv2 exchange %u packet received from %U to %U", - ike0->exchange, - format_ip4_address, ip40->src_address.as_u8, - format_ip4_address, ip40->dst_address.as_u8); + ikev2_elog_uint_peers (IKEV2_LOG_WARNING, "IKEv2 exchange %d " + "received from %d.%d.%d.%d to %d.%d.%d.%d", + ike0->exchange, + ip40->src_address.as_u32, + ip40->dst_address.as_u32); } dispatch0: @@ -2717,7 +2675,7 @@ ikev2_set_initiator_proposals (vlib_main_t * vm, ikev2_sa_t * sa, } if (error) { - clib_warning + ikev2_elog_error ("Didn't find any supported algorithm for IKEV2_TRANSFORM_TYPE_INTEG"); r = clib_error_return (0, "Unsupported algorithm"); return r; @@ -3256,6 +3214,9 @@ ikev2_initiate_sa_init (vlib_main_t * vm, u8 * name) ikev2_send_ike (vm, if_ip, &p->responder.ip4, bi0, len); + ikev2_elog_exchange ("ispi %lx rspi %lx IKEV2_EXCHANGE_SA_INIT sent to " + "%d.%d.%d.%d", clib_host_to_net_u64 (sa0->ispi), 0, + p->responder.ip4.as_u32); } return 0; @@ -3548,8 +3509,8 @@ ikev2_mngr_process_child_sa (ikev2_sa_t * sa, ikev2_child_sa_t * csa) else if (csa->rekey_retries > 0) { csa->rekey_retries--; - clib_warning ("Rekeying Child SA 0x%x, retries left %d", - csa->i_proposals->spi, csa->rekey_retries); + ikev2_log_debug ("Rekeying Child SA 0x%x, retries left %d", + csa->i_proposals->spi, csa->rekey_retries); if (csa->rekey_retries == 0) { csa->rekey_retries = -1; @@ -3568,6 +3529,21 @@ ikev2_mngr_process_child_sa (ikev2_sa_t * sa, ikev2_child_sa_t * csa) return res; } +int +ikev2_set_log_level (ikev2_log_level_t log_level) +{ + ikev2_main_t *km = &ikev2_main; + + if (log_level >= IKEV2_LOG_MAX) + { + ikev2_log_error ("unknown logging level %d", log_level); + return -1; + } + + km->log_level = log_level; + return 0; +} + static void ikev2_mngr_process_ipsec_sa (ipsec_sa_t * ipsec_sa) { diff --git a/src/plugins/ikev2/ikev2_cli.c b/src/plugins/ikev2/ikev2_cli.c index 0933667c4bd..2ca1a5ccfc6 100644 --- a/src/plugins/ikev2/ikev2_cli.c +++ b/src/plugins/ikev2/ikev2_cli.c @@ -589,6 +589,42 @@ ikev2_cli_reference (void) { } +static clib_error_t * +ikev2_set_log_level_command_fn (vlib_main_t * vm, + unformat_input_t * input, + vlib_cli_command_t * cmd) +{ + unformat_input_t _line_input, *line_input = &_line_input; + u8 log_level = IKEV2_LOG_NONE; + clib_error_t *error = 0; + + /* Get a line of input. */ + if (!unformat_user (input, unformat_line_input, line_input)) + return 0; + + if (!unformat (line_input, "%d", &log_level)) + { + error = clib_error_return (0, "unknown input '%U'", + format_unformat_error, line_input); + goto done; + } + int rc = ikev2_set_log_level (log_level); + if (rc < 0) + error = clib_error_return (0, "setting log level failed!"); + +done: + unformat_free (line_input); + return error; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (ikev2_set_log_level_command, static) = { + .path = "ikev2 set logging level", + .function = ikev2_set_log_level_command_fn, + .short_help = "ikev2 set logging level <0-5>", +}; +/* *INDENT-ON* */ + /* * fd.io coding-style-patch-verification: ON * diff --git a/src/plugins/ikev2/ikev2_crypto.c b/src/plugins/ikev2/ikev2_crypto.c index 49629a5dab5..26ff43387e7 100644 --- a/src/plugins/ikev2/ikev2_crypto.c +++ b/src/plugins/ikev2/ikev2_crypto.c @@ -342,11 +342,11 @@ ikev2_calc_integr (ikev2_sa_transform_t * tr, v8 * key, u8 * data, int len) if (tr->md == EVP_sha1 ()) { - clib_warning ("integrity checking with sha1"); + ikev2_elog_debug ("integrity checking with sha1"); } else if (tr->md == EVP_sha256 ()) { - clib_warning ("integrity checking with sha256"); + ikev2_elog_debug ("integrity checking with sha256"); } /* verify integrity of data */ @@ -389,7 +389,7 @@ ikev2_decrypt_data (ikev2_sa_t * sa, u8 * data, int len) /* check if data is multiplier of cipher block size */ if (len % block_size) { - clib_warning ("wrong data length"); + ikev2_elog_error ("wrong data length"); return 0; } @@ -772,7 +772,7 @@ ikev2_load_cert_file (u8 * file) fp = fopen ((char *) file, "r"); if (!fp) { - clib_warning ("open %s failed", file); + ikev2_log_error ("open %s failed", file); goto end; } @@ -780,13 +780,13 @@ ikev2_load_cert_file (u8 * file) fclose (fp); if (x509 == NULL) { - clib_warning ("read cert %s failed", file); + ikev2_log_error ("read cert %s failed", file); goto end; } pkey = X509_get_pubkey (x509); if (pkey == NULL) - clib_warning ("get pubkey %s failed", file); + ikev2_log_error ("get pubkey %s failed", file); end: return pkey; @@ -801,14 +801,14 @@ ikev2_load_key_file (u8 * file) fp = fopen ((char *) file, "r"); if (!fp) { - clib_warning ("open %s failed", file); + ikev2_log_error ("open %s failed", file); goto end; } pkey = PEM_read_PrivateKey (fp, NULL, NULL, NULL); fclose (fp); if (pkey == NULL) - clib_warning ("read %s failed", file); + ikev2_log_error ("read %s failed", file); end: return pkey; diff --git a/src/plugins/ikev2/ikev2_payload.c b/src/plugins/ikev2/ikev2_payload.c index 509483aa655..56bb652e940 100644 --- a/src/plugins/ikev2/ikev2_payload.c +++ b/src/plugins/ikev2/ikev2_payload.c @@ -187,11 +187,6 @@ ikev2_payload_add_sa (ikev2_payload_chain_t * c, if (spi_size) prop->spi[0] = clib_host_to_net_u32 (p->spi); - DBG_PLD ("proposal num %u protocol_id %u last_or_more %u spi_size %u%s%U", - prop->proposal_num, prop->protocol_id, prop->last_or_more, - prop->spi_size, prop->spi_size ? " spi_data " : "", - format_hex_bytes, prop->spi, prop->spi_size); - vec_foreach (t, p->transforms) { vec_add2 (tr_data, tmp, sizeof (*tr) + vec_len (t->attrs)); @@ -205,13 +200,6 @@ ikev2_payload_add_sa (ikev2_payload_chain_t * c, if (vec_len (t->attrs) > 0) clib_memcpy_fast (tr->attributes, t->attrs, vec_len (t->attrs)); - - DBG_PLD - ("transform type %U transform_id %u last_or_more %u attr_size %u%s%U", - format_ikev2_transform_type, tr->transform_type, t->transform_id, - tr->last_or_more, vec_len (t->attrs), - vec_len (t->attrs) ? " attrs " : "", format_hex_bytes, - tr->attributes, vec_len (t->attrs)); } prop->proposal_len = @@ -356,12 +344,6 @@ ikev2_parse_sa_payload (ike_payload_header_t * ikep) int i; int transform_ptr; - DBG_PLD ("proposal num %u len %u last_or_more %u id %u " - "spi_size %u num_transforms %u", - sap->proposal_num, clib_net_to_host_u16 (sap->proposal_len), - sap->last_or_more, sap->protocol_id, sap->spi_size, - sap->num_transforms); - /* IKE proposal should not have SPI */ if (sap->protocol_id == IKEV2_PROTOCOL_IKE && sap->spi_size != 0) goto data_corrupted; @@ -396,14 +378,6 @@ ikev2_parse_sa_payload (ike_payload_header_t * ikep) transform->transform_id = clib_net_to_host_u16 (tr->transform_id); if (tlen > sizeof (*tr)) vec_add (transform->attrs, tr->attributes, tlen - sizeof (*tr)); - - DBG_PLD - ("transform num %u len %u last_or_more %u type %U id %u%s%U", i, - tlen, tr->last_or_more, format_ikev2_sa_transform, transform, - clib_net_to_host_u16 (tr->transform_id), - tlen > sizeof (*tr) ? " attrs " : "", format_hex_bytes, - tr->attributes, tlen - sizeof (*tr)); - transform_ptr += tlen; } @@ -418,7 +392,7 @@ ikev2_parse_sa_payload (ike_payload_header_t * ikep) return v; data_corrupted: - DBG_PLD ("SA payload data corrupted"); + ikev2_elog_detail ("SA payload data corrupted"); ikev2_sa_free_proposal_vector (&v); return 0; } @@ -433,10 +407,11 @@ ikev2_parse_ts_payload (ike_payload_header_t * ikep) for (i = 0; i < tsp->num_ts; i++) { if (tsp->ts[i].ts_type != 7) /* TS_IPV4_ADDR_RANGE */ - { - DBG_PLD ("unsupported TS type received (%u)", tsp->ts[i].ts_type); - continue; - } + { + ikev2_elog_uint (IKEV2_LOG_ERROR, + "unsupported TS type received (%u)", tsp->ts[i].ts_type); + continue; + } vec_add2 (r, ts, 1); ts->ts_type = tsp->ts[i].ts_type; @@ -457,11 +432,6 @@ ikev2_parse_notify_payload (ike_payload_header_t * ikep) ikev2_notify_t *r = 0; u32 spi; - DBG_PLD ("msg_type %U len %u%s%U", - format_ikev2_notify_msg_type, clib_net_to_host_u16 (n->msg_type), - plen, plen > sizeof (*n) ? " data " : "", - format_hex_bytes, n->payload, plen - sizeof (*n)); - r = vec_new (ikev2_notify_t, 1); r->msg_type = clib_net_to_host_u16 (n->msg_type); r->protocol_id = n->protocol_id; @@ -470,7 +440,6 @@ ikev2_parse_notify_payload (ike_payload_header_t * ikep) { clib_memcpy (&spi, n->payload, n->spi_size); r->spi = clib_net_to_host_u32 (spi); - DBG_PLD ("spi %lx", r->spi); } else if (n->spi_size == 0) { @@ -494,34 +463,17 @@ void ikev2_parse_vendor_payload (ike_payload_header_t * ikep) { u32 plen = clib_net_to_host_u16 (ikep->length); - int i; - int is_string = 1; - - for (i = 0; i < plen - 4; i++) - if (!isprint (ikep->payload[i])) - is_string = 0; - - DBG_PLD ("len %u data %s:%U", - plen, - is_string ? "string" : "hex", - is_string ? format_ascii_bytes : format_hex_bytes, - ikep->payload, plen - sizeof (*ikep)); + ikev2_elog_uint (IKEV2_LOG_DEBUG, "vendor payload skipped, len %d", plen); } ikev2_delete_t * ikev2_parse_delete_payload (ike_payload_header_t * ikep) { ike_delete_payload_header_t *d = (ike_delete_payload_header_t *) ikep; - u32 plen = clib_net_to_host_u16 (ikep->length); ikev2_delete_t *r = 0, *del; u16 num_of_spi = clib_net_to_host_u16 (d->num_of_spi); u16 i = 0; - DBG_PLD ("protocol_id %u spi_size %u num_of_spi %u len %u%s%U", - d->protocol_id, d->spi_size, num_of_spi, - plen, plen > sizeof (d) ? " data " : "", - format_hex_bytes, d->spi, plen - sizeof (*d)); - if (d->protocol_id == IKEV2_PROTOCOL_IKE) { r = vec_new (ikev2_delete_t, 1); diff --git a/src/plugins/ikev2/ikev2_priv.h b/src/plugins/ikev2/ikev2_priv.h index 630ba1ba351..aa85b84727a 100644 --- a/src/plugins/ikev2/ikev2_priv.h +++ b/src/plugins/ikev2/ikev2_priv.h @@ -30,13 +30,173 @@ #include #include -#define IKEV2_DEBUG_PAYLOAD 1 +#define foreach_ikev2_log_level \ + _(0x00, LOG_NONE) \ + _(0x01, LOG_ERROR) \ + _(0x02, LOG_WARNING) \ + _(0x03, LOG_INFO) \ + _(0x04, LOG_DEBUG) \ + _(0x05, LOG_DETAIL) \ -#if IKEV2_DEBUG_PAYLOAD == 1 -#define DBG_PLD(my_args...) clib_warning(my_args) -#else -#define DBG_PLD(my_args...) -#endif + +typedef enum ikev2_log_level_t_ +{ +#define _(n,f) IKEV2_##f = n, + foreach_ikev2_log_level +#undef _ + IKEV2_LOG_MAX +} ikev2_log_level_t; + +/* dataplane logging */ +#define _ikev2_elog(_level, _msg) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= _level)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2 " _msg, \ + .format_args = "", \ + }; \ + ELOG_DATA (&vlib_global_main.elog_main, e); \ + } \ +} while (0) + +#define ikev2_elog_sa_state(_format, _ispi) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= IKEV2_LOG_DEBUG)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2: " _format, \ + .format_args = "i8", \ + }; \ + CLIB_PACKED(struct \ + { \ + u64 ispi; \ + }) *ed; \ + ed = ELOG_DATA (&vlib_global_main.elog_main, e); \ + ed->ispi = _ispi; \ + } \ +} while (0) \ + +#define ikev2_elog_exchange(_format, _ispi, _rspi, _addr) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= IKEV2_LOG_DEBUG)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2: " _format, \ + .format_args = "i8i8i1i1i1i1", \ + }; \ + CLIB_PACKED(struct \ + { \ + u64 ispi; \ + u64 rspi; \ + u8 oct1; \ + u8 oct2; \ + u8 oct3; \ + u8 oct4; \ + }) *ed; \ + ed = ELOG_DATA (&vlib_global_main.elog_main, e); \ + ed->ispi = _ispi; \ + ed->rspi = _rspi; \ + ed->oct4 = (_addr) >> 24; \ + ed->oct3 = (_addr) >> 16; \ + ed->oct2 = (_addr) >> 8; \ + ed->oct1 = (_addr); \ + } \ +} while (0) \ + +#define ikev2_elog_uint(_level, _format, _val) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= _level)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2: " _format, \ + .format_args = "i8", \ + }; \ + CLIB_PACKED(struct \ + { \ + u64 val; \ + }) *ed; \ + ed = ELOG_DATA (&vlib_global_main.elog_main, e); \ + ed->val = _val; \ + } \ +} while (0) + +#define ikev2_elog_uint_peers(_level, _format, _val, _ip1, _ip2) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= _level)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2: " _format, \ + .format_args = "i8i1i1i1i1i1i1i1i1", \ + }; \ + CLIB_PACKED(struct { \ + u64 val; \ + u8 i11; u8 i12; u8 i13; u8 i14; \ + u8 i21; u8 i22; u8 i23; u8 i24; }) *ed; \ + ed = ELOG_DATA (&vlib_global_main.elog_main, e); \ + ed->val = _val; \ + ed->i14 = (_ip1) >> 24; \ + ed->i13 = (_ip1) >> 16; \ + ed->i12 = (_ip1) >> 8; \ + ed->i11 = (_ip1); \ + ed->i24 = (_ip2) >> 24; \ + ed->i23 = (_ip2) >> 16; \ + ed->i22 = (_ip2) >> 8; \ + ed->i21 = (_ip2); \ + } \ +} while (0) + +#define ikev2_elog_peers(_level, _format, _ip1, _ip2) \ +do { \ + ikev2_main_t *km = &ikev2_main; \ + if (PREDICT_FALSE (km->log_level >= _level)) \ + { \ + ELOG_TYPE_DECLARE (e) = \ + { \ + .format = "ikev2: " _format, \ + .format_args = "i1i1i1i1i1i1i1i1", \ + }; \ + CLIB_PACKED(struct { \ + u8 i11; u8 i12; u8 i13; u8 i14; \ + u8 i21; u8 i22; u8 i23; u8 i24; }) *ed; \ + ed = ELOG_DATA (&vlib_global_main.elog_main, e); \ + ed->i14 = (_ip1) >> 24; \ + ed->i13 = (_ip1) >> 16; \ + ed->i12 = (_ip1) >> 8; \ + ed->i11 = (_ip1); \ + ed->i24 = (_ip2) >> 24; \ + ed->i23 = (_ip2) >> 16; \ + ed->i22 = (_ip2) >> 8; \ + ed->i21 = (_ip2); \ + } \ +} while (0) + +#define ikev2_elog_error(_msg) \ + _ikev2_elog(IKEV2_LOG_ERROR, "[error] " _msg) +#define ikev2_elog_warning(_msg) \ + _ikev2_elog(IKEV2_LOG_WARNING, "[warning] " _msg) +#define ikev2_elog_debug(_msg) \ + _ikev2_elog(IKEV2_LOG_DEBUG, "[debug] " _msg) +#define ikev2_elog_detail(_msg) \ + _ikev2_elog(IKEV2_LOG_DETAIL, "[detail] " _msg) + +/* logging for main thread */ +#define ikev2_log_error(...) \ + vlib_log(VLIB_LOG_LEVEL_ERR, ikev2_main.log_class, __VA_ARGS__) +#define ikev2_log_warning(...) \ + vlib_log(VLIB_LOG_LEVEL_WARNING, ikev2_main.log_class, __VA_ARGS__) +#define ikev2_log_debug(...) \ + vlib_log(VLIB_LOG_LEVEL_DEBUG, ikev2_main.log_class, __VA_ARGS__) typedef enum { @@ -302,6 +462,12 @@ typedef struct /* API message ID base */ u16 msg_id_base; + + /* log class used for main thread */ + vlib_log_class_t log_class; + + /* logging level */ + ikev2_log_level_t log_level; } ikev2_main_t; extern ikev2_main_t ikev2_main; @@ -361,7 +527,7 @@ ikev2_sa_proposal_t *ikev2_parse_sa_payload (ike_payload_header_t * ikep); ikev2_ts_t *ikev2_parse_ts_payload (ike_payload_header_t * ikep); ikev2_delete_t *ikev2_parse_delete_payload (ike_payload_header_t * ikep); ikev2_notify_t *ikev2_parse_notify_payload (ike_payload_header_t * ikep); - +int ikev2_set_log_level (ikev2_log_level_t log_level); #endif /* __included_ikev2_priv_h__ */ -- 2.16.6