Discussion:
systemd-journald missing crash logs
Add Reply
Farzad Panahi
2018-01-13 00:13:25 UTC
Reply
Permalink
Raw Message
I am running Arch-ARM on RPi3. I have noticed when system crashes I cannot
find any related crash log in journal logs.

Arch Linux ARM on RPi3: `Linux 4.4.37-1-ARCH #1 SMP armv7l GNU/Linux`

Systemd: `systemd 232`

`/etc/systemd/journald.conf`:


[Journal]
Storage=persistent
Compress=yes
#Seal=yes
#SplitMode=uid
SyncIntervalSec=1
#RateLimitIntervalSec=30s
#RateLimitBurst=1000
SystemMaxUse=1.5G
#SystemKeepFree=
#SystemMaxFileSize=
#SystemMaxFiles=100
#RuntimeMaxUse=
#RuntimeKeepFree=
#RuntimeMaxFileSize=
#RuntimeMaxFiles=100
MaxRetentionSec=1month
MaxFileSec=3hour
#ForwardToSyslog=no
#ForwardToKMsg=no
#ForwardToConsole=no
#ForwardToWall=yes
#TTYPath=/dev/console
#MaxLevelStore=debug
#MaxLevelSyslog=debug
#MaxLevelKMsg=notice
#MaxLevelConsole=info
#MaxLevelWall=emerg

Recent crash log:

Dec 29 03:43:48 sudo[21861]: my_user : TTY=unknown ;
PWD=/opt/my_app/repo/src ; USER=root ; COMMAND=/usr/sbin/hciconfig hci0
reset
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session opened for
user root by (uid=0)
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session closed for
user root
Dec 29 03:43:48 my_app.py[17773]: trying to connect to XX:XX:XX:XX:XX:XX
Dec 29 03:43:48 systemd-udevd[21865]: Process '/bin/hciconfig hci0:64
up' failed with exit code 1.
Dec 29 03:43:51 my_app.py[17773]: connection successful :)
-- Reboot --
Jan 03 16:31:25 systemd[1]: Time has been changed
Jan 03 16:31:26 dhcpcd[470]: forked to background, child pid 587
Jan 03 16:31:25 systemd-timesyncd[360]: Synchronized to time server
206.108.0.133:123 (2.arch.pool.ntp.org).
Jan 03 16:31:25 systemd[1]: Starting Update man-db cache...
Jan 03 16:31:25 systemd[1]: Starting Rotate log files...
Jan 03 16:31:25 systemd[1]: Started Verify integrity of password and
group files.
Jan 03 16:31:25 systemd[1]: ssh-tunnel.service: Service hold-off time
over, scheduling restart.


**Looks like that somehow `journald` is failing to `sync` logs when a crash
happens.**

- Is this a known behaviour?
- Is there a workaround for this?


----------
Also I am curious to know if the following claim from [Arch Linux wiki][1]
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
----------
related bug report (old): [Bug 61411 - All logs since last boot gone after
crash/hard reboot][2]

similar issue (old):
https://unix.stackexchange.com/questions/67394/debugging-lock-up-systemd-loses-my-logs

[1]:
https://wiki.archlinux.org/index.php/Rsyslog#journald_with_rsyslog_for_kernel_messages
[2]:
https://bugs.freedesktop.org/show_bug.cgi?id=61411
Lennart Poettering
2018-01-15 12:11:59 UTC
Reply
Permalink
Raw Message
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I cannot
find any related crash log in journal logs.
What specifically is a "crash" supposed to mean?

journald syncs to disk whenever a log message above LOG_ERR is
delivered. I am not sure what "crash" is supposed to mean, but are you
sure that at least one LOG_CRIT/LOG_ALERT/LOG_EMERG message is
delivered to userspace about that?
Post by Farzad Panahi
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
As mentioned above, we wil sync immediately when a
LOG_CRIT/LOG_ALERT/LOG_EMERG log message is seen. We'll also sync on
normal log messages with a delay of 5min at max:

https://github.com/systemd/systemd/blob/master/src/journal/journald-server.c#L1440

if you get get a hard kernel lockup for some reason then this all is
useless however, as userspace won't even get the opportunity to write
anything to disk then... And it doesn't matter if userspace runs
journald or rsyslog.

Anyway, no idea what "crash" is supposed to mean though...

