A következő címkéjű bejegyzések mutatása: kdb. Összes bejegyzés megjelenítése
A következő címkéjű bejegyzések mutatása: kdb. Összes bejegyzés megjelenítése

2014. június 10., kedd

Amikor RAMBO kifogy a RAMbó..

Egy újabb nap, egy újabb kihívás.. Legalább is ezt mondják a hangok odafent. Gyakorlatilag az irodába beérkezve az alábbi "köszöntő" fogad: "A szerver nem elérhető, csinálj valamit!". Jaj de jó, ismét valami ami elé hulla fáradtan le lehet ülni, hogy aztán még jobban lefárasszam magam. Na mindegy, nézzük miből élünk..

Ránézek a szerverre: pingelni lehet, barmiféle kapcsolatot nyitni viszont nem.
HMC-ről nyitott virtual konzolról megvizsgálva a kérdést se jobb a helyzet, csupán a temérdek "unable to fork" hibaüzenet igazolja az eddigi teóriát, hogy bizony itt elfogyott a gép alól a fizikai memória, és még csak azért van életben, mert a paging space-ből még maradt valami ahova ki lehet lapozni azt a kevés memória területet amit a rendszer képes volt felszabadítani.

Mit lehet ilyenkor tenni? A lehetőségeink lényegében az alábbi 3 opcióra korlátozódnak:
- Imádkozunk, hogy a terhelés egy idő után megszűnik, és felszabadul annyi memória, hogy a szervert ismét életképes állapotba lehessen hozni
- Várni hogy az OOM killer végre működésbe lépjen, vagy hogy a rendszer összeessen magától
- Manuálisan újraindítani az egész mindenséget és behúzni +1 strigulát a service outage rubrika mellé

A kérdés már csak az, hogy a 3 opció közül melyik az, amelyik számunkra ÉS a customer számára is elfogadható. Jó, beszélgessünk el a customerrel, hogy akkor mi és hogyan, illetve próbáljunk meg rájönni, hogy melyik opciót is érdemes választani. Valami ilyesmit képzeljetek el:
- A szerviz számára fontos a szerver?
- Naná hogy az, production szerver, 7x24ben elérhetőnek kéne lennie
- A fontosabb szolgáltatás(ok) elérhető(ek)?
- Hááát ami azt illeti igen, csak épp lassú mint a fene.
/* tehát nincs szerviz kiesés, ami azt jelenti, hogy a fontosabb programok még a memóriában elvannak valahogy és onnan még tudnak úgy-ahogy működni is*/
A fontosabb dolgok hála az égnek mennek, de például az utóbbi 4 beütemezett job failed-re futott /* naná, valószínű el se tudott indulni */
- A nem elérhető részek mennyire business kritikusak?
- Hát.. Kis kiesés még belefér, de hosszútávon már komoly problémákat okoz ha a jobok nem futnak le.
- Tudnak e olyan jobról ami ebbe az idő-ablakba lett ütemezve, és esetleg erősen erőforrás igényes lehet?
- Nem, azok a hétvégére vannak csak beütemezve
- Jó. Tehát a szerviz még elérhető, bár funkcionálisan korlatozott. Mivel jelenleg nem tudunk a rendszerről barmit lekérni, így sajna megbecsülni se tudjuk hogy ez a hibajelenség tartós avagy ideiglenes e. A rendszer teljes újraindításával biztosan vissza tudjuk állítani a rendet, viszont az a szolgáltatás ideiglenes, ám teljes kiesésével is jár. Kérdés hogy ez a szerviz szempontjából elfogadható e, vagy inkább várjunk még egy kis időt, hogy hátha magától megszűnik a magas memória terhelés?
- Hát.. A szolgáltatás szempontjából a helyzet nem kritikus, viszont így nem is lehet a rendszert adminisztrálni. A következő fontos job kb 2 óra múlva indulna. Ha az se tud lefutni, az már komoly pénzbeli veszteség lenne a cégnek. Kb mennyi időt vesz igénybe a teljes rendszer újraindítása?
- Az újraindítás viszonylag gyorsan megvan, a visszaellenőrzések viszont eltartanak egy minimum 20 percig. Számoljunk 30 percet mindenre biztos ami biztos.
- Rendben. Akkor még kb 1 órát tudunk várni, és akkor még lesz 30 percünk az esetleges hibaelhárításra. Ha addig se jön helyre a szerver, akkor indítsák újra.

Ok.. Kapott a szerver 1 óra haladékot, hogy bebizonyítsa milyen fából is faragták. Közben azért érdemes elgondolkodni, hogy mi is mehet épp végbe az AIX mélyebb bugyraiban (kernel szinten):
- A rendszer már kidobált minden nem szükséges adatot a fizikai memóriából (temporary cache már tuti nincs, ami még kell és kilapozható az meg már biztosan a paging space-en található)
- Ettől függetlenül a fizikai memóriában nincs szabad hely, ergo új process-t se lehet nyitni/forkolni. /* épp ezért nem is lehet belépni a gépre, mivel ott is minimum egy új shell-t kéne forkolnia a rendszernek */
- Azok a processek amik már a memóriában vannak még képesek funkcionálni /* ezért is képes a szolgáltatás még úgy ahogy életben maradni */
- A rendszer folyamatosan törekszik kiszolgálni a bejövő memória igényeket, illetve fizikai memóriát felszabadítani további page-ek kilapozásával.
- Amennyiben az egységnyi idő alatt bejövő memória kérések száma magasabb mint amit a rendszer adott idő alatt fel tud szabadítani, akkor lényegében egy meglehetősen kellemetlen hógolyó effektus következik be, mivel a futó program által kért memória terület biztosan valami adat számára lett kikérve, - amit a rendszer viszont ilyen esetekben hajlamos gyorsan ki is lapozni - ami viszont csak tovább rontja a helyzetet, mivel a diszken lévő paging sebessége kb egy kerékbilincses csigáéhoz hasonlítható a fizikai memóriához képest => ilyen helyzetben a nagy paging space csak a haláltusát hosszabbítja meg, de ténylegesen nem segít semmit /* főleg ha a process még később vissza is akar olvasni valamit amit a rendszer ma előzőleg kilapozott */
- Ez az állapot addig fennáll amíg az elérhető virtuális (!) memória le nem csökken egy bizonyos szintig: Amikor az elérhető virtualis memory page-ek száma eléri az VMO npswarn értékét (4k-ban tessek számolni), akkor a rendszer kiküld mindenkinek egy SIGDANGER signalt, hogy lehetőséget adjon a processeknek konzisztensen leállni (már ha fel vannak készítve arra hogy az ilyen signal-al kezdjenek valamit). Amennyiben a memória kihasználtság ez után eléri a VMO npskill értékét (vagy mert a programok ignorálták a signalt, vagy mert nem bírtak időben leállni), akkor a kernel szisztematikusan elkezdi legyilkolászni a legfiatalabb processeket amikre "engedélyé van": Ez kb annyit jelent, hogy a process owner UID-ja nincs felsorolva a VMO nokilluid listáján /* alapból pl a 0as UID van ott, ami annyit jelent, hogy a root neve alatt futó processeket a rendszer nem fogja legyilkolni */
- Amennyiben a rendszer nem képes ezzel a módszerrel se memóriát felszabadítani akkor a paging space teljes felhasználása után egy garantált system crash következik, amit aztán egy automatikus restart követ.

A fenti példából azért látszik, hogy van olyan forgatókönyv is, amikor a szerviz számára fontos programot a rendszer nemes egyszerűséggel legyilkolja (már ha a hozza köthető UID nincs rajta a nokilluid listán), ami kb csak 1 fokkal jobb csak a teljes újraindításnál :)
#Megjegyzés - ez azt is jelenti, hogy a fenti VMO paraméterek finomhangolásával amúgy simán életben is lehet tartani egy gépet restart nélkül, csak akkor készüljünk fel arra, hogy időnként 1-2 programot lehet újra kell majd indítgatni.

Eltelt 1 óra.. Sajnos a rendszer nem volt képes visszarángatni magát a valóságba, így az ügyfél kérésére azt újra kellett indítani. Na jó.. de hogyan? Ne tessek félre érteni, nem az a kérdés, hogy milyen paranccsal, vagy min keresztül (HMC azért jó ha van :)). A kérdés inkább arra irányul, hogy azonnal újra kell e indítani mindent, vagy esetleg adunk a rendszernek még 1-2 percet hogy ha már eddig eljutott akkor dobjon már egy system dumpot is, amiből esetleg később még tudunk vizsgálódni. Ismerve a managementet, az utóbbi garantáltan megfontolandó (még akkor is ha nem azonnal indul újra az LPAR), tekintve, hogy biztosan el fog hangzani az a kérdés, hogy "Jó, de mi tömte tele a memóriát?"

# Jó tanács: Mielőtt a Windows-on nevelkedett adminok nekiállnának azonnal újraindítani 1-1 gépet, inkább tanulják meg az alábbi parancsot használni HMC-ről:
chsysstate -m $MACHINE -r lpar -o dumprestart -n $PARTITION

Kb 5-10 percbe telt mire a gép mindent kidumpolt a memóriából, majd elkezdte szépen újraindítani a rendszert, amit gyors program indítgatások és visszaellenőrzések követtek, így a szerviz ismét teljesen elérhető lett és a customer számára kritikus job is le tudott futni minden gond nélkül.. Éljen.. An other success story, good job, well done, champaign.. Na jó, nem egészen..
További kb 1-1,5 órán át még ment a beszélgetés illetve az összefoglalók írása, miután elhangzott customer oldalról az a kérdés amire előzőleg egy meglehetősen nagy fogadást mertem volna kötni: "Ki tudjuk deríteni, hogy mi okozta ezt? Vagy van valami módszer arra, hogy ezt megelőzzük?"
Látjátok, mondtam én :)

Mázlira a dump device-al, és annak beállításaival semmi gond nem volt (dump compression bekapcsolva, dump device mérete megfelelő) és volt is elég hely ahhoz, hogy a dumpot kimásolva egy fájlrendszerre, majd kitömörítve el lehessen kezdeni analizálni, hogy végül is mi a franc volt a géppel.
Persze ahhoz hogy ezt megválaszoljuk azért nem árt tudni, hogy mi is helyezkedik el a memóriában. A teljesség igénye nélkül itt egy kis összefoglaló:
- A kernel számára lefoglalt memória terület (erre szoktak még System occupied memory néven is hivatkozni, ami magában foglalja magát a kernelt (és annak moduljait), a kernel heap-et, a shared memory szegmenseket, memory buffert, kernel cache-t, és a shared library-knak fenntartott memória területet)
- Fájlrendszer cache /* AIX esetében ez JFS, JFS2, NFS cache-t jelent */
- Különböző HW-ek számára fenntartott caching area
- Processek indító binárisainak (futó process binárisa kötelezően a fizikai memóriában helyezkedik el) és esetleges privát library-knek fenntartott memória terület
- A processek számára fenntartott privát memória területek (minden processnek saját memória terület, saját virtuális memória címzéssel)

