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 :)

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

2011. október 16., vasárnap

Elvitte a cica.. De hova bújt???

Pénteken olyan hibába botlottam bele, hogy azt hittem ilyen nem is létezhet.. Így hát amikor sikerült megtalálnom mi és hogy is történ(hetet)t persze, hogy úgy gondoltam, hogy ezt le kell blogoljam.. Íme egy némileg összeszedett beszámoló arról, hogy mi és hogy történt a probléma felderítése során:

Nos hát.. Alap probléma: Restart után a szerveren nem használható a /dev/null...
Nézek ki a fejemből, hogy ez miért és hogy, de a hibaüzenet egyértelműen fogalmaz:
server@user:/home/user $ ls > /dev/null
Permission denied
ksh: /dev/null: cannot create
Gyorsan átmásztam root-ba, megnéztem mi a helyzet a környéken:
server@root:/home/root # ls -ld /dev/null
crw-rw-rw-    1 root     system        2,  2 Oct 15 16:29 /dev/null
server@root:/home/root # ls -ld /dev
drw-------    5 root     system       356352 Oct 15 15:00 /dev
Aham.. hogy csak a root-nak van valami joga a mappára.. Ki lehetett az a hülye, aki átlőtte??? Na mind1, rakjuk helyére..
server@root:/home/root # chmod 775 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 15 15:00 /dev
Kicsit matattam még a gépen, tettem-vettem, amikor is egy újabb parancs kiadásakor ismét ugyan ebbe a hibába botlottam (Permission denied).. Nézem ismét a /dev jogait.. megint 600... Hát mondom ilyen nincs.. valaki ilyen hülye, és még aktívan a gépen is van? Ha megtalálom nem hogy a root jogot veszem el tőle, hanem még a kezét is letöröm.. Ez a kis "lelkesedés" addig tartott, amíg észre nem vettem, hogy rajtam kívül nincs senki a gépen.. Feltételezve, hogy én nem műveltem ilyen hülyeséget néztem hogy akkor ez most WTF.. Valaki távolról, vagy hogy??? Hát mondom akkor játsszuk ezt..

Visszaállítottam a /dev jogait 775-re, majd kb 5-10 mp-enként visszaellenőriztem 'ls -ld /dev'-el, hogy mi is lehet itt.. Kb ezt kaptam:
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 15:10 /dev
server@root:/home/root # ls -ld /dev
drw-------    5 root     system       356352 Oct 14 15:10 /dev
Hát mondom ilyen nincs.. valaki garázdálkodik itt, vagy mifene?? Hát a jó nénikéjét.. Fogjuk már meg..
Első gondolatom az volt, hogy az audit subsystem tökéletesen megfelel ennek kiderítésére.. De nézzük hogy is lehet ezt kivitelezni?
- /etc/security/audit/objects alá fel lehet ugyan venni a /dev-et, de az objects alatt csak read/write/execute event-eket lehet vizsgálni.. Itt meg látható, hogy az nem segítene, ergo ez nem nyert hangszórót
- Gondoltam, hogy ha valami itt a /dev jogait piszkálja, akkor a chmod-ot kell hívnia kötelezően.. Hát akkor induljunk el ebbe az irányba: Vegyünk fel a chmod parancsot az objects alá az alábbi módon:
/usr/bin/chmod:
 x = "CHMOD_USE"
Illetve a /etc/security/audit/events alá az új eventünket:
* chmod execution
  CHMOD_USE = printf "pid: %d, command: %s"
Amint ezzel kész vagyunk indítsuk újra az audit subsystem-et:
server@root:/ # audit shutdown
auditing reset
server@root:/ # audit start
server@root:/ # audit query |grep auditing
auditing on
server@root:/ # audit query |tail -2
 /usr/bin/chmod:
  x = "CHMOD_USE"