Lennart
--
Lennart Poettering, Red Hat
Farzad Panahi
2018-01-22 03:53:42 UTC
Reply
Permalink
Raw Message
Hi Lennart - Thanks for your comments.
Post by Farzad Panahi
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I
cannot
Post by Farzad Panahi
find any related crash log in journal logs.
What specifically is a "crash" supposed to mean?
Crash in my case means that the box becomes unresponsive. Meaning that I
cannot ssh to it anymore until it is power cycled. I do not know what is
happening to the box because there are no logs at the time of crash. Logs
start rolling after the reboot.

journald syncs to disk whenever a log message above LOG_ERR is
Post by Farzad Panahi
delivered. I am not sure what "crash" is supposed to mean, but are you
sure that at least one LOG_CRIT/LOG_ALERT/LOG_EMERG message is
delivered to userspace about that?
I am not sure about that. I just assume if some critical issue is
happening such that it makes the system unresponsive, then there should be
high priority logs associated with it.
Post by Farzad Panahi
Post by Farzad Panahi
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
As mentioned above, we wil sync immediately when a
LOG_CRIT/LOG_ALERT/LOG_EMERG log message is seen. We'll also sync on
https://github.com/systemd/systemd/blob/master/src/
journal/journald-server.c#L1440
if you get get a hard kernel lockup for some reason then this all is
useless however, as userspace won't even get the opportunity to write
anything to disk then... And it doesn't matter if userspace runs
journald or rsyslog.
So I think one of the following is happening:
a) no log is generated at the time of crash (I think this is unlikely)
b) log is generated but does not reach journald
c) log reaches journald but journald does not get a chance to persist it
d) journald persists the log but somehow the log is corrupted and ignored

I think scenario "c" is the most probable one in my case. So I just want to
confirm if kernel panics, then most probably I will not see any logs in my
log files? Is there a recommended workaround to debug such cases?
guenther kuenzel
2018-01-22 07:16:23 UTC
Reply
Permalink
Raw Message
the kernel itself has a remote dump functionality. this might be your only option when your system is not even able to write logs anymore.

https://help.ubuntu.com/lts/serverguide/kernel-crash-dump.html

greetings
Post by Farzad Panahi
Hi Lennart - Thanks for your comments.
 
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I cannot
find any related crash log in journal logs.
What specifically is a "crash" supposed to mean?
Crash in my case means that the box becomes unresponsive. Meaning that I cannot ssh to it anymore until it is power cycled. I do not know what is happening to the box because there are no logs at the time of crash. Logs start rolling after the reboot. 
journald syncs to disk whenever a log message above LOG_ERR is
delivered. I am not sure what "crash" is supposed to mean, but are you
sure that at least one LOG_CRIT/LOG_ALERT/LOG_EMERG message is
delivered to userspace about that?
I am not sure about that. I just assume if some critical issue is happening such that it makes the system unresponsive, then there should be high priority logs associated with it. 
Post by Farzad Panahi
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
As mentioned above, we wil sync immediately when a
LOG_CRIT/LOG_ALERT/LOG_EMERG log message is seen. We'll also sync on
https://github.com/systemd/systemd/blob/master/src/journal/journald-server.c#L1440 <https://github.com/systemd/systemd/blob/master/src/journal/journald-server.c#L1440>
if you get get a hard kernel lockup for some reason then this all is
useless however, as userspace won't even get the opportunity to write
anything to disk then... And it doesn't matter if userspace runs
journald or rsyslog.
So I think one of the following is happening: 
a) no log is generated at the time of crash (I think this is unlikely) 
b) log is generated but does not reach journald 
c) log reaches journald but journald does not get a chance to persist it
d) journald persists the log but somehow the log is corrupted and ignored
I think scenario "c" is the most probable one in my case. So I just want to confirm if kernel panics, then most probably I will not see any logs in my log files? Is there a recommended workaround to debug such cases? 
_______________________________________________
systemd-devel mailing list
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
Lennart Poettering
2018-01-24 08:59:00 UTC
Reply
Permalink
Raw Message
Post by Farzad Panahi
Post by Farzad Panahi
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I
cannot
Post by Farzad Panahi
find any related crash log in journal logs.
What specifically is a "crash" supposed to mean?
Crash in my case means that the box becomes unresponsive. Meaning that I
cannot ssh to it anymore until it is power cycled. I do not know what is
happening to the box because there are no logs at the time of crash. Logs
start rolling after the reboot.
Well, that sounds more like a "hang" than what I would call a
"crash". Now depending on the nature of the hang this might have the
effect that the whole system simply freezes, and if that happens, then
the journal can't do a thing either anymore...
Post by Farzad Panahi
Post by Farzad Panahi
delivered. I am not sure what "crash" is supposed to mean, but are you
sure that at least one LOG_CRIT/LOG_ALERT/LOG_EMERG message is
delivered to userspace about that?
I am not sure about that. I just assume if some critical issue is
happening such that it makes the system unresponsive, then there should be
high priority logs associated with it.
Well, that really depends on the nature of the hang. if the kenrel
just locks up, then userspace won't get scheduled anymore, and hence
no userspace logger in this world would help you tracking this down...
Post by Farzad Panahi
a) no log is generated at the time of crash (I think this is
unlikely)
b) log is generated but does not reach journald
c) log reaches journald but journald does not get a chance to persist it
d) journald persists the log but somehow the log is corrupted and ignored
I think scenario "c" is the most probable one in my case. So I just want to
confirm if kernel panics, then most probably I will not see any logs in my
log files? Is there a recommended workaround to debug such cases?
This is not a journal-specific issue: had kernel lockups are hard to
debug. Without direct console access you are in trouble. make sure to
turn on all printk logging directlyto consoleto track things like that
down... But at that point it's probably better to ask the kernel
community for help...