Kezdjük is azzal ami a legtöbb problémát szokta okozni: Azok a fránya programok. Csak hogy szemléltessem hogy mennyire (nem)vicces tud egy ilyen nyomozás lenni, már itt leszegezem hogy ennek vizsgálatára nyomban 3 különböző módszer van, amik mind mást-mást néznek (ergo más-más eredményt is produkálnak) ... csak hogy az ember élete egyszerű legyen ...
- a kdb-nek van beépített svmon parancsa, ami meglehetősen jól visszaadja az aktuális állapotot, viszont bizonyos helyzetekben hajlamos nem működni. Naná hogy ez is pont egy olyan helyzet:
(0)> svmon * Pid Command Inuse Pin Pgsp Virtual 64-bit Mthrd LPage [kdb_read_mem] no real storage @ F10013AE4747FF70

- Minden process-től ki lehet kérni az éppen lefoglalt fizikai és paging lapokat (nvpages és npsblks értékek) a proc alparancs segítségével, viszont összehasonlítva egy (működő) svmon kimenetével egyértelműen látható, hogy ez nem a ténylegesen lefoglalt összes virtuális memóriát adja vissza, hanem annak csak egy részét (az svmon kimenetéből csupán a working storage és shared library data összegét vagyunk képesek így megállapítani; a heapet, illetve a kernel segment-eket nem). További kellemetlenség, hogy ezt minden egyes processre meg kell vizsgálni, ami vagy egy script formájában történhet meg, vagy sok, türelmesen beírogatott proc es grep parancsok kombinációjával /* a script lassú, kézzel meg még lassabb - marad a script */
# for i in $(echo 'proc *' |kdb dump_file_copy|awk '{print $1}') > do > echo "proc $i" |kdb dump_file_copy |awk '/ nvpages/ || /^pvproc/ {print $3}' | \ > awk 'NR == 1 { printf("%s", $0); } NR != 1 { printf(" %s", $0); } END { printf("\n") }' > done |sort -r -k2 |sed "s/://g" |head -10 java 000000000001F7FC -> ~ 503.9 MB java 000000000001545D -> ~ 340.3 MB java 0000000000007A43 -> ~ 122.2 MB java 00000000000065F0 -> ~ 101.9 MB kuxagent 00000000000024A1 -> ~ 36.6 MB java 0000000000001951 -> ~ 25.3 MB k07agent 000000000000140F -> ~ 20 MB cimserve 0000000000001088 -> ~ 16.5 MB kulagent 0000000000000C37 -> ~ 12.2 MB aixdp_da 0000000000000C02 -> ~ 12 MB
# Megjegyzés - már itt látható, hogy még így is lesznek később problémáink a processek pontos behatárolásával, tekintve, hogy a "java" process rohadtul nem mondja meg, hogy a JVM-en belül mi futott. Erre később még visszatérünk.

- az scb alparancs segítségével is ki lehet kérni az nvpage-eket (process azonosítóra szűrve), itt viszont már a rendszerhez rendelt page-ek is listázva lesznek, ergo szerintem ez a leghasználhatóbb módszer (már ha az svmon valamiért nem működne), plusz az előzőhöz képest jóval gyorsabb is az alap vizsgalat (mivel a page-eket egy körben le tudjuk kérni), viszont itt az is bejön, hogy 1 process több page-et is használhat (már ha többszálusított programról beszélünk), így ezt a vizsgálat során külön figyelembe kell venni. Ezen felül a szűrt processekre (mondjuk top10) így is kell egy extra fork a proc alparanccsal, szóval hiába gyorsabb, attól még azért eléggé macerás így is:
# PVPROC_=""; VPGS_="0" # echo "scb -c 6 0" |kdb dump_file_copy |grep -v 0000000000000000 |grep -w W |awk '{print $10,$7}' |sort | \ > awk '{gsub ("MB","")}{if ($2 ~ "GB") {sub ("GB","");print $1,$2*1024,$3} else {print}}' | while read PVPROC VPGS > do > if [ "${PVPROC}" == "${PVPROC_}" ] > then > VPGS="$(echo ${VPGS_}+${VPGS} |bc)" > else > echo "${PVPROC_} ${VPGS_} ${PGSP_}" > fi > PVPROC_="${PVPROC}" > VPGS_="${VPGS}" > done| sort -rn -k2 |head -10|while read PROC VPGS PGSP > do > printf "%-15s %-15s %-15s\n" \ > $(echo "proc $PROC"|kdb dump_file_copy |awk '/^pvproc/ {printf ("%d %s", "0x"$5, $3)}') "${VPGS} MB" > done 15597570 java 571.6 MB 7274716 java 374.1 MB 4653250 java 271.1 MB 14745724 java 102.9 MB 0 swapper 83.7 MB 3866808 rmcd 61.6 MB 6094860 java 50.3 MB 10354744 kuxagent 38.0 MB 8192024 cimserve 31.5 MB 6946818 k07agent 22.5 MB

Szupi.. akkor most már van valami hozzávetőleges fogalmunk is arról, hogy mi mennyit zabált. nézzük mennyi memória is alt rendelkezésre:
(0)> vmstat |grep "total lru frames" total lru frames (4K units) : 00000000000E53E0 3.6GB
Őőőőőő.. Állj.. A számok valahogy nem stimmelnek: Ha megnézzük, akkor az top10 process is csak kb 1.6 GB-ot volt képes lefoglalni, ami közel sincs a teljes 3.6 GB-hoz (HW cache nélkül). Ami azt jelenti, hogy valamit vagy nagyon sikerült benézni, vagy máshol van Lessie elásva. 1 lépés előre, 3 lépés vissza, kezdjük elölről, de most inkább kezdjük a vizsgálódást magasabb szintről és csak utána menjünk alacsonyabb szintekre:

Fizikai memória (poolonként lebontva - mázlira itt csak 1 pool volt)
(0)> memp * VMP MEMP NB_PAGES FRAMESETS NUMFRB F1000F0009540000 00 000 000E7440 000 001 002 003 000008D4 ^^^^^^^^ ^^^^^^^^ 3700.25 MB 8.8 MB
3700 MB (3.6 GB) fizikai memória összesen, ebből 8,8 MB szabad a dump pillanatában. Eddig stimmt. Nézzük a paginget
(0)> vmker |grep pgsp |egrep "^total|^free" total pgsp blks (numpsblks) : 001A8000 -> 6784 MB free pgsp blks (psfreeblks) : 0010DDE4 -> 4317.8 MB
6.625 GB paging, ebből közel 4.2 GB szabad. Eddig is klappol a történet.
(0)> vmstat |egrep "total perm frames|wlm_hw_pages|vm_nonsys|total perm frames|vm_syspgs" # 'system' pages (vm_syspgs) : 00000000000E2844 3.5GB # non-'system' pages (vm_nonsys) : 00000000000041F8 66.0MB total perm frames (4K units) : 0000000000000187 1.5MB Total unmanaged mem (wlm_hw_pages): 00018BC0 395.8MB
Na jó, itt kicsit sok dolog van, beismerem. Nézzük őket szépen sorjában
- 'system' pages / vm_syspgs - Emlékeztek még a fent említett "kernel-számára fenntartott memória terület"-re? Na ez az :)
- non-'system' pages / vm_nonsys - Fizikai memórián belül azon processekhez tartozó lapok mennyisége amik nem lettek kilapozva a paging space-re
- total perm frames - fájlrendszer cache (JFS, JFS2, NFS)
- Total unmanaged mem / wlm_hw_pages - A szinten fent emlegetett HW cache area.

Na itt már látszik, hogy nem mi vagyunk a hülyék, hanem a rendszer tényleg nagyon élszált, tekintve hogy a fizikai memóriában szinte csak system lapok voltak, a többi meg vagy HW cache, vagy applikáció, egy nagyon kevés FS cache, illetve 1 kis rész ami ezen a query-n nem látszik. Továbbá az is simán látszik, hogy a fenti svmon/proc/scb mérésünk semmit nem ér, ha nem látjuk, hogy mennyi memória terület is lett kilapozva abból amit az applikáció tényleg lefoglalt. Az viszont tuti, hogy a kernelnek nem kéne ennyit lefoglalnia, szóval nézzünk már rá, hogy mi a franc is zabált annyit:
(0)> scb -c 6 100 |grep 0000000000000000 |sort -rn -k4 |head -15 00A14A W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A148 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A147 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A146 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A145 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A144 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A143 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A142 W 64K 256.0MB 256.0MB 0.0MB 256.0MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A149 W 64K 255.8MB 255.7MB 0.0MB 255.8MB 0.0MB 0000 0000000000000000 KHEAP SYS 00A023 W 64K 206.7MB 203.4MB 0.0MB 206.8MB 0.1MB 0000 0000000000000000 KHEAP SYS 00A00E W 64K 187.8MB 53.8MB 0.0MB 188.0MB 0.2MB 0000 0000000000000000 KHEAP SYS 00A14B W 64K 154.1MB 153.9MB 0.0MB 154.1MB 0.0MB 0000 0000000000000000 KHEAP SYS 00E000 W 64K 130.0MB 130.0MB 0.0MB 130.0MB 0.0MB 0000 0000000000000000 MBUF SYS 00A111 W 64K 122.8MB 0.8MB 0.0MB 122.9MB 0.1MB 0000 0000000000000000 KHEAP SYS 00A01C W 64K 87.3MB 86.9MB 0.0MB 87.3MB 0.1MB 0000 0000000000000000 KHEAP SYS
Hat én itt 2 dolgot latok: Rohadt sok Kernel heap-et, meg egy kevéske memory buffert.. Ami azt jelenti, hogy az elején valóban nem benézés esete forgott fent, hanem a rendszer tényleg "Mind megette" játékot játszott, ami viszont némi kis keresgélés után nyomban ki is derül miért:
IV53587: XMGC NOT TRAVERSING ALL KERNEL HEAPS. APPLIES TO AIX 7100-03 14/04/17 PTF PECHANGE

