Re: Bug in ucspilogd v2.2.0.0

From: Colin Booth <cathexis_at_gmail.com>
Date: Sun, 9 Aug 2015 20:53:59 -0700

On Sun, Aug 9, 2015 at 12:17 PM, Laurent Bercot <ska-skaware_at_skarnet.org> wrote:
> On 09/08/2015 20:13, Colin Booth wrote:
>>
>> Ok, I was wrong. I set up a little netcat /dev/log reader and there's
>> no separator at all between messages. At least not one that made it to
>> netcat. It also looks like the new logger stops reading after the
>> first \0, and strips all newlines.
>
>
> ... wat.
>
I know, right?
cathexis_at_radon:~/tmp/log/util-linux-2.27-rc1$ printf "a\0a\0b\0c" | logger
_at_4000000055c7a8e32ce72bac 1000: 1000: user.notice: Aug 9 12:23:43 cathexis: a

cathexis_at_radon:~/tmp/log/util-linux-2.27-rc1$ printf "a\na\nb\nc" | logger
_at_4000000055c7a9001e5d5e6c 1000: 1000: user.notice: Aug 9 12:24:12
cathexis: a<13>Aug 9 12:24:12 cathexis: a<13>Aug 9 12:24:12
cathexis: b<13>Aug 9 12:24:12 cathexis: c

Actually, with a bit more experimenting it's even weirder than I thought:
# printf "a\nb\0c\nd\n" | logger
_at_4000000055c81eaf2d4fdc74 0: 0: user.notice: Aug 9 20:46:19 root:
a<13>Aug 9 20:46:19 root: b<13>Aug 9 20:46:19 root: d

# printf "a\nb\n\0c\nd\n" | logger
_at_4000000055c81ee61b5b7c94 0: 0: user.notice: Aug 9 20:47:14 root:
a<13>Aug 9 20:47:14 root: b<13>Aug 9 20:47:14 root: <13>Aug 9
20:47:14 root: d

rsyslog outputs similar, but doesn't drop the newlines:
# printf "a\nb\n\0c\nd\n" | logger
Aug 9 20:43:23 radon root: a
Aug 9 20:43:23 radon root: b
Aug 9 20:43:23 radon root:
Aug 9 20:43:23 radon root: d

So a null stops logger from sending anything until the next newline.
But ucspilogd is what's dropping the newlines.

>
>> I'll have to take a look
>> at how rsyslog decides what the message end is since my test service
>> logged correctly when rsyslog was pulling on /dev/log.
>
>
> Wild guess: they changed logger/rsyslog to send/receive datagrams
> by default. By Linux magic, it still works with ucspilogd, that reads
> a stream, but doesn't know boundaries.
>
I'd be unsurprised if rsyslog has done datagrams for a while.
omuxsock, the rsyslog log sender module, only does datagrams so I'd be
surprised if imuxsock didn't handle them natively. Hell, they might
have been always sending datagrams but not removing the stream markers
until recently.

Like I said earlier, the ucspilogd change in the s6 HEAD solves all
the ad-hoc logger use issues. Any setup using logger for as a
long-running log sender but reading with ucspilogd (not likely) is
still broken. Hope this helps!

Cheers!
-Colin

-- 
"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
Received on Mon Aug 10 2015 - 03:53:59 UTC

This archive was generated by hypermail 2.3.0 : Sun May 09 2021 - 19:38:49 UTC