rsyslog-relp: imrelp module leaves sockets in CLOSE_WAIT state which leads to file descriptor leak

[Matthew Ruffell]

[Impact]

In recent versions of rsyslog and librelp, the imrelp module leaks file descriptors due to a bug where it does not correctly close sockets, and instead, leaves them in the CLOSE_WAIT state.

This causes rsyslogd on busy servers to eventually hit the limit of maximum open files allowed, which locks rsyslogd up until it is restarted.

A workaround is to restart rsyslogd every month or so to manually close all of the open sockets.

Only users of the imrelp module are affected, and not rsyslog users in general.

[Testcase]

Install the rsyslog-relp module like so:

$ sudo apt install rsyslog rsyslog-relp

Next, generate a working directory, and make a config file that loads the relp module.

$ sudo mkdir /workdir
$ cat << EOF >> ./spool.conf
\$LocalHostName spool
\$AbortOnUncleanConfig on
\$PreserveFQDN on

global(
    workDirectory="/workdir"
    maxMessageSize="256k"
)

main_queue(queue.type="Direct")
module(load="imrelp")
input(
    type="imrelp"
    name="imrelp"
    port="601"
    ruleset="spool"
    MaxDataSize="256k"
)

ruleset(name="spool" queue.type="direct") {
}

# Just so rsyslog doesn't whine that we do not have outputs
ruleset(name="noop" queue.type="direct") {
    action(
        type="omfile"
        name="omfile"
        file="/workdir/spool.log"
    )
}
EOF

Verify that the config is valid, then start a rsyslog server.

$ sudo rsyslogd -f ./spool.conf -N9
$ sudo rsyslogd -f ./spool.conf -i /workdir/rsyslogd.pid

Fetch the rsyslogd PID and check for open files.

$ RLOGPID=$(cat /workdir/rsyslogd.pid)
$ sudo ls -l /proc/$RLOGPID/fd
total 0
lr-x------ 1 root root 64 Dec 17 01:22 0 -> /dev/urandom
lrwx------ 1 root root 64 Dec 17 01:22 1 -> 'socket:[41228]'
lrwx------ 1 root root 64 Dec 17 01:22 3 -> 'socket:[41222]'
lrwx------ 1 root root 64 Dec 17 01:22 4 -> 'socket:[41223]'
lrwx------ 1 root root 64 Dec 17 01:22 7 -> 'anon_inode:[eventpoll]'

We have 3 sockets open by default. Next, use netcat to open 100 connections:

$ for i in {1..100} ; do nc -z 127.0.0.1 601 ; done

Now check for open file descriptors, and there will be an extra 100 sockets
in the list:

$ sudo ls -l /proc/$RLOGPID/fd

https://paste.ubuntu.com/p/f6NQVNbZcR/

We can check the state of these sockets with:

$ ss -t

https://paste.ubuntu.com/p/7Ts2FbxJrg/

The listening sockets will be in CLOSE-WAIT, and the netcat sockets will be in FIN-WAIT-2.

$ ss -t | grep CLOSE-WAIT | wc -l
100

If you install the test package available in the following ppa:

https://launchpad.net/~mruffell/+archive/ubuntu/sf299578-test

When you open connections with netcat, these will be closed properly, and the file descriptor leak will be fixed.

[Where problems could occur]

If a regression were to occur, it would be limited to users of the imrelp module, which is a part of the rsyslogd-relp package, and depends on librelp.

rsyslog-relp is not part of a default installation of rsyslog, and is opt in by changing a configuration file to enable imrelp.