Oksa.. Tehát akkor elvileg ez is a helyén van.. akkor már csak az kell, hogy realtime nézhessük mi is folyik a gépen. Ezt az alábbi módon oldottam meg:
server@root:/ # /usr/sbin/auditstream | /usr/sbin/auditpr -t0 -heRltc |grep CHMOD
Ezzel a paranccsal lényegében direktbe szűrhetek arra, amire szeretnék.. Ergo fogtam magam, nyitottam egy újabb terminált, majd ott követtem a /dev változásait, miközben ez a stream az 'egyes" terminálon szépen futott. Direkt átírtam a chmod jogait ismét 775-re (megint 600on volt), és konstatáltam, hogy az audit igen is látja a módosításom:
CHMOD_USE       OK          root  Fri Oct 14 17:06:52 2011 chmod
Ezt követően csak vártam, és a másodlagos terminálon követtem a /dev esetleges változásait.. Egészen addig amíg a terminálon láttam, hogy a jogok megváltoztak, de az audit ebből semmit nem vett észre... WTF!? Audit stop, mit szúrtam el?? Lehet van máshol is chmod a rendszeren???
server@root:/ # find / -name chmod -type f -ls
 1057    9 -r-xr-xr-x  1 bin       bin           9216 Jul  9  2009 /usr/bin/chmod
Nincs, csak ez az egy.. Akkor meg hogy a fenébe??? Na jó, mind1.. Az auditról tudni illik, hogy azért nem csak az objects file-ja használható, hanem alapértelmezetten az events-ek között jó pár más event is előre van definálva, mint például ezek:
*       chmod()
        FILE_Mode = printf "mode: %o filename %s"

*       fchmod()
        FILE_Fchmod = printf "mode: %o file descriptor %d"
A rendszer alaptelepítés esetén ezeket nem használja (tekintve, hogy iszonyat sok adatot is generálnának), de nekem most ideiglenesen ezek pont jónak tűntek.. Meg is néztem, hogy a configon belül ezek hol vannak definiálva, és a classes alatt gyönyörűen ott sorakozott az alábbi sor:
files = FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create
A FILE_Mode alapból ott volt a files class-ban, viszont a FILE_Fchmod nem, így azt is felvettem (biztosra megyek, úgy voltam vele), így kaptam ezt a sort:
files = FILE_Open,FILE_Read,FILE_Write,FILE_Close,FILE_Link,FILE_Unlink,FILE_Rename,FILE_Owner,FILE_Mode,FILE_Acl,FILE_Privilege,DEV_Create,FILE_Fchmod
Ez után már csak az kellett, hogy ezt a class-t felvegyem a users szekció alatt a root-hoz az alábbi módon:
users:
        root = general,files
        default = objects
Rendicsek.. Akkor ez is megvan.. Biztos ami biztos kiszedtem az objests-ből előzőleg definiált chmod figyelést is, majd újraindítottam az auditot, és eljátszottam pontosan ugyan azt mint előzőleg -> egyik konzolon futott az auditing stream-je (immár grep -E "FILE_Mode|FILE_Fchmod" szűréssel), a másikon meg a /dev vizsgálata. Átállítottam ismét a /dev jogait 775-re (ekkor már kifejezetten idegesített az issue), majd örömmel konstatáltam, hogy az audit észrevette ezt a súlyos cselekményt:
FILE_Mode       OK          root  Fri Oct 14 18:05:25 2011 chmod
Újabb 1-2 percnyi várakozás, és minden elvárás ellenére ugyan az az eredmény!!! -> Az audit nem veszi észre azt ami ezt csinálja, csak azt amit én manuálisan ráengedek.. Ekkor sejtettem, hogy ez valószínű nem valami user hülyesége, hanem lehet valami bug, mert a forkot az audit tuti észrevenné.