Lennart
--
Lennart Poettering, Red Hat
Farzad Panahi
2018-01-19 21:48:03 UTC
Reply
Permalink
Raw Message
Hey guys. I really appreciate any comment on this issue. Please let me know
if this question does not belong to this mailing list.
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I cannot
find any related crash log in journal logs.
Arch Linux ARM on RPi3: `Linux 4.4.37-1-ARCH #1 SMP armv7l GNU/Linux`
Systemd: `systemd 232`
[Journal]
Storage=persistent
Compress=yes
#Seal=yes
#SplitMode=uid
SyncIntervalSec=1
#RateLimitIntervalSec=30s
#RateLimitBurst=1000
SystemMaxUse=1.5G
#SystemKeepFree=
#SystemMaxFileSize=
#SystemMaxFiles=100
#RuntimeMaxUse=
#RuntimeKeepFree=
#RuntimeMaxFileSize=
#RuntimeMaxFiles=100
MaxRetentionSec=1month
MaxFileSec=3hour
#ForwardToSyslog=no
#ForwardToKMsg=no
#ForwardToConsole=no
#ForwardToWall=yes
#TTYPath=/dev/console
#MaxLevelStore=debug
#MaxLevelSyslog=debug
#MaxLevelKMsg=notice
#MaxLevelConsole=info
#MaxLevelWall=emerg
Dec 29 03:43:48 sudo[21861]: my_user : TTY=unknown ;
PWD=/opt/my_app/repo/src ; USER=root ; COMMAND=/usr/sbin/hciconfig hci0
reset
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session opened
for user root by (uid=0)
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session closed
for user root
Dec 29 03:43:48 my_app.py[17773]: trying to connect to
XX:XX:XX:XX:XX:XX
Dec 29 03:43:48 systemd-udevd[21865]: Process '/bin/hciconfig hci0:64
up' failed with exit code 1.
Dec 29 03:43:51 my_app.py[17773]: connection successful :)
-- Reboot --
Jan 03 16:31:25 systemd[1]: Time has been changed
Jan 03 16:31:26 dhcpcd[470]: forked to background, child pid 587
Jan 03 16:31:25 systemd-timesyncd[360]: Synchronized to time server
206.108.0.133:123 (2.arch.pool.ntp.org).
Jan 03 16:31:25 systemd[1]: Starting Update man-db cache...
Jan 03 16:31:25 systemd[1]: Starting Rotate log files...
Jan 03 16:31:25 systemd[1]: Started Verify integrity of password and
group files.
Jan 03 16:31:25 systemd[1]: ssh-tunnel.service: Service hold-off time
over, scheduling restart.
**Looks like that somehow `journald` is failing to `sync` logs when a
crash happens.**
- Is this a known behaviour?
- Is there a workaround for this?
----------
Also I am curious to know if the following claim from [Arch Linux wiki][1]
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
----------
related bug report (old): [Bug 61411 - All logs since last boot gone after
crash/hard reboot][2]
similar issue (old): https://unix.stackexchange.
com/questions/67394/debugging-lock-up-systemd-loses-my-logs
[1]: https://wiki.archlinux.org/index.php/Rsyslog#journald_
with_rsyslog_for_kernel_messages
https://bugs.freedesktop.org/show_bug.cgi?id=61411
林自均
2018-01-20 02:16:52 UTC
Reply
Permalink
Raw Message
Hi Farzad,