The changes to rsyslog implement a testcase which exercises the problematic code to ensure things are working as expected; this
can be enabled manually on build, and has been verified to pass (#7).

[Other]

Upstream bug list:

https://github.com/rsyslog/rsyslog/issues/4350
https://github.com/rsyslog/rsyslog/issues/4005
https://github.com/rsyslog/librelp/issues/188
https://github.com/rsyslog/librelp/pull/193

The following commits fix the problem:

rsyslogd
========

commit baee0bd5420649329793746f0daf87c4f59fe6a6
Author: Andre lorbach <email address hidden>
Date: Thu Apr 9 13:00:35 2020 +0200
Subject: testbench: Add test for imrelp to check broken session handling.
Link: https://github.com/rsyslog/rsyslog/commit/baee0bd5420649329793746f0daf87c4f59fe6a6

librelp
=======

commit 7907c9c57f6ed94c8ce5a4e63c3c4e019f71cff0
Author: Andre lorbach <email address hidden>
Date: Mon May 11 14:59:55 2020 +0200
Subject: fix memory leak on session break.
Link: https://github.com/rsyslog/librelp/commit/7907c9c57f6ed94c8ce5a4e63c3c4e019f71cff0

commit 4a6ad8637c244fd3a1caeb9a93950826f58e956a
Author: Andre lorbach <email address hidden>
Date: Wed Apr 8 15:55:32 2020 +0200
Subject: replsess: fix double free of sendbuf in some cases.
Link: https://github.com/rsyslog/librelp/commit/4a6ad8637c244fd3a1caeb9a93950826f58e956a

commit 3797944fb62273fa1164acd3104f0894b337c4d0
Author: Ognyan Kulev <email address hidden>
Date: Mon Jun 15 14:10:08 2020 +0300
Subject: Fix FD leak when socket shutdown is one-sided
Link: https://github.com/rsyslog/librelp/commit/3797944fb62273fa1164acd3104f0894b337c4d0

[Matthew Ruffell (mruffell)]

Since we only need to change librelp to fix the problem, we won't SRU the testcase to Focal's rsyslog, since there is no need to risk a regression for a testcase, which would effectively be a no-change rebuild.

The testcase is already present in rsyslog on Groovy and Hirsute, marking as released.

I found an extra commit we need for librelp, which is "Fix FD leak when socket shutdown is one-sided". This is needed for the netcat testcase and for basic heartbeat programs like load balancers etc, which open a port to the rsyslog relp port, but doesn't necessarily speak relp protocol over that port.

Building test packages now since my internal tests are now successful once I included "Fix FD leak when socket shutdown is one-sided".

[Matthew Ruffell (mruffell)]

Attached is the debdiff for librelp for Groovy

[Matthew Ruffell (mruffell)]

Attached is the debdiff for librelp for Focal

[Richard Laager (rlaager)]

The test package fixes the issue for me.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "Debdiff for librelp on Groovy" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

[Launchpad Janitor (janitor)]

This bug was fixed in the package librelp - 1.9.0-1ubuntu1

---------------
librelp (1.9.0-1ubuntu1) hirsute; urgency=medium

  * Merge from Debian unstable. (LP: #1910307)
    Remaining changes:
    [ William Grant ]
    - d/p/shrink-receiver-abort-tests.sh: Reduce message count
      so tests pass on slow platforms like riscv64.
    Dropped changes:
    - d/p/python2.diff: No longer needed due to tests being
      ported to python3 in recent versions.
  * Fix file descriptor leak as sockets are stuck in CLOSE_WAIT
    due to not being closed properly due to memory leak. (LP: #1908473)

 -- Matthew Ruffell <email address hidden> Thu, 26 Nov 2020 21:52:43 +0000

[Mauricio Faria de Oliveira (mfo)]

Matthew, thanks for the great work in this bug and patches.

Uploaded to Groovy and Focal w/ trivial changes; attached.

cheers,
Mauricio

...

debdiffs:

I've modified the patch files slightly, as we discussed;
- keep the commit messages;
- use its/patch headers for DEP3, adding Origin: / Bug-Ubuntu:
- added prefix keywords upstream/backport to Origin;,
  and documented changes done to backport patches 2,3.

upstream:

- no additional changes upstream that further change/fix these patches.

downstream:

- changelog looks good.
- version numbers and upgrade path look good.
- no other current uploads/versions in -proposed
- no block-proposed[-<release>] tag

build:

The packages built successfully on all architectures on
a PPA with -proposed enabled (as on build environments.)

tests:

I've done testing with your steps (thanks!) and the new test introduced in patch 2, manually.
Unfortunately it doesn't run at build time as the package --disable-valgrind in debian/rules.

> PASS: basic-sessionbreak-vg.sh # --enable-valgrind in d/rules; install valgrind/libtool; chmod +x

And also we don't have autopkgtests on librelp [1] nor rsyslog [2] (single reverse dep for librelp0).

So the two tests above seem to be really the only tests for this.
All good as both have positive results!

...

$ grep Package: debian/control
Package: librelp0
Package: librelp-dev

$ apt rdepends librelp0
librelp0
Reverse Depends:
  Depends: librelp-dev (= 1.5.0-1ubuntu2)
  Depends: rsyslog-relp (>= 1.5.0)
  Depends: rsyslog-relp (>= 1.4.0)

ubuntu@librelp-f:~/librelp-1.5.0$ apt rdepends librelp-dev
librelp-dev
Reverse Depends:

$ apt-cache show rsyslog-relp | grep Source:
Source: rsyslog
Source: rsyslog

[1] https://autopkgtest.ubuntu.com/packages/librelp
[1] https://autopkgtest.ubuntu.com/packages/rsyslog

[Brian Murray (brian-murray)]

Hello Matthew, or anyone else affected,

Accepted librelp into groovy-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/librelp/1.5.0-1ubuntu2.20.10.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-groovy to verification-done-groovy. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-groovy. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Brian Murray (brian-murray)]

Hello Matthew, or anyone else affected,

Accepted librelp into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/librelp/1.5.0-1ubuntu2.20.04.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Mauricio Faria de Oliveira (mfo)]

focal/riscv64 had 2 failures in the test suite.

i've requested a re-build so it runs again, as
it seems more related to the arch or something
transient than the patchset, as only this arch
and release hit it.
(groovy: all archs ok, focal: other archs ok)

attaching build log for ref (it's lost on retry)

[Mauricio Faria de Oliveira (mfo)]

and now it had only 1 failure in the test suite,
thus indeed a transient/arch-specific flakiness.

re-building once again.

$ zgrep '^FAIL: .*sh$' buildlog_ubuntu-focal-riscv64.librelp_1.5.0-1ubuntu2.20.04.1_BUILDING.txt.gz.*
buildlog_ubuntu-focal-

riscv64.librelp_1.5.0-1ubuntu2.20.04.1_BUILDING.txt.gz.1:FAIL: basic-realistic.sh
buildlog_ubuntu-focal-riscv64.librelp_1.5.0-1ubuntu2.20.04.1_BUILDING.txt.gz.1:FAIL: tls-basic-realistic.sh
buildlog_ubuntu-focal-

riscv64.librelp_1.5.0-1ubuntu2.20.04.1_BUILDING.txt.gz.2:FAIL: tls-basic-realistic.sh

[Mauricio Faria de Oliveira (mfo)]

Same one failure, re-building again.

[Mauricio Faria de Oliveira (mfo)]

Now the two tests failed again.

I have to EOD, and this might benefit from some delay, in case the transient condition just goes away.
Also, let's not overload the riscv64 builder with this so other builds can move on.

We have 7 days in -proposed to look at this in more detail (or the bad condition to go away), and get it built.

[Matthew Ruffell (mruffell)]

Same one failure on today's rebuild. Strange, since this is the exact same code as Groovy.

[Richard Laager (rlaager)]

I tested this on Focal. I installed librelp0 and restart rsyslog. Prior to the change, sockets were stacking up in CLOSE-WAIT (both from normal use and from the netcat test). After the change, sockets are being closed correctly.

[Matthew Ruffell (mruffell)]

Performing verification for librelp in Groovy.

I installed rsyslog-relp 8.2006.0-2ubuntu1 and librelp 1.5.0-1ubuntu2 from -updates to reproduce:

https://paste.ubuntu.com/p/gtn4rcXc72/

From there I set up the configuration script, ran a new instance of rsyslog, and used netcat to open 100 connections to the relp port.

When I checked the list of file descriptors, there were 100 sockets open, in the CLOSE_WAIT state.

From there, I enabled -proposed and installed librelp 1.5.0-1ubuntu2.20.10.1:

https://paste.ubuntu.com/p/nt342PJkQ5/

I started a new rsyslog instance, and used netcat to open 100 connections to the relp port.

All sockets were closed when rsyslog was done with them, and there were no sockets in CLOSE_WAIT.

I also ran the provided testcase in rsyslog, imrelp-sessionbreak-vg.sh.

I did this by:

1) pull-lp-source rsyslog groovy
2) edit debian/rules, add --enable-valgrind, remove --without-valgrind-tests,
3) debuild -uc -us -b