És igen... Persze hogy a rendszer pont ezen az szinten fut:
# oslevel -s 7100-03-01-1341
Customer értesít, állapot elmagyaráz (csak amolyan konyhanyelven, mert az halál biztos, hogy nem akarok 2 órán keresztül arról magyarázkodni -egy jó esetben félig technikus emberkének - hogy az AIX hogyan is manageli a memóriát a motorháztető alatt), következő maintenance window lefoglal, change előkészít, rendszer frissítés a hétvégére beütemez, hátradől, virtuális vállveregetés, a rendszergazda megpihen.
Megpihenne.. Legalább is ha nem baxná az ideg, hogy mi a jó büdös francért kellett kb 2-3 órán át a kernel dumpot túrnia és a fejét vakarnia amikor különböző okoknál fogva valami vagy nem működött, vagy nem azt az eredményt adta amit az ember várna tőle. Mit csinál ilyenkor a (jó)rendszer gazda? Füles be, elkezd valami kódolós zenét hallgatni majd elkezdi az egész francos memória checket lescriptelni, hogy legközelebb már 5 perc alatt meglegyen az, amivel most órákat szívott.
És mivel jófej rendszergazda tudja milyen xar amikor mások is ilyenekkel szívnak, így inkább úgy dönt, hogy szabadon elérhetővé teszi az egészet, szóval ha ne adj isten más is hasonló aljasságokra adná a fejet, az használja szeretettel az alábbi kis scriptecskét arra hogy valami támpontot kapjon a rendszer állapotáról egy sikeres dump után:
https://drive.google.com/file/d/0BzMqRqSWTAToNjdCbUNXd1ZGeVU

A gyengébbek kedvéért azért azt kiemelném hogy az ilyen jellegű outputot is a helyén kell kezelni, ergo akinek nincs tapasztalata ilyen jellegű debugolásokban, annak inkább azt ajánlom, hogy max a scriptet olvasgassa, és próbálja meg megérteni hogy mi és hogy működik mielőtt teljesen vakon megbízna egy netről letöltött scriptben/parancsban :D

Csak úgy a hova tartás végett: a script jelenlegi verziója ilyen outputot generált a fent említett dumpból:
# kdb_memory_check.sh -d dump_file_copy -t 10 Available physical memory: 0.215% (8.828 from 4096 MB ) HW pages: 395.750 MB (9.661% of total memory) FS cache: 1.527 MB (.037% of total memory) Processes occupied memory: 64.441 MB (1.573% of total memory) System occupied memory: 3624.265 MB (88.483% of total memory) Kernel Heap: 3320 MB (91.606% of system memory) Available paging space: 63.648% (4317.890 from 6784 MB) Additional details: SIGDANGER level: 54272 SIGKILL level: 13568 minperm percent: 3.0% maxperm percent: 90.0% maxclient percent: 90.0% Top 10 memory consumer(s) (based on nvpages) Process Name PID Virtual Pages Paged pages java 15597570 571.6 569.9 java 7274716 374.1 372.2 java 4653250 271.1 270.7 java 14745724 102.9 102.3 swapper 0 83.7 24.8 rmcd 3866808 61.6 61.1 java 6094860 50.3 49.8 kuxagent 10354744 38.0 36.8 cimserve 8192024 31.5 31.3 k07agent 6946818 22.5 20.6
Ami a process neveket illeti.. Hát az tényleg a szívás kategóriába tartozik: logikus lenne, hogy a parancs argumentumait is megtaláljuk a memóriában (hisz itt van a /proc alatt, ami meg teljesen memória rezidens), a probléma viszont az, hogy ezt minden process saját maga manageli a saját kis memória területen belül (pontosabban mondva a process-nek fenntartott Guardpage-en belül; a procfs-en belül a psargs meg erre a memória címre mutat), így azt a kernel dumpból nem fogjuk tudni kinyerni direktben...
Viszont ha mázlink van és megmaradt a process név+PID páros valamelyik bufferban/cache-benm akkor simán megpróbálhatunk ezekre rá-greppelni a dumpon belül és megszerezni a teljes process nevet, annak minden argumentumával együtt :)

Na és ezzel tényleg ennyi.. It's Now Safe to Turn Off Your Computer. Legalább is amíg a következő nagy "kihívás" nem köszön be..

2013. május 16., csütörtök

Corrupt system dump - Nem bírja a rendszer, szívjál még egyszer..

Sajnos az elmúlt időszakban inkább project jellegű munkákkal kellett foglalkozzak (ami inkább a tervezési munkálatokat fed le), mint sem tényleges rendszer üzemeltetéssel (ami meg az esetleges hibák debugolását), így el kellett telnie némi kis időnek, míg valami fincsi problémára rá tehettem a kezem.
Most viszont végre sikerült valami kellemesbe is belekóstolnom :)

A történet előzménye röviden a következő: Adott egy nem épp up-to-date AIX rendszer, ami hirtelen dobott egy hátast, plusz a hozzá járó kernel dumpot, és ki kéne deríteni, hogy pontosan mi a fene lehetett a háttérben (az applikáció eléggé nem szereti a magasabb AIX levelt, így mielőtt ráböföghetném, hogy "AIX-et kéne frissíteni wazze" még be kell bizonyítanom, hogy valóban az AIX volt e a ludas). Tekintve, hogy az ilyen jellegű vizsgálódások annyira nem állnak tőlem távol, így örömmel kezdtem neki a probléma megoldásának, bár az örömöm nem tartott sokáig..

Kezdésként nézzük a helyzetet:
# oslevel -s
5300-08-02-0822
// No igen.. Ennek a TL-nek a hivatalos supportja még 2010 Áprilisában járt le, ráadásul még 2010 Májusban kiadtak hozzá az SP10-et. Ez az SP még 2008ban jött ki, szóval gondolhatjátok, hogy milyen régi applikáció futhat rajta, ami miatt még az AIX-et se merik upgrade-elni..
# errpt | head -3
IDENTIFIER TIMESTAMP  T C RESOURCE_NAME  DESCRIPTION
67145A39   0325114513 U S SYSDUMP        SYSTEM DUMP
F48137AC   0325114213 U O minidump       COMPRESSED MINIMAL DUMP

Jó.. Szóval legalább az alapok meg vannak.. Nézzük, hogy mire számítsunk:
# errpt -aj 67145A39
---------------------------------------------------------------------------
LABEL:          DUMP_STATS
IDENTIFIER:     67145A39

Date/Time:       Mon Mar 25 11:45:00 NFT 2013
Sequence Number: 900224
Machine Id:      00CD98ED7C00
Node Id:         application_server
Class:           S
Type:            UNKN
Resource Name:   SYSDUMP         

Description
SYSTEM DUMP

Probable Causes
UNEXPECTED SYSTEM HALT

User Causes
SYSTEM DUMP REQUESTED BY USER

        Recommended Actions
        PERFORM PROBLEM DETERMINATION PROCEDURES

Failure Causes
UNEXPECTED SYSTEM HALT

        Recommended Actions
        PERFORM PROBLEM DETERMINATION PROCEDURES

Detail Data
DUMP DEVICE
/dev/dumplv
DUMP SIZE
            2147483136
TIME
Mon Mar 25 11:40:12 2013
DUMP TYPE (1 = PRIMARY, 2 = SECONDARY)
           2
DUMP STATUS
          -2
ERROR CODE
           0
DUMP INTEGRITY
This dump may be unusable - The alloc_kheap component is missing. 
This dump may be unusable - The alloc_other component is missing. 
This dump is incomplete - The end-of-dump component is missing. 

FILE NAME

PROCESSOR ID
           0
Tehát a rendszer váratlanul megállt, de a keletkezett dump nem teljes.. Innen indul a kihívás..

Tekintve, hogy van egy minidump-unk, így legalább abban reménykedhetünk, hogy abból ki tudunk valamit hámozni. Erre a legegyszerűbb az mdmprpt parancs.
# mdmprpt 
MINIDUMP VERSION 4D32
***************************************************
64-bit Kernel, 108 Entries

Last Error Log Entry: 
         Error ID: 9AA1914A      Resource Name: SYSVMM 
         Detail Data: 0000000042000000 00007FFFFFFFD080 
        F10001005DDD11F0 FFFFFFFFFFFFFFF3

This minidump is corrupted
Meg se lepődök.. Tekintve, hogy a dump-unk incomplete, így nem is vártam konzisztens dump-ot, bár a corrupt dump azt jelenti, hogy esélyünk nincs ezt az entry-t ellenőrizni. Egyedül annyi derül ki, hogy az utolsó jegyzett hiba a 9AA1914A error ID-ra mutat, ami a SYSVMM-hez köthető. Gyors segítség: VMM - Virtual Memory Manager, így innentől már sejthető, hogy itt valami memória művelethez köthető dolgon csúszott meg a rendszer. De azért nézzük meg, hogy a 9AA1914A error ID mit is takar a valóságban:
# grep -i 9AA1914A /usr/include/sys/errids.h
#define ERRID_DSI_MEMOVLY    0x9aa1914a /* A kernel memory overlay has been detected */
Memory overlay - teljesen fedi a VMM hatáskörét, úgy hogy eddig ez rendben is van.. Na de hogyan tovább? Ja igen.. Van még egy dumpunk. Ezt mentsük le a dump device-ról amíg lehet, aztán nézzük meg mit találunk benne:
# dd if=/dev/dumplv of=/dump_check/sysdump bs=4096 count=2147483136
// Itt megállnék egy pillanatra: Normális esetben a dump compression be van kapcsolva, ami azt jelenti, hogy a kiszedett dump-ot még ki is kéne tömöríteni a dmpuncompress paranccsal, jelen esetben viszont erre nem volt szükség, mivel a dump compression ezen a gépen nem volt bekapcsolva. Innentől lehet tippelni, hogy miért is nem fért el a dump, és hogy én ez miatt mennyire de boldog voltam.
# kdb /dump_check/sysdump
The specified kernel file is a 64-bit kernel
sysdump mapped from @ 700000000000000 to @ 70000007ffffe00
Preserving 1411195 bytes of symbol table
First symbol __mulh
Component Names:
 1)  minidump [2 entries]
 2)  dmp_minimal [9 entries]
 3)  dump_pad53 [1 entries]
 4)  proc [4101 entries]
 5)  thrd [7291 entries]
 6)  rasct [1 entries]
 7)  ldr [2 entries]
 8)  iplcb [1 entries]
 9)  errlg [3 entries]
10)  mtrc [98 entries]
11)  lfs [1 entries]
12)  bos [4 entries]
13)  ipc [7 entries]
Premature end of data in dump file.
Component Dump Table has 11523 entries
           START              END 
