Bug 274509

Comment 1 Matthew Seaman 2023-10-16 08:22:37 UTC

Thank you for the report.  Looking at https://github.com/rsyslog/rsyslog/issues/5241 it isn't clear that the two reports are exactly the same issue.  Can I ask if you have linprocfs mounted? 

Anyhow, this is going to need a fix from upstream, so I'll mark the port BROKEN for now.

[helmut@BSDHelmut ~]$ mount
/dev/da0p2 on / (ufs, local)
devfs on /dev (devfs)
/dev/da0p13 on /home (ufs, local, nosuid)
/dev/da0p14 on /tmp (ufs, local, nosuid)
/dev/da0p4 on /usr (ufs, local)
/dev/da0p5 on /var (ufs, local, nosuid)
/dev/da0p7 on /var/amavis (ufs, local, nosuid)
/dev/da0p11 on /var/db/mysql (ufs, local, noexec, nosuid)
/dev/da0p6 on /var/log (ufs, local, noexec, nosuid)
/dev/da0p9 on /var/named (ufs, local, noexec, nosuid)
/dev/da0p8 on /var/spool (ufs, local, noexec, nosuid)
/dev/da0p12 on /var/vsftpd (ufs, local, noatime, noexec, nosuid)
/dev/da0p10 on /var/www (ufs, local, nosuid)
devfs on /var/spool/postfix/dev (devfs)
devfs on /var/spool/postfix-out/dev (devfs)
devfs on /var/amavis/dev (devfs)
devfs on /var/www/dev (devfs)
devfs on /var/www/var/www/vhosts/www.amina-initiative.de/dev (devfs)
devfs on /var/www/var/www/vhosts/akad-dba02/dev (devfs)
devfs on /var/www/var/www/vhosts/akad-int02/dev (devfs)
tmpfs on /var/amavis/tmp (tmpfs, local, noexec, nosuid)
/var/vsftpd/home/anonymous/pub on /var/www/var/www/vhosts/ftp/htdocs (nullfs, local, noatime, noexec, nosuid, read-only)
/var/www/usr/local/etc/nagiosql on /usr/local/etc/nagiosql (nullfs, local, noexec, nosuid)
/var/www/var/spool/nagios on /var/spool/nagios (nullfs, local, noexec, nosuid)
/var/www/var/run/mysqld on /var/run/mysqld (nullfs, local, noexec, nosuid)
/var/www/var/run/apache/clientcaches on /var/run/apache/clientcaches (nullfs, local, noexec, nosuid)
/var/www/var/db/cacti/rra on /var/db/cacti/rra (nullfs, local, noexec, nosuid)
/var/www/var/log/cacti on /var/log/cacti (nullfs, local, noexec, nosuid)
devfs on /var/named/dev (devfs)
/usr/lib/engines on /var/named/usr/lib/engines (nullfs, local)
/usr/local/lib/bind on /var/named/usr/local/lib/bind (nullfs, local)
//UNIX-SMB-DUMMY@FS01/SUBWEBS on /var/www/var/www/smbfs/subwebs (smbfs, noexec, nosuid)
//UNIX-SMB-DUMMY@FS01/INSTALL on /var/www/var/www/smbfs/install (smbfs, noexec, nosuid, read-only)
//UNIX-SMB-DUMMY@FS01/BACULA on /var/db/bacula (smbfs, noexec, nosuid)
//UNIX-SMB-DUMMY@FS01/UNIXBACKUP-FREETZ on /var/vsftpd/home/UNIXBackup/Freetz (smbfs, noexec, nosuid)
[helmut@BSDHelmut ~]$

Comment 3 commit-hook 2023-10-16 08:31:47 UTC

A commit in branch main references this bug:

URL: https://cgit.FreeBSD.org/ports/commit/?id=f1c490b2ec352a5034e1b3319eebc625d320ccd7

commit f1c490b2ec352a5034e1b3319eebc625d320ccd7
Author:     Matthew Seaman <matthew@FreeBSD.org>
AuthorDate: 2023-10-16 08:25:08 +0000
Commit:     Matthew Seaman <matthew@FreeBSD.org>
CommitDate: 2023-10-16 08:29:56 +0000

    sysutils/rsyslog8: Mark broken

    The upgrade to 8.2310.0 has resulted in a non-working version which
    floods the log file with hundreds of messages and consumes all
    available memory:

    Oct 15 16:00:54 BSDHelmut rsyslogd[29360] imuxsock: recvfrom UNIX: Socket operation on non-socket [v8.2310.0]

    Other reports show rsyslog attempting to use Linux /proc which also
    fails.

    Mark broken temporarily pending a response from upstream..

    See https://github.com/rsyslog/rsyslog/issues/5241

    PR:             274509
    Reported by:    Helmut Ritter

 sysutils/rsyslog8/Makefile | 3 +++
 1 file changed, 3 insertions(+)

