Syslog not working (setsockopt SOL_SOCKET SO_TIMESTAMP fails with EINVAL)

[JC-85]

Rsyslog seems to be preinstalled. Starting the daemon with 'sudo service rsyslog start' gives an error message about xconsole not being present but google says that really shouldn't be an issue since this is normal on headless systems, and service rsyslog status says that the dameon is running. Two log-files are created upon start; kern.log and syslog. They give the following messages:

kern.log
rsyslogd: imklog: cannot open kernel log (/proc/kmsg): No such file or directory.

syslog:
rsyslogd: [origin software="rsyslogd" swVersion="7.4.4" x-pid="5583" x-info="http://www.rsyslog.com"] start
rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]
rsyslogd: set SO_TIMESTAMP failed on '/dev/log': Invalid argument
rsyslogd: imklog: cannot open kernel log (/proc/kmsg): No such file or directory.
rsyslogd-2145: activation of module imklog failed [try http://www.rsyslog.com/e/2145 ]
rsyslogd: rsyslogd's groupid changed to 104
rsyslogd: rsyslogd's userid changed to 101
rsyslogd-2039: Could no open output pipe '/dev/xconsole': No such file or directory [try http://www.rsyslog.com/e/2039 ]

I'm guessing this might be related to klogctl not being implemented but I was hoping non-kernel messages would still work. Is this a known issue?

[sunilmut]

kmsg is currently not supported on WSL and so other devices such as /dev/xconsole. Please help us prioritize this by providing this feedback on our User Voice page. And, thanks for the feedback.

[rodrymbo]

So we're writing bash scripts. /usr/bin/logger is installed but not rsyslog.

Are we assuming that all bash scripting is done in an interactive shell, and the only logging needed is what can be created by echo or redirecting stdout/stderr to a file? Maybe the uservoice issue is (or would be) whether or not bash scripters in lxss need syslog-type logging?

I suppose the output of /usr/bin/logger can be sent to a syslog daemon running somewhere. Maybe there's one that would run on the windows side?

Or perhaps there is a "best practices" recommendation about this, a recommendation that bash scripters don't really need logging, or perhaps a way to send logging info to the Windows Event Log Service or another service that could listen for syslog connections and record them into the Windows Event Log?

"Syslog not working" is a feature? Really?

[computergeek125]

rsyslog seems to be working (loosely speaking) for me, at least with the logger command on 14959. I had to disable the imklog module and the resulting non-kernel klog line in rsyslog.conf to get those lines to go away, and I renamed 20-ufw.conf to 20-ufw.conf.disabled for good measure.

sudo chmod g+w /dev/xconsole gets rid of the xconsole message. Not sure if xconsole fully works or not, but the error message is gone.

I'm down to just rsyslogd: set SO_TIMESTAMP failed on '/dev/log': Invalid argument for error messages, but logger still seems to work:

user@Maxwell-BC:~$ logger "hello world"
user@Maxwell-BC:~$ tail -5 /var/log/syslog
Nov  9 23:45:23 Maxwell-BC rsyslogd-2307: warning: ~ action is deprecated, consider using the 'stop' statement instead [v8.16.0 try http://www.rsyslog.com/e/2307 ]
Nov  9 23:45:23 Maxwell-BC rsyslogd: set SO_TIMESTAMP failed on '/dev/log': Invalid argument [v8.16.0]
Nov  9 23:45:23 Maxwell-BC rsyslogd: rsyslogd's groupid changed to 108
Nov  9 23:45:23 Maxwell-BC rsyslogd: rsyslogd's userid changed to 104
Nov  9 23:45:40 Maxwell-BC user: hello world

[steowens]

So how does one get rid of that last error set SO_TIMESTAMP failed on /dev/log. This seems like a bug, since it is getting an invalid argument issue.

[therealkenc]

@sunilmut - Regarding SO_TIMESTAMP, I take as given that WSK doesn't support the socket option for say AF_INET, but a reasonable interim solution which shouldn't take too much effort (in the scheme) is to just populate cmsg_data with the current time as a proxy. No, that isn't when the packet actually came in, but also no, userspace doesn't care in any practical sense when the message came in to the millionth of a second except in fairly specialised scenarios. For AF_UNIX, surely, it came in "just now" is plenty good enough.

@steowens

So how does one get rid of that last error set SO_TIMESTAMP failed on /dev/log

You can comment out the setsockopt(); there is even a TODO to this effect in the source. But like @computergeek125 said it is not blocking.

[therealkenc]

Hmmm, that's most unfortunate. While lack of SO_TIMESTAMP is a soft fail in rsyslogd, it is a hard fail in systemd-journald here.

        r = setsockopt(s->syslog_fd, SOL_SOCKET, SO_TIMESTAMP, &one, sizeof(one));
        if (r < 0)
                return log_error_errno(errno, "SO_TIMESTAMP failed: %m");

An #ifndef WSL on that code and grabbing the current time on the receiving end works around, natch.

[steowens]

Does this require a recompile of the package?

[sunilmut]

SO_TIMESTAMP for TCP & UDP socket is supported for a "long" time now. What type of socket is it trying to set the socket option on? Or, try a newer build and see if it is resolved?

[therealkenc]

Here's the sequence @sunilmut

25610 open("/var/run/rsyslogd.pid", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
25610 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
25610 write(3, "25610", 5)              = 5
25610 close(3)                          = 0
25610 umask(022)                        = 022
25610 lstat("/run/systemd/system/", 0x7fffdb79b260) = -1 ENOENT (No such file or directory)
25610 unlink("/dev/log")                = 0
25610 socket(PF_LOCAL, SOCK_DGRAM, 0)   = 3
25610 bind(3, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 10) = 0
25610 chmod("/dev/log", 0666)           = 0
25610 setsockopt(3, SOL_SOCKET, SO_PASSCRED, [1], 4) = 0
25610 setsockopt(3, SOL_SOCKET, SO_TIMESTAMP, [1], 4) = -1 EINVAL (Invalid argument)

This is on 17101.

[sunilmut]

Thanks @therealkenc. So, this is to support SO_TIMESTAMP for AF_UNIX. Shouldn't be a problem. Marked it for backlog.

[therealkenc]

Does this require a recompile of the package?

Can @steowens or anyone else still following this thread do a sanity confirm: Does rsyslogd work for you in the current Insiders 17xxx (fast or slow ring doesn't matter)? It is failing for me, but per the Nov 9 2016 comment (and my own experience), it was working, and the SO_TIMESTAMP problem is soft. But it is currently failing for me thus:

8146  open("/var/log/syslog", O_WRONLY|O_CREAT|O_NOCTTY|O_APPEND|O_CLOEXEC, 0640) = -1 EACCES (Permission denied)

Which is this unnotable code here. It could be something stupid on my end, but a "yeah works fine" or "no breaks horribly" data point might shave some time off tracking down why.

$ sudo apt install rsyslog
$ sudo rsyslogd -n

and:

$ logger hello

[therealkenc]

Got back to this after more than a week. rsyslogd changes its effective uid.

$ ps -ax -o pid,comm,euser,egroup | grep rsyslogd
 4804 rsyslogd        syslog   syslog

My /var/log/syslog was root:root. You can work around the EACCES with:

$ sudo rm /var/log/syslog
$ sudo touch /var/log/syslog
$ sudo chown syslog:adm /var/log/syslog
$ sudo chmod 640 /var/log/syslog
$ ls -l /var/log/syslog
-rw-r----- 1 syslog adm 0 Mar 13 15:43 /var/log/syslog

I can't tell definitively why my uid:gid was incorrect. I suspect (but can't prove) that Ubuntu rsyslogd would rather be started by systemd. Or the apt postinstall scripts didn't take. Or, quite possibly, I screwed it up myself mucking around. Not enough people actually using rsyslogd (it seems) to track it down further; the above work around (if it is a work around) will have to suffice.

With that, I can say with some definitively that rsyslogd "works" (per issue title). The timestamps are correct, so the missing SO_TIMESTAMP surface in WSL is a very soft fail. From startup with a logger hello.

ken@DESKTOP-4UTIQSF:~$ cat /var/log/syslog
Mar 13 15:51:21 DESKTOP-4UTIQSF rsyslogd: [origin software="rsyslogd" swVersion="8.16.0" x-pid="4804" x-info="http://www.rsyslog.com"] start
[...blah blah]
Mar 13 15:51:21 DESKTOP-4UTIQSF rsyslogd: rsyslogd's groupid changed to 108
Mar 13 15:51:21 DESKTOP-4UTIQSF rsyslogd: rsyslogd's userid changed to 104
Mar 13 15:51:21 DESKTOP-4UTIQSF rsyslogd-2039: Could not open output pipe '/dev/xconsole':: No such file or directory [v8.16.0 try http://www.rsyslog.com/e/2039 ]
Mar 13 15:51:21 DESKTOP-4UTIQSF rsyslogd-2007: action 'action 11' suspended, next retry is Tue Mar 13 15:51:51 2018 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Mar 13 15:59:40 DESKTOP-4UTIQSF ken: hello

[virgilwashere]

Can confirm it's still an issue on 17134.

C:\Windows\System32>ver
Microsoft Windows [Version 10.0.17134.472]

root@firefly:/var/log# cat syslog
Dec 25 11:16:14 firefly rsyslogd: set SO_TIMESTAMP failed on '/dev/log': Invalid argument [v8.32.0]
Dec 25 11:16:14 firefly rsyslogd: imklog: cannot open kernel log (/proc/kmsg): No such file or directory.
Dec 25 11:16:14 firefly rsyslogd: activation of module imklog failed [v8.32.0 try http://www.rsyslog.com/e/2145 ]
Dec 25 11:16:14 firefly rsyslogd: rsyslogd's groupid changed to 106
Dec 25 11:16:14 firefly rsyslogd: rsyslogd's userid changed to 102
Dec 25 11:16:14 firefly rsyslogd:  [origin software="rsyslogd" swVersion="8.32.0" x-pid="14815" x-info="http://www.rsyslog.com"] start

Virgil

[ivanlan9]

This is still a problem in WSL (I'm not yet on WSL2, but thousands aren't). I never had this problem on previous incarnations of WSL, but having moved to a brand-new Windows 10 system in the last few days, it has manifested.

Windows version: 21H2 (OS Build 19044.1387)
WSL uname -a: Linux chuj-kach 4.4.0-19041-Microsoft #1237-Microsoft Sat Sep 11 14:32:00 PST 2021 x86_64 x86_64 x86_64 GNU/Linux

Here's the syslog error:

Dec 6 12:28:35 chuj-kach rsyslogd: set SO_TIMESTAMP failed on '/dev/log': Invalid argument [v8.2001.0]
Dec 6 12:28:35 chuj-kach rsyslogd: imklog: cannot open kernel log (/proc/kmsg): No such file or directory.
Dec 6 12:28:35 chuj-kach rsyslogd: activation of module imklog failed [v8.2001.0 try https://www.rsyslog.com/e/2145 ]
Dec 6 12:28:35 chuj-kach rsyslogd: rsyslogd's groupid changed to 110
Dec 6 12:28:35 chuj-kach rsyslogd: rsyslogd's userid changed to 104
Dec 6 12:28:35 chuj-kach rsyslogd: [origin software="rsyslogd" swVersion="8.2001.0" x-pid="583" x-info="https://www.rsyslog.com"] start