Innentől viszont nyilvánvalóvá vált, hogy az audit e célra itt nem fog bejönni.. Kénytelen voltam elővenni a nagyágyút: trace
Szerencsémre a trace azért meglehetősen jól használható AIX alatt, feltéve ha az ember tudja hogy is használja.. Az már csak hab a tortán, hogy van egy csomó előre definiált trace event group, amik közül az alábbiak közül választhattam (A / JFS2 típusú)
server@root:/ # trcrpt -G |grep jfs2
jfs2 - JFS2: all JFS2 operations (reserved)
jfs2meta - JFS2: metadata operations (reserved)
jfs2user - JFS2: userdata operations (reserved)
jfs2snap - JFS2: snapshot operations (reserved)
Megvan azért annak az előnye, ha nem kell az embernek fejből tudnia az összes hookot :)) Ami viszont engem illetett - úgy voltam vele, hogy ennyi szívás után nem szórakozok: minden JFS2 módosításról tudni akarok!!! Ergo fogtam magam, és az alábbi módon jártam el:
server@root:/ # chmod 775 /dev
server@root:/ # ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 15 15:00 /dev
server@root:/ # trace -a -J jfs2 -o /tmp/trc_raw 
server@root:/ # trcon
A másik konzolon meg az alábbi kis while ciklussal vártam, hogy mikor is történik pontosan (!) a váltás:
server@root:/ # while true;do echo "$(date +"%Y.%m.%d %H:%M:%S") $(ls -ld /dev)";sleep 1;done
2011.10.14 18:42:00 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:01 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:02 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:03 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:04 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:05 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:06 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:07 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:08 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:09 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:10 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:11 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:12 drw-------    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:13 drw-------    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:42:14 drw-------    5 root     system       356352 Oct 14 18:30 /dev
Amint erre a pontra jutottam nyomban le is állítottam a trace-t, majd amikor állítottam volna le ezt a while ciklust konstatálhattam, hogy a CTRL+C nem működik!! -> Mint kiderült: Ha belépéskor nincs a /dev-nek elég joga, akkor a CTRL+C nem fog menni, hiába van jól belőve az 'intr' érték az stty alatt:
server@root:/ # stty -a |grep intr
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = 
Amint átállítottam a /dev jogait, és nyitottam egy új shell-t nyomban visszaállt minden a régibe az adott shellen belül.. A másikon meg killelhettem a ciklust.

Na mind1.. Nézzük azt a trace-t
server@root:/ # trcoff
server@root:/ # trcrpt -O "exec=on,pid=on" /tmp/trc_raw > /tmp/trc_raw.out
server@root:/ # ls -l /tmp/trc_raw.out
-rw-------    1 root     system      7213429 Oct 14 18:26 /tmp/trc_raw.out
Kb sejthetitek miért is nem olyan gyakori a trace használata ebből már: kevesebb mint fél perc alatt majd 7 MB adat generálódott a riportban! Na de, ha már megvannak az adatok, akkor igen is nézzük át mi és hogy lehetett.. A probléma csupán az, hogy ~7 MB-ot átnyálazni kicsit sokáig tart, meg jelen esetben amúgy se célravezető.. Jobb volt inkább megnézni, hogy mely processek használták a /dev-et..

Ehhez első körben tudni kell a /dev inode számát, hogy legalább legyen mire szűrnünk:
server@root:/tmp # istat /dev
Inode 12289 on device 10/5      Directory
Protection: rw-------   
Owner: 0(root)          Group: 0(system)
Link count:   5         Length 356352 bytes

Last updated:   Fri Oct 14 18:30:10 2011
Last modified:  Fri Oct 14 18:30:10 2011
Last accessed:  Fri Oct 14 18:30:27 2011
Oks.. Tehát 12289.. Ezt nyomban át is kell váltanunk hexába, ami meg 3001.. Ezt a számot használva meg könnyen szűrhetünk is. Ha viszont csak így magában tesszük, akkor ilyen hosszú rettentő sorokat kapunk:
server@root:/ # grep -w 3001 /tmp/trc_raw.out |head -5
4DF --1-           -1            0.003434251       0.001326                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
4DF --1-           -1            0.003444816       0.005402                   JFS2 iput: vp = F100011010C3B3E8, count = 0000, ino = 3001, nlink = 0005, getcaller = 2CF9DC
4DF --1-           -1            0.003447171       0.000623                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
4DF --1-           -1            0.003452763       0.003297                   JFS2 iput: vp = F100011010C3B3E8, count = 0000, ino = 3001, nlink = 0005, getcaller = 2CF9DC
4DF --1-           -1            0.003455013       0.000683                   JFS2 iget: vp = F100011010C3B3E8, count = 0001, ino = 3001, dev = 8000000A00000005, getcaller = 2CF754
Ergo lehet jobban járunk ha inkább a statisztikára vagyunk kíváncsiak:
server@root:/ #  grep -w 3001 /tmp/trc_raw.out |awk '{print $2}'|sort|uniq -c
   761 --1-
   2 cdromd
   36 init