Created attachment 245790 [details]
Fix rsyslog 8.2310.0 fork issue

I believe the attached patch fixes the initial issue reported in https://github.com/rsyslog/rsyslog/issues/5241.  I'm not sure if it fixes the imuxsock issue since I haven't been able to reproduce that behavior.  With the patch rsyslog seems to be working with the provided sample config.

Comment 5 Matthew Seaman 2023-10-22 10:23:38 UTC

(In reply to Nathan Huff from comment #4)

Hmm... close_range(2) exists in FreeBSD and autoconf does produce the correct settings in FreeBSD:

```
pkg:~...rsyslog8/work/rsyslog-8.2310.0:% grep -C 1 CLOSE_RANGE config.h
/* Define to 1 if you have the `close_range' function. */
#define HAVE_CLOSE_RANGE 1

--
/* Define to 1 if you have the <linux/close_range.h> header file. */
/* #undef HAVE_LINUX_CLOSE_RANGE_H */
```

so this patch (https://bz-attachments.freebsd.org/attachment.cgi?id=245790) would be a no-op.  On reading the code, messages about:

```
3284.449464175:main thread : rsyslogd.c: closes unneeded files: opendir failed for /proc/self/fd
3284.449487278:main thread : rsyslogd.c: closes unneeded files: opendir failed for /proc/fd
```
are informational only, just tracing process execution -- since FreeBSD does not have '/proc/self/fd' nor necessarily '/proc/fd' the two calls to close_unneeded_open_files() fail and the code falls back to using close_range().   Nothing wrong there.

This seems a red-herring to me -- the real issue is with imuxsock and both the reports in https://github.com/rsyslog/rsyslog/issues/5241 really are actually about the same issue (contrary to my initial impression).

It isn't that close_range doesn't exist it is how they use it.

When rsyslog forks to the background it opens a pipe between the child and parent process which is supposed to be used to signal to the parent when the child is done initializing.  Part of the initialization process is to close open file descriptors.  Before the code looped through all of the file descriptors, but had a check to make sure it didn't close the signalling pipe.

if((i != dbgGetDbglogFd()) && (i != parentPipeFD)) {
  aix_close_it(i); /* AIXPORT */
}

When they switched to close_range they lost that check so the parentPipeFD gets closed during initialization and then the child process tries to write to the closed file descriptor and the parent process never gets the successful initialization message.

A fix for https://github.com/rsyslog/rsyslog/issues/5241 has been merged upstream.

Comment 8 commit-hook 2023-10-24 21:09:41 UTC

A commit in branch main references this bug:

URL: https://cgit.FreeBSD.org/ports/commit/?id=959521fd0d960b4bf9938a2229f29959ee2f8fa3

commit 959521fd0d960b4bf9938a2229f29959ee2f8fa3
Author:     Nathan Huff <nhuff@acm.org>
AuthorDate: 2023-10-24 21:04:00 +0000
Commit:     Matthew Seaman <matthew@FreeBSD.org>
CommitDate: 2023-10-24 21:08:41 +0000

    sysutils/rsyslog8: patch for forking issue due to close_range() call

    Add patch from upstream:

    https://github.com/rsyslog/rsyslog/commit/599b5c7524b76cfc73245206fcce1e2b4d955f21

    After fork if the child process uses close_range to close open file
    descriptors it has no way to exempt the parentPipeFD causing a failure
    to signal successful startup to the parent process. This causes
    failures on all systems that aren't Linux that implement close_range.

    1. Loop through file descriptors between beginClose and
       MAX(parentPipeFD,dbgGetDbglogFd()) making sure not to close those two
       file descriptors.

    2. Potentially use close_range to close all file descriptors above
       MAX(parentPipeFD,dbgGetDbglogFd())

    PR:             274509
    Reported by:    Helmut Ritter
    Obtained from:  https://github.com/rsyslog/rsyslog/pull/5254

 sysutils/rsyslog8/Makefile                         |  4 +--
 .../rsyslog8/files/patch-tools_rsyslogd.c (new)    | 36 ++++++++++++++++++++++
 2 files changed, 37 insertions(+), 3 deletions(-)

Comment 9 Matthew Seaman 2023-10-24 21:11:35 UTC

Patch committed, thanks!