0000000000001000 0000000003E04050 start+000FD8
F00000002FF47600 F00000002FFDC940 __ublock+000000
000000002FF22FF4 000000002FF22FF8 environ+000000
000000002FF22FF8 000000002FF22FFC errno+000000
F100070F00000000 F100070F10000000 pvproc+000000
F100070F10000000 F100070F18000000 pvthread+000000
PFT:
PVT:
id....................0002
raddr.....0000000002000000 eaddr.....F200800090000000
size..............00080000 align.............00001000
valid..1 ros....0 fixlmb.1 seg....0 wimg...2
Unable to establish context with current thread
Unable to establish context with current thread
Unable to find kdb context
Dump analysis on CHRP_SMP_PCI POWER_PC POWER_6 machine with 32 available CPU(s)  (64-bit registers)
Processing symbol table...
.......................done
        ERROR: Unable to acess nfs_syms
(0)> where
Unable to establish context with current thread
Unable to establish context with current thread
[kdb_read_mem] no real storage @ F1000100100EE800
Unable to establish context with current thread
Unable to establish context with current thread
Unable to find kdb context
(0)> f
Unable to establish context with current thread
Unable to establish context with current thread
[kdb_read_mem] no real storage @ F1000100100EE800
Unable to establish context with current thread
Unable to establish context with current thread
Unable to find kdb context
(0)> stat
SYSTEM_CONFIGURATION:
CHRP_SMP_PCI POWER_PC POWER_6 machine with 32 available CPU(s)  (64-bit registers)

SYSTEM STATUS:
sysname... AIX
nodename.. application_server
release... 3
version... 5
build date May 12 2008
build time 23:42:11
label..... 0820A_53N
machine... 00CD98ED7C00
nid....... CD98ED7C
time of crash: Mon Mar 25 11:39:02 2013
age of system: 124 day, 7 hr., 56 min., 32 sec.
xmalloc debug: enabled
Debug kernel error message: A program has tried to store to freed or redzoned xmalloc memory.
Address at fault was 0xF10001005DDD11F0
Na akkor röviden: Az alap parancsok mind elhullanak azon oknál fogva, mert a dump-unk nem teljes, amúgy meg annyit tudunk meg mint előzőleg - memória kezelési gubancok vannak a háttérben.

Egy dolog viszont ott van amit talán lehet használni: a CDT adatok (component-dump tables), amit a kdb az elején jelzett is. Ami nekünk kelhet az jelen esetben a minidump, vagy az errlg tábla, tekintve, hogy ezek még talán tartalmazhatnak valami kis támpontot, hogy merre tovább.

Első körben én a minidump-ra koncentráltam:
(0)> cdt 1
Dump table entries in CDT:

CDT ENTRY VMHANDLE       ALIAS        ADDRESS LENGTH   NAME
  1     1 kernel             0000000002B1AA50 00000046 md head
  1     2 kernel             0000000002F1E9FC 00000E60 minidump
Tekintve, hogy a dump is tartalmazza a minidump-ot, így első körben az volt a tervem, hogy azt fogom kiszedni onnan, majd használható állapotba hozni, viszont egy részről ez -mint utólag kiderült- nem volt kivitelezhető (az okokat most nem tárgyalom), így más útvonalon kellett elinduljak
// Az minidump-al való mókolást szerintem majd egy külön blogban tárgyalom ha lesz rá érdeklődés

Mázlimra az AIX-nek van 1-2 beépített parancsa bizonyos típusú adatok kinyerésére a dump file-okból, csak ezeket valamiért a dokumentációk nem nagyon emlegetik. Az egyik ilyen parancs a dmp_minimal (ami még véletlenül sincs dokumentálva), a másik pedig az errdead (ami még úgy ahogy dokumentált).
Előző célja, hogy az elérhető minidump-ot kinyerje a dump file-ból, és megpróbálja azt értelmezni, utóbbi pedig a boot során keletkezett error logok kinyerésére használható a dump file-ból.
#  /usr/lib/ras/dmprtns/dmp_minimal /dump_check/sysdump|tail -15
traceback:
 iar:0000b920 unknown
  lr:002f7eac slock+148
addr:002f806c slock+308
addr:000090c4 unknown
addr:044901f8 store_packet+70
addr:04490880 pcd_output[DS]+98
addr:044473f8 en_output+1218
addr:0430974c ip_output_post_fw+1f50
addr:04309b04 ip_output+100
addr:0433bb44 tcp_output+2404
addr:0436d2a0 tcp_usrreq+17a8
addr:00223760 sosend+c88
addr:0023b2b8 send+4e0
addr:00003814 unknown
Na, legalább van egy stack-ünk. Megerősítésként azért nem árt átnézni az error logot is. Ehhez simán extractoljuk ki az error logot a dump-ból, majd adjuk oda az errpt-nek:
# /usr/lib/errdead -i ./errpt_out /dump_check/sysdump 
# errpt -i errpt_out
IDENTIFIER TIMESTAMP  T C RESOURCE_NAME  DESCRIPTION
9AA1914A   0325113913 P S SYSVMM         INVALID MEMORY REFERENCE
77EED6D9   0325113913 U S SYSALLOC       Deferred-free or redzoned memory read
Hoppá. Emlékszik még valaki a 9AA1914A-es hibakódra? Igen, ez az amire az mdmprpt is panaszkodott. Legalább ez az infó is megvan akkor. Sajna azonban a 9AA1914A-es error logban nem sok használható infó van, viszont annál több a 77EED6D9-esben:
# errpt -i errpt_out -aj 77EED6D9
---------------------------------------------------------------------------
LABEL:          XM_READ_FREE
IDENTIFIER:     77EED6D9

Date/Time:       Mon Mar 25 11:39:02 NFT 2013
Sequence Number: 1
Machine Id:      00CD98ED7C00
Node Id:         application_server
Class:           S
Type:            UNKN
Resource Name:   SYSALLOC        

Description
Deferred-free or redzoned memory read

Probable Causes
LOADABLE SOFTWARE MODULE
SOFTWARE DEVICE DRIVER
OPERATING SYSTEM

Failure Causes
MEMORY ALLOCATION ERROR

        Recommended Actions
        PERFORM PROBLEM DETERMINATION PROCEDURES
        CONTACT YOUR LOCAL IBM SERVICE REPRESENTATIVE

Detail Data
Stack Trace
slock+11C
slock+304
[90C0]
store_packet+6C
pcd_output[DS]+94
en_output+1214
ip_output_post_fw+1F4C
ip_output+FC
tcp_output+2400
tcp_usrreq+17A4
sosend+C84
send+4DC
[3810]
-errSTKfrm-
Mint látható, a 2 parancs által szerzett stack kb azonos (annyi különbséggel, hogy az errpt az ismeretlen hívások helyére valami -nekünk irreleváns- címet illesztett be), így nyugodtak lehetünk, hogy jó nyomon járunk.

Jó, de innen hova tovább? Azt nem tudjuk megnézni, hogy a regiszterekben milyen adat volt, a forráskódhoz nem férünk hozzá, hogy tudjuk minek és hol is kéne pontosan lennie, csupán egy stack állapotunk van. Ez miatt általában azt szoktam mondani, hogy tessék utána járni, hogy van e olyan APAR, ami hasonló, vagy (ami még jobb) azonos stack-et produkál e, ugyan is ekkor szinte biztosak lehetünk, hogy abba a bug-ba sikerült belebotlanunk, de még hasonlót se találtam ami ilyesmi stack-et írt volna le (a 2 unknown hívás meg pláne nem segít semmit).

Na innentől általában egyenes út a software call felé, de szinte biztos, hogy ilyen dump-al ők se tudnak sokat kezdeni, plusz mivel enyhén outdated AIX level-t futtatunk, így csuklóból közölnék, hogy ez a verzió nem támogatott, illetve ajánlatos lenne azonnal update-elni, mivel azóta már jó pár javítás kijött, és hátha valamelyik erre is megoldást nyújtana.

// Itt akár be is fejezhetném ezt a blog bejegyzést, ugyan is technikailag már sok újdonságot nem fogok leírni, viszont akit érdekel a teljes történet, annak azért leírom, hogy hogy is folytatódik ez a kis történet.

Na szóval. A probléma ezzel a felállással innentől az, hogy az ember 2 szék között a pad alá kerül rövid úton, úgy hogy ez így nem játszható.
Van azonban még 1 kis aranyágacska, amin el lehet indulni: A stackben látható pcd_output hívás nem része a standard AIX hívásoknak, így kis kutakodás után sikerült kideríteni, hogy azt egy extended kernel module biztosítja, ami az IBM RealSecure Server-hez (aka ISS) tartozik, ami akkor szintúgy bekavarhat, úgy hogy ennek a szálnak is utána kell járni.

// Megjegyzés: az ISS egy extra védelmi réteget húz a hálózati kommunikáció elé, és monitorozza a hálózati forgalmat. Ha valami gyanúsat észlel, akkor azt elvileg képes megfogni, így biztosítva némi IDS funkcionalitást. Az outdated AIX verzióra való tekintettel ennek jelenléte még teljesen érthető is..

Első körben a kérdés az, hogy milyen modul biztosítja azt a hívást.. 2 lehetőség van ennek kiderítésére: Vagy rátámaszkodunk a naming convention-re, és azt mondjuk, hogy a pcd_output hívás valószínű valami pcd szerű driver hozza, vagy megnézzük, hogy az ISS csomagban van e, és ha igen, akkor milyen driverek vannak a csomagon belül.
# lslpp -l |grep ISS
  ISSXss.ServerSensor        7.0.0.0  COMMITTED  IBM RealSecure ServerSensor
  ISSXss.ServerSensor        7.0.0.0  COMMITTED  IBM RealSecure ServerSensor
  
# lslpp -f ISSXss.ServerSensor |grep driver
/usr/lib/drivers/
/usr/lib/drivers/pcd.ext
Na.. Így már biztosabbak lehetünk a dolgunkban. Következő kérdés, hogy a modul valóban be volt e töltve a dump pillanatában.. Irány vissza a kdb-be, majd listázzuk ki a betöltött modulokat, és szűrjünk arra amit találtunk:
(0)> lle -k |grep pcd.ext
  9 03EDDB00 0448C000 00016150 00080252 /usr/lib/drivers/pcd.ext
Bingo.. Tehát be volt töltve. Innentől akkor már csak az a kérdés, hogy ez okozta e a hibát, avagy az AIX. 100%-ra pontosan persze nem tudjuk megmondani, de azt azért érdemes megnézni, hogy az ISS-ünk is outdated-e.

Na itt kezdődött a következő problémám.. A hivatalos IBM javítások között a legfrissebb verzió a 7.0.42.2, a rendszeren viszont semmiféle utalás nincs a pontos verzióra nézve, csupán a csomag 7.0.0.0-ás verziószáma, ami viszont véletlenül se használható támpont.
A végleges megoldás végül az lett, hogy leszedtem a javítást az IBM FixCentral oldaláról, kicsomagoltam a base64 encode-olt telepítőt (így kaptam egy BFF csomagot), abból kibontottam a tényleges file-okat, és összehasonlítottam a checksum értékeket a rendszeren lévőkkel: Egyeztek -> Tehát ebből a programból legalább a legfrissebb verzió volt telepítve a gépre.

