You are not logged in.

#1 2016-05-20 12:32:46

0x3048
Member
Registered: 2016-05-20
Posts: 6

Journald isn't working

Last year my journald worked just fine. Then I changed hostname in /etc/hostname. Some time after that I noticed journalctl wasn't showing most of the entries. I tried different ways to solve the issue but none on them helped, except changing Storage type to volatile.

Now I want to try solving this again. I've changed hostname back to localhost (though not sure it's related), then moved /var/log/journal to journal.save, recreated it with "pacman -S systemd", changed Storage to "persistent", and did a couple of reboots.

Unfortunately the issue persists:

$ journalctl -b 0 --no-pager
-- Logs begin at Fri 2016-05-20 14:32:22 EEST, end at Fri 2016-05-20 14:40:25 EEST. --
May 20 14:38:45 localhost devmon[447]: WARNING: multiple instances of devmon appear to be running (my pid=447):
May 20 14:38:45 localhost devmon[447]:   447 ?        Ss     0:00 /bin/bash /usr/bin/devmon
May 20 14:38:47 localhost devmon[447]: device: [/dev/sr0]
May 20 14:38:47 localhost devmon[447]:     systeminternal: [0]
May 20 14:38:47 localhost devmon[447]:     usage:          []
May 20 14:38:47 localhost devmon[447]:     type:           []
May 20 14:38:47 localhost devmon[447]:     label:          []
May 20 14:38:47 localhost devmon[447]:     ismounted:      [0]
May 20 14:38:47 localhost devmon[447]:     nopolicy:       [0]
May 20 14:38:47 localhost devmon[447]:     hasmedia:       [0]
May 20 14:38:47 localhost devmon[447]:     opticaldisc:    [1]
May 20 14:38:47 localhost devmon[447]:     numaudiotracks: [0]
May 20 14:38:47 localhost devmon[447]:     blank:          [0]
May 20 14:38:47 localhost devmon[447]:     media:          []
May 20 14:38:47 localhost devmon[447]:     partition:      [0]
May 20 14:39:28 localhost systemd[872]: Starting D-Bus User Message Bus Socket.
May 20 14:39:28 localhost systemd[872]: Listening on Sound System.
May 20 14:39:28 localhost systemd[872]: Reached target Paths.
May 20 14:39:28 localhost systemd[872]: Reached target Timers.
May 20 14:39:28 localhost systemd[872]: Listening on D-Bus User Message Bus Socket.
May 20 14:39:28 localhost systemd[872]: Reached target Sockets.
May 20 14:39:28 localhost systemd[872]: Reached target Basic System.
May 20 14:39:28 localhost systemd[872]: Started Music Player Daemon.
May 20 14:39:28 localhost systemd[872]: Reached target Default.
May 20 14:39:28 localhost systemd[872]: Startup finished in 256ms.
May 20 14:39:35 localhost systemd[872]: Started D-Bus User Message Bus.
May 20 14:39:40 localhost systemd[872]: Starting Sound Service...
May 20 14:39:42 localhost systemd[872]: Started Sound Service.
May 20 14:39:47 localhost dbus-daemon[926]: Activating service name='org.gnome.GConf'
May 20 14:39:47 localhost dbus-daemon[926]: Successfully activated service 'org.gnome.GConf'
May 20 14:39:50 localhost dbus-daemon[926]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
May 20 14:39:50 localhost systemd[872]: Starting Virtual filesystem service...
May 20 14:39:50 localhost dbus-daemon[926]: Successfully activated service 'org.gtk.vfs.Daemon'
May 20 14:39:50 localhost systemd[872]: Started Virtual filesystem service.
May 20 14:40:24 localhost dbus-daemon[926]: Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service'
May 20 14:40:24 localhost systemd[872]: Starting Accessibility services bus...
May 20 14:40:25 localhost dbus-daemon[926]: Successfully activated service 'org.a11y.Bus'
May 20 14:40:25 localhost systemd[872]: Started Accessibility services bus.
May 20 14:40:25 localhost at-spi-bus-launcher[1128]: ** (process:1128): WARNING **: Failed to register client: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.SessionManager was not provided by any .service files
$ groups
lp wheel users vboxusers wireshark systemd-journal

