Merge pull request #13016 from opensourcerouting/feature/ospf_logging_upstream_backport

ospfd, ospfd6: Add more logging
This commit is contained in:
Donald Sharp 2023-03-17 07:55:09 -04:00 committed by GitHub
commit 3bf4d3b45d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 107 additions and 76 deletions

View File

@ -921,7 +921,11 @@ void ospf6_receive_lsa(struct ospf6_neighbor *from,
/* (1) LSA Checksum */ /* (1) LSA Checksum */
if (!ospf6_lsa_checksum_valid(new->header)) { if (!ospf6_lsa_checksum_valid(new->header)) {
if (is_debug) if (is_debug)
zlog_debug("Wrong LSA Checksum, discard"); zlog_debug(
"Wrong LSA Checksum %s (Router-ID: %pI4) [Type:%s Checksum:%#06hx), discard",
from->name, &from->router_id,
ospf6_lstype_name(new->header->type),
ntohs(new->header->checksum));
ospf6_lsa_delete(new); ospf6_lsa_delete(new);
return; return;
} }

View File

@ -280,8 +280,9 @@ int ospf6_process_grace_lsa(struct ospf6 *ospf6, struct ospf6_lsa *lsa,
if (IS_DEBUG_OSPF6_GR) if (IS_DEBUG_OSPF6_GR)
zlog_debug( zlog_debug(
"%s, Grace LSA received from %pI4, grace interval:%u, restart reason :%s", "%s, Grace LSA received from %s(%pI4), grace interval:%u, restart reason:%s",
__func__, &restarter->router_id, grace_interval, __func__, restarter->name, &restarter->router_id,
grace_interval,
ospf6_restart_reason_desc[restart_reason]); ospf6_restart_reason_desc[restart_reason]);
/* Verify Helper enabled globally */ /* Verify Helper enabled globally */

View File

@ -410,26 +410,29 @@ static void ospf6_hello_recv(struct in6_addr *src, struct in6_addr *dst,
/* HelloInterval check */ /* HelloInterval check */
if (ntohs(hello->hello_interval) != oi->hello_interval) { if (ntohs(hello->hello_interval) != oi->hello_interval) {
zlog_warn( zlog_warn(
"VRF %s: I/F %s HelloInterval mismatch: (my %d, rcvd %d)", "VRF %s: I/F %s HelloInterval mismatch from %pI6 (%pI4): (my %d, rcvd %d)",
oi->interface->vrf->name, oi->interface->name, oi->interface->vrf->name, oi->interface->name, src,
oi->hello_interval, ntohs(hello->hello_interval)); &oh->router_id, oi->hello_interval,
ntohs(hello->hello_interval));
return; return;
} }
/* RouterDeadInterval check */ /* RouterDeadInterval check */
if (ntohs(hello->dead_interval) != oi->dead_interval) { if (ntohs(hello->dead_interval) != oi->dead_interval) {
zlog_warn( zlog_warn(
"VRF %s: I/F %s DeadInterval mismatch: (my %d, rcvd %d)", "VRF %s: I/F %s DeadInterval mismatch from %pI6 (%pI4): (my %d, rcvd %d)",
oi->interface->vrf->name, oi->interface->name, oi->interface->vrf->name, oi->interface->name, src,
oi->dead_interval, ntohs(hello->dead_interval)); &oh->router_id, oi->dead_interval,
ntohs(hello->dead_interval));
return; return;
} }
/* E-bit check */ /* E-bit check */
if (OSPF6_OPT_ISSET(hello->options, OSPF6_OPT_E) if (OSPF6_OPT_ISSET(hello->options, OSPF6_OPT_E) !=
!= OSPF6_OPT_ISSET(oi->area->options, OSPF6_OPT_E)) { OSPF6_OPT_ISSET(oi->area->options, OSPF6_OPT_E)) {
zlog_warn("VRF %s: IF %s E-bit mismatch", zlog_warn("VRF %s: IF %s E-bit mismatch from %pI6 (%pI4)",
oi->interface->vrf->name, oi->interface->name); oi->interface->vrf->name, oi->interface->name, src,
&oh->router_id);
return; return;
} }
@ -687,8 +690,9 @@ static void ospf6_dbdesc_recv_master(struct ospf6_header *oh,
if (ntohl(dbdesc->seqnum) != on->dbdesc_seqnum) { if (ntohl(dbdesc->seqnum) != on->dbdesc_seqnum) {
zlog_warn( zlog_warn(
"DbDesc recv: Sequence number mismatch Nbr %s (%#lx expected)", "DbDesc recv: Sequence number mismatch Nbr %s (received %#lx, %#lx expected)",
on->name, (unsigned long)on->dbdesc_seqnum); on->name, (unsigned long)ntohl(dbdesc->seqnum),
(unsigned long)on->dbdesc_seqnum);
thread_add_event(master, seqnumber_mismatch, on, 0, thread_add_event(master, seqnumber_mismatch, on, 0,
NULL); NULL);
return; return;
@ -906,8 +910,9 @@ static void ospf6_dbdesc_recv_slave(struct ospf6_header *oh,
if (ntohl(dbdesc->seqnum) != on->dbdesc_seqnum + 1) { if (ntohl(dbdesc->seqnum) != on->dbdesc_seqnum + 1) {
zlog_warn( zlog_warn(
"DbDesc slave recv: Sequence number mismatch Nbr %s (%#lx expected)", "DbDesc slave recv: Sequence number mismatch Nbr %s (received %#lx, %#lx expected)",
on->name, (unsigned long)on->dbdesc_seqnum + 1); on->name, (unsigned long)ntohl(dbdesc->seqnum),
(unsigned long)on->dbdesc_seqnum + 1);
thread_add_event(master, seqnumber_mismatch, on, 0, thread_add_event(master, seqnumber_mismatch, on, 0,
NULL); NULL);
return; return;
@ -1537,20 +1542,25 @@ static int ospf6_rxpacket_examin(struct ospf6_interface *oi,
struct ospf6_header *oh, struct ospf6_header *oh,
const unsigned bytesonwire) const unsigned bytesonwire)
{ {
struct ospf6_neighbor *on;
if (MSG_OK != ospf6_packet_examin(oh, bytesonwire)) if (MSG_OK != ospf6_packet_examin(oh, bytesonwire))
return MSG_NG; return MSG_NG;
on = ospf6_neighbor_lookup(oh->router_id, oi);
/* Area-ID check */ /* Area-ID check */
if (oh->area_id != oi->area->area_id) { if (oh->area_id != oi->area->area_id) {
if (oh->area_id == OSPF_AREA_BACKBONE) if (oh->area_id == OSPF_AREA_BACKBONE)
zlog_warn( zlog_warn(
"VRF %s: I/F %s Message may be via Virtual Link: not supported", "VRF %s: I/F %s (%s, Router-ID: %pI4) Message may be via Virtual Link: not supported",
oi->interface->vrf->name, oi->interface->name); oi->interface->vrf->name, oi->interface->name,
on ? on->name : "null", &oh->router_id);
else else
zlog_warn( zlog_warn(
"VRF %s: I/F %s Area-ID mismatch (my %pI4, rcvd %pI4)", "VRF %s: I/F %s (%s, Router-ID: %pI4) Area-ID mismatch (my %pI4, rcvd %pI4)",
oi->interface->vrf->name, oi->interface->name, oi->interface->vrf->name, oi->interface->name,
on ? on->name : "null", &oh->router_id,
&oi->area->area_id, &oh->area_id); &oi->area->area_id, &oh->area_id);
return MSG_NG; return MSG_NG;
} }
@ -1558,9 +1568,10 @@ static int ospf6_rxpacket_examin(struct ospf6_interface *oi,
/* Instance-ID check */ /* Instance-ID check */
if (oh->instance_id != oi->instance_id) { if (oh->instance_id != oi->instance_id) {
zlog_warn( zlog_warn(
"VRF %s: I/F %s Instance-ID mismatch (my %u, rcvd %u)", "VRF %s: I/F %s (%s, Router-ID: %pI4) Instance-ID mismatch (my %u, rcvd %u)",
oi->interface->vrf->name, oi->interface->name, oi->interface->vrf->name, oi->interface->name,
oi->instance_id, oh->instance_id); on ? on->name : "null", &oh->router_id, oi->instance_id,
oh->instance_id);
return MSG_NG; return MSG_NG;
} }

View File

@ -196,10 +196,12 @@ static void ospf6_neighbor_state_change(uint8_t next_state,
/* log */ /* log */
if (IS_OSPF6_DEBUG_NEIGHBOR(STATE)) { if (IS_OSPF6_DEBUG_NEIGHBOR(STATE)) {
zlog_debug("Neighbor state change %s: [%s]->[%s] (%s)", zlog_debug(
on->name, ospf6_neighbor_state_str[prev_state], "Neighbor state change %s (Router-ID: %pI4): [%s]->[%s] (%s)",
ospf6_neighbor_state_str[next_state], on->name, &on->router_id,
ospf6_neighbor_event_string(event)); ospf6_neighbor_state_str[prev_state],
ospf6_neighbor_state_str[next_state],
ospf6_neighbor_event_string(event));
} }
/* Optionally notify about adjacency changes */ /* Optionally notify about adjacency changes */
@ -209,10 +211,13 @@ static void ospf6_neighbor_state_change(uint8_t next_state,
OSPF6_LOG_ADJACENCY_DETAIL) OSPF6_LOG_ADJACENCY_DETAIL)
|| (next_state == OSPF6_NEIGHBOR_FULL) || (next_state == OSPF6_NEIGHBOR_FULL)
|| (next_state < prev_state))) || (next_state < prev_state)))
zlog_notice("AdjChg: Nbr %s: %s -> %s (%s)", on->name, zlog_notice(
ospf6_neighbor_state_str[prev_state], "AdjChg: Nbr %pI4(%s) on %s: %s -> %s (%s)",
ospf6_neighbor_state_str[next_state], &on->router_id,
ospf6_neighbor_event_string(event)); vrf_id_to_name(on->ospf6_if->interface->vrf->vrf_id),
on->name, ospf6_neighbor_state_str[prev_state],
ospf6_neighbor_state_str[next_state],
ospf6_neighbor_event_string(event));
if (prev_state == OSPF6_NEIGHBOR_FULL if (prev_state == OSPF6_NEIGHBOR_FULL
|| next_state == OSPF6_NEIGHBOR_FULL) { || next_state == OSPF6_NEIGHBOR_FULL) {

View File

@ -629,12 +629,13 @@ static void nsm_notice_state_change(struct ospf_neighbor *nbr, int next_state,
if (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_CHANGES) if (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_CHANGES)
&& (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_DETAIL) && (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_DETAIL)
|| (next_state == NSM_Full) || (next_state < nbr->state))) || (next_state == NSM_Full) || (next_state < nbr->state)))
zlog_notice("AdjChg: Nbr %pI4(%s) on %s: %s -> %s (%s)", zlog_notice(
&nbr->router_id, "AdjChg: Nbr %pI4, NbrIP %pI4 (%s) on %s: %s -> %s (%s)",
ospf_get_name(nbr->oi->ospf), IF_NAME(nbr->oi), &nbr->router_id, &nbr->src,
lookup_msg(ospf_nsm_state_msg, nbr->state, NULL), ospf_get_name(nbr->oi->ospf), IF_NAME(nbr->oi),
lookup_msg(ospf_nsm_state_msg, next_state, NULL), lookup_msg(ospf_nsm_state_msg, nbr->state, NULL),
ospf_nsm_event_str[event]); lookup_msg(ospf_nsm_state_msg, next_state, NULL),
ospf_nsm_event_str[event]);
/* Advance in NSM */ /* Advance in NSM */
if (next_state > nbr->state) if (next_state > nbr->state)

View File

@ -308,8 +308,10 @@ static int ospf_check_md5_digest(struct ospf_interface *oi,
ck = ospf_crypt_key_lookup(OSPF_IF_PARAM(oi, auth_crypt), ck = ospf_crypt_key_lookup(OSPF_IF_PARAM(oi, auth_crypt),
ospfh->u.crypt.key_id); ospfh->u.crypt.key_id);
if (ck == NULL) { if (ck == NULL) {
flog_warn(EC_OSPF_MD5, "interface %s: ospf_check_md5 no key %d", flog_warn(
IF_NAME(oi), ospfh->u.crypt.key_id); EC_OSPF_MD5,
"interface %s: ospf_check_md5 no key %d, Router-ID: %pI4",
IF_NAME(oi), ospfh->u.crypt.key_id, &ospfh->router_id);
return 0; return 0;
} }
@ -320,9 +322,9 @@ static int ospf_check_md5_digest(struct ospf_interface *oi,
&& ntohl(nbr->crypt_seqnum) > ntohl(ospfh->u.crypt.crypt_seqnum)) { && ntohl(nbr->crypt_seqnum) > ntohl(ospfh->u.crypt.crypt_seqnum)) {
flog_warn( flog_warn(
EC_OSPF_MD5, EC_OSPF_MD5,
"interface %s: ospf_check_md5 bad sequence %d (expect %d)", "interface %s: ospf_check_md5 bad sequence %d (expect %d), Router-ID: %pI4",
IF_NAME(oi), ntohl(ospfh->u.crypt.crypt_seqnum), IF_NAME(oi), ntohl(ospfh->u.crypt.crypt_seqnum),
ntohl(nbr->crypt_seqnum)); ntohl(nbr->crypt_seqnum), &ospfh->router_id);
return 0; return 0;
} }
@ -345,9 +347,10 @@ static int ospf_check_md5_digest(struct ospf_interface *oi,
/* compare the two */ /* compare the two */
if (memcmp((caddr_t)ospfh + length, digest, OSPF_AUTH_MD5_SIZE)) { if (memcmp((caddr_t)ospfh + length, digest, OSPF_AUTH_MD5_SIZE)) {
flog_warn(EC_OSPF_MD5, flog_warn(
"interface %s: ospf_check_md5 checksum mismatch", EC_OSPF_MD5,
IF_NAME(oi)); "interface %s: ospf_check_md5 checksum mismatch, Router-ID: %pI4",
IF_NAME(oi), &ospfh->router_id);
return 0; return 0;
} }
@ -426,10 +429,11 @@ static int ospf_make_md5_digest(struct ospf_interface *oi,
if (stream_get_endp(op->s) != op->length) if (stream_get_endp(op->s) != op->length)
/* XXX size_t */ /* XXX size_t */
flog_warn(EC_OSPF_MD5, flog_warn(
"%s: length mismatch stream %lu ospf_packet %u", EC_OSPF_MD5,
__func__, (unsigned long)stream_get_endp(op->s), "%s: length mismatch stream %lu ospf_packet %u, Router-ID %pI4",
op->length); __func__, (unsigned long)stream_get_endp(op->s),
op->length, &ospfh->router_id);
return OSPF_AUTH_MD5_SIZE; return OSPF_AUTH_MD5_SIZE;
} }
@ -896,11 +900,11 @@ static void ospf_hello(struct ip *iph, struct ospf_header *ospfh,
/* Compare Router Dead Interval. */ /* Compare Router Dead Interval. */
if (OSPF_IF_PARAM(oi, v_wait) != ntohl(hello->dead_interval)) { if (OSPF_IF_PARAM(oi, v_wait) != ntohl(hello->dead_interval)) {
flog_warn(EC_OSPF_PACKET, flog_warn(
"Packet %pI4 [Hello:RECV]: RouterDeadInterval mismatch (expected %u, but received %u).", EC_OSPF_PACKET,
&ospfh->router_id, "Packet %pI4 [Hello:RECV]: RouterDeadInterval mismatch on %s (expected %u, but received %u).",
OSPF_IF_PARAM(oi, v_wait), &ospfh->router_id, IF_NAME(oi),
ntohl(hello->dead_interval)); OSPF_IF_PARAM(oi, v_wait), ntohl(hello->dead_interval));
return; return;
} }
@ -910,8 +914,8 @@ static void ospf_hello(struct ip *iph, struct ospf_header *ospfh,
!= ntohs(hello->hello_interval)) { != ntohs(hello->hello_interval)) {
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"Packet %pI4 [Hello:RECV]: HelloInterval mismatch (expected %u, but received %u).", "Packet %pI4 [Hello:RECV]: HelloInterval mismatch on %s (expected %u, but received %u).",
&ospfh->router_id, &ospfh->router_id, IF_NAME(oi),
OSPF_IF_PARAM(oi, v_hello), OSPF_IF_PARAM(oi, v_hello),
ntohs(hello->hello_interval)); ntohs(hello->hello_interval));
return; return;
@ -919,8 +923,8 @@ static void ospf_hello(struct ip *iph, struct ospf_header *ospfh,
} }
if (IS_DEBUG_OSPF_EVENT) if (IS_DEBUG_OSPF_EVENT)
zlog_debug("Packet %pI4 [Hello:RECV]: Options %s vrf %s", zlog_debug("Packet %pI4 [Hello:RECV]: Options on %s %s vrf %s",
&ospfh->router_id, &ospfh->router_id, IF_NAME(oi),
ospf_options_dump(hello->options), ospf_options_dump(hello->options),
ospf_vrf_id_to_name(oi->ospf->vrf_id)); ospf_vrf_id_to_name(oi->ospf->vrf_id));
@ -934,8 +938,8 @@ static void ospf_hello(struct ip *iph, struct ospf_header *ospfh,
* relationship. * relationship.
*/ */
flog_warn(EC_OSPF_PACKET, flog_warn(EC_OSPF_PACKET,
"Packet %pI4 [Hello:RECV]: T-bit on, drop it.", "Packet %pI4 [Hello:RECV]: T-bit ON on %s, drop it.",
&ospfh->router_id); &ospfh->router_id, IF_NAME(oi));
return; return;
} }
#endif /* REJECT_IF_TBIT_ON */ #endif /* REJECT_IF_TBIT_ON */
@ -947,8 +951,8 @@ static void ospf_hello(struct ip *iph, struct ospf_header *ospfh,
* the bit should be set in DD packet only. * the bit should be set in DD packet only.
*/ */
flog_warn(EC_OSPF_PACKET, flog_warn(EC_OSPF_PACKET,
"Packet %pI4 [Hello:RECV]: O-bit abuse?", "Packet %pI4 [Hello:RECV]: O-bit abuse? on %s",
&ospfh->router_id); &ospfh->router_id, IF_NAME(oi));
#ifdef STRICT_OBIT_USAGE_CHECK #ifdef STRICT_OBIT_USAGE_CHECK
return; /* Reject this packet. */ return; /* Reject this packet. */
#else /* STRICT_OBIT_USAGE_CHECK */ #else /* STRICT_OBIT_USAGE_CHECK */
@ -2475,10 +2479,11 @@ static int ospf_check_auth(struct ospf_interface *oi, struct ospf_header *ospfh)
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"interface %s: auth-type mismatch, local %s, rcvd Null", "interface %s: auth-type mismatch, local %s, rcvd Null, Router-ID %pI4",
IF_NAME(oi), IF_NAME(oi),
lookup_msg(ospf_auth_type_str, lookup_msg(ospf_auth_type_str,
iface_auth_type, NULL)); iface_auth_type, NULL),
&ospfh->router_id);
return 0; return 0;
} }
if (!ospf_check_sum(ospfh)) { if (!ospf_check_sum(ospfh)) {
@ -2497,18 +2502,20 @@ static int ospf_check_auth(struct ospf_interface *oi, struct ospf_header *ospfh)
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"interface %s: auth-type mismatch, local %s, rcvd Simple", "interface %s: auth-type mismatch, local %s, rcvd Simple, Router-ID %pI4",
IF_NAME(oi), IF_NAME(oi),
lookup_msg(ospf_auth_type_str, lookup_msg(ospf_auth_type_str,
iface_auth_type, NULL)); iface_auth_type, NULL),
&ospfh->router_id);
return 0; return 0;
} }
if (memcmp(OSPF_IF_PARAM(oi, auth_simple), ospfh->u.auth_data, if (memcmp(OSPF_IF_PARAM(oi, auth_simple), ospfh->u.auth_data,
OSPF_AUTH_SIMPLE_SIZE)) { OSPF_AUTH_SIMPLE_SIZE)) {
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn(EC_OSPF_PACKET, flog_warn(
"interface %s: Simple auth failed", EC_OSPF_PACKET,
IF_NAME(oi)); "interface %s: Simple auth failed, Router-ID %pI4",
IF_NAME(oi), &ospfh->router_id);
return 0; return 0;
} }
if (!ospf_check_sum(ospfh)) { if (!ospf_check_sum(ospfh)) {
@ -2527,18 +2534,19 @@ static int ospf_check_auth(struct ospf_interface *oi, struct ospf_header *ospfh)
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"interface %s: auth-type mismatch, local %s, rcvd Cryptographic", "interface %s: auth-type mismatch, local %s, rcvd Cryptographic, Router-ID %pI4",
IF_NAME(oi), IF_NAME(oi),
lookup_msg(ospf_auth_type_str, lookup_msg(ospf_auth_type_str,
iface_auth_type, NULL)); iface_auth_type, NULL),
&ospfh->router_id);
return 0; return 0;
} }
if (ospfh->checksum) { if (ospfh->checksum) {
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"interface %s: OSPF header checksum is not 0", "interface %s: OSPF header checksum is not 0, Router-ID %pI4",
IF_NAME(oi)); IF_NAME(oi), &ospfh->router_id);
return 0; return 0;
} }
/* only MD5 crypto method can pass ospf_packet_examin() */ /* only MD5 crypto method can pass ospf_packet_examin() */
@ -2551,9 +2559,10 @@ static int ospf_check_auth(struct ospf_interface *oi, struct ospf_header *ospfh)
bug? */ bug? */
!ospf_check_md5_digest(oi, ospfh)) { !ospf_check_md5_digest(oi, ospfh)) {
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn(EC_OSPF_MD5, flog_warn(
"interface %s: MD5 auth failed", EC_OSPF_MD5,
IF_NAME(oi)); "interface %s: MD5 auth failed, Router-ID %pI4",
IF_NAME(oi), &ospfh->router_id);
return 0; return 0;
} }
return 1; return 1;
@ -2561,8 +2570,8 @@ static int ospf_check_auth(struct ospf_interface *oi, struct ospf_header *ospfh)
if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV)) if (IS_DEBUG_OSPF_PACKET(ospfh->type - 1, RECV))
flog_warn( flog_warn(
EC_OSPF_PACKET, EC_OSPF_PACKET,
"interface %s: invalid packet auth-type (%02x)", "interface %s: invalid packet auth-type (%02x), Router-ID %pI4",
IF_NAME(oi), pkt_auth_type); IF_NAME(oi), pkt_auth_type, &ospfh->router_id);
return 0; return 0;
} }
} }