// Ez úton is üzenném minden programozónak, hogy valami nyamvadt verziózást rakjatok már bele a programotokba, különben lehetetlen lesz lekövetni, hogy épp mikor kell frissíteni az adott szoftvert.

Tehát a felállás innentől a következő: Van egy program, aminek a kernel module-ja szinte biztos, hogy szerepet kapott a hibában, viszont az a jelenlegi legfrissebb verzió, ergo vagy sikerült egy olyan bugba belebotlani, amire még vagy nincs javítás, vagy még nem is ismert, vagy tényleg az AIX outdated státusza okozta a galibát, és kompatibilitási hibával állunk szemben. Utóbbit sajna biztosra meg nem lehet mondani, mivel a hivatalos dokumentum véletlenül se taglalja, hogy van e TL/SP függősége, így nem maradt más hátra, mint közölni a customerrel, hogy nagy eséllyel tényleg frissíteni kéne az AIX-et (Minimum felrakni a legutolsó Service packot ehhez a TL-hez; azt az applikáció nagyobb eséllyel éli túl, mint mondjuk egy TL upgrade-et), bekapcsolni a dump compression-t, és ha az után is előjön a probléma, akkor újabb SW call-t nyitni. Ha ez nem kivitelezhető, akkor sorry, de ez egy olyan known risk amivel együtt kell majd élnie.

2013. január 29., kedd

Mickey egér, HACMP, meg a többiek..

Némileg úgy érzem most magam, mint ahogy régen a BBC stábja érezhette magát, amikor is 1946ban (állítólag, bár egyesek szerint ez is kacsa) ismét ott folytatták az ominózus Mickey Mouse történetet, ahol anno 1939 Szeptember 1.-jén abbahagyták.

Ok, némileg túlzó a kép, de azért nekem is volt 1-2 komolyabb harcom az elmúlt 1-2 hónapban, munkahely váltás, költözés külföldre, meg ami vele jár.. Szóval nem volt eseménytelen az elmúlt időszak, ami sajna a blog rovására is ment láthatólag.
Na de viszont most megpróbálom azt amit anno a BBC-sek is - folytatni ahol abbamaradt minden, mintha misem történt volna..

Na szóval.. Aktuális problémánk tárgya egy HACMP-s node, ahol a clcomdES daemon fölött elkezdtek körözni a keselyűk, ugyan is ránézésre halottnak nézett ki..
Az AIX kommandó az újraélesztést megkezdte, de a beteg nem reagált a kezelésre:
[server:root:/home/root:] lssrc -s clcomdES
Subsystem         Group            PID          Status 
 clcomdES         clcomdES                      inoperative
[server:root:/home/root:] startsrc -s clcomdES
0513-059 The clcomdES Subsystem has been started. Subsystem PID is 7033284.
[server:root:/home/root:] 
[server:root:/home/root:] lssrc -s clcomdES   
Subsystem         Group            PID          Status 
 clcomdES         clcomdES                      inoperative
Az orvosi lapot átnézve kiderült, hogy betegünk valószínű még is él, csak vagy kómába esett, vagy önmagán kívül van:
[server:root:/:] tail -1 /var/hacmp/clcomd/clcomd.log 
Mon Jan 28 15:03:18 2013: bind (../../../../../../../src/43haes/usr/sbin/cluster/clcomd/clcomd.c:5533): Address already in use
Persze minderről a hatóságok semmit nem tudtak..
[server:root:/var/hacmp/clcomd:] ps -ef |grep clcom 
    root 5480538 7143926   0 15:05:31  pts/1  0:00 grep clcom 
.. csak annyit, hogy a clcomdES által gyakran használt erőforrásokat valami tényleg épp fogja:
# Kis magyarázat: a clcomdES által használt default port a 6191
[server:root:/var/hacmp/clcomd:] netstat -Aan |grep 6191 |grep LISTEN
f10006000243c398 tcp4       0      0  *.6191             *.*                LISTEN
Ilyenkor általában csak odasétál az ember az illetékes besúgóhoz, megkéri hogy mondja már meg ki jár rá a dugi csokira, de szomorúan kell konstatáljuk, hogy halvány lila fogalma nincs:
[server:root:/var/hacmp/clcomd:] rmsock f10006000243c398 tcpcb
getprocdata: malloc failed
Na jó... Ha a szokványos eszközök nem mennek, akkor tényleg muszáj lesz nekünk is bemocskolnunk a kezünk, és megnézni hogy a Disc-réten mi ROMolhatott el..

Kezdjük is a kernellel, ha már a gyanúsítgatásnál tartunk ("Ahol a kormány, ott van a gáz.."). Aki olvasta eddig a blogomat annak ez a fordulat azt hiszem nem lesz komolyabb meglepetés :)
Akinek még is, annak javaslom az itt emlegetett módszerek és parancsok áttanulmányozását a folytatás előtt

Na szóval.. a netstat megsúgta nekünk, hogy a f10006000243c398-es dugi csokira jár rá a kis szellemünk, úgy hogy kezdjünk el az után nyomozni első körben:
[server:root:/var/hacmp/clcomd:] kdb
(0)> ns
Symbolic name translation off
(0)> si f10006000243c398 tcpcb |grep ACTIVE
F100070F01012000 16456*clcomd   ACTIVE 004812E 0031166 00000003184E1400   0 0014

(0)> proc F100070F01012000 |head
              SLOT NAME     STATE      PID    PPID          ADSPACE  CL #THS

F100070F01012000 16456 clcomd   ACTIVE 004812E 0031166 00000003184E1400   0 0014
Hoppá.. Tehát a socketet még is csak egy clcomd fogja, de akkor miért nem vették észre a nyomozó kollégák??
(0)> hcal 004812E
Value hexa: 0004812E          Value decimal: 295214

[server:root:/:] ps -fp 295214
     UID     PID    PPID   C    STIME    TTY  TIME CMD
       -  295214       -   -                     - <exiting>
Ja kérem.. Ez itt egy megrendezett öngyilkossággal egybekötött biztosítási csalás.. Na keressük meg a cinkosokat:
(0)> proc F100070F01012000 |grep THREAD
THREAD..... threadlist :F100070F10807300 
THREAD..... threadcount:00000014  ........... active     :00000002

(0)> th F100070F10807300 |head
                SLOT NAME     STATE    TID PRI   RQ CPUID  CL  WCHAN

F100070F10807300 32883  ZOMB  0731E3 03C    0         0  

NAME................ 
WTYPE............... WZOMB    
.................tid :00000000000731E3  ......tsleep :FFFFFFFFFFFFFFFF
...............flags :00000000  ..............flags2 :00000000
...........pmcontext :00000000
DATA.........pvprocp :F100070F01012000 
Hoppá.. Nekromancia, vagy mifene? Ki mozgatja a szálakat?
(0)> th F100070F10807300 |grep prev 
LINKS.....prevthread :F100070F10008C00 
LINKS.....prevthread :0000000000000000

(0)> th F100070F10008C00 |head
F100070F10008C00  140 clcomd   SLEEP 08C029 03C    4         0  F100070F010121B8 
Jó.. 1 megvan.. Vannak még?
(0)> th -n clcomd
                SLOT NAME     STATE    TID PRI   RQ CPUID  CL  WCHAN

F100070F10007C00  124 clcomd   SLEEP 07C0ED 03C    4         0  F1000110129D9A70 01125380 
F100070F10008C00  140 clcomd   SLEEP 08C029 03C    4         0  F100070F010121B8 
Aham.. szóval 2 fő process, 1-1 threaddel.. Na és ők épp mit csinálnak?
(0)> f F100070F10008C00
pvthread+008C00 STACK:
[0005EEF4]ep_sleep+000128 (0000000000056DA0, A0000000000090B2 [??])
[0014384C]kexitx+000F6C (??)
[0015AAD8]kexit+000080 ()
[kdb_get_virtual_memory] no real storage @ FFFFFFFF3FFFE40

(0)> f F100070F10007C00
pvthread+007C00 STACK:
[002FF8C0]slock+0006A4 (00000000002E0268, 80000000000090B2 [??])
[00009558].simple_lock+000058 ()
[002CB3D0]j2_rename+000188 (??, ??, ??, ??, ??, ??, ??)
[00408C34]vnop_rename+0002B4 (??, ??, ??, ??, ??, ??, ??)
[0046A8F4]rename+00030C (??, ??)
[0486570C]my_rename+0001C4 (0000000020023728, 00000000200C149C)
[00003810].svc_instr+000110 ()
[kdb_get_virtual_memory] no real storage @ 200C0FD8
[10013190]log_printf+0002FC (00000000, 00000000, 00000000, 00000000,
   00000000, 00000000, 00000000, 00000000)
Az egyik épp ki akar lépni, de azért még vár egy kicsit (tapsra talán, meg nem mondom), de a másik már érdekesebb: Ott a jelek szerint épp valami JFS2-es FS alatt volt valami átnevezősdi, ami valahogy még is csak megbicsaklott..
És hiába tűnt ez az elején HACMP hibának, a bizonyítékok alapján ez inkább tűnik AIX issue-nak.. A pénz csak pénz, a stack az meg csak stack na..
Azok alapján meg az ügy erősen hajaz az alábbi hibák egyikére:
- IZ96928
- IZ40258
Na most ha megnézitek, akkor azért ezek a bűnügyi megelőző kezelések nem épp a legfrissebben szabadult bűnözőkre lettek kitalálva (avagy jó régi patchekről van szó).. Úgy hogy ha már itt tartunk nézzük már meg, hogy ezt a drágát melyik korból szalajthatták?
[server:root:/:] oslevel -s
5300-08-08-0943
Jah.. Jó.. Ez a TL/SP még anno 2009 Novemberében lett kiadva.. Az se ma volt.. Had ne mondjam azóta mennyi fix kijött, jah meg az 5.3as AIX hivatalos supportja is lejárt 2012 Áprilisában.
Na szóval itt rendesen el vannak egyesek maradva.. És hiába kérdezik meg az SWG-sek (software group) hogy tuti minden patch fent van e, attól még a hülye AIX admin csak abból főzhet amit a konyhában talál (amíg ki nem derül, hogy a Műanyag tálba lévő melegítendő kaját lehet még sem a sütőn kellett volna megpróbálni felmelegíteni).

Tanulság: Ha tetszik, ha nem tessék már azokat a rohadt rendszereket frissíteni (és nem csak a security miatt)

