netfilter buglog - Dec 2019 - [Bug 1392] New: nft stalls on EGAIN upon repeatedly flushing and populating a set

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

            Bug ID: 1392
           Summary: nft stalls on EGAIN upon repeatedly flushing and
                    populating a set
           Product: nftables
           Version: unspecified
          Hardware: x86_64
                OS: Gentoo
            Status: NEW
          Severity: normal
          Priority: P5
         Component: nft
          Assignee: pablo at netfilter.org
          Reporter: kfm at plushkava.net

Created attachment 580
  --> https://bugzilla.netfilter.org/attachment.cgi?id=580&action=edit
bash script that reproduces the issue filed

Recently, I was assisting somebody in the course of adjusting some scripts that
generate an ipset consisting of IPv6 bogons, so as to use native nftables sets.
While testing on my own machine, I found that nft appeared to sporadically
hang.

Upon further investigation, I found that the process - which entails one
"flush" and one "add element" command - was being carried
out rapidly at first,
only to encounter difficulties if repeated without flushing and recomposing the
underlying table entirely. The attached script acts as a reproducer. Here is
some sample output from my machine:

  [0]: Iteration #1
  [1]: Iteration #2
  [429]: Iteration #3
  [845]: Iteration #4

This means that the set was populated in a second or less (good), only to take
approximately 428 seconds on the second attempt (very bad). A single CPU core
is pegged throughout the second - and all subsequent - iterations. Some casual
stracing implies that there is some issue communicating with netlink. An EAGAIN
occurs, followed by a long stall.

Also, at one point, the following error appeared in my terminal, though I have
not been able to reproduce it:

  netlink: Error: Could not process rule: No space left on device

This machine is using the following components:

  Linux 5.4.6
  glibc-2.29
  libmnl-1.0.4
  libnfnetlink-1.0.1
  libnftnl-1.1.5
  nftables-0.9.3

My expectation is that repeated adjustment of the set be as efficient as it is
upon the first population, and that the overall reliability is commensurate
with that of ipset.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20191230/c7297ac1/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #1 from kfm at plushkava.net ---
I adjusted the script to strace just the first and second iterations, with
relative timestamps included. These traces are attached. For the second trace,
things go off the rails at the following timestamps:

  0.000077
  0.186808
426.479353

I emphasize that this is fully reproducible. When the script is run again, the
ruleset is re-composed, and the first iteration is always fast.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20191231/f541f218/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #2 from kfm at plushkava.net ---
Created attachment 582
  --> https://bugzilla.netfilter.org/attachment.cgi?id=582&action=edit
Iteration #1 trace (xz compressed)

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20191231/76181eba/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #3 from kfm at plushkava.net ---
Created attachment 583
  --> https://bugzilla.netfilter.org/attachment.cgi?id=583&action=edit
Iteration #2 trace (xz compressed)

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20191231/b04c4eb4/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|nft stalls on EGAIN upon    |nft stalls on EAGAIN upon
                   |repeatedly flushing and     |repeatedly flushing and
                   |populating a set            |populating a set

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20191231/bc52a136/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1439

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200703/f3c41e8a/attachment-0001.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

Timo Sigurdsson <public_timo.s at silentcreek.de> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |public_timo.s at silentcreek.d
                   |                            |e

--- Comment #4 from Timo Sigurdsson <public_timo.s at silentcreek.de> ---
(In reply to kfm from comment #0)
> Also, at one point, the following error appeared in my terminal, though I
> have not been able to reproduce it:
> 
>   netlink: Error: Could not process rule: No space left on device
I think I experienced the same or a similar issue once and I also couldn't
reproduce it. I once got a message from nft saying it failed to allocate
memory. I think it was during a run of `nft -cf' for my script containing
the
ipv6 bogons set.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200703/e9229fc4/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #5 from kfm at plushkava.net ---
(In reply to Timo Sigurdsson from comment #4)
> I think I experienced the same or a similar issue once and I also
couldn't
> reproduce it. I once got a message from nft saying it failed to allocate
> memory. I think it was during a run of `nft -cf' for my script
containing
> the ipv6 bogons set.
As it happens, I have been able to reproduce it many times since. I allowed the
script that I wrote to refresh my (IPv4) bogons set to run periodically, even
though it doesn't work well. The method employed is similar to the attached
script. That is, it tries to empty the set then add the new elements in a
single pass. It runs at 4 hour intervals and generates the "No space left
on
device" about 5 or 6 times a day.

Not only that, but it regularly triggers the following errors:

    Error: interval overlaps with an existing one
    Error: Could not process rule: File exists

For reference, my set definition is as follows:

    set bogons {
        type ipv4_addr
        flags interval,timeout
        auto-merge
        timeout 4h5m
    }

The intent was to try to work around the initial inability to reliably update
sets atomically by instead mimicking the behaviour of "ipset -exist
add". Of
course, it doesn't work properly. Nothing works. The only effect was to
expose
myself to additional bugs, some of which I ought to file but the sheer range of
issues that I encountered has greatly diminished my motivation of late.

In short, I can discern no viable method of:

1) atomically updating a set without reloading the entire ruleset (if it even
is atomic)
2) adding elements that may or may not already exist without errors and/or
side-effects

