2013. március 3., vasárnap

"Mondanám hogy szőke, de sötét mint az éjszaka"

Azt hiszem írtam már ezen a blogon párszor, hogy az ember egy idő tán meglehetősen magasra emeli a mércét ha arról van szó, hogy min is lepődik meg X évnyi pályafutás után de sose mondja senki, hogy még ilyenkor se tudja kiverni semmi a biztosítékot.. Avagy amikor az ember azt hinné, hogy mélyebbre már nem lehet süllyedni, de valaki még is megtalálja a Mariana-árok mélyén a dugót, kihúzza azt, és a lezúduló víztömeg őt is magával ragadja..

Azok a pillanatok amikor az emberi hülyeség extra adag szorgalommal párosul.
Na ez is egy ilyen volt..

A történet ott kezdődik, hogy a /app_fs filerendszer elérhetetlenné vált a rendszeren, és valaki meg (hogy hogy nem) szerette volna viszont látni. Az ember ilyenkor megnézi az alap dolgokat (nincs e overmount, elérhető e a VG egyáltalán, mountolva van e az FS), majd konstatálja, hogy valami tényleg nem kerek:
server1:root:[/] # mount |grep -c /app_fs
0
server1:root:[/] # lsvg -l appvg |grep applv       
applv              jfs2       320     320     1    closed/syncd  /app_fs
server1:root:[/] # lslv -l applv
applv:/app_fs
PV                COPIES        IN BAND       DISTRIBUTION  
hdisk7            320:000:000   27%           000:089:089:089:053 
server1:root:[/] # lsvg -p appvg
appvg:
PV_NAME           PV STATE          TOTAL PPs   FREE PPs    FREE DISTRIBUTION
hdisk2            active            319         0           00..00..00..00..00
hdisk3            active            1599        0           00..00..00..00..00
hdisk4            active            799         0           00..00..00..00..00
hdisk5            active            959         0           00..00..00..00..00
hdisk6            active            319         32          00..00..00..00..32
hdisk7            missing           447         127         90..00..00..00..37
Őő... Jaj... Na szóval.. Van az FS, ami épp closed-ban van (ez meg is magyarázza hova tűnt a filerendszer :)), ami épp a hdisk7en terül el, ami meg kopp hiányzik az lsvg szerint.. AIX mit tud minderről?
server1:root:[/] # lsdev -Cc disk
hdisk0 Available  Virtual SCSI Disk Drive
hdisk1 Available  Virtual SCSI Disk Drive
hdisk2 Available  Virtual SCSI Disk Drive
hdisk3 Available  Virtual SCSI Disk Drive
hdisk4 Available  Virtual SCSI Disk Drive
hdisk5 Available  Virtual SCSI Disk Drive
hdisk6 Available  Virtual SCSI Disk Drive
hdisk7 Available  Virtual SCSI Disk Drive

server1:root:[/] # lspv |grep appvg
hdisk5          00c3b9f4e1709f60                    appvg           active
hdisk2          00c5effd70395ab2                    appvg           active
hdisk3          00c5effd7c2e18d2                    appvg           active
hdisk4          00c3b9f4aeed3ccd                    appvg           active
hdisk7          00c3b9f4b2a59c9b                    appvg           active
hdisk6          00c3b9f47a309de6                    appvg           active
Él és virul, minden szép, akkor meg mi a fene? Olvassunk már rá a VGDA-ra...
server1:root:[/] # for i in $(lsvg -p appvg |awk '/hdisk/{print $1}');do echo "$i \c";readvgda /dev/$i|grep vg_id;done    
hdisk2 vg_id:           00c5effd00004c000000010da807da15
hdisk3 vg_id:           00c5effd00004c000000010da807da15
hdisk4 vg_id:           00c5effd00004c000000010da807da15
hdisk5 vg_id:           00c5effd00004c000000010da807da15
hdisk6 vg_id:           00c5effd00004c000000010da807da15
hdisk7 vg_id:           00c5effd00004c0000000110796187ae
őőő.. What?? Na szóval.. van egy PV, elérhető, elvileg része a VG-nek, gyakorlatilag meg nem (más a vg_id)... Kis gondolkodás hogy is lehet ez, majd szembejött a megvilágosodás hangos kürt szóval: Ezt a PV-t valaki más is használatba vette!

Tekintve, hogy Virtual diszk, így spuri a VIO-hoz, majd gyors lekérdezések után elő is jött a bűnös probléma:
padmin:vios:[/home/padmin] $ lsmap -all |grep -p hdisk108
VTD                   server2_hdisk4
Status                Available
LUN                   0x8700000000000000
Backing device        hdisk108
Physloc               U7311.D20.0637FDC-P1-C02-T1-W5005076801302EA8-L19000000000000