Any solution?

Last edited by 0x3048 (2016-05-21 07:37:59)

Offline

#2 2016-05-20 18:32:03

ewaller
Administrator
From: Pasadena, CA
Registered: 2009-07-13
Posts: 19,739

Re: Journald isn't working

What happens if you run that as root?


Nothing is too wonderful to be true, if it be consistent with the laws of nature -- Michael Faraday
Sometimes it is the people no one can imagine anything of who do the things no one can imagine. -- Alan Turing
---
How to Ask Questions the Smart Way

Offline

#3 2016-05-21 08:35:38

0x3048
Member
Registered: 2016-05-20
Posts: 6

Re: Journald isn't working

ewaller wrote:

What happens if you run that as root?

Results are the same:

$ sudo journalctl -b 0 --no-pager
-- Logs begin at Fri 2016-05-20 14:32:22 EEST, end at Sat 2016-05-21 10:33:04 EEST. --
May 21 10:32:11 localhost devmon[467]: WARNING: multiple instances of devmon appear to be running (my pid=467):
May 21 10:32:11 localhost devmon[467]:   467 ?        Ss     0:00 /bin/bash /usr/bin/devmon
May 21 10:32:13 localhost devmon[467]: device: [/dev/sr0]
May 21 10:32:13 localhost devmon[467]:     systeminternal: [0]
May 21 10:32:13 localhost devmon[467]:     usage:          []
May 21 10:32:13 localhost devmon[467]:     type:           []
May 21 10:32:13 localhost devmon[467]:     label:          []
May 21 10:32:13 localhost devmon[467]:     ismounted:      [0]
May 21 10:32:13 localhost devmon[467]:     nopolicy:       [0]
May 21 10:32:13 localhost devmon[467]:     hasmedia:       [0]
May 21 10:32:13 localhost devmon[467]:     opticaldisc:    [1]
May 21 10:32:13 localhost devmon[467]:     numaudiotracks: [0]
May 21 10:32:13 localhost devmon[467]:     blank:          [0]
May 21 10:32:13 localhost devmon[467]:     media:          []
May 21 10:32:13 localhost devmon[467]:     partition:      [0]
May 21 10:32:29 localhost systemd[12577]: Reached target Paths.
May 21 10:32:29 localhost systemd[12577]: Reached target Timers.
May 21 10:32:29 localhost systemd[12577]: Listening on Sound System.
May 21 10:32:29 localhost systemd[12577]: Starting D-Bus User Message Bus Socket.
May 21 10:32:29 localhost systemd[12577]: Listening on D-Bus User Message Bus Socket.
May 21 10:32:29 localhost systemd[12577]: Reached target Sockets.
May 21 10:32:29 localhost systemd[12577]: Reached target Basic System.
May 21 10:32:29 localhost systemd[12577]: Started Music Player Daemon.
May 21 10:32:29 localhost systemd[12577]: Reached target Default.
May 21 10:32:29 localhost systemd[12577]: Startup finished in 368ms.
May 21 10:32:36 localhost systemd[12577]: Started D-Bus User Message Bus.
May 21 10:32:36 localhost dbus-daemon[12960]: Successfully activated service 'org.freedesktop.systemd1'
May 21 10:32:41 localhost systemd[12577]: Starting Sound Service...
May 21 10:32:43 localhost systemd[12577]: Started Sound Service.
May 21 10:32:58 localhost dbus-daemon[12960]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
May 21 10:32:58 localhost systemd[12577]: Starting Virtual filesystem service...
May 21 10:32:58 localhost dbus-daemon[12960]: Successfully activated service 'org.gtk.vfs.Daemon'
May 21 10:32:58 localhost systemd[12577]: Started Virtual filesystem service.
May 21 10:33:03 localhost dbus-daemon[12960]: Activating service name='org.gnome.GConf'
May 21 10:33:03 localhost dbus-daemon[12960]: Successfully activated service 'org.gnome.GConf'
May 21 10:33:03 localhost dbus-daemon[12960]: Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service'
May 21 10:33:04 localhost systemd[12577]: Starting Accessibility services bus...
May 21 10:33:04 localhost dbus-daemon[12960]: Successfully activated service 'org.a11y.Bus'
May 21 10:33:04 localhost systemd[12577]: Started Accessibility services bus.
May 21 10:33:04 localhost at-spi-bus-launcher[25071]: ** (process:25071): WARNING **: Failed to register client: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.SessionManager was not provided by any .service files

