Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1365987 - journalctl -M CONTAINER_UUID returns No journal files were found.
Summary: journalctl -M CONTAINER_UUID returns No journal files were found.
Keywords:
Status: ASSIGNED
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd
Version: 7.2
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: systemd-maint
QA Contact: qe-baseos-daemons
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-08-10 17:07 UTC by Chris Evich
Modified: 2018-08-01 23:28 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:


Attachments (Terms of Use)

Description Chris Evich 2016-08-10 17:07:30 UTC
Description of problem:
On RHELAH 7.2.6, systemd inside a container functions for services, but gathering journal information from inside container does not.  

Version-Release number of selected component (if applicable):
RHELAH 7.2.6:
    docker-selinux-1.10.3-46.el7.10.x86_64
    docker-common-1.10.3-46.el7.10.x86_64
    oci-systemd-hook-0.1.4-4.git41491a3.el7.x86_64
    docker-1.10.3-46.el7.10.x86_64
    docker-rhel-push-plugin-1.10.3-46.el7.10.x86_64
    cockpit-docker-0.114-2.el7.x86_64
    docker-novolume-plugin-1.10.3-46.el7.10.x86_64
    python-docker-py-1.7.2-1.el7.noarch
    oci-register-machine-0-1.7.git31bbcd2.el7.x86_64
    docker-lvm-plugin-1.10.3-46.el7.10.x86_64
    docker-latest-1.10.3-46.el7.10.x86_64

How reproducible:
Always


Steps to Reproduce:
1. # cat <<EOF | docker build -t systemd_inside -
# cat <<EOF | docker build -t systemd_inside -
FROM rhel7/rhel:latest
ENV container docker
RUN yum -y install httpd; yum -y update; yum clean all; systemctl enable httpd
CMD [ "/sbin/init" ]                         
EOF
2. # docker run -d systemd_inside
3. # journalctl -M CONTAINER_UUID

Actual results:
No journal files were found.

Expected results:
Container's journal is displayed

Additional info:
Also reproduces with fedora 24-based build as per
https://github.com/projectatomic/oci-systemd-hook/blob/master/README.md

Otherwise systemd inside the container does seem to behave appropriately / as expected.

Comment 2 Lukáš Nykrýn 2016-08-10 19:41:02 UTC
Could you try add --merge option?

