Re: Bug in ucspilogd v2.2.0.0
On Sun, Aug 9, 2015 at 12:17 PM, Laurent Bercot 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@radon:~/tmp/log/util-linux-2.27-rc1$ printf "a\0a\0b\0c" | logger @400055c7a8e32ce72bac 1000: 1000: user.notice: Aug 9 12:23:43 cathexis: a cathexis@radon:~/tmp/log/util-linux-2.27-rc1$ printf "a\na\nb\nc" | logger @400055c7a9001e5d5e6c 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 @400055c81eaf2d4fdc74 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 @400055c81ee61b5b7c94 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
Re: Bug in ucspilogd v2.2.0.0
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'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. -- Laurent
Re: Bug in ucspilogd v2.2.0.0
On Sun, Aug 9, 2015 at 10:23 AM, Laurent Bercot wrote: > On 09/08/2015 19:12, Colin Booth wrote: >> >> I haven't experimented with it yet, but I think the messages from >> long-running logger processes are null-separated, just not the last >> line. I'll take a look later today when I have time. > > > Ah, that's easy enough to fix. Please try with the latest s6 git > and tell me if it works for you. > > -- > Laurent 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. The ucspilogd fix works for the single message case which should be good enough for handling script output. Using logger as a cheap stdout syslog injector in supervised services seems like a no-go for now, at least when ucspilogd is handling reception. 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. 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 19:12, Colin Booth wrote: I haven't experimented with it yet, but I think the messages from long-running logger processes are null-separated, just not the last line. I'll take a look later today when I have time. Ah, that's easy enough to fix. Please try with the latest s6 git and tell me if it works for you. -- Laurent
Re: Bug in ucspilogd v2.2.0.0
On Sun, Aug 9, 2015 at 6:20 AM, Olivier Brunel wrote: > On 08/09/15 10:44, Laurent Bercot wrote: >> 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 ? >> That would do it. heliocat is running Debian 8, whereas radon is running Debian unstable. Debian 8 is on bsdutils 2.25.2 and unstable on 2.26.2. >> Grrr. If "logger" starts sending incomplete lines, I may have to change >> the ucspilogd code to accommodate it. > > Had a quick look at this (procrastination & stuff :p) and it seems to me > this is probably a bug in logger actually. At some point[1] they started > not to use syslog(3) anymore but implementing things on their own instead. > However, there's a difference with glibc's implementation, specifically > when using a SOCK_STREAM the later adds a NUL byte as record terminator, > which the former does not. Hence there's never a terminating NUL byte > from logger anymore and ucspilogd fails w/ EPIPE. > > HTH, > -j > > [1] > https://github.com/karelzak/util-linux/commit/1d57503378bdcd838365d625f6d2d0a09da9c29d > > Thanks, checking logger versions was next on my list, right below going to bed. Ok, looks like the bsdutils upgrade back in May broke it, the timing lines up perfectly. Though it's my own damn fault for not noticing until now. It's unlikely that logger will get fixed, since rsyslog is able to properly parse messages that logger is sending so from the maintainers perspective this probably isn't going to get classified as a bug. Entertainingly, switching ucspilogd for xargs -0 -- works for single-shot log messages. Using logger as a supervised log/run doesn't work, xargs won't print anything until it's told to terminate at which point it execs into echo and dumps its output. I haven't experimented with it yet, but I think the messages from long-running logger processes are null-separated, just not the last line. I'll take a look later today when I have time. 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 08/09/15 10:44, Laurent Bercot wrote: > 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. Had a quick look at this (procrastination & stuff :p) and it seems to me this is probably a bug in logger actually. At some point[1] they started not to use syslog(3) anymore but implementing things on their own instead. However, there's a difference with glibc's implementation, specifically when using a SOCK_STREAM the later adds a NUL byte as record terminator, which the former does not. Hence there's never a terminating NUL byte from logger anymore and ucspilogd fails w/ EPIPE. HTH, -j [1] https://github.com/karelzak/util-linux/commit/1d57503378bdcd838365d625f6d2d0a09da9c29d
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, [{"<13>Aug 9 07:26:07 cathexis: wo"..., 8191},
{NULL, 0}], 2) = 34
(...)
Dysfunctional:
[pid 31983] readv(0, [{"<13>Aug 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
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, [{"<13>Aug 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}, {"<13>Aug 9 07:26:07 cathexis: wo"..., 33}], 2) = 0
Dysfunctional:
[pid 31983] readv(0, [{"<13>Aug 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}, {"<13>Aug 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