2012. november 4., vasárnap

HACMP failover issue - Unable to unmount the filesystem

Az ember egy idő után már hajlamos azt hiszi, hogy azért nem lehet könnyen meglepni, ha már egy csomó szívást átélt, meg már a kdb-s bugyrokat is megjárta.. Hiába tudjuk, hogy Murphy csak az ilyen jelekre vár, mindig azt hisszük, hogy fel tudjuk venni vele a kesztyűt.. Aztán az ember szembe kap egy általánosnak tűnő problémát, elkezdi a saját kis módján investigálni, majd akkor koppan amikor rájön, hogy valami mégse úgy megy ahogy kéne, vagy valami még így is van amire nem gondolt előzőleg.

Ez se volt most másként.. Felhívtak kollégák, hogy lenne egy HACMP failover probléma: Szegény RG nem tud átállni, és meg kéne már nézni, hogy mi a rákért nem..
Hát jó.. hacmp.out túrás , és elég gyorsan szembejön az első gyanús jel:
***************************
Nov 3 2012 19:42:13 !!!!!!!!!! ERROR !!!!!!!!!!
***************************
Nov 3 2012 19:42:13 cl_deactivate_vgs: Failed varyoff of appvg.
Aham.. na jó.. nézzük mi van még itt, ami miatt ez előjöhetett:
+app_rg:cl_deactivate_vgs(5.910):appvg[vgs_varyoff+282] varyoffvg appvg
0516-012 lvaryoffvg: Logical volume must be closed.  If the logical
        volume contains a filesystem, the umount command will close
        the LV device.
0516-942 varyoffvg: Unable to vary off volume group appvg.
Ahh.. haladunk.. Mi törpént az FS-el?
+app_rg:cl_deactivate_fs(.160)[fs_umount+58] umount /var/mqm/RGmount
umount: error unmounting /dev/RG_LV: Device busy
+app_rg:cl_deactivate_fs(2.160)[fs_umount+66] : At this point, unmount of /var/mqm/RGmount has not worked. So,
+app_rg:cl_deactivate_fs(2.160)[fs_umount+67] : Send a SIGKILL to all processes having open file
+app_rg:cl_deactivate_fs(2.160)[fs_umount+68] : descriptors within this logical volume to allow
+app_rg:cl_deactivate_fs(2.160)[fs_umount+69] : the umount to succeed.
+app_rg:cl_deactivate_fs(2.160)[fs_umount+71] date '+%h %d %H:%M:%S.000'
Nov 03 19:38:46.000
+app_rg:cl_deactivate_fs(2.160)[fs_umount+72] fuser -k -u -x /dev/RG_LV
/dev/RG_LV:   782460(wasRGuser)  782460(wasRGuser)  868596(wasRGuser)  868596(wasRGuser)  938078(wasRGuser)  938078(wasRGuser) 1081448(wasRGuser) 1081448(wasRGuser)
+app_rg:cl_deactivate_fs(2.740)[fs_umount+73] fuser -c -k -u -x /var/mqm/RGmount
/var/mqm/RGmount:
+app_rg:cl_deactivate_fs(3.260)[fs_umount+74] date '+%h %d %H:%M:%S.000'
Nov 03 19:38:47.000
+app_rg:cl_deactivate_fs(3.260)[fs_umount+77] : Wait 2 seconds for the kills to be effective
+app_rg:cl_deactivate_fs(3.260)[fs_umount+79] sleep 2
+app_rg:cl_deactivate_fs(5.260)[fs_umount+82] : Unmount of /var/mqm/RGmount failed. If the force option can be used, try it here.
+app_rg:cl_deactivate_fs(5.260)[fs_umount+84] [[ -n '' ]]
+app_rg:cl_deactivate_fs(5.260)[fs_umount+99] (( 0 == 57 ))
+app_rg:cl_deactivate_fs(5.260)[fs_umount+123] (( 0 == 60 ))
+app_rg:cl_deactivate_fs(5.260)[fs_umount+52] ((count++ ))
+app_rg:cl_deactivate_fs(5.260)[fs_umount+52] (( count <= 60))
+app_rg:cl_deactivate_fs(5.260)[fs_umount+55] : Try to unmount the file system
+app_rg:cl_deactivate_fs(5.270)[fs_umount+56] date '+%h %d %H:%M:%S.000'
+app_rg:cl_deactivate_fs(5.270)[fs_umount+56] : Attempt 2 of 61 to unmount at Nov 03 19:38:49.000
+app_rg:cl_deactivate_fs(5.270)[fs_umount+58] umount /var/mqm/RGmount
umount: error unmounting /dev/RG_LV: Device busy.
Ez a fázis már az application stop után van, ergo a HACMP joggal van felháborodva, hogy miért nem szabad már a device, ha ő azt át akarja adni a másik node-na.. Sebaj, 5.3 óta fel van készítve a HA erre is, gyenge fuser -kux az LV-re megoldja.. fuser -ckux után látszik, hogy tényleg nem maradt process ami használná az FS-t, úgy hogy semmi gáz, mehet az umount..
De álj.. Megint device busy?? Na innen indul a vicces rész.. Főleg amikor az ember eljut a logban eddig:
+app_rg:cl_deactivate_fs(194.630)[fs_umount+56] : Attempt 61 of 61 to unmount at Nov 03 19:41:58.000
+app_rg:cl_deactivate_fs(194.630)[fs_umount+58] umount /var/mqm/RGmount
umount: error unmounting /dev/RG_LV: Device busy
+app_rg:cl_deactivate_fs(194.760)[fs_umount+66] : At this point, unmount of /var/mqm/RGmount has not worked. So,
+app_rg:cl_deactivate_fs(194.760)[fs_umount+67] : Send a SIGKILL to all processes having open file
+app_rg:cl_deactivate_fs(194.760)[fs_umount+68] : descriptors within this logical volume to allow
+app_rg:cl_deactivate_fs(194.760)[fs_umount+69] : the umount to succeed.
+app_rg:cl_deactivate_fs(194.760)[fs_umount+71] date '+%h %d %H:%M:%S.000'
Nov 03 19:41:58.000
+app_rg:cl_deactivate_fs(194.770)[fs_umount+72] fuser -k -u -x /dev/RG_LV
/dev/RG_LV:
+app_rg:cl_deactivate_fs(195.300)[fs_umount+73] fuser -c -k -u -x /var/mqm/RGmount
/var/mqm/RGmount:
+app_rg:cl_deactivate_fs(195.810)[fs_umount+74] date '+%h %d %H:%M:%S.000'
Nov 03 19:41:59.000
+app_rg:cl_deactivate_fs(195.810)[fs_umount+77] : Wait 2 seconds for the kills to be effective
+app_rg:cl_deactivate_fs(195.810)[fs_umount+79] sleep 2
+app_rg:cl_deactivate_fs(197.810)[fs_umount+82] : Unmount of /var/mqm/RGmount failed. If the force option can be used, try it here.
+app_rg:cl_deactivate_fs(197.810)[fs_umount+84] [[ -n '' ]]
+app_rg:cl_deactivate_fs(197.810)[fs_umount+99] (( 60 == 57 ))
+app_rg:cl_deactivate_fs(197.810)[fs_umount+123] (( 60 == 60 ))
+app_rg:cl_deactivate_fs(197.810)[fs_umount+126] : Out of retries to unmount /var/mqm/RGmount. Game over, man, game over.
+app_rg:cl_deactivate_fs(197.810)[fs_umount+128] cl_echo 25 'cl_deactivate_fs: Failed umount of /var/mqm/RGmount.\n' cl_deactivate_fs /var/mqm/RGmount
A "Game over, man, game over" kedves kis üzenet a fejlesztőktől, és meg meg is mosolyogtatna ha nem látnám, hogy szegény HA-m 61x próbálta meg lenyomni a szerencsétlen FS-t de mind végig Device busy-t kapott.

OS oldalról elnézve az FS valóban ott van a mount alatt, és ha én akarom leszedni akkor ugyan azt kapom:
server@root:/ # mount |grep RGmount
         /dev/RG_LV     /var/mqm/RGmount   jfs2   Nov 03 19:22 rw,log=INLINE
server@root:/ # fuser -cux /dev/RG_LV
server@root:/ # umount /var/mqm/RGmount
umount: 0506-349 Cannot unmount /dev/RG_LV: The requested resource is busy.
Na akkor áljunk meg itt picit.. Mi az amit érdemes megnézni ilyenkor?
- Használja e valami az FS-t
- Megtettem, nem dobott semmit..
- Haszmálja e az LV-t valami?
- Ez az amit a HACMP is megnézett, és aminek amúgy több értelme is van, mint az FS-t nézni -> van 1-2 olyan parancs ami az LV-ket cseszteti direktben, ergo ha a /dev/LV-re ráengedünk egy fuser-t akkor azokat is meg tudjuk fogni.. A HA 1x ezeket le is gyilkolta, viszont utána már nem talált semmit
- Nincs e submount az adott FS alatt
- Amennyiben egy másik FS van a lemountolandó alá felhúzva, úgy persze, hogy a kernel nem engedi nekünk az umountot (Ilyenkor a submountot kell első körben leszedni). Ezt könnyen ellenőrizhetjük is a mount paranccsal, de itt sajna ez se játszik, mivel nem volt egy submount se
- AIO/CIO használatban van?
- Ezen a rendszeren konkrétan pont egyik sincs, viszont ezek is képesek ilyen szintű lockokat összehozni. Viszont a HA épp ezért is próbálkozik 61x (ami itt közel 3 percig ment is), hogy az ilyen dolgokkal se legyen gáz, ha ne adj isten az AIO/CIO nem volt elég gyors adott pillanatban. Mint látható ez itt szintén nem jött be.
- Named Pipe?
- Egzotikum, viszont nem szabad figyelmen kívül hagyni.. Alapvetően Inter-process communication célokra szolgál olyan esetekben ahol a jogosultság szeparáció nem teszi lehetővé a normális IPC kommunikációt direkt memórián keresztül (Hozzáteszem, hogy ez inkább a régebbi appoknál bevett eljárá. Az AIX jó ideje tud direktben memóriában adatot átadni különböző jogosultsági szinteken futó alkalmazásoknak Shared Memory-n keresztül (szintén az IPC része). Ilyen esetekben az applikáció képes egy ilyen "pipe" file-t létrehozni, és sima chmod-os/ACL-es megoldással másik user alatt futó applikációnak átadni az adatot direktben. A probléma ezekkel viszont annyi, hogy nincs tényleges file írás/olvasás, mivel az egész hóbelebancot az AIX memórián belül képes lezongorázni, így meg a fuser se veszi észre, hogy a háttérben szopatják a népet, mivel az fopen/fwrite/fclose és hasonló eventekre figyel főként.

Persze kérdés, hogy hogy járunk ezeknek utána.
- Egyik módszer a http://p1ngw1n.blogspot.hu/2012/02/fuser-nemileg-maskent.html-ban felvázolt módszer
- Másik meg az lsof :)