Mindjárt jobb.. Tehát.. 761 hozzáférés a kernel részéről, 2 hozzáférés a cdromd-től, 36 az inittől.. A kernellel ugye nem sokat tudok kezdeni (az meg csak nem vetemedik ilyenre!), ergo maradt a másik 2 - cdromd, meg init.. Első körben így hát fogtam magam, 'stopsrc -s cdromd'-vel leállítottam a daemon-t, visszalőttem a /dev-et 775-re, majd vártam, hogy változik e a jogosultsága.. Változott.. Ergo akkor nem a cdromd.. Vissza is kapcsoltam.

A másik lehetőség az init volt.. Erről ugye annyit illik tudni, hogy a /etc/inittab file-ban tárolt bejegyzések alapján ténykedik. Amennyiben egy program/script respawn-ra van állítva, akkor az időről időre meg is hívódik, ami meg is magyarázná, hogy hogy lehet az, hogy user interakció nélkül változzon a /dev jogosultsága.. Nade a baj az, hogy az inittab-ban azért csak úgy nem turkálunk, a cdromd-hez hasonló teszteléseket (állítsuk le, aztán nézzük meg jó lesz e úgy) meg itt már nem biztos hogy jó ötletnek tartanám..

Azt viszont tudnunk kell, hogy amennyiben az inittab indít valamit, úgy annak a bejegyzése beleíródik a wtmp-be is.. Én meg az előző mérésemből tudtam a pontos időpontot (18:42:12), így az alapján már könnyen el lehetett indulni:
server@root:/ # cat /var/adm/wtmp |/usr/sbin/acct/fwtmp |grep "Fri Oct 14 18:42:1[012]"
         cons                         8 155664 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 58206 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 58206 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 58208 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 58208 0000 0001 1318614131                                  Fri Oct 14 18:42:11 2011
cons     cons                         5 221186 0000 0000 1318614131                                  Fri Oct 14 18:42:11 2011
         cons                         8 221186 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 57910 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
         cons                         8 57910 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 221188 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
         cons                         8 221188 0000 0001 1318614132                                  Fri Oct 14 18:42:12 2011
cons     cons                         5 221190 0000 0000 1318614132                                  Fri Oct 14 18:42:12 2011
Aham.. Tehát a cons bejegyzés a ludas.. Az meg a getty-t hívogatja..
server@root:/ # lsitab cons
cons:0123456789:respawn:/usr/sbin/getty /dev/console
Respawn is ahogy vártam, de most komolyan a getty okozna nekem ilyen gondokat? Hát nézzük meg:
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
/dev/: TSM was unable to open port "/dev/"
drw-------    5 root     system       356352 Oct 14 18:30 /dev
Aham.. Hát most vagy én vagyok nagyon balszerencsés, és pont abban az időben történt más is, vagy a getty tényleg ilyen problémákkal küszködik.. (A TSM-es hibára még visszatérek). Tekintve, hogy a 'getty /dev/console'-t manapság inkább csak virtual console-okhoz használják, így szívfájdalom nélkül kikapcsoltam, majd vártam, hogy történjen valami:
server@root:/tmp # chitab cons:0123456789:off:"/usr/sbin/getty /dev/console"
server@root:/tmp # chmod 755 /dev
server@root:/ # while true;do echo "$(date +"%Y.%m.%d %H:%M:%S") $(ls -ld /dev)";sleep 1;done
2011.10.14 18:46:11 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
......
2011.10.14 18:46:40 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:46:57 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:22 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:38 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:47:58 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
...
2011.10.14 18:48:20 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:21 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:22 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:23 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:24 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:25 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:26 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:27 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:28 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
2011.10.14 18:48:29 drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
Ctrl+C.. Őszinte leszek.. Még mindig nem értettem a dolgot.. Ezek szerint tényleg a getty okozza a problémát.. De miért?? Nézzük a konzol beállításokat:
server@root:/tmp # lscons -a
 current = NULL
 console_logname = /var/adm/ras/conslog
 console_logsize = 32768
 console_logverb = 1
 console_tagverb = 0
Na jó.. Beismerem.. Ez tényleg nem egészséges.. Ezt azonnal orvosolni kell:
server@root:/tmp # chcons -a login=enable /dev/vty0
chcons: Console login cannot be enabled because the console device
        is not an available lft, tty, or vty.
