Journalctl. User unit's output disappears

Question

I have a very simple SystemD user unit:

~/.config/systemd/user/logtest.service

[Unit]
Description=log test
After=network.target

[Service]
Type=oneshot
ExecStart=/home/andrey/tmp/1.sh

[Install]
WantedBy=default.target

1.sh is just echo

#!/bin/bash
echo "123"

I start it systemctl start --user logtest.service
Then I check logs journalctl --user-unit logtest -n5 but I can't see my 123 in this output. Why????

journalctl  --user-unit  logtest -n5                                                                          
-- Logs begin at Сб 2016-10-15 22:17:53 +07, end at Пт 2017-01-06 16:03:16 +07. --
янв 06 16:03:15 andrcomp systemd[1524]: Started log test.
янв 06 16:03:16 andrcomp systemd[1524]: Starting log test...
янв 06 16:03:16 andrcomp systemd[1524]: Started log test.
янв 06 16:03:16 andrcomp systemd[1524]: Starting log test...
янв 06 16:03:16 andrcomp systemd[1524]: Started log test.

But If I add sleep 1 to 1.sh:

#!/bin/bash
echo "123"
sleep 1

Then 123 appears in my log

$ journalctl  --user-unit  logtest -n5                                                                          
-- Logs begin at Сб 2016-10-15 22:17:53 +07, end at Пт 2017-01-06 16:10:25 +07. --
янв 06 16:07:57 andrcomp systemd[1524]: Starting log test...
янв 06 16:07:57 andrcomp systemd[1524]: Started log test.
янв 06 16:10:24 andrcomp systemd[1524]: Starting log test...
янв 06 16:10:24 andrcomp 1.sh[3760]: 123
янв 06 16:10:25 andrcomp systemd[1524]: Started log test.

Why?

If I check all user logs then 123 is here (without sleep in 1.sh)

$ journalctl --user -n5                                                                                         
-- Logs begin at Вс 2016-12-18 16:15:56 +07, end at Пт 2017-01-06 16:13:32 +07. --
янв 06 16:13:32 andrcomp 1.sh[3997]: 123
янв 06 16:13:32 andrcomp systemd[1524]: Started log test.
янв 06 16:13:32 andrcomp systemd[1524]: Starting log test...
янв 06 16:13:32 andrcomp 1.sh[4007]: 123
янв 06 16:13:32 andrcomp systemd[1524]: Started log test.

But I need to see certain unit logs only

It works fine as system unit (/usr/lib/systemd/system/logtest_syst.service)

$ journalctl -u logtest_syst                                                                                    
-- Logs begin at Сб 2016-10-15 22:17:53 +07, end at Пт 2017-01-06 15:43:59 +07. --
янв 06 15:43:59 andrcomp systemd[1]: Starting log test...
янв 06 15:43:59 andrcomp 1.sh[1082]: 123
янв 06 15:43:59 andrcomp systemd[1]: Started log test.

What's the magick with sleep? Or may be it is not a correct way to check user unit logs?

Answer 1

There is bug marked as CLOSED CANTFIX about this: Journalctl miss to show logs from unit

According to Michal Sekletar, Senior Software Engineer at Red Hat:

This is a known issue. systemd-journald sometimes fails to record information about unit from which log message originates. There is a higher probability of hitting this problem if the process that logs the message is short lived.

[...]

Logs are not disappearing anywhere. It's just that for some log messages that originate from short lived processes journald can't figure out respective cgroup (unit). Thus you will not see those log lines if you apply filtering based on unit name. We can't do anything about this until kernel gives us a way to gather cgroup information in non racy way. But then again, logs are there and your first command that uses time based filtering proves that.

So you should be able to see the output of your script (the one without the sleep) using a command such as:

journalctl --since "2016-10-15 22:17:53"