Dotaz: Chybný čas v logu od kernelu

[pet I.]

S překvapením jsme našli v logu takto posunuté časy:

srv ~ # grep 23302 /var/log/debug
2016-03-11 09:20:42 srv [local3 debug] myinit[23292]: Starting process [/usr/bin/rtevent] (23302)
2016-03-11 09:20:42 srv [local3 info] myinit[23292]: Run /usr/bin/rtevent num: 1, pid: 23302
2016-03-11 08:58:15 srv [kern info] kernel[]: rtevent[23302]: segfault at 7ffe4f7528b0 ip 00007fe85339cf78 sp 00007ffe4f7528a0 error 6 in libcom.so.2.3.1[7fe853265000+195000]
2016-03-11 09:30:34 srv [local3 notice] myinit[23292]: Process [/usr/bin/rtevent] (23302) KILLED 11
srv ~ #

Proces myinit spustil proces rtevent a po jeho pádu toto zalogoval. Tyto časy jsou správné. Ale pád zalogoval i kernel, a to s časem cca o 1/2 hodiny dříve. Nechápu proč.

Celý systém běží v UTC. Běží tam NTP démon, systém je zasynchronizovaný a momentálně za sebou má cca 36 dní bez rebootu.

Nechápete někdo co se tam děje?

Odpovědi

[trubicoid2]

nechapeme

v dmesg je co? o 1/2 h drive? tak tam je 08:58? tak tomu bych veril, 9:20 a 9:30 bude nejaka blbost v syslogu nebo co mas, jakou tam mas konfiguraci?

[Michal Kubeček]

V kernelovém logu nic takového není, tam jsou jen časové známky, které víceméně odpovídají času od bootu. Příkaz dmesg je sice umí převádět na lidsky srozumitelné datum a čas, ale to je obecně jen nepřesná aproximace (na což upozorňuje i dokumentace). Jedno z možných vysvětlení by bylo že syslog místo aby použil aktuální čas, se ho pokusí nějak dopočítat z té časové známky, takže když se to rozjede, bude v logu nesmysl, ale to bych považoval za hodně nešťastný nápad.

Vzhledem k tomu, že tazatel nenapsal, jaký syslog používá (a jestli v tom není zamíchaný ještě systemd-journald), můžeme jen spekulovat.

[trubicoid2]

jo, to nevadi, kdyz si neprestartoval tak ze znacky v dmesg a uptime poznas v kolik to bylo

nepresnosti jsem si nevsiml, to se asi vztahuje na sleep, coz na serveru nemas, ne?

dmesg -e jsem neznal, vypada to, ze to funguje

jeste doporucuji barevny dmesg -L

[Michal Kubeček]

jo, to nevadi, kdyz si neprestartoval tak ze znacky v dmesg a uptime poznas v kolik to bylo

Přibližně.

nepresnosti jsem si nevsiml, to se asi vztahuje na sleep, coz na serveru nemas, ne?

Není to jen suspend, jsou i jiné důvody, proč to nemusí přesně odpovídat.

[pet I.]

srv ~ # dmesg -e | grep 23302
[Mar11 08:58] rtevent[23302]: segfault at 7ffe4f7528b0 ip 00007fe85339cf78 sp 00007ffe4f7528a0 error 6 in libcom.so.2.3.1[7fe853265000+195000]
srv ~ # 

Starší výskyt, čas opět souhlasí s dmesg -e:

2016-02-08 17:14:46 srv [daemon info] ntpd[3434]: Deleting interface #75 enp7s0.28, 192.168.28.202#123, interface stats: received=0, sent=0, dropped=0, active_time=14997 secs
2016-02-08 17:11:36 srv [kern info] kernel[]: rtevent[13546]: segfault at 7ffc0ab4bfe8 ip 00007ff37720cb58 sp 00007ffc0ab4bff0 error 6 in libcom.so.2.3.1[7ff3770d5000+195000]
2016-02-08 17:16:05 srv [local3 notice] cassinit[13515]: Process [/usr/bin/rtevent] (13546) KILLED 11

Vypadá to, že to opravdu blbě převádí ten syslog. Používám syslog-ng-3.7.2, v pondělí se podívám do dokumentace jestli se s tím dá něco udělat. Systém je Gentoo, kernel vlastní. Pokud někdo máte nějaký tip co s tím, tak sem s ním.

[Trubicoid2]

V gentoo mám metalog, můžeš zkusit místo syslog-ng