There also should be at least one more boot in this (from 14:38 to 16:14, see timestamps below):

$ sudo journalctl --list-boots --no-pager
 0 a61b37fd34264a9c870530b102a85972 Fri 2016-05-20 14:32:22 EEST—Fri 2016-05-20 14:32:47 EEST
$ journalctl -b -1 --no-pager
-- Logs begin at Fri 2016-05-20 14:32:22 EEST, end at Sat 2016-05-21 10:33:04 EEST. --
May 20 14:38:45 localhost devmon[447]: WARNING: multiple instances of devmon appear to be running (my pid=447):
May 20 14:38:45 localhost devmon[447]:   447 ?        Ss     0:00 /bin/bash /usr/bin/devmon
May 20 14:38:47 localhost devmon[447]: device: [/dev/sr0]
May 20 14:38:47 localhost devmon[447]:     systeminternal: [0]
May 20 14:38:47 localhost devmon[447]:     usage:          []
May 20 14:38:47 localhost devmon[447]:     type:           []
May 20 14:38:47 localhost devmon[447]:     label:          []
May 20 14:38:47 localhost devmon[447]:     ismounted:      [0]
May 20 14:38:47 localhost devmon[447]:     nopolicy:       [0]
May 20 14:38:47 localhost devmon[447]:     hasmedia:       [0]
May 20 14:38:47 localhost devmon[447]:     opticaldisc:    [1]
May 20 14:38:47 localhost devmon[447]:     numaudiotracks: [0]
May 20 14:38:47 localhost devmon[447]:     blank:          [0]
May 20 14:38:47 localhost devmon[447]:     media:          []
May 20 14:38:47 localhost devmon[447]:     partition:      [0]
May 20 14:39:28 localhost systemd[872]: Starting D-Bus User Message Bus Socket.
May 20 14:39:28 localhost systemd[872]: Listening on Sound System.
May 20 14:39:28 localhost systemd[872]: Reached target Paths.
May 20 14:39:28 localhost systemd[872]: Reached target Timers.
May 20 14:39:28 localhost systemd[872]: Listening on D-Bus User Message Bus Socket.
May 20 14:39:28 localhost systemd[872]: Reached target Sockets.
May 20 14:39:28 localhost systemd[872]: Reached target Basic System.
May 20 14:39:28 localhost systemd[872]: Started Music Player Daemon.
May 20 14:39:28 localhost systemd[872]: Reached target Default.
May 20 14:39:28 localhost systemd[872]: Startup finished in 256ms.
May 20 14:39:35 localhost systemd[872]: Started D-Bus User Message Bus.
May 20 14:39:40 localhost systemd[872]: Starting Sound Service...
May 20 14:39:42 localhost systemd[872]: Started Sound Service.
May 20 14:39:47 localhost dbus-daemon[926]: Activating service name='org.gnome.GConf'
May 20 14:39:47 localhost dbus-daemon[926]: Successfully activated service 'org.gnome.GConf'
May 20 14:39:50 localhost dbus-daemon[926]: Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
May 20 14:39:50 localhost systemd[872]: Starting Virtual filesystem service...
May 20 14:39:50 localhost dbus-daemon[926]: Successfully activated service 'org.gtk.vfs.Daemon'
May 20 14:39:50 localhost systemd[872]: Started Virtual filesystem service.
May 20 14:40:24 localhost dbus-daemon[926]: Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service'
May 20 14:40:24 localhost systemd[872]: Starting Accessibility services bus...
May 20 14:40:25 localhost dbus-daemon[926]: Successfully activated service 'org.a11y.Bus'
May 20 14:40:25 localhost systemd[872]: Started Accessibility services bus.
May 20 14:40:25 localhost at-spi-bus-launcher[1128]: ** (process:1128): WARNING **: Failed to register client: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.SessionManager was not provided by any .service files
May 20 15:47:58 localhost dbus-daemon[926]: Activating via systemd: service name='org.gtk.vfs.Metadata' unit='gvfs-metadata.service'
May 20 15:47:58 localhost systemd[872]: Starting Virtual filesystem metadata service...
May 20 15:47:58 localhost dbus-daemon[926]: Successfully activated service 'org.gtk.vfs.Metadata'
May 20 15:47:58 localhost systemd[872]: Started Virtual filesystem metadata service.
May 20 16:14:25 localhost systemd[872]: Stopping Virtual filesystem metadata service...
May 20 16:14:25 localhost systemd[873]: pam_unix(systemd-user:session): session closed for user artem
May 20 16:14:25 localhost systemd[872]: Stopped target Default.
May 20 16:14:25 localhost devmon[447]: devmon: stopped
May 20 16:14:25 localhost systemd[872]: Stopping Sound Service...
May 20 16:14:25 localhost systemd[872]: Stopping Virtual filesystem service...
May 20 16:14:25 localhost systemd[872]: Stopping Music Player Daemon...
May 20 16:14:25 localhost systemd[872]: Stopping D-Bus User Message Bus...
May 20 16:14:25 localhost systemd[872]: Stopping Accessibility services bus...
May 20 16:14:25 localhost systemd[872]: Stopped Virtual filesystem metadata service.
May 20 16:14:25 localhost systemd[872]: Stopped Accessibility services bus.
May 20 16:14:25 localhost systemd[872]: Stopped D-Bus User Message Bus.
May 20 16:14:25 localhost systemd[872]: Stopped Sound Service.
May 20 16:14:25 localhost systemd[872]: Stopped Music Player Daemon.
May 20 16:14:25 localhost systemd[872]: Stopped Virtual filesystem service.
May 20 16:14:25 localhost systemd[872]: Stopped target Basic System.
May 20 16:14:25 localhost systemd[872]: Stopped target Timers.
May 20 16:14:25 localhost systemd[872]: Stopped target Paths.
May 20 16:14:25 localhost systemd[872]: Stopped target Sockets.
May 20 16:14:25 localhost systemd[872]: Closed Sound System.
May 20 16:14:25 localhost systemd[872]: Closed D-Bus User Message Bus Socket.
May 20 16:14:25 localhost systemd[872]: Reached target Shutdown.
May 20 16:14:25 localhost systemd[872]: Starting Exit the Session...
May 20 16:14:25 localhost systemd[872]: Received SIGRTMIN+24 from PID 7468 (kill).

