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)