Is OSPF route delete logging incomplete or am I missing it in another debug log?

[Cerebus]

Discussed in #16760

^{Originally posted by Cerebus September 6, 2024}
Version 9.1 currently but I can upgrade if necessary.

I have debug ospf zebra enabled b/c I want to see changes to the routing table.

When a distant link that's part of an ECMP set dies and OSPF processes the LSA, it does not log the deletion of the ECMP route.

E.g., given the starting point:

192.168.0.6/31 nhid 33 via 192.168.0.1 dev eth1 proto ospf metric 20
192.168.0.12/31 nhid 34 proto ospf metric 20
        nexthop via 192.168.0.3 dev eth2 weight 1
        nexthop via 192.168.0.1 dev eth1 weight 1

The 0.6/31 link is traversed by 0.12/31 destinations over the eth1 link. If that distant link dies, OSPF logs:

2024/09/06 20:33:41.726 OSPF: [GEBDT-G1CP1] Zebra: Route delete 192.168.0.6/31
2024/09/06 20:33:41.726 OSPF: [RDXQE-Z6A3B] Zebra: Route add 192.168.0.12/31 nexthop 192.168.0.3, ifindex=115 eth2

And the resulting table:

192.168.0.12/31 nhid 26 via 192.168.0.3 dev eth2 proto ospf metric 20

The resulting table is correct, but the log omits the deletion of 0.12/31 nexthop via eth1. Is this info in another debug log, or is this a bug?

[donaldsharp]

The code is telling you the route is being replaced w/ 1 nexthop.

[Cerebus]

You're saying the delete is implicit, but if the link is later restored, both are logged:

2024/09/06 20:40:33.211 OSPF: [RDXQE-Z6A3B] Zebra: Route add 192.168.0.12/31 nexthop 192.168.0.1, ifindex=96 eth1
2024/09/06 20:40:33.211 OSPF: [RDXQE-Z6A3B] Zebra: Route add 192.168.0.12/31 nexthop 192.168.0.3, ifindex=115 eth2

In this case the nexthop is cumulative, not a replacement. If there's an implicit route delete in one case but not in the other, how would an observer know the difference?

ETA: I omitted the route additions for the 0.6/31 prefix as they're not really relevant.

[mjstapp]

ospf debugs each nexthop one-by-one - that's just ... how that particular debug is written

[donaldsharp]

There is no delete on a route replacement. I believe that is your confusion. All the code is saying replace the route with this new one and here is the list of nexthops I am sending down.

[Cerebus]

I'm tracking, but the confusion is in the logging, not in me.

Say, frex, that I'm parsing the events and reconstructing the FIB. On any given Route add event, I don't know if this event is a replacement or an addition. These are very different events. I can't assume one or the other b/c the resulting FIB state will be wrong. The router has it correct, but I can't determine that from the logging.

If I have to look into the future to determine if a given Route add should be a replacement -- e.g., looking for a block of closely-timed Route add for the same prefix and treating the set as a replacement -- then the logging is at fault. Logs should fully reflect the events taking place at the moment of the log.

[donaldsharp]

Mark is correct that is just how these debugs are written, nor am I going to sanction a change in debug logs to stuff a bunch of nexthops on one line. Debug logs are meant to be readable by a human. I disagree with the notion that all debugs should reflect a single event as well, debug logs are meant to help the developer debug the code when something has gone wrong, that is it. Informational/Warning and Error I would agree with you, though. We also MAKE no guarantee about debug logs. They can and do change from release to release as we improve things. Hell one of the major problems with debugs that I am still fixing are debugs that don't include the vrf in them( thanks for pointing this out to me for these debugs, I'll address that).

In any event reading debug logs is not a way that I would ever recommend for doing what I think you are trying to do, although in all honesty I am not really sure what you are trying to do so I cannot really point you in a direction. ospfd has a way to peak into it's database. Zebra has some basic scripting with lua that has a way to hook into rib processing. What is the actual end goal of your problem?

[Cerebus]

In any event reading debug logs is not a way that I would ever recommend for doing what I think you are trying to do, although in all honesty I am not really sure what you are trying to do so I cannot really point you in a direction. ospfd has a way to peak into it's database.

I'm running emulated networks (at scale -- 100's to 1000's of nodes), capturing atomic changes to the RIB at all nodes, and analyzing the network's resilience given a range of disruption events. I've been adapting the ideas from this paper and will eventually apply them independent of the routing protocol.

Everything is there in the ospfd zebra logs except this one RIB change with ECMP paths. It's frustrating. :)

Zebra has some basic scripting with lua that has a way to hook into rib processing.

