netlink reports an error=-33 on reading a netlink socket

[stcheng]

ERR portsyncd: :- readMe: netlink reports an error=-33 on reading a netlink socket

[pavel-shirshov]

#define NLE_DUMP_INTR       33

"Dump inconsistency detected, interrupted",

https://github.com/thom311/libnl/blob/7bf2e64654de75578db34b0eab53a3e4d106d65f/include/netlink/errno.h#L52
https://github.com/thom311/libnl/blob/7bf2e64654de75578db34b0eab53a3e4d106d65f/lib/error.c#L49

[prsunny]

I think in this case, the netlink flag would be set to NLM_F_DUMP_INTR which means the messages are incomplete

[lguohan]

is this related to the non-blocking socket issue?

[jipanyang]

Not 100 percent sure, but it seems more of kernel internal processing.
http://elixir.free-electrons.com/linux/v3.16.48/source/include/net/netlink.h#L620
https://patchwork.ozlabs.org/patch/369126/

[jipanyang]

Update: Have not been able to read through the netlink_dump() and the callers of it throughly, one of my guess is that:
netlink library function recvmsgs() is reading a multipart message, it records the the seq number of the message and passes it down to kernel for next message, if for any reason the kernel updated the link objects in between, it will cause sequence number change, and the next netlink get request will return with NLM_F_DUMP_INTR flag.

non-blocking socket might increased the chance of this problem, since it won't wait in recvmsgs() for NLMSG_DONE message if no data available on socket immediately, but instead come out and wait on Select().

SWSS_LOG_DEBUG("netlink reports NLE_AGAIN on reading a netlink socket"); could be changed to NOTICE level for now so we may check whether NLE_DUMP_INTR always happens after NLE_AGAIN

Update 2:
netlink: advertise incomplete dumps
Consider the following situation:

• a dump that would show 8 entries, four in the first
  round, and four in the second
• between the first and second rounds, 6 entries are
  removed
• now the second round will not show any entry, and
  even if there is a sequence/generation counter the
  application will not know
  torvalds/linux@670dc28

Update 3:
it looks the seq number is generated within kernel, but not from user space.
http://elixir.free-electrons.com/linux/v3.16.48/source/net/core/rtnetlink.c#L1250
http://elixir.free-electrons.com/linux/v3.16.48/source/net/ipv4/devinet.c#L1547

[prsunny]

Yes, maybe we can change this to NOTICE for now.

[vivekrnv]

Hi all,

I've recently observed this one of our regression runs.

Apr  5 22:24:18.409195 DUT NOTICE swss#portsyncd: :- onMsg: nlmsg type:16 key:eth3 admin:0 oper:0 addr:00:00:00:00:00:0d ifindex:16 master:0
Apr  5 22:24:18.409195 DUT NOTICE swss#portsyncd: :- onMsg: nlmsg type:16 key:eth1 admin:0 oper:0 addr:00:00:00:00:00:0e ifindex:17 master:0
Apr  5 22:24:18.409195 DUT NOTICE swss#portsyncd: :- onMsg: nlmsg type:16 key:eth3 admin:0 oper:0 addr:00:00:00:00:00:0d ifindex:16 master:0
Apr  5 22:24:18.409195 DUT NOTICE swss#portsyncd: :- onMsg: nlmsg type:16 key:eth1 admin:0 oper:0 addr:00:00:00:00:00:0e ifindex:17 master:0
Apr  5 22:24:18.409195 DUT ERR swss#portsyncd: :- readData: netlink reports an error=-33 on reading a netlink socket

Did anyone encounter this issue after libnl version 3.5.0 upgrade.

@pavel-shirshov I have a question on your comment in the PR #3967 "3.5.0 fixes (at least declared) following issue which bites us sometimes". Can you share the commit/patch which addressed this issue? I was not able to find any Release Notes for 3.5.0 version as such.

[vivekrnv]

syslog_with_netlink_debug_flag_enabled.log

I've enabled NCDB flag to record the netlink messages and luckily the 'error=-33' log was also seen after a few trails

After some analysis, these are my observations regarding the reason for this log:

1. Could definitely be the reason specified in the Linux Kernel PR. or

2. Portsyncd listens to kernel notifications for