Comment 3 Chris Evich 2016-08-11 16:58:16 UTC
(In reply to Lukáš Nykrýn from comment #2)
> Could you try add --merge option?


[root@localhost ~]# journalctl --merge -M e979692c263e1b1221671c6e77c3965b
No journal files were found.

Comment 4 Lukáš Nykrýn 2016-08-12 10:08:02 UTC
Can you please suggest how could I easily prepare some test environment. I've tried that on latest 7.3 and first I had a problem with writing repo file to the container, that it failed in creating a random layer during the build (seems to be selinux related) and now I don't have network inside the container. And the cryptic error messages from docker does not help at all.

Comment 5 Lukáš Nykrýn 2016-08-12 10:13:05 UTC
Or maybe just please check if you have /var/log/journal/YOUR_CONTAINER_ID or /run/journal/YOUR_CONTAINER_ID directory and try if you can read it directly journalctl -D  /run/log/YOUR_CONTAINER_ID

Comment 7 Chris Evich 2016-08-12 13:58:57 UTC
Replied privately.  Short answer:  Directory exists in /var/log/journal but is empty.  There is no /run/journal directory.

Comment 8 Daniel Walsh 2017-03-12 12:15:50 UTC
I want to verify this is not an oci-systemd-hook issue.  Reassigning.

Comment 9 Tom Sweeney 2017-05-10 13:38:51 UTC
Assignment based on e-mail stream with Jan Synacek.  This functionality works on Fedora which uses version 231 of systemd and also works on RHEL with systemd version 233.  I suspect that a patch in version 230 fixed this where sd_journal_open_container functionality was deprecated and how journalctl reads the various system.journal files was greatly overhauled.  I however did not locate that particular patch or patches.  I noted the change in systemd/NEWS and saw some of the changes in the code.

Comment 11 Daniel Walsh 2017-05-11 13:08:41 UTC
Docker or more specifically oci-sytemd-hook is reporting the location of the journal file to sytemd, based on the MACHINE-ID of the container.  The data gets written, but I believe that Tom is reporting that this location is different on with older versions of systemd?

Perhaps the location is different between Fedora and RHEL7 version?

Comment 12 Tom Sweeney 2017-05-11 16:30:34 UTC
I'm still seeing the issue when I do as the original reporter showed.  I'm using the latest updated RHEL that I can find and systemd-219-30.el7_3.8.x86_64.  I believe the issue is due to changes with how journalctl looks up the directory for a container.  Unless I mis-read the code, that appeared to have been updated in v230 of systemd when the sd_journal_open_container function was deprecated and the functionality for finding the system.journal file location was overhauled when the -M param was in use.

I was not able to replicate your test method.  When I did ls /var/lib/machines, the directory was empty.  Further I don't believe we should need to change anything on the container.  This should just work as it does on Fedora.

As you can see in my tests below, journalctl -M works on RHEL if the system.journal file is instead located at: /var/lib/docker/devicemapper/mnt/{*}/rootfs/var/log/journal

Where {*} is the devicename found for "GraphDriver" in the `docker inspect {containerid}` output.  That is the alpha-numeric value after the last dash in the "DeviceName" field.  For this test, that json look like:


        "GraphDriver": {
            "Name": "devicemapper",
            "Data": {
                "DeviceId": "14",
                "DeviceName": "docker-253:0-5839-1261178e606dcdb5dd139a985071560b02d769acdd86c9a1125dbcbafae8358a",
                "DeviceSize": "10737418240"
            }
 
If I upgrade systemd on this system to the one from the copr repository, keeping the same version of oci-systemd-hook, then 'journalctl -M {containerid}' works fine with the system.journal file in the expected /var/log/journal/{machineID}/system.journal location.

Here's the setup on my machine and the testing that follows.  If I've holes somewhere in this process, please let me know. 

I'm using:

# rpm -qa | grep systemd
systemd-libs-219-30.el7_3.8.x86_64
systemd-python-219-30.el7_3.8.x86_64
oci-systemd-hook-0.1.7-2.git2788078.el7.x86_64
systemd-sysv-219-30.el7_3.8.x86_64
systemd-219-30.el7_3.8.x86_64

# uname -a
Linux rhelbz.localdomain 3.10.0-514.10.2.el7.x86_64 #1 SMP Mon Feb 20 02:37:52 EST 2017 x86_64 x86_64 x86_64 GNU/Linux
# cat /etc/*release
NAME="Red Hat Enterprise Linux Server"
VERSION="7.3 (Maipo)"
ID="rhel"
ID_LIKE="fedora"
VERSION_ID="7.3"
PRETTY_NAME="Employee SKU"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:7.3:GA:server"
HOME_URL="https://www.redhat.com/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 7"
REDHAT_BUGZILLA_PRODUCT_VERSION=7.3
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="7.3"
Red Hat Enterprise Linux Server release 7.3 (Maipo)
Red Hat Enterprise Linux Server release 7.3 (Maipo)


Test output

# cat <<EOF | docker build -t systemd_inside -
> FROM rhel7/rhel:latest
> ENV container docker
> RUN yum -y install httpd; yum -y update; yum clean all; systemctl enable httpd
> CMD [ "/sbin/init" ]                         
> EOF
(removed lots of happy output)
Step 4 : CMD /sbin/init
 ---> Running in 434b064a833a
 ---> 9e4000dbc20a
Removing intermediate container 434b064a833a
Successfully built 9e4000dbc20a
# docker run -d systemd_inside
7282b69db309f43f981461140a29390f49688a8975a24d265696a746d3832f2c
machinectl
MACHINE                          CLASS     SERVICE
7282b69db309f43f981461140a29390f container docker 

1 machines listed.
# journalctl -M 7282b69db309f43f981461140a29390f
No journal files were found.
-- No entries --
[root@rhelbz ~]# ls /var/log/journal/7282b69db309f43f981461140a29390f
system.journal
#cp /var/log/journal/7282b69db309f43f981461140a29390f/system.journal /var/lib/docker/devicemapper/mnt/1261178e606dcdb5dd139a985071560b02d769acdd86c9a1125dbcbafae8358a/rootfs/var/log/journal
# journalctl -M 7282b69db309f43f981461140a29390f
-- Logs begin at Thu 2017-05-11 11:51:02 EDT, end at Thu 2017-05-11 11:51:02 EDT. --
May 11 11:51:02 7282b69db309 systemd-journal[15]: Runtime journal is using 4.0M (max allowed 8.0M, trying to leave 9.6M fre
May 11 11:51:02 7282b69db309 systemd-journal[15]: Permanent journal is using 8.0M (max allowed 2.1G, trying to leave 3.2G f
May 11 11:51:02 7282b69db309 systemd-journal[15]: Time spent on flushing to /var is 501us for 2 entries.
May 11 11:51:02 7282b69db309 systemd-journal[15]: Journal started
May 11 11:51:02 7282b69db309 systemd[1]: Starting Flush Journal to Persistent Storage...
(more happy output removed)

Comment 13 Daniel Walsh 2017-05-11 18:58:10 UTC
Not sure if I have suggested this before, but this feels like a mount namespace issue.  If you nsenter -m -t PIDOFDOCKER sh and then execute the journal -M UUID, does it work?

Comment 14 Tom Sweeney 2017-05-12 14:01:31 UTC
Dan you'd suggested it earlier and it didn't work then.  I just triple checked and changing the namespace doesn't help.  I've included my test output below.  Just in case I grabbed the wrong pid I also tried 10514 and 10728 with the same results.

[root@rhelbz ~]# docker run -d systemd_inside
32225e2387053c7eb27b896af459fd03e3da0fac4a8543022166501f95379f7a
[root@rhelbz ~]# machinectl
MACHINE                          CLASS     SERVICE
32225e2387053c7eb27b896af459fd03 container docker 

1 machines listed.
[root@rhelbz ~]# ls /var/log/journal
32225e2387053c7eb27b896af459fd03  7282b69db309f43f981461140a29390f
[root@rhelbz ~]# journalctl -M 32225e2387053c7eb27b896af459fd03
No journal files were found.
-- No entries --

[root@rhelbz ~]# ps aux | grep docker
root     10510  0.0  1.7 576516 32088 ?        Ssl  09:47   0:00 /usr/bin/dockerd-current --add-runtime docker-runc=/usr/libexec/docker/docker-runc-current --default-runtime=docker-runc --authorization-plugin=rhel-push-plugin --exec-opt native.cgroupdriver=systemd --userland-proxy-path=/usr/libexec/docker/docker-proxy-current --selinux-enabled --log-driver=journald --signature-verification=false --add-registry registry.access.redhat.com
root     10514  0.0  0.4 288592  8800 ?        Ssl  09:47   0:00 /usr/bin/docker-containerd-current -l unix:///var/run/docker/libcontainerd/docker-containerd.sock --shim docker-containerd-shim --metrics-interval=0 --start-timeout 2m --state-dir /var/run/docker/libcontainerd/containerd --runtime docker-runc --runtime-args --systemd-cgroup=true
root     10665  0.0  0.2  31220  5576 ?        Ssl  09:48   0:00 /usr/libexec/docker/rhel-push-plugin
root     10728  0.0  0.2 272148  3896 ?        Sl   09:49   0:00 /usr/bin/docker-containerd-shim-current 32225e2387053c7eb27b896af459fd03e3da0fac4a8543022166501f95379f7a /var/run/docker/libcontainerd/32225e2387053c7eb27b896af459fd03e3da0fac4a8543022166501f95379f7a /usr/libexec/docker/docker-runc-current
root     10814  0.0  0.0 112648   964 pts/0    R+   09:52   0:00 grep --color=auto docker

[root@rhelbz ~]# nsenter -m -t 10510 sh
sh-4.2# journalctl -M 32225e2387053c7eb27b896af459fd03
No journal files were found.
-- No entries --

Comment 15 Jan Synacek 2017-05-29 13:31:07 UTC
As Tom already pointed out, this would probably be fixed by backporting https://github.com/systemd/systemd/commit/5d1ce25728856956c1fbfe05b491067f83bd2216 and https://github.com/systemd/systemd/commit/d38c62cc76a14d9a91edd8d27aa4cdcd0edc5eec. I have tried to backport the former and it gets insanely complicated, so I gave up and couldn't really verify that those patches are the correct ones.

An easy work around is running "journalctl -D /var/log/journal/<id>" instead of "journalctl -M <id>". Also, docker must be doing something funny as the bug doesn't reproduce with systemd-nspawn.


Note You need to log in before you can comment on or make changes to this bug.