Mivel az első módszert anno már lefedtem, így maradjunk az egyszerűbbnél, és nézzük, hogy az lsof-el mit is látunk ilyenkor :)
server@root:/ # lsof |grep /var/mqm/RGmount
runmqlsr_  933958 wasRGuser    6u  unix              35,13                0t0 5255524237690535936 /var/mqm/RGmount/qmgrs/APILOT!PRT!QMGR/@qmpersist/spipe/ccc.933958
runmqlsr_  933958 wasRGuser    9u  unix 0xf100020000837c08             0t1728                     /var/mqm/RGmount/qmgrs/APILOT!PRT!QMGR/@qmpersist/spipe/pmpipe
runmqlsr_  933958 wasRGuser   12u  unix 0xf100020000736408             0t1852                     /var/mqm/RGmount/qmgrs/APILOT!PRT!QMGR/@qmpersist/spipe/pmpipe
amqzmgr0  1093830 wasRGuser    8u  unix              35,13                0t0 5255524237690535936 /var/mqm/RGmount/qmgrs/MQRG/@qmpersist/spipe/pmpipe
amqzmgr0  1200368 wasRGuser    8u  unix              35,13                0t0 5255524237690535936 /var/mqm/RGmount/qmgrs/APILOT!PRT!QMGR/@qmpersist/spipe/pmpipe
runmqlsr_ 1605678 wasRGuser    6u  unix              35,13                0t0 5255524237690535936 /var/mqm/RGmount/qmgrs/MQRG/@qmpersist/spipe/ccc.1605678
runmqlsr_ 1605678 wasRGuser    9u  unix 0xf100020002275408             0t1728                     /var/mqm/RGmount/qmgrs/MQRG/@qmpersist/spipe/pmpipe
runmqlsr_ 1605678 wasRGuser   12u  unix 0xf100020001ee7808             0t1852                     /var/mqm/RGmount/qmgrs/MQRG/@qmpersist/spipe/pmpipe

BINGO.. Innen már akkor csak akkor gyilkolásznunk kell :)
server@root:/ # kill -9 933958 1093830 1200368 1605678
server@root:/ # umount /var/mqm/RGmount
server@root:/ #
Innen pedig tovább lehet akkor lökni a HA-t is a túloldalra

A történet tanulsága:
- lusta embereknek kötelező az lsof (az experteknek meg a kdb :))
- A HACMP (attól függetlenül, hogy az idők során szinte mindenre próbálták felkészíteni) se tud mindent lekezelni
- A fejlesztőknek is van humora :)
- Murphy lehet, hogy köcsög mindig, de valahogy még is az ilyen szívásokkal tanulja meg az ember, hogy mennyire is halandó, és lényegében így tanulja csak meg azokat a leckéket, amikre más nem lenne képes megtanítani (se iskola, se oktatás, se certifikációk)

2012. február 14., kedd

fuser - némileg másként

A múltkor blogbejegyzés után kedvet kaptam némi kis turkászásban a kernel térben, úgy hogy íme egy újabb szösszenet arról, hogy a rendszernek mit is kell csinálnia amikor mi csak úgy dobálózunk a parancsokkal :)

Na szóval.. A mostani alkalomra a fuser nevű parancsot néztem ki magamnak.. Sokat nem kell róla mondani: Általános ismérve, hogy ha egy FS nyitva van, akkor ezt szoktuk meghívni, hogy megnézzük mi is fogja. Nézzük, hogy ezt a funkciót a kernel térből hogy is lehetne elérni:

Első körben kell nekünk egy mount point.. Az én esetemben ez a /opt/IBM lesz, mert miért ne :)

Első körben a kontroll teszt: Nézzük, hogy a rendszer mit is tud róla:
test_server@root:/ # fuser -cux /opt/IBM
/opt/IBM:  1130574c(root) 1253494c(root)
Szupi.. Na akkor nézzük ugyan ezt a kernel térben. A módszer az alábbi dióhéjban:
- Meg kell keresni az adott mount point memória pointerjét
- Ezt a pointert használva megnézni az elérhető I-node bejegyzések pointereit, majd leválogatni amire van bármiféle hivatkozás
- A leválogatott hivatkozásokat alapul véve meg kell nézni, hogy melyiknek mi a Gnode (generic node structure) szegmense
- Ezen segmensekből már le tudjuk válogatni, hogy melyiknek milyen thread a szülője, amiből meg direkt megtalálhatjuk a thread-hez rendelt PID-et.

A valóságban:
Első körben ugye a mount-hoz tartozó cím kell. Annyi probléma van, hogy a mount-ot kikérve ilyen összevisszaságot kapunk:
(0)> mount
                           GFS             DATA TYPE    FLAGS
  1 F10001001D6868B0 014D4D60 F1000100206D2080 JFS2    DEVMOUNT
... /dev/hd4 mounted over /
  2 F10001001D686950 014D4D60 F1000100206A4480 JFS2    DEVMOUNT
... /dev/hd2 mounted over /usr
  3 F10001001D6869F0 014D4D60 F1000100206FB080 JFS2    DEVMOUNT
... /dev/hd9var mounted over /var
  4 F10001001D686810 014D4D60 F1000100206FC880 JFS2    DEVMOUNT
... /dev/hd3 mounted over /tmp
És így tovább.. Ez persze felvet 2 gondot:
- Komolyan végig kell mindent böngésszek, úgy hogy közben kifolyik a szemem?
- Miért nem lehet ezt 1 sorban kirakni, hogy legalább greppelni lehessen rá?

Persze azért annyira mégse rossz a helyzet, csak kicsit bűvészkedni kell az awk-al, és nyomban meglesz az ami nekünk kell:
(0)> mount |awk '{a[NR]=$0} /\/opt\/IBM$/ {print a[NR],a[NR-1]}'
... /dev/IBMlv mounted over /opt/IBM  14 F100010020684550 014D4D60 F1000100226C2C80 JFS2    DEVMOUNT

Ugye hogy így szebb.. Na szóval megvan a pointerünk (F100010020684550). Akkor kérjük le milyen i-node bejegyzések vannak alatta:
(0)> mount F100010020684550 |grep -E "DIR|REG|SOCK" |tail -5
 648 F1000100241643E8     0 F1000100241640B0 F100010020684550 DIR
 649 F1000100240E03E8     0 F1000100240E00B0 F100010020684550 DIR
 650 F100010024092FE8     1 F100010024092CB0 F100010020684550 REG
 651 F10001002411B7E8     2 F10001002411B4B0 F100010020684550 DIR
 652 F1000100226D2FE8     1 F1000100226D2CB0 F100010020684550 DIR  ROOT
Na itt egy újabb probléma.. Mi ez a sok szám, és mit jelentenek? Nos A válasz a következő:
- Az első és második oszlop lényegében ugyan azt takarja. Az első az index-szám, a második pedig a VFS_VNODE pointer.
- A 3. szám egy úgy nevezett counter. Ez mutatja, hogy hány kernel thread használja éppen az adott VFS_VNODE-ot.
- A 4. lesz a VFS_VNODE-hoz tartozó GNODE.
- Az 5.-et most bocs de kihagyom, mert érdektelen jelen szempontból

Ami nekünk ezek közül kell, az azok a GNODE regiszterek, amelyeknek COUNT-ja nagyobb mint 0. Ezt kb az alábbi scriptelési módszerrel tudjuk előhozni:
(0)> mount F100010020684550|grep -E "DIR|REG|SOCK" |awk ' { if ($3 != "0") print }'
 154 F100010036F6A3E8     1 F100010036F6A0B0 F100010020684550 REG
 157 F100010036F3A3E8     1 F100010036F3A0B0 F100010020684550 REG
 160 F100010036F99FE8     1 F100010036F99CB0 F100010020684550 REG
 163 F100010036F69FE8     1 F100010036F69CB0 F100010020684550 REG
 266 F100010036FA6FE8     1 F100010036FA6CB0 F100010020684550 REG
 556 F1000100244D2FE8     1 F1000100244D2CB0 F100010020684550 REG
 557 F1000100243B57E8     1 F1000100243B54B0 F100010020684550 REG
 558 F1000100244CC3E8     1 F1000100244CC0B0 F100010020684550 REG
 559 F1000100244EBBE8     1 F1000100244EB8B0 F100010020684550 REG
 560 F1000100243B0BE8     1 F1000100243B08B0 F100010020684550 REG
 561 F1000100244CB7E8     1 F1000100244CB4B0 F100010020684550 REG
 562 F1000100244A93E8     1 F1000100244A90B0 F100010020684550 REG
 563 F1000100244C8BE8     1 F1000100244C88B0 F100010020684550 REG
 652 F1000100226D2FE8     1 F1000100226D2CB0 F100010020684550 DIR  ROOT

Egy baj van - Ez a lista helyenként iszonyat nagy.. Itt se épp rövid.. A problémám meg az, hogy az itt található GNODE ID-kat kéne mind végigjárjam az alábbi módon:
(0)> gnode F1000100243B08B0 |grep gn_seg
gn_seg........ 00000000000086A6
(0)> scb 2 00000000000086A6 |grep pvproc
pvproc pointer           (pvproc)   : 0000000000000000

(0)> gnode F1000100244C88B0 |grep gn_seg
gn_seg........ 00000000000246AD
(0)> scb 2 00000000000246AD |grep pvproc
pvproc pointer           (pvproc)   : 0000000000000000

