Re: Bug in ucspilogd v2.2.0.0
2015-08-12 2:54 GMT-03:00 Laurent Bercot: ucspilogd doesn't care about the chosen trailer character. It will treat \0 and \n equally as line terminators - which is the only sensible choice when logging to a text file and prepending every line with some data. Oh. Then logger version 2.26.2 should work fine adding the -T option, and does for me using ucspilogd from s6-2.1.6.0 (which I believe didn't change for 2.2.0.0). $ logger -V logger from util-linux 2.26.2 $ BANNER=ucspilogd test s6-ipcserver test-socket fdmove -c 1 2 ucspilogd BANNER 2out $ printf This\nshould\n | logger -Tu test-socket -p user.warning $ printf work\nfine\n | logger -Tu test-socket -p user.alert $ logger -Tu test-socket -p user.info then. $ cat out ucspilogd test: user.warn: Aug 2121:05:40 test: This ucspilogd test: user.warn: Aug 21 21:05:40 test: should ucspilogd test: user.alert: Aug 21 21:05:44 test: work ucspilogd test: user.alert: Aug 21 21:05:44 test: fine ucspilogd test: user.info: Aug 21 21:05:51 test: then. Of course, it worked with /dev/log too. Thanks, G.
Re: Bug in ucspilogd v2.2.0.0
On 12/08/2015 04:45, Guillermo wrote: I don't know about syslog on /dev/log, but for syslog over a network there is this: Yeah, I know about the syslog RFCs. The mild way to put it is that they're about as useful, well-engineered and enticing as a steaming pile of donkey shit. And donkey shit can at least be used as manure. Logs are data, if they need to be transported over the network, there's no lack of complex, over-engineered and insecure ways to transport data over the network - no need to come up with yet another one specifically for logs, with its own quirks and idiosyncratic formatting that peeks into user content when it has no business doing so. You want to standardize a universal format for logs (gl with that), then write a RFC about a universal format for logs, don't mix that with a network protocol, like, duh. The only part of syslog that is worth normalizing is the interaction between syslog() and syslogd, on the *local* machine, because there's a lot of code using syslog() that doesn't care about the network, and several implementations of syslogd. And, of course, that's exactly the part those RFCs do not talk about. It shouldn't come as a surprise when you know that Eric Allman, of sendmail shame, is the original syslog designer, and the author of RFC 5424, Rainer Gerhards, is also the main author of rsyslogd. Do these people actually get *respect* for what they do? Geez this community lacks critical thinking. Or using ucspilogd with option datagram mode sockets, which would also make musl syslog() work. It's more complicated than that. A datagram syslogd server cannot listen() and accept(); it receives messages from every process that uses syslog(). A datagram /dev/log socket enforces the fan-in, enforces a single instance of syslogd that has to analyze and authenticate every single log message from the whole machine, which is precisely what I want to avoid; ucspilogd makes no sense in this case, you have to use a complete (and big and inefficient) syslogd implementation. ucspilogd relies on the fact that there's a SOCK_STREAM super-server above it to fork an instance per openlog() connection, and that its stdin is private to this connection. That's what allows it to be so simple - and not having the syslog() client try talking to a SOCK_STREAM socket completely defeats it. And GNU libc syslog() works fine using ucspilogd with current stream mode sockets using non-transparent framing with NUL as trailer character behaviour :P ucspilogd doesn't care about the chosen trailer character. It will treat \0 and \n equally as line terminators - which is the only sensible choice when logging to a text file and prepending every line with some data. glibc syslog() works because it does some ugly, ugly things like trying with SOCK_DGRAM, and retrying with SOCK_STREAM if it failed. In the absence of normalization for syslog(), I'm afraid this is the only possible behaviour, though; I've swallowed my tears and submitted a feature request to musl. -- Laurent
Re: Bug in ucspilogd v2.2.0.0
2015-08-10 18:15 GMT-03:00 Laurent Bercot:
Oh, it's a mess. A huge mess; there doesn't seem to be any authority
on the details of the syslog protocol. No normative body, the client
is in the libc, the server is an application: a definite recipe for
success!
I don't know about syslog on /dev/log, but for syslog over a network
there is this:
RFC 3164 - The BSD Syslog Protocol
http://www.rfc-editor.org/rfc/rfc3164.txt
RFC 5424 - The Syslog Protocol (transport-independent part, obsoletes RFC 3164)
http://www.rfc-editor.org/rfc/rfc5424.txt
And the transport mappings:
RFC 5426 - Transmission of Syslog Messages over UDP
http://www.rfc-editor.org/rfc/rfc5426.txt
RFC 6587 - Transmission of Syslog Messages over TCP
http://www.rfc-editor.org/rfc/rfc6587.txt
RFC 5425 - Transport Layer Security (TLS) Transport Mapping for Syslog
http://www.rfc-editor.org/rfc/rfc5425.txt
RFC 6012 - Datagram Transport Layer Security (DTLS) Transport Mapping for Syslog
http://www.rfc-editor.org/rfc/rfc6012.txt
Logger has --rfc3164 and --rfc5424 options, and has references to the
above documents in the source code and man page, so AFAICS it is aware
of and complies with them for messages sent over a network to a remote
syslog server, and uses the same code for communication over UNIX
domain sockets. The non-transparent framing described in the TCP
document (section 3.4.2 starting on page 7) is relevant to the
reported issue.
Glancing over the version 2.26.2 source code:
https://git.kernel.org/cgit/utils/util-linux/util-linux.git/plain/misc-utils/logger.c?id=v2.26.2
I understand that logger uses datagram mode UNIX domain sockets unless
there is a -T option without a -n option (check the logger_open and
unix_socket functions), and uses non-transparent framing in stream
mode, but with LF ('\n') instead of NUL ('\0') as the trailer
character, as suggested by the TCP mappings document (while
acknowledging that NUL is also in widespread use). And version 2.27
will add an --octet-count option to select octet-counting framing.
Moreover, when reading from stdin (check the logger_stdin function)
logger only sends a message when it receives LF characters (discarding
them) or detects an EOF. It copies verbatim every other character to
the output buffer, but later it uses string manipulation functions
that treat NUL as an end-of-string marker, so I guess that would
explain the weird behaviour of ignoring all input between a NUL and a
subsequent LF. This probably translates to logger doesn't expect NUL
characters in its input stream, don't do that.
As for ucspilogd... who knows. The printf examples without the NULs
would supposedly work as expected using ucspilogd with option stream
mode sockets using non-transparent framing with LF as trailer
character, if it had one, and piping to 'logger -T'. Or using
ucspilogd with option datagram mode sockets, which would also make
musl syslog() work. And GNU libc syslog() works fine using ucspilogd
with current stream mode sockets using non-transparent framing with
NUL as trailer character behaviour :P
Cheers!
G.
Bug in ucspilogd v2.2.0.0
Hi Laurent,
I'm pretty sure some change in skalibs v2.3.6.0 broke some types of
message handling in ucspilogd. Specifically, a computer I have running
skalibs v2.3.5.1 and s6 v2.1.6.0 is able to read messages sent via the
logger command, whereas a computer I have running skalibs v2.3.6.0 and
s6 v2.2.0.0 cannot.
ucspilogd v2.2.0.0 gives the following when I send a message via logger:
root@radon:~# logger woo
@400055c6fe44103957dc ucspilogd: fatal: unable to read from stdin:
Broken pipe
ucspilogd v2.1.6.0:
root@heliocat:~# logger woo
@400055c6fe7401034cdc 0: 0: user.notice: Aug 9 07:16:32 heliocat: woo
I initially thought it was in the handoff code between s6-ipcserverd
and ucspilogd but after stracing the s6-ipcserverd process and
following forked off children, I'm pretty sure the issue is in
ucspilogd (or, more correctly, the skalibs functions that ucspilogd
wraps since the main program hasn't changed in months).
I haven't yet dug into the skalibs code to see what changed between
those tags, or started bisecting it to find out which commit broke.
However, the difference between a functional and non-functional log
write in strace is the following:
Functional:
[pid 19388] readv(0, [{13Aug 9 07:26:07 cathexis: wo..., 8191},
{NULL, 0}], 2) = 34
[pid 19388] writev(1, [{1000: 1000: user.notice: Aug 9 ..., 55},
{NULL, 0}], 2) = 55
[pid 19388] readv(0,
[{\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0...,
8158}, {13Aug 9 07:26:07 cathexis: wo..., 33}], 2) = 0
Dysfunctional:
[pid 31983] readv(0, [{13Aug 8 23:46:57 cathexis: wo..., 8191},
{NULL, 0}], 2) = 33
[pid 31983] readv(0,
[{\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0...,
8159}, {13Aug 8 23:46:57 cathexis: wo, 32}], 2) = 0
[pid 31983] writev(2, [{ucspilogd: fatal: unable to read..., 57},
{NULL, 0}], 2) = 57
Some syslog messages generated via non-logger sources work, such as
auth messages. Those have the same readv, writev, readv pattern.
Let me know if you need more.
Cheers!
--
If the doors of perception were cleansed every thing would appear to
man as it is, infinite. For man has closed himself up, till he sees
all things thru' narrow chinks of his cavern.
-- William Blake
Re: Bug in ucspilogd v2.2.0.0
On 09/08/2015 09:27, Colin Booth wrote:
I haven't yet dug into the skalibs code to see what changed between
those tags, or started bisecting it to find out which commit broke.
The git diff between 2.3.5.1 and current HEAD is pretty small, and
there's really nothing that changed in the graph of functions
accessed by skagetlnsep(), the failing entry point.
Functional:
[pid 19388] readv(0, [{13Aug 9 07:26:07 cathexis: wo..., 8191},
{NULL, 0}], 2) = 34
(...)
Dysfunctional:
[pid 31983] readv(0, [{13Aug 8 23:46:57 cathexis: wo..., 8191},
{NULL, 0}], 2) = 33
The path leading to the first invocation of readv() hasn't changed,
but readv() gives different results. My first suspicion is that logger
isn't sending the last character (newline or \0) in the second case
before exiting, which skagetlnsep() interprets as I was unable to
read a full line before EOF happened and reports as EPIPE.
Are you using the same version of logger on both machines ?
Grrr. If logger starts sending incomplete lines, I may have to change
the ucspilogd code to accommodate it.
--
Laurent
