On Tue, Nov 02, 2021 at 05:27:11PM +0000, Stuart Henderson wrote:
> I've recently started seeing a number of flaps with ospfd/ospf6d
> with invalid seq nums / "seq num mismatch, bad flags" logged.
> Not quite sure what's going yet as they must be occurring on
> various local switched segments on one nic and also on ethernet
> wan circuits direct to router on a separate pcie nic, anyway
> it's made it clear that very few of the log messages relating
> to neighbours identify which interface is involved.
>
> I don't know if it makes sense to commit or not, but there's a
> diff below adding the interface wherever the neighbour ID is logged
> if anyone's interested (same changes to both ospfd and ospf6d).
>
>
> Nov 2 11:29:30 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.2:
> invalid seq num, mine 20d22487 his 20d22485
> Nov 2 11:29:30 ospf6d[89545]: recv_db_description: neighbor ID
> xxxxxxxxxx.2: invalid seq num, mine 4cabc5c1 his 4cabc5c0
> Nov 2 11:29:34 ospf6d[89545]: recv_db_description: neighbor ID
> xxxxxxxxxx.1: invalid seq num, mine 98360a5 his 98360a4
> Nov 2 11:29:34 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.1:
> invalid seq num, mine f708c646 his f708c645
> Nov 2 11:29:38 ospfd[78532]: recv_db_description: neighbor ID
> xxxxxxxxxx.11: invalid seq num, mine e4068bcc his e4068bcb
> Nov 2 11:30:06 ospf6d[89545]: recv_db_description: neighbor ID
> xxxxxxxxxx.3: seq num mismatch, bad flags
> Nov 2 11:30:14 ospf6d[89545]: recv_db_description: neighbor ID
> xxxxxxxxxx.1: invalid seq num, mine 98360ae his 98360ad
> Nov 2 11:30:14 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.1:
> invalid seq num, mine f708c64f his f708c64e
> Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.2:
> invalid seq num, mine 20d22493 his 20d22490
> Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.2:
> invalid seq num, mine 20d22493 his 20d22492
> Nov 2 11:30:39 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.2:
> invalid seq num, mine 20d2249c his 20d2249b
> Nov 2 11:30:59 ospf6d[89545]: recv_db_description: neighbor ID
> xxxxxxxxxx.11: seq num mismatch, bad flags
> Nov 2 11:30:59 ospfd[78532]: recv_db_description: neighbor ID
> xxxxxxxxxx.11: seq num mismatch, bad flags
> Nov 2 11:31:09 ospfd[78532]: recv_db_description: neighbor ID xxxxxxxxxx.1:
> invalid seq num, mine f708c65c his f708c65b
>
I think this addition makes sense. Over which link a neighbor is connected
can only be looked up via ospfctl. It's valuable having this info in the
logs when analysing past events.
Diff reads fine, applies and compiles.
OK remi
>
> Index: ospf6d/database.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/database.c,v
> retrieving revision 1.20
> diff -u -p -r1.20 database.c
> --- ospf6d/database.c 15 Jul 2020 14:47:41 -0000 1.20
> +++ ospf6d/database.c 2 Nov 2021 17:11:38 -0000
> @@ -60,9 +60,9 @@ send_db_description(struct nbr *nbr)
> case NBR_STA_INIT:
> case NBR_STA_2_WAY:
> case NBR_STA_SNAP:
> - log_debug("send_db_description: neighbor ID %s: "
> + log_debug("send_db_description: neighbor ID %s (%s): "
> "cannot send packet in state %s", inet_ntoa(nbr->id),
> - nbr_state_name(nbr->state));
> + nbr->iface->name, nbr_state_name(nbr->state));
> goto fail;
> case NBR_STA_XSTRT:
> bits |= OSPF_DBD_MS | OSPF_DBD_M | OSPF_DBD_I;
> @@ -160,8 +160,8 @@ recv_db_description(struct nbr *nbr, cha
> int dupe = 0;
>
> if (len < sizeof(dd_hdr)) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> - "bad packet size", inet_ntoa(nbr->id));
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> + "bad packet size", inet_ntoa(nbr->id), nbr->iface->name);
> return;
> }
> memcpy(&dd_hdr, buf, sizeof(dd_hdr));
> @@ -170,9 +170,10 @@ recv_db_description(struct nbr *nbr, cha
>
> /* db description packet sanity checks */
> if (ntohs(dd_hdr.iface_mtu) > nbr->iface->mtu) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "invalid MTU %d expected %d", inet_ntoa(nbr->id),
> - ntohs(dd_hdr.iface_mtu), nbr->iface->mtu);
> + nbr->iface->name, ntohs(dd_hdr.iface_mtu),
> + nbr->iface->mtu);
> return;
> }
>
> @@ -180,8 +181,9 @@ recv_db_description(struct nbr *nbr, cha
> nbr->last_rx_bits == dd_hdr.bits &&
> ntohl(dd_hdr.dd_seq_num) == nbr->dd_seq_num - nbr->dd_master ?
> 1 : 0) {
> - log_debug("recv_db_description: dupe from neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("recv_db_description: dupe from "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> dupe = 1;
> }
>
> @@ -190,9 +192,9 @@ recv_db_description(struct nbr *nbr, cha
> case NBR_STA_ATTEMPT:
> case NBR_STA_2_WAY:
> case NBR_STA_SNAP:
> - log_debug("recv_db_description: neighbor ID %s: "
> + log_debug("recv_db_description: neighbor ID %s (%s): "
> "packet ignored in state %s", inet_ntoa(nbr->id),
> - nbr_state_name(nbr->state));
> + nbr->iface->name, nbr_state_name(nbr->state));
> return;
> case NBR_STA_INIT:
> /* evaluate dr and bdr after issuing a 2-Way event */
> @@ -222,10 +224,10 @@ recv_db_description(struct nbr *nbr, cha
> /* M only case: we are master */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> return;
> }
> nbr->dd_seq_num++;
> @@ -241,9 +243,10 @@ recv_db_description(struct nbr *nbr, cha
> }
> } else {
> /* ignore packet */
> - log_debug("recv_db_description: neighbor ID %s: "
> + log_debug("recv_db_description: neighbor ID %s (%s): "
> "packet ignored in state %s (bad flags)",
> - inet_ntoa(nbr->id), nbr_state_name(nbr->state));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_state_name(nbr->state));
> }
> break;
> case NBR_STA_XCHNG:
> @@ -251,16 +254,17 @@ recv_db_description(struct nbr *nbr, cha
> case NBR_STA_FULL:
> if (dd_hdr.bits & OSPF_DBD_I ||
> !(dd_hdr.bits & OSPF_DBD_MS) == !nbr->dd_master) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> - "seq num mismatch, bad flags", inet_ntoa(nbr->id));
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> + "seq num mismatch, bad flags", inet_ntoa(nbr->id),
> + nbr->iface->name);
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
>
> if (nbr->last_rx_options != dd_hdr.opts) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "seq num mismatch, bad options",
> - inet_ntoa(nbr->id));
> + inet_ntoa(nbr->id), nbr->iface->name);
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -273,10 +277,10 @@ recv_db_description(struct nbr *nbr, cha
> }
>
> if (nbr->state != NBR_STA_XCHNG) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -286,10 +290,10 @@ recv_db_description(struct nbr *nbr, cha
> /* master */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x, master",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -298,10 +302,10 @@ recv_db_description(struct nbr *nbr, cha
> /* slave */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num + 1) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x, slave",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -385,8 +389,9 @@ db_tx_timer(int fd, short event, void *a
> send_db_description(nbr);
> break;
> default:
> - log_debug("db_tx_timer: neighbor ID %s: unknown neighbor state",
> - inet_ntoa(nbr->id));
> + log_debug("db_tx_timer: neighbor ID %s (%s): "
> + "unknown neighbor state",
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> }
>
> Index: ospf6d/kroute.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/kroute.c,v
> retrieving revision 1.65
> diff -u -p -r1.65 kroute.c
> --- ospf6d/kroute.c 10 Sep 2020 05:18:16 -0000 1.65
> +++ ospf6d/kroute.c 2 Nov 2021 17:11:38 -0000
> @@ -1107,7 +1107,7 @@ send_rtmsg(int fd, int action, struct kr
> /*
> * We don't have an interface address in that network,
> * so we install a cloning route. The kernel will then
> - * do neigbor discovery.
> + * do neighbor discovery.
> */
> bzero(&ifp, sizeof(ifp));
> ifp.addr.sdl_len = sizeof(struct sockaddr_dl);
> Index: ospf6d/lsack.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/lsack.c,v
> retrieving revision 1.8
> diff -u -p -r1.8 lsack.c
> --- ospf6d/lsack.c 28 Dec 2019 09:25:24 -0000 1.8
> +++ ospf6d/lsack.c 2 Nov 2021 17:11:38 -0000
> @@ -105,8 +105,8 @@ recv_ls_ack(struct nbr *nbr, char *buf,
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_ack: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -127,7 +127,8 @@ recv_ls_ack(struct nbr *nbr, char *buf,
> }
> if (len > 0) {
> log_warnx("recv_ls_ack: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> break;
> @@ -141,8 +142,8 @@ lsa_hdr_check(struct nbr *nbr, struct ls
> {
> /* invalid age */
> if ((ntohs(lsa_hdr->age) < 1) || (ntohs(lsa_hdr->age) > MAX_AGE)) {
> - log_debug("lsa_hdr_check: invalid age, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("lsa_hdr_check: invalid age, neighbor ID %s (%s)",
> + inet_ntoa(nbr->id), nbr->iface->name);
> return (0);
> }
>
> @@ -157,15 +158,17 @@ lsa_hdr_check(struct nbr *nbr, struct ls
> case LSA_TYPE_EXTERNAL:
> break;
> default:
> - log_debug("lsa_hdr_check: invalid LSA type %d, neighbor ID %s",
> - lsa_hdr->type, inet_ntoa(nbr->id));
> + log_debug("lsa_hdr_check: invalid LSA type %d, "
> + "neighbor ID %s (%s)",
> + lsa_hdr->type, inet_ntoa(nbr->id), nbr->iface->name);
> return (0);
> }
>
> /* invalid sequence number */
> if (ntohl(lsa_hdr->seq_num) == RESV_SEQ_NUM) {
> - log_debug("ls_hdr_check: invalid seq num, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("ls_hdr_check: invalid seq num, "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return (0);
> }
>
> Index: ospf6d/lsreq.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/lsreq.c,v
> retrieving revision 1.12
> diff -u -p -r1.12 lsreq.c
> --- ospf6d/lsreq.c 19 Jan 2021 09:53:11 -0000 1.12
> +++ ospf6d/lsreq.c 2 Nov 2021 17:11:38 -0000
> @@ -96,8 +96,8 @@ recv_ls_req(struct nbr *nbr, char *buf,
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_req: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -209,7 +209,8 @@ ls_req_tx_timer(int fd, short event, voi
> return;
> default:
> log_debug("ls_req_tx_timer: unknown neighbor state, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> break;
> }
>
> Index: ospf6d/lsupdate.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/lsupdate.c,v
> retrieving revision 1.20
> diff -u -p -r1.20 lsupdate.c
> --- ospf6d/lsupdate.c 19 Jan 2021 09:53:11 -0000 1.20
> +++ ospf6d/lsupdate.c 2 Nov 2021 17:11:38 -0000
> @@ -243,8 +243,9 @@ recv_ls_update(struct nbr *nbr, char *bu
> u_int32_t nlsa;
>
> if (len < sizeof(nlsa)) {
> - log_warnx("recv_ls_update: bad packet size, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_warnx("recv_ls_update: bad packet size, "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> memcpy(&nlsa, buf, sizeof(nlsa));
> @@ -260,8 +261,8 @@ recv_ls_update(struct nbr *nbr, char *bu
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_update: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -269,13 +270,15 @@ recv_ls_update(struct nbr *nbr, char *bu
> for (; nlsa > 0 && len > 0; nlsa--) {
> if (len < sizeof(lsa)) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> memcpy(&lsa, buf, sizeof(lsa));
> if (len < ntohs(lsa.len)) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> ospfe_imsg_compose_rde(IMSG_LS_UPD, nbr->peerid, 0,
> @@ -285,7 +288,8 @@ recv_ls_update(struct nbr *nbr, char *bu
> }
> if (nlsa > 0 || len > 0) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> break;
> @@ -497,8 +501,8 @@ ls_retrans_timer(int fd, short event, vo
> if (nlsa == 0) {
> /* something bad happened retry later */
> log_warnx("ls_retrans_timer: sending LS update "
> - "to neighbor ID %s failed",
> - inet_ntoa(nbr->id));
> + "to neighbor ID %s (%s) failed",
> + inet_ntoa(nbr->id), nbr->iface->name);
> log_debug("ls_retrans_timer: type: %04x len:
> %u",
> ntohs(le->le_ref->hdr.type),
> le->le_ref->len);
> Index: ospf6d/neighbor.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospf6d/neighbor.c,v
> retrieving revision 1.17
> diff -u -p -r1.17 neighbor.c
> --- ospf6d/neighbor.c 22 Jun 2020 18:18:20 -0000 1.17
> +++ ospf6d/neighbor.c 2 Nov 2021 17:11:38 -0000
> @@ -136,9 +136,10 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
>
> if (nbr_fsm_tbl[i].state == -1) {
> /* event outside of the defined fsm, ignore it. */
> - log_warnx("nbr_fsm: neighbor ID %s, "
> + log_warnx("nbr_fsm: neighbor ID %s (%s), "
> "event %s not expected in state %s",
> - inet_ntoa(nbr->id), nbr_event_names[event],
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_event_names[event],
> nbr_state_name(old_state));
> return (0);
> }
> @@ -184,8 +185,9 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
> }
>
> if (ret) {
> - log_warnx("nbr_fsm: error changing state for neighbor ID %s, "
> - "event %s, state %s", inet_ntoa(nbr->id),
> + log_warnx("nbr_fsm: error changing state for neighbor "
> + "ID %s (%s), event %s, state %s",
> + inet_ntoa(nbr->id), nbr->iface->name,
> nbr_event_names[event], nbr_state_name(old_state));
> return (-1);
> }
> @@ -218,10 +220,11 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
> if_fsm(nbr->iface, IF_EVT_NBR_CHNG);
>
> log_debug("nbr_fsm: event %s resulted in action %s and "
> - "changing state for neighbor ID %s from %s to %s",
> + "changing state for neighbor ID %s (%s) from %s to %s",
> nbr_event_names[event],
> nbr_action_names[nbr_fsm_tbl[i].action],
> - inet_ntoa(nbr->id), nbr_state_name(old_state),
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_state_name(old_state),
> nbr_state_name(nbr->state));
>
> if (nbr->iface->type == IF_TYPE_VIRTUALLINK) {
> @@ -437,8 +440,9 @@ nbr_adj_timer(int fd, short event, void
> return;
>
> if (nbr->state & NBR_STA_ACTIVE && nbr->state != NBR_STA_FULL) {
> - log_warnx("nbr_adj_timer: failed to form adjacency with %s",
> - inet_ntoa(nbr->id));
> + log_warnx("nbr_adj_timer: failed to form adjacency with "
> + "neighbor ID %s on interface %s",
> + inet_ntoa(nbr->id), nbr->iface->name);
> nbr_fsm(nbr, NBR_EVT_ADJTMOUT);
> }
> }
> @@ -527,7 +531,8 @@ nbr_act_snapshot(struct nbr *nbr)
> /* we need to wait for the old snapshot to finish */
> if (nbr->dd_snapshot) {
> log_debug("nbr_act_snapshot: giving up, old snapshot running "
> - "for neigbor ID %s", inet_ntoa(nbr->id));
> + "for neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return (nbr_act_restart_dd(nbr));
> }
> ospfe_imsg_compose_rde(IMSG_DB_SNAPSHOT, nbr->peerid, 0, NULL, 0);
> @@ -615,8 +620,9 @@ nbr_act_delete(struct nbr *nbr)
> tv.tv_sec = DEFAULT_NBR_TMOUT;
>
> if (evtimer_add(&nbr->inactivity_timer, &tv)) {
> - log_warnx("nbr_act_delete: error scheduling neighbor ID %s "
> - "for removal", inet_ntoa(nbr->id));
> + log_warnx("nbr_act_delete: error scheduling "
> + "neighbor ID %s (%s) for removal",
> + inet_ntoa(nbr->id), nbr->iface->name);
> }
>
> return (nbr_act_clear_lists(nbr));
> @@ -640,7 +646,8 @@ nbr_act_clear_lists(struct nbr *nbr)
> int
> nbr_act_hello_check(struct nbr *nbr)
> {
> - log_debug("nbr_act_hello_check: neighbor ID %s", inet_ntoa(nbr->id));
> + log_debug("nbr_act_hello_check: neighbor ID %s (%s)",
> + inet_ntoa(nbr->id), nbr->iface->name);
>
> return (-1);
> }
> Index: ospfd/database.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospfd/database.c,v
> retrieving revision 1.34
> diff -u -p -r1.34 database.c
> --- ospfd/database.c 15 Jul 2019 18:26:39 -0000 1.34
> +++ ospfd/database.c 2 Nov 2021 17:11:38 -0000
> @@ -62,9 +62,9 @@ send_db_description(struct nbr *nbr)
> case NBR_STA_INIT:
> case NBR_STA_2_WAY:
> case NBR_STA_SNAP:
> - log_debug("send_db_description: neighbor ID %s: "
> + log_debug("send_db_description: neighbor ID %s (%s): "
> "cannot send packet in state %s", inet_ntoa(nbr->id),
> - nbr_state_name(nbr->state));
> + nbr->iface->name, nbr_state_name(nbr->state));
> goto fail;
> case NBR_STA_XSTRT:
> bits |= OSPF_DBD_MS | OSPF_DBD_M | OSPF_DBD_I;
> @@ -166,8 +166,8 @@ recv_db_description(struct nbr *nbr, cha
> int dupe = 0;
>
> if (len < sizeof(dd_hdr)) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> - "bad packet size", inet_ntoa(nbr->id));
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> + "bad packet size", inet_ntoa(nbr->id), nbr->iface->name);
> return;
> }
> memcpy(&dd_hdr, buf, sizeof(dd_hdr));
> @@ -176,9 +176,10 @@ recv_db_description(struct nbr *nbr, cha
>
> /* db description packet sanity checks */
> if (ntohs(dd_hdr.iface_mtu) > nbr->iface->mtu) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "invalid MTU %d expected %d", inet_ntoa(nbr->id),
> - ntohs(dd_hdr.iface_mtu), nbr->iface->mtu);
> + nbr->iface->name, ntohs(dd_hdr.iface_mtu),
> + nbr->iface->mtu);
> return;
> }
>
> @@ -186,8 +187,9 @@ recv_db_description(struct nbr *nbr, cha
> nbr->last_rx_bits == dd_hdr.bits &&
> ntohl(dd_hdr.dd_seq_num) == nbr->dd_seq_num - nbr->dd_master ?
> 1 : 0) {
> - log_debug("recv_db_description: dupe from neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("recv_db_description: dupe from "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> dupe = 1;
> }
>
> @@ -196,9 +198,9 @@ recv_db_description(struct nbr *nbr, cha
> case NBR_STA_ATTEMPT:
> case NBR_STA_2_WAY:
> case NBR_STA_SNAP:
> - log_debug("recv_db_description: neighbor ID %s: "
> + log_debug("recv_db_description: neighbor ID %s (%s): "
> "packet ignored in state %s", inet_ntoa(nbr->id),
> - nbr_state_name(nbr->state));
> + nbr->iface->name, nbr_state_name(nbr->state));
> return;
> case NBR_STA_INIT:
> /* evaluate dr and bdr after issuing a 2-Way event */
> @@ -212,10 +214,10 @@ recv_db_description(struct nbr *nbr, cha
> return;
> nbr->capa_options = dd_hdr.opts;
> if ((nbr->capa_options & nbr->options) != nbr->options) {
> - log_warnx("recv_db_description: neighbor ID %s "
> + log_warnx("recv_db_description: neighbor ID %s (%s) "
> "sent inconsistent options %x vs. %x",
> - inet_ntoa(nbr->id), nbr->capa_options,
> - nbr->options);
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->capa_options, nbr->options);
> }
> /*
> * check bits: either I,M,MS or only M
> @@ -235,10 +237,10 @@ recv_db_description(struct nbr *nbr, cha
> /* M only case: we are master */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> return;
> }
> nbr->dd_seq_num++;
> @@ -254,9 +256,10 @@ recv_db_description(struct nbr *nbr, cha
> }
> } else {
> /* ignore packet */
> - log_debug("recv_db_description: neighbor ID %s: "
> + log_debug("recv_db_description: neighbor ID %s (%s): "
> "packet ignored in state %s (bad flags)",
> - inet_ntoa(nbr->id), nbr_state_name(nbr->state));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_state_name(nbr->state));
> }
> break;
> case NBR_STA_XCHNG:
> @@ -264,16 +267,17 @@ recv_db_description(struct nbr *nbr, cha
> case NBR_STA_FULL:
> if (dd_hdr.bits & OSPF_DBD_I ||
> !(dd_hdr.bits & OSPF_DBD_MS) == !nbr->dd_master) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> - "seq num mismatch, bad flags", inet_ntoa(nbr->id));
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> + "seq num mismatch, bad flags", inet_ntoa(nbr->id),
> + nbr->iface->name);
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
>
> if (nbr->last_rx_options != dd_hdr.opts) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "seq num mismatch, bad options",
> - inet_ntoa(nbr->id));
> + inet_ntoa(nbr->id), nbr->iface->name);
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -286,10 +290,10 @@ recv_db_description(struct nbr *nbr, cha
> }
>
> if (nbr->state != NBR_STA_XCHNG) {
> - log_warnx("recv_db_description: neighbor ID %s: "
> + log_warnx("recv_db_description: neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -299,10 +303,10 @@ recv_db_description(struct nbr *nbr, cha
> /* master */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x, master",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -311,10 +315,10 @@ recv_db_description(struct nbr *nbr, cha
> /* slave */
> if (ntohl(dd_hdr.dd_seq_num) != nbr->dd_seq_num + 1) {
> log_warnx("recv_db_description: "
> - "neighbor ID %s: "
> + "neighbor ID %s (%s): "
> "invalid seq num, mine %x his %x, slave",
> - inet_ntoa(nbr->id), nbr->dd_seq_num,
> - ntohl(dd_hdr.dd_seq_num));
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr->dd_seq_num, ntohl(dd_hdr.dd_seq_num));
> nbr_fsm(nbr, NBR_EVT_SEQ_NUM_MIS);
> return;
> }
> @@ -398,8 +402,9 @@ db_tx_timer(int fd, short event, void *a
> send_db_description(nbr);
> break;
> default:
> - log_debug("db_tx_timer: neighbor ID %s: unknown neighbor state",
> - inet_ntoa(nbr->id));
> + log_debug("db_tx_timer: neighbor ID %s (%s): "
> + "unknown neighbor state",
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> }
>
> Index: ospfd/lsack.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospfd/lsack.c,v
> retrieving revision 1.22
> diff -u -p -r1.22 lsack.c
> --- ospfd/lsack.c 15 Jul 2019 18:26:39 -0000 1.22
> +++ ospfd/lsack.c 2 Nov 2021 17:11:38 -0000
> @@ -111,8 +111,8 @@ recv_ls_ack(struct nbr *nbr, char *buf,
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_ack: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -133,7 +133,8 @@ recv_ls_ack(struct nbr *nbr, char *buf,
> }
> if (len > 0) {
> log_warnx("recv_ls_ack: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> break;
> @@ -147,8 +148,8 @@ lsa_hdr_check(struct nbr *nbr, struct ls
> {
> /* invalid age */
> if ((ntohs(lsa_hdr->age) < 1) || (ntohs(lsa_hdr->age) > MAX_AGE)) {
> - log_debug("lsa_hdr_check: invalid age, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("lsa_hdr_check: invalid age, neighbor ID %s (%s)",
> + inet_ntoa(nbr->id), nbr->iface->name);
> return (0);
> }
>
> @@ -161,15 +162,17 @@ lsa_hdr_check(struct nbr *nbr, struct ls
> case LSA_TYPE_EXTERNAL:
> break;
> default:
> - log_debug("lsa_hdr_check: invalid LSA type %d, neighbor ID %s",
> - lsa_hdr->type, inet_ntoa(nbr->id));
> + log_debug("lsa_hdr_check: invalid LSA type %d, "
> + "neighbor ID %s (%s)",
> + lsa_hdr->type, inet_ntoa(nbr->id), nbr->iface->name);
> return (0);
> }
>
> /* invalid sequence number */
> if (ntohl(lsa_hdr->seq_num) == RESV_SEQ_NUM) {
> - log_debug("ls_hdr_check: invalid seq num, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_debug("ls_hdr_check: invalid seq num, "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return (0);
> }
>
> Index: ospfd/lsreq.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospfd/lsreq.c,v
> retrieving revision 1.22
> diff -u -p -r1.22 lsreq.c
> --- ospfd/lsreq.c 19 Jan 2021 09:25:53 -0000 1.22
> +++ ospfd/lsreq.c 2 Nov 2021 17:11:38 -0000
> @@ -99,8 +99,8 @@ recv_ls_req(struct nbr *nbr, char *buf,
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_req: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -212,7 +212,8 @@ ls_req_tx_timer(int fd, short event, voi
> return;
> default:
> log_debug("ls_req_tx_timer: unknown neighbor state, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> break;
> }
>
> Index: ospfd/lsupdate.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospfd/lsupdate.c,v
> retrieving revision 1.49
> diff -u -p -r1.49 lsupdate.c
> --- ospfd/lsupdate.c 19 Jan 2021 09:25:53 -0000 1.49
> +++ ospfd/lsupdate.c 2 Nov 2021 17:11:38 -0000
> @@ -238,8 +238,9 @@ recv_ls_update(struct nbr *nbr, char *bu
> u_int32_t nlsa;
>
> if (len < sizeof(nlsa)) {
> - log_warnx("recv_ls_update: bad packet size, neighbor ID %s",
> - inet_ntoa(nbr->id));
> + log_warnx("recv_ls_update: bad packet size, "
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> memcpy(&nlsa, buf, sizeof(nlsa));
> @@ -255,8 +256,8 @@ recv_ls_update(struct nbr *nbr, char *bu
> case NBR_STA_XSTRT:
> case NBR_STA_SNAP:
> log_debug("recv_ls_update: packet ignored in state %s, "
> - "neighbor ID %s", nbr_state_name(nbr->state),
> - inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", nbr_state_name(nbr->state),
> + inet_ntoa(nbr->id), nbr->iface->name);
> break;
> case NBR_STA_XCHNG:
> case NBR_STA_LOAD:
> @@ -264,13 +265,15 @@ recv_ls_update(struct nbr *nbr, char *bu
> for (; nlsa > 0 && len > 0; nlsa--) {
> if (len < sizeof(lsa)) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> memcpy(&lsa, buf, sizeof(lsa));
> if (len < ntohs(lsa.len)) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> ospfe_imsg_compose_rde(IMSG_LS_UPD, nbr->peerid, 0,
> @@ -280,7 +283,8 @@ recv_ls_update(struct nbr *nbr, char *bu
> }
> if (nlsa > 0 || len > 0) {
> log_warnx("recv_ls_update: bad packet size, "
> - "neighbor ID %s", inet_ntoa(nbr->id));
> + "neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return;
> }
> break;
> @@ -491,8 +495,8 @@ ls_retrans_timer(int fd, short event, vo
> if (nlsa == 0) {
> /* something bad happened retry later */
> log_warnx("ls_retrans_timer: sending LS update "
> - "to neighbor ID %s failed",
> - inet_ntoa(nbr->id));
> + "to neighbor ID %s (%s) failed",
> + inet_ntoa(nbr->id), nbr->iface->name);
> TAILQ_REMOVE(&nbr->ls_retrans_list, le, entry);
> nbr->ls_ret_cnt--;
> le->le_when = nbr->iface->rxmt_interval;
> Index: ospfd/neighbor.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/ospfd/neighbor.c,v
> retrieving revision 1.49
> diff -u -p -r1.49 neighbor.c
> --- ospfd/neighbor.c 19 Nov 2019 09:55:55 -0000 1.49
> +++ ospfd/neighbor.c 2 Nov 2021 17:11:38 -0000
> @@ -136,9 +136,10 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
>
> if (nbr_fsm_tbl[i].state == -1) {
> /* event outside of the defined fsm, ignore it. */
> - log_warnx("nbr_fsm: neighbor ID %s, "
> + log_warnx("nbr_fsm: neighbor ID %s (%s), "
> "event %s not expected in state %s",
> - inet_ntoa(nbr->id), nbr_event_names[event],
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_event_names[event],
> nbr_state_name(old_state));
> return (0);
> }
> @@ -184,8 +185,9 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
> }
>
> if (ret) {
> - log_warnx("nbr_fsm: error changing state for neighbor ID %s, "
> - "event %s, state %s", inet_ntoa(nbr->id),
> + log_warnx("nbr_fsm: error changing state for neighbor "
> + "ID %s (%s), event %s, state %s",
> + inet_ntoa(nbr->id), nbr->iface->name,
> nbr_event_names[event], nbr_state_name(old_state));
> return (-1);
> }
> @@ -217,10 +219,11 @@ nbr_fsm(struct nbr *nbr, enum nbr_event
> if_fsm(nbr->iface, IF_EVT_NBR_CHNG);
>
> log_debug("nbr_fsm: event %s resulted in action %s and "
> - "changing state for neighbor ID %s from %s to %s",
> + "changing state for neighbor ID %s (%s) from %s to %s",
> nbr_event_names[event],
> nbr_action_names[nbr_fsm_tbl[i].action],
> - inet_ntoa(nbr->id), nbr_state_name(old_state),
> + inet_ntoa(nbr->id), nbr->iface->name,
> + nbr_state_name(old_state),
> nbr_state_name(nbr->state));
>
> if (nbr->iface->type == IF_TYPE_VIRTUALLINK) {
> @@ -523,7 +526,8 @@ nbr_act_snapshot(struct nbr *nbr)
> /* we need to wait for the old snapshot to finish */
> if (nbr->dd_snapshot) {
> log_debug("nbr_act_snapshot: giving up, old snapshot running "
> - "for neigbor ID %s", inet_ntoa(nbr->id));
> + "for neighbor ID %s (%s)", inet_ntoa(nbr->id),
> + nbr->iface->name);
> return (nbr_act_restart_dd(nbr));
> }
> ospfe_imsg_compose_rde(IMSG_NEIGHBOR_CAPA, nbr->peerid, 0,
> @@ -616,8 +620,9 @@ nbr_act_delete(struct nbr *nbr)
> tv.tv_sec = DEFAULT_NBR_TMOUT;
>
> if (evtimer_add(&nbr->inactivity_timer, &tv)) {
> - log_warnx("nbr_act_delete: error scheduling neighbor ID %s "
> - "for removal", inet_ntoa(nbr->id));
> + log_warnx("nbr_act_delete: error scheduling "
> + "neighbor ID %s (%s) for removal",
> + inet_ntoa(nbr->id), nbr->iface->name);
> }
>
> return (nbr_act_clear_lists(nbr));
> @@ -641,7 +646,8 @@ nbr_act_clear_lists(struct nbr *nbr)
> int
> nbr_act_hello_check(struct nbr *nbr)
> {
> - log_debug("nbr_act_hello_check: neighbor ID %s", inet_ntoa(nbr->id));
> + log_debug("nbr_act_hello_check: neighbor ID %s (%s)",
> + inet_ntoa(nbr->id), nbr->iface->name);
>
> return (-1);
> }
>