Hö??? WTF??? Mi van a vty0-val?
server@root:/tmp # lsdev -Cctty
vty0 Defined  Asynchronous Terminal
Jah hogy úgy.. Na ezt rántsuk már be akkor:
server@root:/tmp # cfgmgr -l vty0
Method error (/etc/methods/cfgtty -l vty0 ):
        0514-040 Error initializing a device into the kernel.
Na menj a tudod hova... Van más is amiről tudnom kéne??
server@root:/ # lsdev |grep vs
vsa0        Defined            LPAR Virtual Serial Adapter
vsa1        Defined            LPAR Virtual Serial Adapter
vsa2        Available          LPAR Virtual Serial Adapter
server@root:/ # lsdev |grep vty
vty0        Defined            Asynchronous Terminal
Aham.. LPAR profil alapján csak 1 Virtual Serial Adapter van (ezek szerint az lesz a vsa2), de akkor ez miért lát 3at?? Na mind.. Gyomláljunk, mert ez így gázos:
server@root:/ # for i in vty0 vsa2 vsa1 vsa0;do rmdev -dl $i;done
vty0 deleted
vsa2 deleted
vsa1 deleted
vsa0 deleted
server@root:/ # cfgmgr
server@root:/ # lsdev |egrep "vty|vsa"
vty0        Available          Asynchronous Terminal
vsa0        Available          LPAR Virtual Serial Adapter
server@root:/ # chcons -a login=enable /dev/vty0
chcons: console login enabled, effective on next system boot
chcons: console assigned to: /dev/vty0, effective on next system boot
Oks.. Mindjárt jobb.. Console-al mi van?
server@root:/ # pstart
console DISABLE
vty0 ENABLE
Na ez még gázos lehet.. Akkor ezt is rakjuk helyre:
server@root:/ # penable console
server@root:/ # pstart
console ENABLE
vty0 ENABLE
Ez után ismét megnéztem mi és hogy áll.. Sajna azt kellett tapasztaljam, hogy a penable igaz, hogy helyére rakta a console-t, viszont az inittab-ban is újra engedélyezte a cons bejegyzést.. Ez miatt ismét rakhattam off-ba, illetve lőhettem vissza a /dev-et 775-re.. Viszont sajna a jelek szerint a getty még mindig nem ment normálisan:
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 18:30 /dev
/dev/: TSM was unable to open port "/dev/"
drw-------    5 root     system       356352 Oct 14 18:30 /dev
Hát jó.. akkor nem maradt más restart.. Ami láss csodát.. Megoldotta a problémát!
server@root:/tmp # ls -ld /dev; /usr/sbin/getty /dev/console;ls -ld /dev
drwxrwxr-x    5 root     system       356352 Oct 14 19:10 /dev
drwxrwxr-x    5 root     system       356352 Oct 14 19:10 /dev

Éljen.. akkor problem solved.. Na de azért bennem felmerült 1-2 dolog.. Az első, hogy mint látható, most a TSM nem dobott hibát. Tekintve, hogy a TSM-es hiba direktben a /dev-re hivatkozott, így erősen esélyesnek tartom, hogy a problémának ehhez is köze lehet.. Tekintve, hogy ez egy TSM szerver, így nem csodálkoznék, ha ez egy TSM bug lenne, viszont a neten körbeszaglászva ilyen, vagy ehhez hasonló hibaleírást véletlenül se sikerült találnom.. A gyanúmat még jobban alátámasztja az, hogy a getty által piszkált file-ok a /dev alatt default 622-es jogot kapnak (hacsak ezt az ODM-ben nem bíráljuk felül, de ilyen itt nem volt)
Az viszont a probléma ellen szól, hogy a TSM-nek semmi köze nem szabadna legyen ezen a szinten a rendszerhez, pláne nem a getty futtatásakor. Így az is elképzelhető, hogy ez is csak egy a sok side affect közül (mint pl a CTRL+C-s hiba) ami amúgy egy getty-os bug.
Mindazonáltal a hiba meglehetősen furcsa volta, illetve a hiba keresési mód miatt úgy gondoltam, hogy ez az írás megér egy blog bejegyzés (tudom - jó hosszú lett)