It will eventually build tests, and imrelp-sessionbreak-vg.sh passes:

make[5]: Entering directory '/home/ubuntu/rsyslog-8.2006.0/tests'
...
PASS: imrelp-sessionbreak-vg.sh
...

We pass both the upstream testsuite and the testcase from the bug report.

The file descriptor leak has been fixed, happy to mark as verified for Groovy.

[Matthew Ruffell (mruffell)]

Performing verification for Focal

I installed rsyslog-relp 8.2001.0-1ubuntu1.1 and librelp0 1.5.0-1ubuntu2 from -updates.

From there I set up the configuration file, launched a new rsyslog instance, and
used netcat to set 100 packets to the relp port.

https://paste.ubuntu.com/p/jCs9Dy6FYF/

As we can see, there are 100 sockets still open in the CLOSE_WAIT state.

From there I enabled -proposed and installed librelp 1.5.0-1ubuntu2.20.04.1.

I started a new instance of rsyslog, and used netcat to send another 100 packets
to the relp port. This time, all sockets were closed and not left in CLOSE_WAIT.

https://paste.ubuntu.com/p/vdzsVTctmf/

I also ran the testcase from the upstream testsuite, imrelp-sessionbreak-vg.sh.

I did this by:

1) pull-lp-source rsyslog focal
2) edit debian/rules, add --enable-valgrind, remove --without-valgrind-tests,
3) wget https://github.com/rsyslog/rsyslog/commit/baee0bd5420649329793746f0daf87c4f59fe6a6.patch
4) quilt import baee0bd5420649329793746f0daf87c4f59fe6a6.patch
5) quilt push
6) chmod +x tests/imrelp-sessionbreak-vg.sh
6) debuild -uc -us -b

