2011. november 27., vasárnap

Csontváz a szekrényből

Érdekes dolog az amikor az ember olyan régi hibákkal találkozik, amikről azt hitte már rég kihalt.. Így volt ez akkor is, amikor az alábbi problémával sikerült szembesülnöm:

Rutin feladatnak indult, mint megannyi más dolog a munkám során: Egy HACMP cluster alá kell új diszkeket, illetve VG-ket definiálni, a hozzájuk tartozó filerendszerekkel együtt.
A dolog ugye annyira nem is nehéz:
- Adjuk hozzá az új LUN-okat a node-okhoz storage-ról (jelen esetben VIO-ról de részletkérdés)
- Ez után bizonyosodjunk meg róla, hogy minden LUN-nak van saját PVID-ja (enélkül ugyan is a HA nem fog törődni az új diszkekkel)
- Konfigoljuk fel a cluster alatt az új device-okat a "Discover HACMP-related Information from Configured Nodes" parancsal
- Amint megvan hozzunk létre egy új VG-t a HA alatt (Tegyünk egy szivességet magunknak és legyen scalable :))
- Majd alá a szükséges LV-ket
- Illetve az FS-eket is (újabb tipp: INLINE logolás sokat segít)
- Ez után extended verification-el nézzük meg, hogy a cluster konzisztensen lát e mindent

Ez persze mind online megy, és semmiféle outage-el nem jár.. A nagykönyv szerint..
Épp ezért is lepődtem meg, amikor a gépen futó alkalmazások adminjai egyszerre sikítottak fel, hogy mi a fene is történt, mert a gépen futó több adatbázis, és alkalmazás is egyszerre ficcent el..

Az applikációs (DB2) logokból nyomban ki is jön, hogy mi az első nyom amin el tudunk indulni:
FUNCTION: DB2 UDB, oper system services, sqloEDUSIGCHLDHandler, probe:50
DATA #1 : 
An EDU with process id 2121840 was terminated by a SIGKILL signal.
It is not possible to produce a trap file in this case.
SIGKILL.. még jobb.. oks.. akkor nézzük a hacmp.out-ot:
+7101  Reference string: Thu.Nov.17.14:55:10.GMT.2011.cl_deactivate_fs.All_filesystems.app_rg.ref
+7102  app_rg:cl_deactivate_fs[476] [[ false = true ]]
+7103  app_rg:cl_deactivate_fs[482] [ sequential = parallel ]
+7104  app_rg:cl_deactivate_fs[492] [ REAL = EMUL ]
+7105  app_rg:cl_deactivate_fs[497] fs_umount /var/mqm cl_deactivate_fs app_rg_deactivate_fs.tmp
+7106  app_rg:cl_deactivate_fs[4] FS=/var/mqm
+7107  app_rg:cl_deactivate_fs[5] PROGNAME=cl_deactivate_fs
+7108  app_rg:cl_deactivate_fs[6] TMP_FILENAME=app_rg_deactivate_fs.tmp
+7109  app_rg:cl_deactivate_fs[7] STATUS=0
+7110  app_rg:cl_deactivate_fs[10] app_rg:cl_deactivate_fs[10] lsfs -c /var/mqm
+7111  app_rg:cl_deactivate_fs[10] tail -1
+7112  app_rg:cl_deactivate_fs[10] cut -c6-
+7113  app_rg:cl_deactivate_fs[10] cut -d: -f2
+7114  lv=lvmqm
+7115  app_rg:cl_deactivate_fs[12] [ 0 -ne 0 ]
+7116  app_rg:cl_deactivate_fs[23] mount
+7117  app_rg:cl_deactivate_fs[23] fgrep -s -x /dev/lvmqm
+7118  app_rg:cl_deactivate_fs[23] awk { print $1 }
+7119  app_rg:cl_deactivate_fs[25] [ 0 -eq 0 ]
+7120  app_rg:cl_deactivate_fs[38] fuser -k -u -x /dev/lvmqm
+7121  /dev/lvmqm:   397382k(mqm)  438366(mqm)  454864k(mqm)  524364k(mqm)  569576k(mqm)  647266(mqm)  704590(mqm)  860414(mqm)  929994k(mqm)  991310k(mqm) 1122476k(mqm) 1126602k(mqm) 1138738k(mqm) 1232932(mqm) 1314926(mqm) 1335538k(mqm) 1556634k(mqm) 1675270k(mqm) 1708056k(mqm) 1835182(mqm) 1900648(mqm) 1904850k(mqm) 1949698k(mqm) 2465990k(mqm) 3268838k(mqm) 3547274k(mqm)
Na ez meg pláne nem az amire azt szoktam mondani, hogy "vicces".. Jó.. Idegbaj eltesz a sufniba, nézzük tovább mi indította az egészet:
+3123  Nov 17 14:55:05 EVENT START: reconfig_resource_release_primary
+3124
+3125  + [[ high = high ]]
+3126  + version=1.90
+3127  + echo arguments:
+3128  arguments:
+3129  + DCD=/etc/es/objrepos
+3130  + SCD=/usr/es/sbin/cluster/etc/objrepos/stage
+3131  + ACD=/usr/es/sbin/cluster/etc/objrepos/active
+3132  + set -a
+3133  + cllsparam -n node1
+3134  + ODMDIR=/usr/es/sbin/cluster/etc/objrepos/active
+3135  + eval NODE_NAME=node1 VERBOSE_LOGGING=high PS4='${GROUPNAME:-}:${PROGNAME}[$LINENO] ' DEBUG_LEVEL=Standard LC_ALL='C'
+3136  + NODE_NAME=node1 VERBOSE_LOGGING=high PS4=${GROUPNAME:-}:${PROGNAME}[$LINENO]  DEBUG_LEVEL=Standard LC_ALL=C
+3137  :reconfig_resource_release_primary[767] set +a
És ennyi!! Semmi error, semmi fatal exception.. Semmi.. Biztosra mentem, és megnéztem a smit.log-ot is, hogy mi a lóturót művelhettem akkor, hátha tényleg köze is van ennek ahhoz amit csináltam:
+54051  Verification has completed normally.
+54052
+54053  clsnapshot: Creating file /usr/es/sbin/cluster/snapshots/active.0.odm...
+54054
+54055  clsnapshot: Succeeded creating Cluster Snapshot: active.0.
+54056
+54057  cldare: Requesting a refresh of the Cluster Manager...
+54058
+54059  ---- end ----
+54060
+54061  [Nov 17 2011, 14:55:05]
Igen, erre emlékszel.. Itt futtattam a clverify-cationt.. De 2 dolog is nyomban feltűnik:
- A cldare-t refreshelte a verification a legvégén.
- Ennek időpontja 14.55.05 volt, ami pontosan megegyezik a hacmp.out-ban lévő "EVENT START: reconfig_resource_release_primary" esemény időpontjával..

