[megoldva]na ez mi volt? - log elemzés (25 sor) segítségkérés

Linux-kezdő

Sziasztok!

Vihar volt tegnap, kis költségvetésű helyeken üzemeltetett szerverekkel persze gond volt a gyenge háttértámogatás miatt (szünetmentes, etc.), így matatni kellett.
A log túrása közben találtam a következőre (ami vélhetőleg a vihar idejére esik): 


Jul 15 17:27:46 szki named[1721]: using default UDP/IPv6 port range: [1024, 65535]
Jul 15 17:27:46 szki named[1721]: listening on IPv4 interface ppp0, 89.132.60.137#53
Jul 15 17:27:46 szki named[1721]: reloading configuration succeeded
Jul 15 17:27:46 szki named[1721]: any newly configured zones are now loaded
Jul 15 17:29:27 172.16.0.251 %LINK-W-Down:  g20
Jul 15 17:29:28 172.16.0.251 %LINK-W-Down:  g10
Jul 15 17:29:28 szki kernel: [2854428.789717] eth2: link down
Jul 15 17:29:29 szki kernel: [2854429.582666] atl1 0000:02:00.0: eth3 link is down
Jul 15 17:30:26 szki syslog-ng[1764]: syslog-ng starting up; version='3.1.3'
Jul 15 17:30:26 szki kernel: [    0.000000] Initializing cgroup subsys cpuset
Jul 15 17:30:26 szki kernel: [    0.000000] Initializing cgroup subsys cpu
Jul 15 17:30:26 szki kernel: [    0.000000] Linux version 2.6.32-5-686 (Debian 2.6.32-45) (dannf@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Sun May 6 04:01:19 UTC 2012
Jul 15 17:30:26 szki kernel: [    0.000000] KERNEL supported cpus:
Jul 15 17:30:26 szki kernel: [    0.000000]   Intel GenuineIntel
Jul 15 17:30:26 szki kernel: [    0.000000]   AMD AuthenticAMD
Jul 15 17:30:26 szki kernel: [    0.000000]   NSC Geode by NSC
Jul 15 17:30:26 szki kernel: [    0.000000]   Cyrix CyrixInstead
Jul 15 17:30:26 szki kernel: [    0.000000]   Centaur CentaurHauls
Jul 15 17:30:26 szki kernel: [    0.000000]   Transmeta GenuineTMx86
Jul 15 17:30:26 szki kernel: [    0.000000]   Transmeta TransmetaCPU
Jul 15 17:30:26 szki kernel: [    0.000000]   UMC UMC UMC UMC
Jul 15 17:30:26 szki kernel: [    0.000000] BIOS-provided physical RAM map:
Jul 15 17:30:26 szki kernel: [    0.000000]  BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
Jul 15 17:30:26 szki kernel: [    0.000000]  BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
Jul 15 17:30:26 szki kernel: [    0.000000]  BIOS-e820: 00000000000e4000 - 0000000000100000 (reserved)

Amit én látok ebből: a 172.16.0.251 eszköz egy okos switch, ami a linuxra loggol, és jelenti, hogy a linkek elvesztek. Ez után a linux maga is logolja, hogy a linkek elvesztek. Egy perccel később a syslog-ng újraindul (hogy ez normális-e menet közben, nem tudom; az merült még fel bennem, hogy ez nem is a következő logsor előtt történt, de ezt a gyenge lábakon álló feltételezést nem tudom megvédeni).
UGYANEBBEN A MÁSODPERCBEN (tehát a syslog-ng újraindulásával emberileg tekintve egyszerre) egy boot log indul.
Na ezt nem értem. Ha volt restart, akkor az alaplap BIOS felállása nem 0sec, hanem eltart egy ideig. Ha újraindult a gép, akkor itt időkiesésnek kellene jelentkeznie. Ha nem indult újra a gép, akkor a linux, mint sw hogyan indulhatott újra a hw újraindulása nélkül?

Na ebben kellene nekem egy kis útmutatás. Köszönettel.

  • 2173 megtekintés

( muszi v | 2012. 07. 16., h – 10:01 )

17:29:29 az utolso, aramszunet elotti logbejegyzes, valoszinuleg par masodperccel kesobb ujra is indult a geped, es 17:30:26-kor indult el megint a syslog-ng. A szogletes zarojelben levo szam az uptime, masodpercben.

Köszönöm. Ezen már el tudnék indulni.

Az még mindig zavar, hogy a syslog-ng ha az újraindulás után logolta a saját restartját, akkor miért az előző boottime alapján számolta a boot óta eltelt időt? (Látható, hogy az 17xx mp-es logidőpontok szerepelnek az előtte lévő sorokban is).

Mit nem értek jól abban, amit mondani akartál?

A daemonoknál (named, syslog-ng) a szögletes zárójelben a daemon PID-je van:

Jul 15 17:27:46 szki named[1721]: using default UDP/IPv6 port range: [1024, 65535]
Jul 15 17:30:26 szki syslog-ng[1764]: syslog-ng starting up; version='3.1.3'

A kernel esetében van csak szó uptime másodpercekről:
Jul 15 17:29:28 szki kernel: [2854428.789717] eth2: link down
Jul 15 17:29:29 szki kernel: [2854429.582666] atl1 0000:02:00.0: eth3 link is down
Jul 15 17:30:26 szki kernel: [ 0.000000] Initializing cgroup subsys cpuset

Ok, tehát akkor a syslog-ng indulásáig valahol gyűlik a boot log-ja, majd amikor a syslog-ng is elindul, akkor az addigi log RTC szerint azonos mp-cel, de különböző boot-óta-eltelt-idő-mp-ben -nel kerül a logba. A syslog-ng indulása után már a boot-óta-eltelt-idő-mp-ben és az RTC szerinti idő múlása összhangban van.

Pl. az előzőnél itt indul valahol a syslog-ng, csak a logrész elejére kerül erről a jelentés, aztán jön az, amig addig felgyűlt, és innen már valósidejű: 


Jul 15 17:30:26 szki kernel: [   51.119947] NET: Registered protocol family 24
Jul 15 17:30:26 szki acpid: starting up with netlink and the input layer
Jul 15 17:30:27 szki authdaemond: modules="authpam", daemons=5
Jul 15 17:30:27 szki authdaemond: Installing libauthpam

Syslog-ng-ig 51 sec telt el, de mindez a logban RTC szerin egy mp-en belül látszik. Így már helyesen látom?

a syslog-ng indulásáig valahol gyűlik a boot log-ja

A kernel gyujti egy cirkularis pufferben (default 64k, 

CONFIG_LOG_BUF_SHIFT

).

majd amikor a syslog-ng is elindul, akkor az addigi log RTC szerint azonos mp-cel, de különböző boot-óta-eltelt-idő-mp-ben -nel kerül a logba.

Indulaskor a boot szkriptek lekerdezik a kerneltol az addig osszegyult logokat (Debianon a 

bootmisc.sh

), majd elmentik az egeszet a 

/var/log/dmesg

-be.

mindez a logban RTC szerin egy mp-en belül látszik. Így már helyesen látom?

Igen.

Köszönöm, ismét egy finomsággal több mára, amit megismerhettem... :)

Viszont ez a fentiek tükrében azt jelenti, hogy ~9mp alatt eljutott a HW odáig, hogy a kernel fusson (hiszen a logban RTC szerint ~1 perc telt el, a syslog-ng indulását viszont a kernel futásának 51. mp-ére tehetjük, ígyhát 9 sec alatt kellett elinduljon a kernel a HW újraindulásának kezdetétől.

Jól értem?