That's news to me, I'll look into it. Thanks for the pointer.

Debug logs are meant to be readable by a human.

I get that, but even the human gets confused in this instance; thus this discussion. My specific use case might be very niche, but the general use case -- understanding the local change to the RIB after a distant event -- is not.

[mjstapp]

it may be possible to revise the debug that isn't clear to you - to indicate in the first line more about the event that's happening - why don't you look into that?

Debug logs are meant to be readable by a human.

I get that, but even the human gets confused in this instance; thus this discussion. My specific use case might be very niche, but the general use case -- understanding the local change to the RIB after a distant event -- is not.

[Cerebus]

The zebra Lua dataplane hook looks promising, but Lua script is loaded into an empty namespace, so necessary global functions like pairs and ipairs are missing. Kind of makes it hard to iterate over the context table.

And no, local pairs = pairs doesn't help, you have to do that before setting the namespace.

[Cerebus]

So, our story so far:

Working off current HEAD w/ the unrelease log.trace() method:

local ops = {[0]="NONE", "ROUTE_INSTALL", "ROUTE_UPDATE", "ROUTE_DELETE", "ROUTE_NOTIFY",
             "NH_INSTALL", "NH_UPDATE", "NH_DELETE", "LSP_INSTALL", "LSP_UPDATE",
             "LSP_DELETE", "LSP_NOTIFY", "PW_INSTALL", "PW_UNINSTALL", "SYS_ROUTE_ADD",
             "SYS_ROUTE_DELETE", "ADDR_INSTALL", "ADD_UNINSTALL", "MAC_INSTALL",
             "MAC_DELETE", "NEIGH_INSTALL", "NEIGH_UDPATE", "NEIGH_DELETE",
             "VTEP_ADD", "VTEP_DELETE", "RULE_ADD", "RULE_DELETE", "RULE_UPDATE",
             "NEIGH_DISCOVER", "BR_PORT_UPDATE", "IPTABLE_ADD", "IPTABLE_DELETE",
             "IPSET_ADD", "IPSET_DELETE", "IPSET_ENTRY_ADD", "IPSET_ENTRY_DELETE",
             "NEIGH_IP_INSTALL", "NEIGH_IP_DELETE", "NEIGH_TABLE_UPDATE", "GRE_SET",
             "INTF_ADDR_ADD", "INTF_ADDR_DELETE", "INTF_NETCONFIG", "INTF_INSTALL",
             "INTF_UPDATE", "INTF_DELETE", "TC_QDISC_INSTALL", "TC_QDISC_UNINSTALL",
             "TC_QDISC_CLASS_ADD", "TC_QDISC_CLASS_DELETE", "TC_QDISC_CLASS_UPDATE",
             "TC_QDISC_FILTER_ADD", "TC_QDISC_FILTER_DELETE", "TC_QDISC_FILTER_UPDATE",
             "STARTUP_STAGE", "SRV6_ENCAP_SRCADDR_SET"}

function on_rib_process_dplane_results(ctx)
   local rinfo = ctx.rinfo
   local event = "op=" .. ops[ctx.zd_op] .. " dest=" .. rinfo.zd_dest.network .. " ifname=" .. ct
   local nhe = rinfo.nhe
   event = event .. " nhe.id=" .. nhe.id
   log.info(event)
   log.trace(rinfo.zd_ng) -- only works on FRR HEAD; unreleased code
   return {}
end

Logs:

2024/09/20 21:00:31.501 ZEBRA: [JZMNV-MDH8J] op=ROUTE_UPDATE dest=1.1.0.1/32 nhe.id=29
2024/09/20 21:00:31.501 ZEBRA: [GCZ7N-MM9D9] {
  1: {
    nh_encap_type: 0
    nh_label_type: 0
    weight: 1
    backup_idx: 0
    type: 3
    ifindex: 287
    srte_color: 0
    vrf_id: 0
    flags: 3
    backup_num: 0
  }
  2: {
    nh_encap_type: 0
    nh_label_type: 0
    weight: 1
    backup_idx: 0
    type: 3
    ifindex: 289
    srte_color: 0
    vrf_id: 0
    flags: 3
    backup_num: 0
  }
}

So it's a single dataplane event (DPLANE_OP_ROUTE_UPDATE) that replaces the current route entries for the prefix with the set of nexthops in the group.

The logging code turns this into multiple log lines, one per member of the nexthop group as "Route add". Yes, humans can grok what's happening but it's much harder for code -- and not just my code, but log analysis code e.g. in Kibana or Loki.

