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)

AIX mounting issue

Kicsit régebbi eset(2009.08), de gondoltam inkább lebloggolom, mintsem az enyészeté legyen, mert annál azért többet ér :)

Nos hát.. Alapvető probléma a következő: A rendszer indulásakor egy csomó filerendszer nem jön fel normálisan, holott a /etc/filesystems alatt szépen be van állítva, hogy azoknak bizony fel kell jönniük. A Volume Group szépen aktiválódik, de az alatta lévő FS-ek a rendszer indulásakor nem jönnek fel (Ha manuálisan mountoljuk őket, akkor viszont igen)

Kiegészítő információk:
- Az AIX kicsit régi a gépen (5300-10-01-0921) de ez nem indokolja a rendszer hibáját.
- A bootolás után a console log ilyen randaságokat tartalmaz:

0 Sun Aug 16 16:43:35 BST 2009 mount: 0506-324 Cannot mount /dev/lv_ap02n8log on /vfs=jfs2log=/dev/loglv27: A file or directory in the path name does not exist.
0 Sun Aug 16 16:43:35 BST 2009 mount: 0506-324 Cannot mount /dev/lv_ap02n2temp01 on /dev=/dev/lv_ap02n2data02log=/dev/loglv20: A file or directory in the path name does not exist.
0 Sun Aug 16 16:43:35 BST 2009 mount: 0506-324 Cannot mount /dev/lv_ap02n3data02 on /dev=/dev/lv_ap02n2temp02log=/dev/loglv20check=false: A file or directory in the path name does not exist.
0 Sun Aug 16 16:43:35 BST 2009 mount: 0506-324 Cannot mount /dev/lv_ap03n9log on /vfs=jfs2: A file or directory in the path name does not exist.

Mint az látszik a console logból a rendszer össze vissza kavarva próbál valami mount félét össze hozni, de nagyon kevés sikerrel.
Na de a kérdés.. Miért, és hogy?
Ehhez első körben vizsgáljuk meg, hogy mi (és hogy) is lenne a felelős ennek folyamatnak a lezongorázásáért:

A folyamat alapvetően egyszerű: a rendszer IPL-je során amint átvált a rendszer rc2-be nyomban elkezdi a /etc/inittab-ot feldolgozni, illetve az ott feltüntetett parancsokat/scripteket végrehajtani. Az egyik ilyen alap script a /etc/rc, ami a mountolásért is felel. Az akkor rendszeren az alábbi kód volt ezért a felelős (megjegyzés - a kód verziószáma 1.20.1.7 - ez még később fontos lesz)

# Perform file system checks
# The -f flag skips the check if the log has been replayed successfully
fsck -fp

# Perform all auto mounts
dspmsg rc.cat 4 ' Performing all automatic mounts \n'

cat /etc/filesystems | tr -d ' ' | tr -d '\t' | grep -vp "vfs=nfs" | grep -vp "vfs=cachefs"> /tmp/fs1.$$

# Collecting entries except nfs
lines=`wc -l /tmp/fs1.$$ | awk '{print $1}'`

# Calculate the number of lines
cnt=1

# Remove the file 'fs2.$$' if it already exists
if [ -f /tmp/fs2.$$ ]
then
        rm -f /tmp/fs2.$$
fi

# Compare each line in the file '/tmp/fs1.$$'
# If it is a comment line or just having the filesystem name,
# just write it to '/tmp/fs2.$$'
# Otherwise, add a tab before that line and write it to '/tmp/fs2.$$'

while [ $cnt -le $lines ]
do
        cat /tmp/fs1.$$ | head -$cnt | tail -1 | grep "^[\*/]"  1> /dev/null
        if [ $? -eq 0 ]
        then
                cat /tmp/fs1.$$ | head -$cnt | tail -1 >> /tmp/fs2.$$
        else
                param=`cat /tmp/fs1.$$ | head -$cnt | tail -1`
                echo "\t"$param >> /tmp/fs2.$$
        fi
        cnt=`expr $cnt + 1`
done
mount /tmp/fs2.$$ /etc/filesystems
mount all
umount /etc/filesystems
rm -f /tmp/fs1.$$ /tmp/fs2.$$

Nah.. mit is látunk itt...
- Első körben a rendszer létrehoz egy /tmp/fs1.$$ file-t ($$ a PID szám, amivel maga a /etc/rc fut), amit aztán majd alapnak fog használni. A file-ból minden tab és szóköz hiányzik, illetve a cachefs-eket is kikapja belőle a grep -vp.
- Aztán egy $lines változót használva a rendszer megnézi, hogy az így keletkezett file hány soros (bár sztem kicsit undorítóan csinálja, de hát ízlés kérdése).
- Mindezek után egy counter-t használva ($lines értékéig) egy teljes while ciklus indul, ami egy (szerintem szintén undorító módon) sorról-sorra végigmegy, és megnézi, hogy az adott sor '*'-al, avagy '/'-el kezdődik e (grep visszatérési értéke). Amennyiben igen, úgy az adott sor átkerül egy /tmp/fs2.$$ file-ba. Amennyiben mégse így történne akkor is, csak az adott sor kap maga elé egy tabulátort.
- Amint a ciklus lefut egy meglehetősen furcsa módszerrel a /tmp/fs2.$$-ban lévő FS-eket mountolja a rendszer (figyelem - a /etc/filesystems helyére felülmountolódik a /tmp/fs2.$$ ), majd a standard mount all parancsal minden a file-ban szereplő FS mountolódik (aminek a mount paramétere nem 'false').
- Amint ezzel is kész feloldja az előző mountot, majd törli a temporary file-okat.

