Re: ospfd/ospf6d, interfaces in log messages
Remi Locherer(remi.loche...@relo.ch) on 2021.11.03 22:23:44 +0100:
> On Tue, Nov 02, 2021 at 05:27:11PM +, 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
> > xx.2: invalid seq num, mine 20d22487 his 20d22485
> > Nov 2 11:29:30 ospf6d[89545]: recv_db_description: neighbor ID
> > xx.2: invalid seq num, mine 4cabc5c1 his 4cabc5c0
> > Nov 2 11:29:34 ospf6d[89545]: recv_db_description: neighbor ID
> > xx.1: invalid seq num, mine 98360a5 his 98360a4
> > Nov 2 11:29:34 ospfd[78532]: recv_db_description: neighbor ID
> > xx.1: invalid seq num, mine f708c646 his f708c645
> > Nov 2 11:29:38 ospfd[78532]: recv_db_description: neighbor ID
> > xx.11: invalid seq num, mine e4068bcc his e4068bcb
> > Nov 2 11:30:06 ospf6d[89545]: recv_db_description: neighbor ID
> > xx.3: seq num mismatch, bad flags
> > Nov 2 11:30:14 ospf6d[89545]: recv_db_description: neighbor ID
> > xx.1: invalid seq num, mine 98360ae his 98360ad
> > Nov 2 11:30:14 ospfd[78532]: recv_db_description: neighbor ID
> > xx.1: invalid seq num, mine f708c64f his f708c64e
> > Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID
> > xx.2: invalid seq num, mine 20d22493 his 20d22490
> > Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID
> > xx.2: invalid seq num, mine 20d22493 his 20d22492
> > Nov 2 11:30:39 ospfd[78532]: recv_db_description: neighbor ID
> > xx.2: invalid seq num, mine 20d2249c his 20d2249b
> > Nov 2 11:30:59 ospf6d[89545]: recv_db_description: neighbor ID
> > xx.11: seq num mismatch, bad flags
> > Nov 2 11:30:59 ospfd[78532]: recv_db_description: neighbor ID
> > xx.11: seq num mismatch, bad flags
> > Nov 2 11:31:09 ospfd[78532]: recv_db_description: neighbor ID
> > xx.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.
I thought i had okayed this yesterday already ;)
Makes complete sense.
> Diff reads fine, applies and compiles.
same.
> OK remi
ok benno
>
> >
> > 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 - 1.20
> > +++ ospf6d/database.c 2 Nov 2021 17:11:38 -
> > @@ -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(_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 @@
Re: ospfd/ospf6d, interfaces in log messages
On Tue, Nov 02, 2021 at 05:27:11PM +, 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 xx.2:
> invalid seq num, mine 20d22487 his 20d22485
> Nov 2 11:29:30 ospf6d[89545]: recv_db_description: neighbor ID
> xx.2: invalid seq num, mine 4cabc5c1 his 4cabc5c0
> Nov 2 11:29:34 ospf6d[89545]: recv_db_description: neighbor ID
> xx.1: invalid seq num, mine 98360a5 his 98360a4
> Nov 2 11:29:34 ospfd[78532]: recv_db_description: neighbor ID xx.1:
> invalid seq num, mine f708c646 his f708c645
> Nov 2 11:29:38 ospfd[78532]: recv_db_description: neighbor ID
> xx.11: invalid seq num, mine e4068bcc his e4068bcb
> Nov 2 11:30:06 ospf6d[89545]: recv_db_description: neighbor ID
> xx.3: seq num mismatch, bad flags
> Nov 2 11:30:14 ospf6d[89545]: recv_db_description: neighbor ID
> xx.1: invalid seq num, mine 98360ae his 98360ad
> Nov 2 11:30:14 ospfd[78532]: recv_db_description: neighbor ID xx.1:
> invalid seq num, mine f708c64f his f708c64e
> Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xx.2:
> invalid seq num, mine 20d22493 his 20d22490
> Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xx.2:
> invalid seq num, mine 20d22493 his 20d22492
> Nov 2 11:30:39 ospfd[78532]: recv_db_description: neighbor ID xx.2:
> invalid seq num, mine 20d2249c his 20d2249b
> Nov 2 11:30:59 ospf6d[89545]: recv_db_description: neighbor ID
> xx.11: seq num mismatch, bad flags
> Nov 2 11:30:59 ospfd[78532]: recv_db_description: neighbor ID
> xx.11: seq num mismatch, bad flags
> Nov 2 11:31:09 ospfd[78532]: recv_db_description: neighbor ID xx.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 - 1.20
> +++ ospf6d/database.c 2 Nov 2021 17:11:38 -
> @@ -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(_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));
> +
ospfd/ospf6d, interfaces in log messages
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 xx.2:
invalid seq num, mine 20d22487 his 20d22485
Nov 2 11:29:30 ospf6d[89545]: recv_db_description: neighbor ID xx.2:
invalid seq num, mine 4cabc5c1 his 4cabc5c0
Nov 2 11:29:34 ospf6d[89545]: recv_db_description: neighbor ID xx.1:
invalid seq num, mine 98360a5 his 98360a4
Nov 2 11:29:34 ospfd[78532]: recv_db_description: neighbor ID xx.1:
invalid seq num, mine f708c646 his f708c645
Nov 2 11:29:38 ospfd[78532]: recv_db_description: neighbor ID xx.11:
invalid seq num, mine e4068bcc his e4068bcb
Nov 2 11:30:06 ospf6d[89545]: recv_db_description: neighbor ID xx.3:
seq num mismatch, bad flags
Nov 2 11:30:14 ospf6d[89545]: recv_db_description: neighbor ID xx.1:
invalid seq num, mine 98360ae his 98360ad
Nov 2 11:30:14 ospfd[78532]: recv_db_description: neighbor ID xx.1:
invalid seq num, mine f708c64f his f708c64e
Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xx.2:
invalid seq num, mine 20d22493 his 20d22490
Nov 2 11:30:22 ospfd[78532]: recv_db_description: neighbor ID xx.2:
invalid seq num, mine 20d22493 his 20d22492
Nov 2 11:30:39 ospfd[78532]: recv_db_description: neighbor ID xx.2:
invalid seq num, mine 20d2249c his 20d2249b
Nov 2 11:30:59 ospf6d[89545]: recv_db_description: neighbor ID xx.11:
seq num mismatch, bad flags
Nov 2 11:30:59 ospfd[78532]: recv_db_description: neighbor ID xx.11:
seq num mismatch, bad flags
Nov 2 11:31:09 ospfd[78532]: recv_db_description: neighbor ID xx.1:
invalid seq num, mine f708c65c his f708c65b
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 - 1.20
+++ ospf6d/database.c 2 Nov 2021 17:11:38 -
@@ -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(_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: "
