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.