In the case of ipset, the first approach is rendered trivial due to the
existence of the "swap" command and the second works precisely as
designed and
documented.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200703/4457b41e/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #6 from Timo Sigurdsson <public_timo.s at silentcreek.de> ---
I'm surprised this works at all for you with the auto-merge flag set, as
described in bug #1404 (and I see you're subscribed to that as well).
Because
with that, I cannot update any set atomically. When I remove it, it works,
however only if the set is not as large.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200703/447c7594/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #7 from kfm at plushkava.net ---
(In reply to Timo Sigurdsson from comment #6)
> I'm surprised this works at all for you with the auto-merge flag set,
as
> described in bug #1404 (and I see you're subscribed to that as well).
Don't worry. It didn't :(

Suffice to say that I have completely given up on attempting to make this work.
I don't think it can be done with nftables in its present state.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200714/e9a54464/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

Pablo Neira Ayuso <pablo at netfilter.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |ASSIGNED

--- Comment #8 from Pablo Neira Ayuso <pablo at netfilter.org> ---
Could you please check if current nftables git snapshot fixes the problem for
you? Specifically, this small patch should speed up the reload time for large
interval sets.

http://git.netfilter.org/nftables/commit/?id=40ef308e19b6db02017a8a650406b0c6d37be750

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200721/394d5469/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #9 from kfm at plushkava.net ---
I tried to compile it but encountered the following error:

netlink_linearize.c:720:28: error: ‘NFTNL_EXPR_IMM_CHAIN_ID’ undeclared (first
use in this function); did you mean ‘NFTNL_EXPR_IMM_CHAIN’?

I'm attaching the complete build log.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200721/d4322ef8/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #10 from kfm at plushkava.net ---
Created attachment 600
  --> https://bugzilla.netfilter.org/attachment.cgi?id=600&action=edit
nftables-40ef308-build.log

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200721/28c74ba3/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #11 from kfm at plushkava.net ---
Off-topic: This bugzilla instance doesn't define a charset in the
Content-Type
header in the course of serving text/* attachments. It would probably make
sense to default to UTF-8, if possible. Otherwise, most user agents will assume
ISO-8859-1.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200721/1008b72c/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #12 from Pablo Neira Ayuso <pablo at netfilter.org> ---
(In reply to kfm from comment #9)
> I tried to compile it but encountered the following error:
> 
> netlink_linearize.c:720:28: error: ‘NFTNL_EXPR_IMM_CHAIN_ID’ undeclared
> (first use in this function); did you mean ‘NFTNL_EXPR_IMM_CHAIN’?
> 
> I'm attaching the complete build log.
Refresh your libnftnl git snapshot too.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200721/edcf0f18/attachment-0001.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1431

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200730/34cc57df/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1404

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200730/26bbd9ec/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #13 from kfm at plushkava.net ---
I have installed nftables (commit ca2e6e0) with libnftnl (commit a4db940) and
done some light testing with kernels 5.4.60 and 5.7.16. The good news is that
the exact issue reported by the opening comment no longer occurs. The bad news
is that there are some other issues that arise.

For both kernels, I conducted 9 tests amounting to the cross product of 3 set
configurations and 3 testing methodologies. The set configurations shall be
labelled with letters:

  A = type ipv4_addr; flags interval
  B = type ipv4_addr; flags interval; auto-merge
  C = type ipv4_addr; flags interval; auto-merge; timeout 4h5m

The testing methodologies shall be labelled with numbers:

  1 = (set empty; populate) x 1
  2 = (set populated; flush; populate) x 500
  3 = (set populated; no flush; populate) x 500

Hence, "1" means to attempt to populate the set just once after
loading the
ruleset containing the set definition. "2" means to re-populate 500
times in
succession, with a flush command in-between. Likewise for "3", just
with no
flush command between interations. In the case that there is a flush command,
it is integrated into the nft command stream, like so:-

  {
      if (( do_flush )); then
          echo 'flush set ip raw bogons'
      fi
      echo 'add element ip raw bogons { '
      grep -v '^#' /var/tmp/bogons.raw | tr '\n' ,
      echo ' }'
  } | nft -f - || exit

Below are the results of the nine tests, with wall time reported for some of
them.

  ╔════╦══════════════╦══════════════╗
  ║    ║    5.4.60    ║    5.7.16    ║
  ╠════╬══════════════╬══════════════╣
  ║ A1 ║      OK      ║      OK      ║
  ╠════╬══════════════╬══════════════╣
  ║ A2 ║ OK (14.015s) ║ OK (9.355s)  ║
  ╠════╬══════════════╬══════════════╣
  ║ A3 ║ OK (47.325s) ║ OK (30.718s) ║
  ╠════╬══════════════╬══════════════╣
  ║ B1 ║      OK      ║      OK      ║
  ╠════╬══════════════╬══════════════╣
  ║ B2 ║ OK (13.274s) ║ OK (9.934s)  ║
  ╠════╬══════════════╬══════════════╣
  ║ B3 ║     FAIL     ║     FAIL     ║
  ╠════╬══════════════╬══════════════╣
  ║ C1 ║      OK      ║      OK      ║
  ╠════╬══════════════╬══════════════╣
  ║ C2 ║ OK (13.514s) ║ OK (8.941s)  ║
  ╠════╬══════════════╬══════════════╣
  ║ C3 ║     FAIL     ║     FAIL     ║
  ╚════╩══════════════╩══════════════╝

Let's begin with the good. There is no apparent difference in the behaviour
of
either kernel except that 5.7 is faster. Tests {A,B,C}2 pass, implying that I
am now able to successfuly use the flush-then-add method of atomically
repopulating a set.

Now for the bad. Test A3 passes, even though the auto-merge flag isn't
defined.
On the other hand, tests {B,C}3 - where the auto-merge flag IS defined - fail.
This is confusing to me. If anything, I would expect A3 to fail because all of
the elements being added already exist. Here are the error messages reported in
the cases of failure:

  /dev/stdin:2:820-833: Error: interval overlaps with an existing one
  /dev/stdin:1:1-20343: Error: Could not process rule: File exists

Finally, while test A3 passes, it is noticeably slower than test A2, which
incorporates a flush command for each iteration. I arranged for two similar
tests, using a hash:net ipset. One test relied on the use of "ipset
flush" for
each iteration, and the other relied on the use "ipset -exist". I
understand
that it might not be entirely fair to compare the -exist option to the
auto-merge flag. Nevertheless, I found that both of the ipset test cases
completed in approximately 18 seconds, implying that the -exist option has a
low performance impact.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200823/a77d4c5e/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1451

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200823/71198a0a/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

--- Comment #14 from kfm at plushkava.net ---
So that the error messages for cases {B,C}3 can be better understood, I shall
attach the exact command stream that was given to nft.

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200823/2515583c/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
 Attachment #582 is|0                           |1
           obsolete|                            |
 Attachment #583 is|0                           |1
           obsolete|                            |
 Attachment #600 is|0                           |1
           obsolete|                            |

--- Comment #15 from kfm at plushkava.net ---
Created attachment 604
  --> https://bugzilla.netfilter.org/attachment.cgi?id=604&action=edit
netfilter-bug-1392-comment-14-nft-stream.txt

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200823/cf704abf/attachment-0001.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1454

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200824/257cbcd0/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1438

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200828/420bd301/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Blocks|                            |1461

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200829/dba11207/attachment.html>

https://bugzilla.netfilter.org/show_bug.cgi?id=1392

kfm at plushkava.net changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           See Also|                            |https://bugzilla.netfilter.
                   |                            |org/show_bug.cgi?id=1464

-- 
You are receiving this mail because:
You are watching all bug changes.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.netfilter.org/pipermail/netfilter-buglog/attachments/20200913/2810c659/attachment.html>