Files seem to be consistent:

$ journalctl --verify
PASS: /var/log/journal/1f238d989b5d4163b619937e314757bc/user-1000.journal                                                          
PASS: /var/log/journal/1f238d989b5d4163b619937e314757bc/system.journal

Can't say that about journal before I recreated it, but I guess a corruption is result of my attempts to get this working.

Just now I noticed that previous system journal was 45M with 40M max limit, and that for one boot (seems to be after change to persistent storage, but before changing hostname back to localhost and /var/log/journal recreations) journal was working normally. What caught my attention is this:

May 20 12:42:59 dragonfly systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.

I've put system.journal from journal.save to pastebin.

Last edited by 0x3048 (2016-05-21 08:40:32)

Offline

#4 2016-05-22 09:00:04

0x3048
Member
Registered: 2016-05-20
Posts: 6

Re: Journald isn't working

0x3048 wrote:

What caught my attention is this:

May 20 12:42:59 dragonfly systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.

So today I booted from Gparted live iso and mounted / to /mnt and did "ls -l /mnt/var" and guess what I found? Missing journald logs! Hooray.

I made a copy of them, cleaned /var directory and rebooted into main OS. After that I looked into current journal and found that it's still missing entries. Also found this in dmesg:

[   10.969415] systemd-journald[205]: File /var/log/journal/1f238d989b5d4163b619937e314757bc/system.journal corrupted or uncleanly shut down, renaming and replacing.