(0)> gnode F100010036F99CB0 |grep gn_seg
gn_seg........ 00000000000732D8
(0)> scb 2 00000000000732D8 |grep pvproc
pvproc pointer           (pvproc)   : F100070F00045000
3.-ra csak ráhibáztam az egyikre, de persze ezt így egyesével végigjátszani valami halál.. Mindenesetre ha megvan a pvproc cím, akkor abból már az egyik process-t meg is találhatjuk:
(0)> proc F100070F00045000 |grep ^pvproc
pvproc+045000  276 java     ACTIVE 011404E 0132076 0000000030588400   0 0013
(0)> hcal 011404E
Value hexa: 0011404E          Value decimal: 1130574
Bingo.. 1130574 az egyik PID amint fentebb is láttunk.. Na de akkor hogy is lehet ezt normálisan végignézni, úgy hogy az összes GNODE ID-t végigjátsszuk? Hát, a szomorú hír, hogy a kdb nem tud belső scriptelést, így a shell-re kell támaszkodjunk, ami meg egy részről iszonyat erőforrás zabáló, más részről meg a sok fork miatt ágyúval verébre módszer is. Annyi segítségünk mondjuk van, hogy a kdbnek van '-script' kapcsolója, ami pont az ilyen munkákat igyekszik megkönnyíteni, de azért ez még mindig kevés az optimális működéshez.
test_server@root:/ # for GN_SEG in $(
>       for GNODE_ID in $(echo mount F100010020684550|kdb -script |grep -E "DIR|REG|SOCK" |awk ' { if ($3 != "0") print }')
>       do
>               echo gnode $GNODE_ID|kdb -script|awk '/gn_seg/ {print $NF}'
>       done)
> do
>       echo scb 2 $GN_SEG |kdb -script|awk '/pvproc/ {print}'
> done|sort -u|grep -v 0000000000000000
pvproc pointer           (pvproc)   : F100070F00045000
pvproc pointer           (pvproc)   : F100070F0004C800
Ebből kiindulva már nem nehéz megtalálni azt amire végső soron pályázunk (viszalépés kdb-be, majd.. )
(0)> proc F100070F00045000 |grep ^pvproc
pvproc+045000  276 java     ACTIVE 011404E 0132076 0000000030588400   0 000E
(0)> hcal 011404E
Value hexa: 0011404E          Value decimal: 1130574

(0)> proc F100070F0004C800 |grep ^pvproc
pvproc+04C800  306 sh       ACTIVE 0132076 0000001 0000000008466400   0 0001
(0)> hcal 0132076
Value hexa: 00132076          Value decimal: 1253494

1130574, 1253494. Amiket fentebb is láttunk.. Sőt, még azt is tudjuk, hogy egy sh, meg egy java processről van szó :)
Ha ne adj isten lusták vagyunk visszamenni a fenti script után a kdb-be, akkor némi kis módosítással nyomban ki is lehet kérni az ID-ket:

test_server@root:/ # MOUNT=$(echo mount |kdb -script|awk '{a[NR]=$0} /\/opt\/IBM$/ {print a[NR-1]}'|awk '{print $2}')
test_server@root:/ # for PVPROC in $(
>       for GN_SEG in $(
>               for GNODE_ID in $(echo "mount $MOUNT" |kdb -script|grep -E "DIR|REG|SOCK" |awk ' { if ($3 != "0") print $4}')
>               do
>                       echo gnode $GNODE_ID|kdb -script|awk '/gn_seg/ {print $NF}'
>               done)
>       do
>               echo scb 2 $GN_SEG |kdb -script|awk '/pvproc/ {print $NF}'
>       done|sort -u|grep -v 0000000000000000)
> do
>       echo proc $PVPROC|kdb -script|grep ^pvproc
> done
pvproc+045000  276 java     ACTIVE 011404E 0132076 0000000030588400   0 0017
pvproc+04C800  306 sh       ACTIVE 0132076 0000001 0000000008466400   0 0001

# Mint fent említettem: A módszer csak azokra a GNODE-okra működik aminek a countere (aktív thread-je) nagyobb mint 0. Ez azért problémás, mert ha egy process használ egy file-t, de az épp nem aktív (írás nélküli file, pl tail esetén), akkor ez a módszer is hibádzik. További probléma, hogy a submount-okat (amik szintén fogják az FS-t umount esetén) szintén nem képes kijelezni, szóval nyugodtan tekintsétek ezt is amolyan érdekességnek, tekintve, hogy mind a fuser, mind az lsof bőven alkalmasabb ezeknek a megkeresésére (általában - volt amikor ez a módszer talált meg nekem egy olyan thread-et, amiről más program sose hallott)

2012. január 31., kedd

Adott program által nyitott port (nem épp hagyományos módszerrel :))

Nemrég szegeztek nekem egy érdekes kérdést az AIX működésével kapcsolatban, ténylegesen, hogy hogyan lehet megtudni, hogy egy program milyen TCP portot tart nyitva.
Persze mondhatnánk, hogy a standard módszer a válasz a kérdésre, miszerint:

- Megnézzük, hogy az adott portot melyik socket címen lehet elérni:
testsystem:root # netstat -Aan |grep LISTEN |grep "\*\.22"
f1000200032b7b98 tcp4       0      0  *.22               *.*                LISTEN
- Majd a socketra ráengedve egy rmsock-ot nyomban meg is tudjuk az eredményt..
testsystem:root # rmsock f1000200032b7b98 tcpcb
The socket 0x32b7808 is being held by proccess 1290348 (sshd).
- Azaz, hogy jelen esetben az sshd fogja a 22es portot.
testsystem:root # ps -fp 1290348
     UID     PID    PPID   C    STIME    TTY  TIME CMD
    root 1290348  475196   0 03:32:57      -  0:00 /usr/sbin/sshd
Na de, itt nem errol volt szó!

A probléma ugyan is az, hogy mi azt szeretnénk tudni, hogy egy program milyen TCP portot fog, nem pedig, hogy egy elérhető portot mely alkalmazás tart nyitva. Ez persze megfordítja az egész kérdést, és a netstat-os lehetőséget is totál megtorpedózza.

Persze mondhatnánk, hogy ott az lsof, az tudja e, de tételezzük fel, hogy nem rendelkezünk ilyen eszközzel, hanem csak az alap AIX-hez adott base toolokkal.. Ez esetben ki mihez nyúlna??

Nos.. Én úgy gondoltam, hogy ha lúd, legalább legyen kövér: Menjünk le kernel szintre, és túrjunk benne könyékig amennyire csak lehet. Nézzük, hogy ez mit is eredményezett esetemben:

Első körben ugye indítsuk el a kdb-t, majd ha már bent vagyunk kapcsoljuk ki a Symbolic name Translation-t, mert engem személy szerint zavarni szokott amikor nem a teljes címet írja ki a kdb, hanem csak egy részét (pvthread+??????)
testsystem:root # kdb
(0)> ns
Symbolic name translation off
Ez után térjünk a lényegre.. Azt ugye tudjuk, hogy most az SSH programról beszélünk, aminek meg mint fentebb láthattuk a PID-je 1290348. Nézzük ez milyen címen tanyázik épp:
(0)> tpid -d 1290348|grep "0  $"
                SLOT NAME     STATE    TID PRI   RQ CPUID  CL  WCHAN
F100070F10023A00  570*sshd     SLEEP 23A099 03C    1         0
Oks.. Akkor ez is megvan . Menjünk tovább.. Tudni kéne, hogy az adott process milyen descriptorokat tart nyitva.. Ezt viszonylag könnyen megnézhetjük a user (u) paranccsal:
(0)> u -f F100070F10023A00 |grep -w fd
   fd      0 fp..F1000714500DAE58 count..00000000 flags. ALLOCATED
   fd      1 fp..F1000714500293E0 count..00000000 flags. ALLOCATED
   fd      2 fp..F1000714503CFE60 count..00000000 flags. ALLOCATED
   fd      3 fp..F100071450926220 count..00000001 flags. ALLOCATED
Ezek közül az egyik címen egy socket referenciának kell lennie, amennyiben az adott program valóban nyitott portot.. Sajna nem tudhatjuk pontosan melyik az, így muszáj ezen végigmennünk egyesével.. Mázlimra csak 4 van, így ez nem olyan nagy probléma..
(0)> file F1000714500DAE58 |grep -w ^SOCKET
(0)> file F1000714500293E0 |grep -w ^SOCKET
(0)> file F1000714503CFE60 |grep -w ^SOCKET
(0)> file F100071450926220 |grep -w ^SOCKET
SOCKET......... F1000200032B7808
BINGO.. Nézzük mit találtunk.. Első körben menjünk biztosra, és ellenőrizzük vissza, hogy a socket melyik process-hoz van rendelve
(0)> sock F1000200032B7808 |grep proc
proc/fd:  315/3
A 3as fd az még fentebbről ismerős lehet, de hogy kerül ide a 315? Egyszerűen úgy, hogy a socketet nyitáshoz is kell egy thread, ergo valószínű, hogy a 315ös SLOT alatt az ssh-nak egy subthread-je kell legyen. Tehát nézzük meg azt a subthread-et
(0)> th F100070F10023A00 |grep -w pvprocp |grep ">$"
DATA...........pvprocp :F100070F0004EC00 <F100070F0004EC00>
És ez alatt vajon milyen SLOT ID lapul?
(0)> proc F100070F0004EC00
             SLOT NAME     STATE      PID    PPID          ADSPACE  CL #THS
F100070F0004EC00  315*sshd     ACTIVE 013B06C 007403C 0000000041E95400   0 0001
315. BINGO.. Tehát akkor jó irányba haladtunk.. Akkor irány tova..

Tehát tudjuk, hogy a socketünk a F1000200032B7808 címen foglal helyet. Nézzük, hogy ez alá milyen pcb címet rendelt a rendszer:
(0)> sock F1000200032B7808 |grep -w pcb
    pcb.....@F1000200032B7A90  proto...@0000000004444880
Stimt.. Akkor még az is kell, hogy ez alatt a milyen PPCB cím van:
(0)>  tcb F1000200032B7A90 |grep ppcb
    ppcb........@F1000200032B7B98  route_6.....@F1000200032B7AE8
32B7B98.. Nem jött ez már szembe velünk valahol??? Ááá.. megvan.. az rmsock-nál! Dehogynem.. Tehát megvan a socket amit ténylegesen kerestünk.. Lehet tippelni milyen porton figyel :)
(0)> si F1000200032B7B98 tcpcb |grep lport
    oflowinfo... 00000000 lport....... 00000016 latype...... 00000000
(0)> hcal 16
Value hexa: 00000016          Value decimal: 22
16(hex) == 22(dec). Tehát a 22es porton.. Pontosan ez kellett nekünk!

Ha ezek után se hisszük, hogy jó socketre leltünk, akkor könnyű szerrel visszaellenőrizhetjük ezt is:
(0)> si F1000200032B7B98 tcpcb |grep socket
   laddr_6.....@F1000200032B7AC8  socket......@F1000200032B7808
F1000200032B7808.. Ez stimmel.. Tehát jól csináltunk mindent :))

Persze mondanom se kell, hogy ezt persze le lehet scriptelni, csak kérdés, hogy megéri e :) Az tény, hogy ha nincs a kezünk ügyében semmi használható eszköz, akkor használható ez is, de elég durva turkálást kell elkövetnünk, hogy ezt megtudjuk.. Arról nem is szólva, hogy ehhez eléggé mély szintre kell lemennünk, és a sok hülye számtól az ember szeme könnyen golyózni kezd :)