RTM_NEWLINK (When create or set attributes on a link happens)
RTM_DELLINK (when deletion of a link happens).
In paralell, it also requests for a dump (only once) of Kernel DB of links using RTM_GETLINK (Link: https://github.com/Azure/sonic-swss/blob/master/portsyncd/portsyncd.cpp#L86).
All of these use the same socket.

I believe there is a coalescing of messages received between RTM_GETLINK (has a non-zero sequence number) and RTM_NEWLINK (has a 0 sequence number since it's a kernel notification).

RTM_GETLINK Dump Response from Kernel:
Jun  8 03:52:57.445331 sonic INFO swss#/supervisord: portsyncd --------------------------   BEGIN NETLINK MESSAGE ---------------------------
Jun  8 03:52:57.445563 sonic INFO swss#/supervisord: portsyncd   [NETLINK HEADER] 16 octets
Jun  8 03:52:57.445797 sonic INFO swss#/supervisord: portsyncd     .nlmsg_len = 1316
Jun  8 03:52:57.446245 sonic INFO swss#/supervisord: portsyncd     .type = 16 <route/link::new>
Jun  8 03:52:57.446414 sonic INFO swss#/supervisord: portsyncd     .flags = 2 <MULTI>
Jun  8 03:52:57.446556 sonic INFO swss#/supervisord: portsyncd     .seq = 1623124377
Jun  8 03:52:57.446693 sonic INFO swss#/supervisord: portsyncd     .port = 322961436
[PAYLOAD]
<Truncated>

RTM_NEWLINK Notification:
Jun  8 03:52:57.566113 sonic INFO swss#/supervisord: portsyncd --------------------------   BEGIN NETLINK MESSAGE ---------------------------
Jun  8 03:52:57.566535 sonic INFO swss#/supervisord: portsyncd   [NETLINK HEADER] 16 octets
Jun  8 03:52:57.566782 sonic INFO swss#/supervisord: portsyncd     .nlmsg_len = 1320
Jun  8 03:52:57.567376 sonic INFO swss#/supervisord: portsyncd     .type = 16 <route/link::new>
Jun  8 03:52:57.567675 sonic INFO swss#/supervisord: portsyncd     .flags = 0 <>
Jun  8 03:52:57.569135 sonic INFO swss#/supervisord: portsyncd     .seq = 0
Jun  8 03:52:57.569344 sonic INFO swss#/supervisord: portsyncd     .port = 0
Jun  8 03:52:57.569448 sonic INFO swss#/supervisord: portsyncd   [PAYLOAD]
[PAYLOAD]
<Truncated>

# Kernel Code which sets the inconsistency flag
static inline void
nl_dump_check_consistent(struct netlink_callback *cb,
			 struct nlmsghdr *nlh)
{
	if (cb->prev_seq && cb->seq != cb->prev_seq)
		nlh->nlmsg_flags |= NLM_F_DUMP_INTR;
	cb->prev_seq = cb->seq;
}

It is not very clear to spot which of these pair of notification caused this inconsistency from the log attached because they all happen in < 1 second interval.

However, I am not sure of how the prev_seq and seq attrs of netlink_callback are set and i might be wrong here in thinking that sequence numbers from different requests (RTM_GETLINK & RTM_NEWLINK) are somehow causing the NLM_F_DUMP_INTR flag to become 1

[lguohan]

@vivekreddynv, do you know what is the implication for receiving such message? do we need to do anything or not?

[vivekrnv]

@vivekreddynv, do you know what is the implication for receiving such message? do we need to do anything or not?

What implication does this have?
This is Non-functional in nature as we do see it coming up intermittently in our regression runs, but the tests doesn't fail. I've checked libnl code to verify the flow. Although the dump received from the kernel has the flag (NLM_F_DUMP_INTR) enabled, the libnl would still continue to read all the entries in the dump. Ref: [Link]. So, any dumps from the kernel are not left out and portsyncd handles it accordingly (https://www.infradead.org/~tgr/libnl/doc/api/nl_8c_source.html#l00810)

Why does this happen?
I am not entirely sure as to why. The reason specified in this PR could be the reason (torvalds/linux@670dc28). For this to happen, the kernel entries for the links have to be modified while the multi-part dump from the kernel to the user-space process is in progress. It might be the case that physical state of the port is changing while this is happening. Or I think, (Again, i might be wrong on this) it could be because of my comment above.

As a side note, There is an also an issue reported in libnl3 (not from SONiC) Link regarding this. So, currently, This log seems harmless and no functional impact is observed. For any additional info, further investigation has to be taken into.