However, I wasn't able to found renamed system.journal. I bet journald saved it into /var/... directory (not partition).

But let's get back to the point. I looked into system.journal from /var directory and found out that journald starts before var.mount:

May 21 10:32:02 localhost systemd-journald[208]: Journal started
...
May 21 10:32:07 localhost systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.
May 21 10:32:07 localhost systemd[1]: Mounting /var...
May 21 10:32:08 localhost systemd[1]: Mounted /var.

Now I realize I should've noted that I have /var on separate partition in the first place.

I understand this issue like this: "Storage=auto" by default, so when journald starts before var.mount, it begins writing into /run, and after /var gets mounted, flushes to disk. But if "Storage=persistent", journald creates log/journal directory in /var, even though var.mount wasn't executed yet. And even if storage gets changed back to auto, directory stays there (if not manually removed) and journald writes system journal to it every boot.

I'm going to change storage to auto, reboot into live iso, clean /var (again), and boot back into main OS. Done that, now journal works as expected.

I would mark thread as solved, but please let me know what you think. Is it a bug? Is it Arch-specific? Should it be reported upstream? Should it be noted in systemd's ArchWiki page?

Last edited by 0x3048 (2016-05-22 12:05:47)

Offline

#5 2016-05-22 12:46:12

Spider.007
Member
Registered: 2004-06-20
Posts: 1,175

Re: Journald isn't working

According to https://github.com/systemd/systemd/issu … -153134270 this shouldn't happen. Have a look at systemctl status systemd-journal-flush.service; does it start after /var is mounted? It should, because it contains

RequiresMountsFor=/var/log/journal

Last edited by Spider.007 (2016-05-22 12:47:04)

Offline

#6 2016-05-22 15:15:50

0x3048
Member
Registered: 2016-05-20
Posts: 6

Re: Journald isn't working

systemd-journal-flush.service starts after var.mount, like it should. The fact that system journal ends in /var directory as if it wasn't mounted is beyond me.

I made a reboot with clean /var and then copied created files, preserving ownership and timestamps.
1. Note mtime:

$ stat journal 
  File: 'journal'
  Size: 4096      	Blocks: 8          IO Block: 4096   directory