VTD                   server1_hdisk7
Status                Available
LUN                   0x8400000000000000
Backing device        hdisk108
Physloc               U7311.D20.0637FDC-P1-C02-T1-W5005076801302EA8-L19000000000000
És valóban.. És akkor mit csinál a másik gépen a PV?
server2:root:[/] # lspv
hdisk0          00c3b9f42b11232e                    rootvg          active 
hdisk1          00c3b9f4724a36f5                    rootvg          active 
hdisk2          00c5effd70926735                    dbvg        active 
hdisk3          00c3b9f418b7da43                    dbvg        active 
hdisk4          00c3b9f4b2a59c9b                    dbvg        active 
hdisk5          00c3b9f47715582b                    dbvg        active 
Na most alapjáraton ilyenkor jut eszembe tanult kollégám szava járása miszerint: "Some people just need a hug... around their neck... with a rope."

Egy óriási mázlink volt csak.. Ez:
server2:root:[/] # lspv -l hdisk4
server2:root:[/] # 
Tehát.. Ott a másik szerver, valaki idióta kiassignolta ugyan azt a LUN-t neki, majd berakta egy másik VG-be, ami felül is vágta a VGDA-t, de mákunkra nem használja ezen felül semmire, így a PV-n lévő adat a VGDA-t leszámítva sértetlen.

# Azt azért jegyezzük meg, hogy valaminek az ilyen nagyságrendű elcseszése is igen nagy erőfeszítésbe telik, ugyan is mind a VIO szerver, mind az AIX közli, hogy "Ez mintha már használatban lenne, úgy hogy ha biztos vagy a dolgodban, akkor a -force-ot add még meg a parancshoz" ergo 2x is szorgalmas hülyének kell lennie valakinek, hogy ezt összehozza..

Na jó.. akkor a kérdés már csak az, hogy hogy is varázsoljuk vissza a PV-t a helyére..
A hivatalos megoldás kb annyi, hogy "Reméljük van backupod az FS-ről, mert az FS-t/LV-t törölni kell, kiszedni a PV-t mind a 2 VG-ből (a 2. szerveren menni fog, az eredetin csak félig), szedd le a VIO-ról a LUN zónázást, majd aztán extendvg-vel rakd vissza a PV-t az eredeti VG-be, hozd létre a filerendszert, aztán backupból töltsd vissza az adatokat".

Na ez pont az amit nem akarunk :) (Meg ez a blog bejegyzés se született volna akkor meg).. A mi célunk, hogy az adatokat élve visszaszerezzük. A hogyan már jobb kérdés. Ami tiszta az az, hogy az új VG-ben nem maradhat a PV, úgy hogy onnan szedjük ki, aztán meg a VIO-ról szedjük le a LUN allokációt, hogy csak a source szerveren legyen a PV elérhető.

A következő "elméleti" lépés pedig az lenne, hogy rakjuk vissza a VGDA-t az érintett PV alá..
Ennek kivitelezése némi kis elméleti háttérismeretet igényel:
- AIX alatt minden VG felépítése azonos (az elmélet legalább is, a kivitelezésben vannak némi eltérések)
- Minden VG-ben lévő PV tartalmazza a VGDA-t (A PV elején), amely leírja, hogy a VG alatt pontosan milyen PVID-jű diszkek találhatók, azokon belül melyik PV-n milyen LV-k (és milyen kiosztásban) helyezkednek el, van e LV tükrözés (mirroring), és hasonló úri huncutságok.
- Ergo a dolog szépsége, hogy mindenki tud többé kevésbé mindenkiről mindent, 1-2 dolgot leszámítva, és csak 1-2 alapvető dolog különbözik

# Megjegyzem azért, hogy van a VGDA-ban 1-2 olyan adat is, ami meglehetősen szemétnek minősül és PV-nként eltérhet, de azokkal most nem fogok foglalkozni
Na szóval a feladat a következő: Fogjunk a VG-ből egy egészséges diszket, pakoljuk át a VGDA-ját a hibás PV-re, írjuk át azt ami PV specifikus, aztán imádkozzunk, hogy minden menni fog

!!! Had ne mondjam, hogy ez a módszer véletlenül és semmilyen körülmény között sem támogatott hivatalosan, így ha valakinek van IBM-es szerződése az inkább nyisson PMR-t ha tényleg fontos adatról van szó!!!