It will eventually build tests, and imrelp-sessionbreak-vg.sh passes:

make[5]: Entering directory '/home/ubuntu/rsyslog-8.2001.0/tests'
...
PASS: imrelp-sessionbreak-vg.sh
...

We pass both the upstream testsuite and the testcase from the bug report.

The file descriptor leak has been fixed, happy to mark as verified for Focal.

[Mauricio Faria de Oliveira (mfo)]

Hi Matthew,

I've kicked one or two rebuilds today, and still see the (same) one or two tests failing.

I'm out this week so can't look much more into it (althogh I'm admittedly curious about it :)

If you can take a look at these FTBFS test case failures, that would be awesome; all archs must pass for the SRU to be released. Maybe you can get access to a riscv64 instance, or the issue perhaps reproduces in QEMU?

Otherwise I can try and take a look on Monday.

cheers,
Mauricio

[Matthew Ruffell (mruffell)]

Hi Mauricio,

It seems riscv64 passes on Groovy due to tests being skipped on the riscv64 architecture.

From Groovy's build log:

https://paste.ubuntu.com/p/NCJPDVSbSW/

If you look at the man page for dh_auto_test it mentions:

If the DEB_BUILD_OPTIONS environment variable contains nocheck, no tests will be performed.

nocheck was added to riscv64 by default for all packages in Groovy as a part of this change to dpkg in bug 1891686.

The test cases basic-realistic.sh and tls-basic-realistic.sh fail on Focal because they attempt to send 100,000 packets between the server and the client, and we get to various stages, like 00029000 msgs sent, and now 00047000 msgs sent with some changes William made to the builders, before it times out and assumes the channel is dead, and the test fails.

https://paste.ubuntu.com/p/hwYXSbKPPV/

We aren't going to hit the 100,000 packets on riscv anytime soon. I think I will open a new bug to adjust the packet counts from 100,000 down to 10,000 for basic-realistic.sh and tls-basic-realistic.sh, which resembles what has been done for receiver-abort.sh and tls-receiver-abort.sh.

[Mauricio Faria de Oliveira (mfo)]

Hi Matthew,

Thanks for the analysis.

We'll need such changes on top of what's in -proposed (ie, in an incremental version), re-uploaded.

Please see `dpkg-buildpackage -v` to generate a package build including the version in -proposed plus the new version with the workaround for the test-case.

And as always, feel free to reach out if there's anything I can help with!

cheers,
Mauricio

[Matthew Ruffell (mruffell)]

Hi Mauricio,

I filed bug 1912969 to fix the FTBFS for librelp on focal. Adjusting the packets down from 50,000 to 10,000 makes the build succeed on riscv64.

I attached two debdiffs, one an incremental patch from 1.5.0-1ubuntu2.20.04.1, and the other a full patch from 1.5.0-1ubuntu2.

Please review and sponsor.

Thanks,
Matthew

[Mauricio Faria de Oliveira (mfo)]

Thanks again, Matthew.

I've reviewed and sponsored the new debdiff for Focal, with the existing changes (so we have .20.04.1 and .2 in the same upload, going in focal-proposed again.)

Further details added in bug 1912969.

[Łukasz Zemczak (sil2100)]

Hello Matthew, or anyone else affected,

Accepted librelp into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/librelp/1.5.0-1ubuntu2.20.04.2 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

[Matthew Ruffell (mruffell)]

Performing verification for Focal.

I installed rsyslog-relp 8.2001.0-1ubuntu1.1 and librelp0 1.5.0-1ubuntu2 from -updates.

From there I set up the configuration file, launched a new rsyslog instance, and used netcat to set 100 packets to the relp port.

https://paste.ubuntu.com/p/HfSDvNJzpX/

As we can see, there are 100 sockets still open in the CLOSE_WAIT state.

From there I enabled -proposed and installed librelp 1.5.0-1ubuntu2.20.04.2.

I started a new instance of rsyslog, and used netcat to send another 100 packets to the relp port. This time, all sockets were closed and not left in CLOSE_WAIT.

https://paste.ubuntu.com/p/tjXHhQ2293/

I also ran the testcase from the upstream testsuite, imrelp-sessionbreak-vg.sh.

I did this by:

1) pull-lp-source rsyslog focal
2) edit debian/rules, add --enable-valgrind, remove --without-valgrind-tests,
3) wget https://github.com/rsyslog/rsyslog/commit/baee0bd5420649329793746f0daf87c4f59fe6a6.patch
4) quilt import baee0bd5420649329793746f0daf87c4f59fe6a6.patch
5) quilt push
6) chmod +x tests/imrelp-sessionbreak-vg.sh
6) debuild -uc -us -b

