Re: [PATCH] systemd: Fix the problem of an empty journal on boot

[Khem Raj <raj.khem@gmail.com>]

> On Mar 7, 2015, at 11:37 AM, Khem Raj <raj.khem@gmail.com> wrote:
> 
> On Fri, Mar 6, 2015 at 1:18 AM, Khem Raj <raj.khem@gmail.com> wrote:
>> 
>>> On Mar 5, 2015, at 10:01 PM, randy.e.witt@linux.intel.com wrote:
>>> 
>>>> On Mar 5, 2015 6:13 PM, "Randy Witt" <randy.e.witt@linux.intel.com> wrote:
>>>>> 
>>>>> systemd by default tries to write the journal to /var/log/journal.
>>>>> But base-files has a symlink /var/log -> /var/volatile/log. And
>>>>> /var/volatile is a tmpfs mount in /etc/fstab.
>>>>> 
>>>>> If the journal service started before /var/volatile was mounted (which
>>>>> was the typical scenario) then the journal would appear empty since
>>>>> the old location was mounted over.
>>>>> 
>>>>> This change fixes the problem by ensuring that the journal doesn't start
>>>>> until after the mount happens.
>>>>> 
>>>> 
>>>> What happens if folks have a different fstab then default? Will it still
>>>> work
>>> 
>>> Yes, the "After" only changes behavior if something else has caused
>>> var-volatile.mount to be in the set of services to be started.
>>> 
>>> I verified that was the case by removing /var/volatile from /etc/fstab and
>>> the journal still starts with no errors.
>> 
>> perfect thanks. I will test it out in few hrs myself.
> 
> for some reason, my console never comes up now. I am not sure if this
> is the patch causing it. I will try to single it out.

This patch should not be applied, but I see it has been applied anyway meanwhile, So we might have to solve this issue differently. 

This is actually the cause of my console not coming up. It was coming up after 15 minutes
systemd-analyse blame said systemd-tmpfiles-setup-dev.service is taking 14 mins to come up.
I then traced through it and the problem is evident that its trying to write journal when creating /dev entries but we have delayed the journald starting point and caused a use-before-define situation.
I deleted /var/volatile symlinks and let /var/log be proper directory and same for /var/tmp. All worked fine, without this patch. We should probably stop doing /var/volatile thing anyway its not in FHS standard either, for ro-rfs do something else ( may be copy-binds into /tmp/) and for general case just leave it alone. 

00:04:23 read(4, "#  This file is part of systemd."..., 4096) = 1244
00:04:23 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/user\" does not match"..., 62}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:04:33 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/user\" does not match"..., 62}, {"\n", 1}], 5) = 90
00:04:33 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/utmp\" does not match"..., 62}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:04:43 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/utmp\" does not match"..., 62}, {"\n", 1}], 5) = 90
00:04:43 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/ask-password"..., 78}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Resou
rce temporarily unavailable)
00:04:53 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/ask-password"..., 78}, {"\n", 1}], 5) = 106
00:04:53 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/seats\" does "..., 71}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:03 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/seats\" does "..., 71}, {"\n", 1}], 5) = 99
00:05:03 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/sessions\" do"..., 74}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:13 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/sessions\" do"..., 74}, {"\n", 1}], 5) = 102
00:05:13 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/users\" does "..., 71}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:23 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/users\" does "..., 71}, {"\n", 1}], 5) = 99
00:05:23 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/machines\" do"..., 74}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:33 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/machines\" do"..., 74}, {"\n", 1}], 5) = 102
00:05:33 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/systemd/shutdown\" do"..., 74}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:43 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/systemd/shutdown\" do"..., 74}, {"\n", 1}], 5) = 102
00:05:43 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/log\" does not match "..., 61}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:05:53 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/log\" does not match "..., 61}, {"\n", 1}], 5) = 89
00:05:53 sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=7\nSYSLOG_FACILITY=3\nCOD"..., 284}, {"MESSAGE=", 8}, {"Entry \"/run/log/journal\" does no"..., 69}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 EAGAIN (Reso
urce temporarily unavailable)
00:06:03 writev(5, [{"<31>", 4}, {"systemd-tmpfiles", 16}, {"[114]: ", 7}, {"Entry \"/run/log/journal\" does no"..., 69}, {"\n", 1}], 5) = 97
00:06:03 open("/etc/machine-id", O_RDONLY|O_NOCTTY|O_LARGEFILE|O_CLOEXEC) = 6