A módszer kicsit tényleg furcsán néz ki (nekem főleg a sorról-sorra végigmenős módszertől borsódzik a hátam), viszont elméletben működnie kellett volna.. Akkor hol volt a probléma?? Nos.. végeztem pár tesztet, majd a szemem fennakadt, amikor nem az általam várt eredmények jöttek ki:

A használt script a következő volt:

#!/bin/ksh
set -x
lines=`wc -l /tmp/fs1.temp | awk '{print $1}'`
cnt=1

while [ $cnt -le $lines ]
do
        cat /tmp/fs1.temp | head -$cnt | tail -1 | grep "^[\*/]"  1> /dev/null
        if [ $? -eq 0 ]
        then
                cat /tmp/fs1.temp | head -$cnt | tail -1 >> /tmp/fs2.temp
        else
                param=`cat /tmp/fs1.temp | head -$cnt | tail -1`
                echo "\t"$param >> /tmp/fs2.temp
        fi
        cnt=`expr $cnt + 1`
done

Lényegében azonos a standard scriptel, az eredmény (/tmp/fs2.temp) viszont nem az volt amit vártam:

/var:
dev=/dev/hd9var
vfs=jfs2
    log=/dev/hd8
    mount=automatic
check=false
type=bootfs
    vol=/var
    free=false
quota=no

/tmp:
    dev=/dev/hd3
    vfs=jfs2
log=/dev/hd8
mount=automatic
check=false
vol=/tmp
free=false
quota=no

/proc:
    dev=/proc
    vol="/proc"
    mount=true
    check=false
    free=false
    vfs=procfs

Mit látható.. A TAB-ok egy csomó helyen nem kerültek a helyükre.. Na akkor nézzük meg azt az elágazást kicsit közelebbről:

cat /tmp/fs1.temp | head -$cnt | tail -1 | grep "^[\*/]"  1> /dev/null
if [ $? -eq 0 ]
then
        cat /tmp/fs1.temp | head -$cnt | tail -1 >> /tmp/fs2.temp
else
        param=`cat /tmp/fs1.temp | head -$cnt | tail -1`
        echo "\t"$param >> /tmp/fs2.temp
fi

Tehát.. Ha a $? (előző parancs (grep) Return Code-ja) 0 akkor csak rakja bele, ha meg nem akkor toldja meg egy tabbal.. Hát jó. csináljunk egy kis tesztet:

server:root # while true;do cat /tmp/fs1.temp | head -172| tail -1 | grep "^[\*/]"  1>/dev/null;echo $?;done
1
2
13
13
13
13
13
13

És kb itt nyomtam Ctrl+C-t..

Mit is csináltam? - egy végelenített ciklust, amikor is folyamatosan ugyan azt az adatot kértem ki (head+tail) majd megnéztem a grep return code-ját.. Az viszont azonos adat esetén (172. sor) különböző eredményt produkált! Wattafák???

Nos.. Mint kiderült sikerült belefutni egy meglehetősen érdekes issue-ba. Ennek az issue-nak neve is volt: IZ43276: KSH MAY RETURN INCORRECT RETURN CODE FOR PIPED COMMANDS APPLIES TO AIX 5300-11

Aha... Hogy úgy... Én is üdvözöllek.. A problémámon ez a tudás akkor viszont még nem segített.. A patch-et csak 2010ben adták ki, ami azt jelentette, hogy én 2009ben még csak feliratkozhattam a fix "hírlevél mondóra" és várhattam, hogy javítják a hibát..

Viszont mint kiderült azért volt kerülőút: Az AIX 5.3 TL6-tól (TL10-en van a rendszer, emlékeztek? :) a /etc/rc file már a 1.20.1.9 verzión volt, ami ugyen ezt a problémát (FS-ek mountolása) sokkal szebben oldotta meg:

# Remove the file 'fs1.$$' if it already exists
rm -f /tmp/fs1.$$

# handle the egrep line carefully: between each pair of brackets is a tab
# followed by a space, and the tab may get lost if you copy and paste the line
egrep -vp "^[ ]*vfs[ ]*=[ ]*(cachefs|nfs|cifs)[ ]*$" \
/etc/filesystems > /tmp/fs1.$$

mount /tmp/fs1.$$ /etc/filesystems
mount all
umount /etc/filesystems
rm -f /tmp/fs1.$$

Éljenek a Reguláris kifejezések.. Ennek a kódnak köszönhetően pedig (mivel nem használ hülye visszatérési értékeket) a mount problémám megoldódott (persze a rendszeren lévő további scriptek amik erre támaszkodtak ettől még szívhatták).

Egy kérdés maradt csak nyitva - Ha ez TL6tól elérhető volt, akkor miért nem ez a verzió volt elérhető a TL10-es AIX alatt is?

A válasz persze "prózai" - A fejlesztők szerint a /etc/rc file-t a customer (ha nem is nyugodtan, de.. ) bármikor szerkesztheti, így úgy gondolták, hogy az upgrade során ezt a file-t inkább ne piszkálják (hisz új funkciót amúgy se hoz) upgrade során. Ergo ha a rendszer egy régebbi szintről ( < TL6 ) lett felhúzva TL10-re, akkor az upgrade véletlenül se fogja a frissebb file-t a helyére pakolni. Max akkor ha a rendszert már az elejétől fogva TL6, vagy afölötti verzióval telepítették (ergo az újabb /etc/rc már alapból része a telepítő csomagnak)..

Igen.. Én is örültem amikor megtudtam :)