Bug in ucspilogd v2.2.0.0

[Colin Booth]

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

[Laurent Bercot]

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