I could alter this logging with the zebra dataplane Lua hook -- except that Lua is crippled with an incomplete namespace. The only way to iterate over a Lua array or table is pairs() and ipairs(), but these aren't loaded into the Lua script namespace. That's probably a bug and I'll open a separate issue.

In addition, it would be nice to be able to pull in data from the OS, but that will require require and that's not in the namespace either. That's a sandboxing issue with security implications, I think, so worth it's own discussion.

The other option is to change the logging behavior to log the entire nexthop group in one entry. If I can figure it out I'll submit a PR and we can discuss the merits there.

[Cerebus]

Closing this; #16907 fixes the Lua namespace so walking the rinfo structure is now possible, and this hook can be used to generate the data I want.

[Cerebus]

If anyone else ever lands here looking for similar, here's what I finally ended up with. I don't like using io.popen() and if I ever need to get back to this I'll look at baking in a Lua iproute2 package and see if I can require it.

-- Cribbed from zebra_dplane.h (dropped the DPLANE_OP prefix)
local ops = {[0]="NONE", "ROUTE_INSTALL", "ROUTE_UPDATE", "ROUTE_DELETE", "ROUTE_NOTIFY",
             "NH_INSTALL", "NH_UPDATE", "NH_DELETE", "LSP_INSTALL", "LSP_UPDATE",
             "LSP_DELETE", "LSP_NOTIFY", "PW_INSTALL", "PW_UNINSTALL", "SYS_ROUTE_ADD",
             "SYS_ROUTE_DELETE", "ADDR_INSTALL", "ADD_UNINSTALL", "MAC_INSTALL",
             "MAC_DELETE", "NEIGH_INSTALL", "NEIGH_UDPATE", "NEIGH_DELETE",
             "VTEP_ADD", "VTEP_DELETE", "RULE_ADD", "RULE_DELETE", "RULE_UPDATE",
             "NEIGH_DISCOVER", "BR_PORT_UPDATE", "IPTABLE_ADD", "IPTABLE_DELETE",
             "IPSET_ADD", "IPSET_DELETE", "IPSET_ENTRY_ADD", "IPSET_ENTRY_DELETE",
             "NEIGH_IP_INSTALL", "NEIGH_IP_DELETE", "NEIGH_TABLE_UPDATE", "GRE_SET",
             "INTF_ADDR_ADD", "INTF_ADDR_DELETE", "INTF_NETCONFIG", "INTF_INSTALL",
             "INTF_UPDATE", "INTF_DELETE", "TC_QDISC_INSTALL", "TC_QDISC_UNINSTALL",
             "TC_QDISC_CLASS_ADD", "TC_QDISC_CLASS_DELETE", "TC_QDISC_CLASS_UPDATE",
             "TC_QDISC_FILTER_ADD", "TC_QDISC_FILTER_DELETE", "TC_QDISC_FILTER_UPDATE",
             "STARTUP_STAGE", "SRV6_ENCAP_SRCADDR_SET"}

function on_rib_process_dplane_results(ctx)
   local rinfo = ctx.rinfo
   local event = "op=" .. ops[ctx.zd_op] .. " dest=" .. rinfo.zd_dest.network
   if rinfo.zd_ng then
      for k, v in pairs(rinfo.zd_ng) do
         event = event .. " if." .. k .. "="
         local handle = io.popen("ip --json link | jq -r '.[] | select(.ifindex == " .. v.ifindex .. ") | .ifname'")
         event = event .. handle:read()
         handle:close()
      end
   end
   log.info(event)
   return {}

Logging on a distant link down LSA:

2024/10/08 12:34:02.718 ZEBRA: [JZMNV-MDH8J] op=ROUTE_DELETE dest=192.168.0.6/31 if.1=eth1
2024/10/08 12:34:02.721 ZEBRA: [JZMNV-MDH8J] op=ROUTE_UPDATE dest=192.168.0.12/31 if.1=eth2
2024/10/08 12:34:03.721 ZEBRA: [JZMNV-MDH8J] op=ROUTE_UPDATE dest=1.1.0.1/32 if.1=eth2

Logs on the link back up LSA:

2024/10/08 12:34:26.587 ZEBRA: [JZMNV-MDH8J] op=ROUTE_INSTALL dest=192.168.0.6/31 if.1=eth1
2024/10/08 12:34:26.592 ZEBRA: [JZMNV-MDH8J] op=ROUTE_UPDATE dest=192.168.0.12/31 if.1=eth1 if.2=eth2
2024/10/08 12:34:27.594 ZEBRA: [JZMNV-MDH8J] op=ROUTE_UPDATE dest=1.1.0.1/32 if.1=eth1 if.2=eth2

Extended logging might be another option but in my specific case logs are going to stdout for aggregation by other tooling.