It will eventually build tests, and imrelp-sessionbreak-vg.sh passes:

make[5]: Entering directory '/home/ubuntu/rsyslog-8.2001.0/tests'
...
PASS: imrelp-sessionbreak-vg.sh
...

We pass both the upstream testsuite and the testcase from the bug report.

The file descriptor leak has been fixed, happy to mark as verified for Focal.

[Launchpad Janitor (janitor)]

This bug was fixed in the package librelp - 1.5.0-1ubuntu2.20.10.1

---------------
librelp (1.5.0-1ubuntu2.20.10.1) groovy; urgency=medium

  * Fix file descriptor leak as sockets are stuck in CLOSE_WAIT
    due to not being closed properly due to memory leak. (LP: #1908473)
    - d/p/lp1908473-01-replsess-fix-double-free-of-sendbuf-in-some-cases.patch
    - d/p/lp1908473-02-fix-memory-leak-on-session-break.patch
    - d/p/lp1908473-03-Fix-FD-leak-when-socket-shutdown-is-one-sided.patch

 -- Matthew Ruffell <email address hidden> Sun, 03 Jan 2021 19:50:00 +1300

[Brian Murray (brian-murray)]

The verification of the Stable Release Update for librelp has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package librelp - 1.5.0-1ubuntu2.20.04.2

---------------
librelp (1.5.0-1ubuntu2.20.04.2) focal; urgency=medium

  * Reduce message count in tests/(tls-)basic-realistic.sh so they reliably
    succeed on slow platforms like riscv64. (LP: #1912969)
    - d/p/shrink-basic-realistic-tests.sh

librelp (1.5.0-1ubuntu2.20.04.1) focal; urgency=medium

  * Fix file descriptor leak as sockets are stuck in CLOSE_WAIT
    due to not being closed properly due to memory leak. (LP: #1908473)
    - d/p/lp1908473-01-replsess-fix-double-free-of-sendbuf-in-some-cases.patch
    - d/p/lp1908473-02-fix-memory-leak-on-session-break.patch
    - d/p/lp1908473-03-Fix-FD-leak-when-socket-shutdown-is-one-sided.patch

 -- Matthew Ruffell <email address hidden> Mon, 25 Jan 2021 12:29:04 +1300