It seems that you missed Lennart's comments? It's here:
https://lists.freedesktop.org/archives/systemd-devel/2018-January/040162.html

John
Post by Farzad Panahi
Hey guys. I really appreciate any comment on this issue. Please let me
know if this question does not belong to this mailing list.
Post by Farzad Panahi
I am running Arch-ARM on RPi3. I have noticed when system crashes I
cannot find any related crash log in journal logs.
Arch Linux ARM on RPi3: `Linux 4.4.37-1-ARCH #1 SMP armv7l GNU/Linux`
Systemd: `systemd 232`
[Journal]
Storage=persistent
Compress=yes
#Seal=yes
#SplitMode=uid
SyncIntervalSec=1
#RateLimitIntervalSec=30s
#RateLimitBurst=1000
SystemMaxUse=1.5G
#SystemKeepFree=
#SystemMaxFileSize=
#SystemMaxFiles=100
#RuntimeMaxUse=
#RuntimeKeepFree=
#RuntimeMaxFileSize=
#RuntimeMaxFiles=100
MaxRetentionSec=1month
MaxFileSec=3hour
#ForwardToSyslog=no
#ForwardToKMsg=no
#ForwardToConsole=no
#ForwardToWall=yes
#TTYPath=/dev/console
#MaxLevelStore=debug
#MaxLevelSyslog=debug
#MaxLevelKMsg=notice
#MaxLevelConsole=info
#MaxLevelWall=emerg
Dec 29 03:43:48 sudo[21861]: my_user : TTY=unknown ;
PWD=/opt/my_app/repo/src ; USER=root ; COMMAND=/usr/sbin/hciconfig hci0
reset
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session opened
for user root by (uid=0)
Dec 29 03:43:48 sudo[21861]: pam_unix(sudo:session): session closed
for user root
Dec 29 03:43:48 my_app.py[17773]: trying to connect to
XX:XX:XX:XX:XX:XX
Dec 29 03:43:48 systemd-udevd[21865]: Process '/bin/hciconfig hci0:64
up' failed with exit code 1.
Dec 29 03:43:51 my_app.py[17773]: connection successful :)
-- Reboot --
Jan 03 16:31:25 systemd[1]: Time has been changed
Jan 03 16:31:26 dhcpcd[470]: forked to background, child pid 587
Jan 03 16:31:25 systemd-timesyncd[360]: Synchronized to time server
206.108.0.133:123 (2.arch.pool.ntp.org).
Jan 03 16:31:25 systemd[1]: Starting Update man-db cache...
Jan 03 16:31:25 systemd[1]: Starting Rotate log files...
Jan 03 16:31:25 systemd[1]: Started Verify integrity of password and
group files.
Jan 03 16:31:25 systemd[1]: ssh-tunnel.service: Service hold-off time
over, scheduling restart.
**Looks like that somehow `journald` is failing to `sync` logs when a
crash happens.**
- Is this a known behaviour?
- Is there a workaround for this?
----------
Also I am curious to know if the following claim from [Arch Linux
Since the syslog component of systemd, journald, does not flush its
logs to disk during normal operation, these logs will be gone when the
machine is shut down abnormally (power loss, kernel lock-ups, ...). In
the case of kernel lock-ups, it is pretty important to have some
kernel logs for debugging. Until journald gains a configuration option
for flushing kernel logs, rsyslog can be used in conjunction with
journald.
----------
related bug report (old): [Bug 61411 - All logs since last boot gone
after crash/hard reboot][2]
https://unix.stackexchange.com/questions/67394/debugging-lock-up-systemd-loses-my-logs
https://wiki.archlinux.org/index.php/Rsyslog#journald_with_rsyslog_for_kernel_messages
https://bugs.freedesktop.org/show_bug.cgi?id=61411
_______________________________________________
systemd-devel mailing list
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
Loading...