[systemd-devel] rsync output is not captured in the journal

[Igor Bukanov]

I attach strace log for systemd. I have in my test unit:

# cat test.service
[Service]
ExecStart=/usr/bin/bash -c 'echo rsync copy'
ExecStart=/var/rsync -vv /etc/hostname /tmp/h6
ExecStart=/usr/bin/bash -c 'echo system rsync'
ExecStart=/usr/bin/rsync -vv /etc/hostname /tmp/h2
ExecStart=/usr/bin/bash -c 'echo
"================================================================"'
StandardError=journal
StandardOutput=journal
Type=oneshot

Here /var/rsync is a copy of /usr/bin/rsync. After systemctl start
test the journal output generated with journalctl -eau test contains:

Jan 05 13:28:36 miranda bash[4982]: rsync copy
Jan 05 13:28:36 miranda rsync[4984]: delta-transmission disabled for
local transfer or --whole-file
Jan 05 13:28:36 miranda rsync[4984]: hostname
Jan 05 13:28:36 miranda rsync[4984]: total: matches=0  hash_hits=0
false_alarms=0 data=8
Jan 05 13:28:36 miranda rsync[4984]: sent 94 bytes  received 102 bytes
 392.00 bytes/sec
Jan 05 13:28:36 miranda rsync[4984]: total size is 8  speedup is 0.04
Jan 05 13:28:36 miranda bash[4988]: system rsync
Jan 05 13:28:36 miranda bash[4994]:
================================================================

Note that there is no output between lines system rsync and =========.

>From strace output I see that the message  "delta-transmission
disabled for " is printed to stdout twice, first from pid 4984 which
is a copy of rsync and the second time from pid 4990 which
/usr/bin/rsync. For some reason the second output is ignored. I see
the difference between pids is that for 4990 that has not produced any
output there was an extra call:

4990  ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or
TCGETS <unfinished ...>
4991  write(1, "\1\0\0\7\0", 5 <unfinished ...>
4990  <... ioctl resumed> , 0x7fff79087a80) = -1 ENOTTY (Inappropriate
ioctl for device)

This ioctl is not present in rsync with PID 4984.



On 5 January 2015 at 13:04, Mantas Mikulėnas <grawity at gmail.com> wrote:
> On Mon, Jan 5, 2015 at 1:44 PM, Igor Bukanov <igor at mir2.org> wrote:
>> On 5 January 2015 at 12:21, Mantas Mikulėnas <grawity at gmail.com> wrote:
>>> Run it under `strace -D` – the problem may be related to rsync's
>>> parent being pid1.
>>
>> Under strace -D the problem disappeared as well. The problem also
>> disappears if I run rsync like in:
>>
>> ExecStart=/usr/bin/bash -c 'exec /usr/bin/rsync -vv /etc/hostname /tmp/h3'
>>
>> So the only way to see the problem is using rsync directly in
>> ExecStart like in    ExecStart=/usr/bin/rsync -vv /etc/hostname /tmp/
>
> Attach `strace -f -p 1` to systemd then, and have it follow forks.
>
> Perhaps also trace journald (the receiving end of rsync's stdout).
>
> --
> Mantas Mikulėnas <grawity at gmail.com>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: trace.log.xz
Type: application/x-xz
Size: 16872 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/systemd-devel/attachments/20150105/cd302ca5/attachment-0001.bin>