Device: 807h/2055d	Inode: 12845083    Links: 3
Access: (0755/drwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2016-05-22 17:57:20.343234907 +0300
Modify: 2016-05-22 17:51:51.710286033 +0300
Change: 2016-05-22 17:57:14.711233506 +0300
 Birth: -

2. Journal starts with these lines (17:51, same as /var/log/journal/ mtime):

May 22 17:51:51 dragonfly systemd-journald[206]: Runtime journal (/run/log/journal/) is 8.0M, max 187.8M, 179.8M free.
May 22 17:51:51 dragonfly systemd-journald[206]: System journal (/var/log/journal/) is 8.0M, max 100.0M, 92.0M free.
May 22 17:51:51 dragonfly systemd-journald[206]: Time spent on flushing to /var is 891us for 2 entries.

3. And this line shouldn't be there, because I've just cleaned /var using live iso:

May 22 17:51:58 dragonfly systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.
May 22 17:51:58 dragonfly systemd[1]: Mounting /var...
May 22 17:51:58 dragonfly systemd[1]: Mounted /var.
May 22 17:51:58 dragonfly systemd[1]: Starting Flush Journal to Persistent Storage...
May 22 17:51:59 dragonfly systemd[1]: Started Flush Journal to Persistent Storage.

Last edited by 0x3048 (2016-05-22 17:59:22)

Offline

#7 2016-05-28 11:29:04

Spider.007
Member
Registered: 2004-06-20
Posts: 1,175

Re: Journald isn't working

Can you post your fstab? Also, try `mount -o bind / /mnt/root` and have a look at /mnt/root/var; see if it is still empty.

As an alternative approach, try removing the journal directory from your root partition; and creating a file with the name 'journal' instead. Chattr that as immutable and reboot. It'd be interesting to see if an error will occur, and who will throw that

Offline

#8 2016-06-02 05:58:00

0x3048
Member
Registered: 2016-05-20
Posts: 6

Re: Journald isn't working

$ cat /etc/fstab
# 
# /etc/fstab: static file system information
#
# <file system>	<dir>	<type>	<options>	<dump>	<pass>

tmpfs   /tmp	tmpfs	nodev,nosuid	0 0

# /dev/sda5
UUID=cc5e6db2-5ad3-445c-834f-228f36f3e0b9	/	ext4	rw,relatime,data=ordered	0 1

# /dev/sda4
UUID=6ee2e6f1-653e-4ea2-aafe-deface0dcaae	/boot	ext4	rw,relatime,data=ordered	0 2

# /dev/sda2
UUID=8C48-3FB4	/boot/efi	vfat	rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro	0 2

# /dev/sda6
UUID=4d5d2d77-ba07-4904-aeba-7ff68ebeb590	/var	ext4	rw,relatime,data=ordered,acl	0 2

# /dev/sda7
#UUID=325491a7-d433-42d2-a67a-4442c2ff6dc9	/home	ext4	rw,relatime,data=ordered	0 2

# /dev/sda3
#UUID=2e2a73d9-fe6d-4bb7-a596-64f14c79fff1	none	swap	defaults	0 0

# /dev/sda8
#UUID=18A844190BEFDCE4 none auto defaults,noauto 0 0
# /dev/sda10
#UUID=18A6DD4BA6DD29D0 none auto defaults,noauto 0 0

Commands below were executed after reboot with clean /var directory and 'Storage=persistent' :

$ sudo mount -o bind / /mnt/
$ ls -la /mnt/var/ 
total 12
drwxr-xr-x  3 root root 4096 Jun  2 09:00 .
drwxr-xr-x 18 root root 4096 Oct  9  2015 ..
drwxr-xr-x  3 root root 4096 Jun  2 09:00 log
$ ls -la /mnt/var/log
total 12
drwxr-xr-x 3 root root 4096 Jun  2 09:00 .
drwxr-xr-x 3 root root 4096 Jun  2 09:00 ..
drwxr-xr-x 3 root root 4096 Jun  2 09:00 journal
$ cd /mnt/var/log         
$ sudo rm -r journal 
$ ls -la
total 8
drwxr-xr-x 2 root root 4096 Jun  2 09:15 .
drwxr-xr-x 3 root root 4096 Jun  2 09:00 ..
$ sudo touch journal
$ sudo chattr +i journal
$ lsattr journal 
----i--------e-- journal

Rebooting again now... Done.

$ dmesg | grep journal
[   11.211020] systemd-journald[209]: Failed to open system journal: Not a directory
[   16.628457] systemd-journald[209]: Received request to flush runtime journal from PID 1
$ journalctl -b 0 --no-pager | grep -E '(journal|/var)'
Jun 02 09:23:06 dragonfly systemd-journald[209]: Runtime journal (/run/log/journal/) is 8.0M, max 187.8M, 179.8M free.
Jun 02 09:23:06 dragonfly systemd-journald[209]: Journal started
Jun 02 09:23:11 dragonfly systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.
Jun 02 09:23:11 dragonfly systemd[1]: Mounting /var...
Jun 02 09:23:11 dragonfly systemd[1]: Mounted /var.
Jun 02 09:23:12 dragonfly systemd-journald[209]: System journal (/var/log/journal/) is 36.5M, max 100.0M, 63.4M free.
Jun 02 09:23:12 dragonfly systemd-journald[209]: Time spent on flushing to /var is 75.163ms for 917 entries.

Last edited by 0x3048 (2016-06-02 06:28:59)

Offline

Board footer

Powered by FluxBB