[OE-core] [PATCH] systemd: Fix the problem of an empty journal on boot

Wed Mar 11 05:09:28 UTC 2015

> On Mar 10, 2015, at 9:48 PM, Khem Raj <raj.khem at gmail.com> wrote:
> 
>> 
>> On Mar 7, 2015, at 11:37 AM, Khem Raj <raj.khem at gmail.com> wrote:
>> 
>> On Fri, Mar 6, 2015 at 1:18 AM, Khem Raj <raj.khem at gmail.com> wrote:
>>> 
>>>> On Mar 5, 2015, at 10:01 PM, randy.e.witt at linux.intel.com wrote:
>>>> 
>>>>> On Mar 5, 2015 6:13 PM, "Randy Witt" <randy.e.witt at 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. 

Remove mounting of /var/volatile from /etc/fstab

tmpfs                /var/volatile        tmpfs      defaults              0  0

Then add a mount unit file for it

/lib/systemd/system/var-volatile.mount

#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.

[Unit]
Description=Temporary Directory
Documentation=man:hier(7)
Documentation=http://www.freedesktop.org/wiki/Software/systemd/APIFileSystems
ConditionPathIsSymbolicLink=!/var/volatile
DefaultDependencies=no
Conflicts=umount.target
Before=local-fs.target umount.target

[Mount]
What=tmpfs
Where=/var/volatile
Type=tmpfs
Options=mode=1777,strictatime

solves this use-before-define issue, even when /var/volatile is mounted as tmpfs as we do in OE.

Now encode this logic up under DISTRO_FEATURE = “systemd” and we have a complete solution :)

Ideally we should mount /var/volatile as tmpfs only when using ro-rfs and do this whole orchestration of

if systemd add the above mount service + the service created for holding journald start point ( that got added in the patch above )

no changes are required for sysvinit

> 
> 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