Akkor kezdjük az első lépést.. VGDA átmásolás.. Hogy ezt meg tudjuk csinálni 1x is tudnunk kell a VGDA méretét, ez viszont VG típusonként más, úgy hogy tudni kell a VG típusát is :) Ehhez kell egy VG-n belüli PV, amin még minden rendben van, legyen ez mondjuk a hdisk2 (mert csak, amúgy bármelyik másik jó lenne)
server1:root:[/] # readvgda /dev/hdisk2 |grep type
.....    readvgda_type: smallvg
vgtype:         0

# Némi kis segítség a VGDA méretének megállapításában:
# Small VG: 17x 128K
# Big VG: 71x 128K
# Scalable: 548x 128K

Jó.. Most hogy tudjuk mi és merre csináljunk egy backupot a jelenlegi VGDA-ról (igen, amit előzőleg nulláztunk, de akkor is legyen lehetőség visszaállítani ami volt), aztán vágjuk is felül :)
server1:root:[/] # dd if=/dev/hdisk7 of=/tmp/hdisk7.smallvg.vgda.save bs=128K count=17
17+0 records in
17+0 records out
server1:root:[/] # dd if=/dev/hdisk2 of=/dev/hdisk7 bs=128K count=17
17+0 records in
17+0 records out
A következő egyedi azonosító a PV ID-ja lenne (nem összekeverendő a PVID-val), ami megmondja, hogy az adott diszk hányadik is a VG-n belül. Ehhez első körben meg kell keresni, hogy az adott adat hol is tárolódik (VG-nként máshol, de mindig az LVM leíró környékén). Én általában az első 1000 szektorcsoportot keresem végig:
server1:root:[/] # lquerypv -h /dev/hdisk2 0 1000 |grep LVM
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
Szupi.. Tehát 0E00 körül keződidik az LVM leíró része.
Akkor most nézzük meg mi van azon a környéken:
server1:root:[/] # lquerypv -h /dev/hdisk2 e00 40
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 013FFEFF 00000100 00010019  |.....?..........|  
00000E30   00000008 00000080 000008BA 001E0000  |................|
Na most ebből lehet nem sok derül ki annak aki nem tudja mit keressen, de ha összenézzük ugyan ezt a többi diszk VGDA-jával, akkor remélhetőleg már könyebben rájön mindenki hol is van a kutya elásva:
server1:root:[/] # for i in $(lsvg -p appvg |grep -v hdisk7 |awk '/hdisk/{print $1}');do echo $i;lquerypv -h /dev/$i e00 40;done
hdisk2
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 013FFEFF 00000100 00010019  |.....?..........|  <= '0001' a 0x0E2C címnél
00000E30   00000008 00000080 000008BA 001E0000  |................|
hdisk3
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 063FFEFF 00000100 00020019  |.....?..........|  <= '0002' a 0x0E2C címnél
00000E30   00000008 00000080 000008BA 001E0000  |................|
hdisk4
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 031FFEFF 00000100 00030019  |................|  <= '0003' a 0x0E2C címnél
00000E30   00000008 00000080 000008BA 001E0000  |................|
hdisk5
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 03BFFEFF 00000100 00040019  |................|  <= '0004' a 0x0E2C címnél
00000E30   00000008 00000080 000008BA 001E0000  |................|
hdisk6
00000E00   5F4C564D 00C5EFFD 00004C00 0000010D  |_LVM......L.....|
00000E10   A807DA15 00001074 00000832 00000088  |.......t...2....|
00000E20   000008C2 013FFEFF 00000100 00050019  |.....?..........|  <= '0005' a 0x0E2C címnél
00000E30   00000008 00000080 000008BA 001E0000  |................|
Ha megfigyelitek, akkor az VGDA leírók ezen része szinte teljesen egyezik, kivétel a 0x0E2D címen lévő érték, ami szépen növekszik 1től 5ig.. Na most ha még emlékeztek a post elejére, akkor 6 PV volt hivatalosan ebben a VG-ben:
server1:root:[/] # readvgda /dev/hdisk2 |grep pv_id |cat -n
     1  pv_id:          00c5effd7c2e18d2
     2  pv_id:          00c5effd70395ab2
     3  pv_id:          00c3b9f4aeed3ccd
     4  pv_id:          00c3b9f4e1709f60
     5  pv_id:          00c3b9f47a309de6
     6  pv_id:          00c3b9f4b2a59c9b 