Ergo itt tényleg lehet valami kapcsolat.. Kicsit nézelődve meg is találtam mi az:
IY82802 - https://www-304.ibm.com/support/docview.wss?uid=isg1IY82802

* USERS AFFECTED:
* Users of HACMP R530 with the cluster.es.server.events fileset
* at the 5.3.0.2 or 5.3.0.3 level.

Ez most komoly??
server@root # lslpp -l cluster.es.server.events |grep cluster.es.server.events|sort -u
  cluster.es.server.events   5.3.0.0  COMMITTED  ES Server Events
  cluster.es.server.events   5.3.0.3  COMMITTED  ES Server Events
Jah igen.. komoly..
Összefoglalva: Sikerült belefutnom egy 2007es bug-ba, ami egy egyszerű online művelet során ámokfutásba kezdett, és legyilkolt minden HA alatt futó applikációt. Hogy hogy sikerült egy ekkora bogárnak több mint 4 évig megélnie a rendszeren? Nos.. Így vettük át az előző tulajtól, és marha módon feltételeztük, hogy ő figyelt rá eléggé.. Hiba volt..

For the record:
- Átvett rendszer alatt tessék mindent átnézni (tudom, könnyű mondani), különös tekintettel a hiányzó javításokra (főleg ha azok ilyen kritikusak)
- Ez a bejegyzés azért született, hogy más is tanulhasson belőle. Nem vagyok büszke rá, hogy egy ilyen kritikus "csontvázat" csak akkor sikerült észlelnünk, amikor az már kibújt a szekrényből. Mentegetőzhetnék azzal, hogy a "ha működik ne nyúlj hozzá"
elv érvényesül általában, vagy, hogy "nincs idő a pro-aktivitásra" de mindegyik csak üres kifogás lenne saját magammal szemben is. Legyen ez egy szükséges felhívás mind magam, mind a te (kedves olvasó) részedre, hogy azért fél,1 évente tessék az ilyen dolgokat is átnézni, és igen is kell ezekre is időt találni*

* Megjegyzem, hogy sajna ezzel se leszünk képesek elkerülni a komoly hibákat 100%-ban, viszont a már ismert hibákból adódó lehetséges problémákat legalább ki tudjuk küszöbölni

Nincsenek megjegyzések:

Megjegyzés küldése