Rsyslog losing log message when file does not exist

Question

I'm encountering case when rsyslog message is lost when the file its supposed to write to does not exist.

Here is my setup:

• log server 192.168.1.2 have such config:

module(load="imtcp")
input(type="imtcp" port="514")
$template MyRemoteLog1,"/nfs/some/dir/%FROMHOST-IP%/%programname%/%$year%-%$month%-%$day%.log"
$template MyRemoteLog2,"/nfs/other/dir/%FROMHOST-IP%/%syslogfacility-text%.%syslogseverity-text%.%programname%.log"
$template MsgOnly,"%msg:2:$:%\n"

if $FROMHOST-IP== ['192.168.1.3'] AND $SYSLOGFACILITY-TEXT== ['local5'] then ?MyRemoteLog1;MsgOnly
& stop

if $FROMHOST-IP== ['192.168.1.3'] then ?MyRemoteLog2
& stop

• client that send log 192.168.1.3 have such config:

*.* @@192.168.1.2:514

• I have also tried changing 192.168.1.3's config to become like such but the problem persists:

*.* action(type="omfwd"
           Target="192.168.1.2"
           Port="514"
           resendlastmsgonreconnect="on"
           action.resumeRetryCount="-1"
           queue.filename="queue"
           queue.size="100000"
           queue.saveonshutdown="on"
           Protocol="tcp" )

Basically, if local5 then it's stored to /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log, but if it's not local5 then it's stored to /nfs/other/dir/192.168.1.3/user.notice.mytag.log in logserver

Also, my setup write the log files to nfs mounted disk (if it matters).

The problem is as such:

1. system already running (logs have been written)
2. in 192.168.1.3(client), run date | logger -p local5.debug -t mytag
3. in 192.168.1.2(server), new file /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log is created, but content is blank
4. in 192.168.1.3(client), run date | logger -p local5.debug -t mytag (again)
5. in 192.168.1.2(server), file /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log is written (message in step 4 is written, but message in step 2 is lost)
6. in 192.168.1.2(server), delete the file, then run rsyslog rotate script like such: rm /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log ; /usr/lib/rsyslog/rsyslog-rotate
7. in 192.168.1.3(client), run date | logger -p local5.debug -t mytag (again)
8. in 192.168.1.2(server), new file /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log is created, but content is blank

I think that this experiment shows that when file is not exist yet, it will be created but the content is not written. Why is that so?

At first I thought that it might be because of rsyslog over plain TCP is not reliable and that I might need to use RELP. But after such experiment, I don't think the problem is on network.

Here is my nfs mount: 172.16.1.4:/some/dir/nfs_export on /nfs type nfs (rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.1.4,mountvers=3,mountport=38559,mountproto=udp,local_lock=none,addr=172.16.1.4)

After turning on rsyslog debug message by adding config $DebugFile /tmp/rsyslogdebug.txt and config $DebugLevel 1 and running this command:

kill -USR1 `ps aux | grep rsyslog | tr -s ' ' | cut -d' ' -f2 | head -n1`

I managed to find such logs in /tmp/rsyslogdebug.txt:

7792.776708768:main Q:Reg/w0  : omfile.c: omfile: file to log to: /nfs/some/dir/192.168.1.3/mytag/2022-03-15.log
7792.779333692:main Q:Reg/w0  : errmsg.c: Called LogMsg, msg: error during config processing: omfile: chown for file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' failed: Operation not permitted
7792.779415835:main Q:Reg/w0  : operatingstate.c: osf: MSG error during config processing: omfile: chown for file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' failed: Operation not permitted: signaling new internal message via SIGTTOU: 'error during config processing: omfile: chown for file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' failed: Operation not permitted [v8.2001.0 try https://www.rsyslog.com/e/2207 ]'
7792.779567477:main thread    : janitor.c: janitorRun() called
7792.779745372:main Q:Reg/w0  : errmsg.c: Called LogMsg, msg: error during config processing: Could not open dynamic file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' [state -3000] - discarding message
7792.779812889:main Q:Reg/w0  : operatingstate.c: osf: MSG error during config processing: Could not open dynamic file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' [state -3000] - discarding message: signaling new internal message via SIGTTOU: 'error during config processing: Could not open dynamic file '/nfs/some/dir/192.168.1.3/mytag/2022-03-15.log' [state -3000] - discarding message [v8.2001.0 try https://www.rsyslog.com/e/2207 ]'

Answer 1

The hint is in messsage error during config processing: omfile: chown for file

I assume that the process goes like this:

1. rsyslog creates the file if not exist, (if already exist, skip to step 3)
2. then chmod and chown it to its user and group as defined in config file (if not exist),
3. then rsyslog write/append to file

I think when it goes to step 2, it failed, leaving file with owner syslog:syslog, therefore when subsequent log message is received, it just skips to step 3 and successfully write the message. Hence all first message is deleted

But the default configuration given by Ubuntu 20.04 is

$FileOwner syslog
$FileGroup adm

Therefore it tries to chown to syslog:adm

When I change its configuration to

$FileOwner syslog
$FileGroup syslog

The error no longer occurs.

But there's still unsolved question:

• when the directory it writes to is inside nfs mount, such error happens
• when the directory it writes to is NOT inside nfs mount, such error DOES NOT happen