Tehát, a PV ID (!=PVID) a hiányzó diszkünknél a 6os lesz, amit vissza is kéne írni a megfelelő pontra.. dd-vel ez megoldható, de ahhoz decimálisan tudnunk kell a pontos poziciót:
server1:root:[/] # echo "ibase=16; E2D" |bc
3629
3629.. Jó. Akkor írjuk is be a helyére a megfelelő értéket:
server1:root:[/] # echo "\06" | dd of=/dev/hdisk7 bs=1 count=1 seek=3629
1+0 records in
1+0 records out
Ez után jön akkor a tényleges PVID. Ha még emlékeztek, akkor erre anno mutattam is egy módszert, amit ismét elő is szedek, és visszaírom az eredetileg a PV-n lévő PVID-t:

A script maga:
server1:root:[/] # cat /tmp/chpvid.sh
#!/usr/bin/ksh
pvid=$1
disk=$2
set -A a `echo $pvid|\
awk ' {
 for (f=1; f <= length($0); f=f+2) {
 print "ibase=16\nobase=8\n"toupper(substr($0,f,2))
 }
}'|\
bc 2>/dev/null`
/usr/bin/echo "\0"${a[0]}"\0"${a[1]}"\0"${a[2]}"\0"${a[3]}"\0"\
${a[4]}"\0"${a[5]}"\0"${a[6]}"\0"${a[7]}"\0\0\0\0\0\0\0\0\c"|\
dd bs=1 seek=128 of=/dev/$disk
A futtatás módja:
server1:root:[/] # sh /tmp/chpvid.sh 00c3b9f4b2a59c9b hdisk7
16+0 records in
16+0 records out
Visszaellenőrzés:
server1:root:[/] # od -A n -j 128 -N 8 -x /dev/hdisk7
         00c3 b9f4 b2a5 9c9b
VGDA ellenőrzés:
server1:root:[/] # for i in $(lsvg -p appvg |awk '/hdisk/{print $1}');do echo "$i \c";readvgda /dev/$i|grep vg_id;done    
hdisk2 vg_id:           00c5effd00004c000000010da807da15
hdisk3 vg_id:           00c5effd00004c000000010da807da15
hdisk4 vg_id:           00c5effd00004c000000010da807da15
hdisk5 vg_id:           00c5effd00004c000000010da807da15
hdisk6 vg_id:           00c5effd00004c000000010da807da15
hdisk7 vg_id:           00c5effd00004c000000010da807da15
Még mielött tényleg bármit is csinálnánk nézzük meg, hogy minden tényleg úgy van ahogy volt:
server1:root:[/] # lsvg -p appvg
appvg:
PV_NAME           PV STATE          TOTAL PPs   FREE PPs    FREE DISTRIBUTION
hdisk2            active            319         0           00..00..00..00..00
hdisk3            active            1599        0           00..00..00..00..00
hdisk4            active            799         0           00..00..00..00..00
hdisk5            active            959         0           00..00..00..00..00
hdisk6            active            319         32          00..00..00..00..32
hdisk7            missing           447         127         90..00..00..00..37
Aztán térdre imára, és varyon-oljuk vissza a VG-t:
server1:root:[/] # varyonvg appvg
server1:root:[/] # lsvg -p appvg
appvg:
PV_NAME           PV STATE          TOTAL PPs   FREE PPs    FREE DISTRIBUTION
hdisk2            active            319         0           00..00..00..00..00
hdisk3            active            1599        0           00..00..00..00..00
hdisk4            active            799         0           00..00..00..00..00
hdisk5            active            959         0           00..00..00..00..00
hdisk6            active            319         32          00..00..00..00..32
hdisk7            active            447         127         90..00..00..00..37

Hoppá... alakul a molekula :) Nézzük mi van szeretett filerendszerünkel:
server1:root:[/] # mount /app_fs
Replaying log for /dev/applv.
mount: /dev/applv on /app_fs_rest: Unformatted or incompatible media
The superblock on /dev/applv is dirty.  Run a full fsck to fix.
Na jó.. ez várható volt.. Adjuk meg amit kér:
server1:root:[/] # fsck /dev/applv
The current volume is: /dev/applv
Primary superblock is valid.
*** Phase 1 - Initial inode scan
*** Phase 2 - Process remaining directories
*** Phase 3 - Process remaining files
*** Phase 4 - Check and repair inode allocation map
*** Phase 5 - Check and repair block allocation map
File system is clean.
Superblock is marked dirty; FIX? y
All observed inconsistencies have been repaired.
Aztán próbáljuk meg újra:
server1:root:[/] # mount /app_fs
server1:root:[/] # 
Profit :))

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)