Les apparences sont quelques fois trompeuses… Petite démonstration confirmant cet adage.
Situons le contexte : plusieurs DBA Oracle nous remontent un incident sur un de leur serveur. Le symptôme étant le suivant : connexion impossible. Après une rapide vérification le diagnostic initiale semble être le bon. Petite connexion au déport console du serveur et me voilà devant un message des plus explicite « Unable to fork ». Hop, je provoque un petit panic et en avant pour une petite analyse.
Avant de me lancer tête baissée dans l’analyse du core, je m’intéresse aux logs du serveur en recherchant le pattern fork.
Jan 22 13:05:43 myserver sshd[7716]: [ID 800047 auth.error] error: fork: Error 0
Jan 22 13:08:06 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance
svc:/network/nrpe/tcp:default: Resource temporarily unavailable
Jan 22 13:08:36 eqds2dstdby002 last message repeated 1 time
Jan 22 13:09:59 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance
svc:/network/nrpe/tcp:default: Resource temporarily unavailable
A partir de 13:05, il semble que le serveur ne pouvait plus « forker » de nouveau process. Je vais faire parler le core !?
# cd /var/crash/myserver
# savecore –f vmdump.0
savecore -f vmdump.0
savecore: System dump time: Tue Jan 22 14:54:46 2013
savecore: saving system crash dump in /var/crash/myserver/{unix,vmcore}.0
Constructing namelist /var/crash/myserver/unix.0
Constructing corefile /var/crash/myserver/vmcore.0
8:36 92% done
9:22 100% done: 3571069 of 3571069 pages saved
# mdb –k 0
Loading modules: [ unix genunix specfs dtrace zfs sd mpt px ssd fcp fctl sockfs ip hook neti qlc dls sctp arp
usba md cpc fcip random crypto logindmux ptm ufs sppp ipc nfs lofs ]
> fork_fail_pending/D
fork_fail_pending:
fork_fail_pending: 1
Il s’agit bien d’un problème de fork. Combien de processus généré ?
> ::ps !grep -v FLAGS | wc -l
29952
29952 processus en machine !! Sachant que la limite haute se situe vers 30000, je comprends mieux le problème. Essayons dans savoir plus. Quel est le contributeur ? S’agit-il d’une « mauvaise bouche » dans un script (merci la fork bomb) ?
> ::ps
S PID PPID PGID SID UID FLAGS
ADDR NAME
R 0 0 0 0 0
0x00000001 00000000018b09c0 sched
R 4510 0 0 0 0 0x00020001
00000600e4766018 zpool-oradg00
R 92 0 0 0 0
0x00020001 00000600b4821960 zpool-spool
R 88 0 0 0 0
0x00020001 00000600b4823290 zpool-dump
R 86 0 0 0 0
0x00020001 00000600b21b6ca8 zpool-asmdg00
R 7 0 0 0 0
0x00020001 00000600b21b9270 vmtasks
R 3 0 0 0 0
0x00020001 000006009bdb4008 fsflush
R 2 0 0 0 0
0x00020001 000006009bdb4ca0 pageout
Z 1 0 0 0 0
0x4a004000 000006009bdb5938 init
Z 4712 1 11 11 0 0x5a006002
0000060146e6c0d0 p_ctscd
Z 4713 1 11 11 0 0x5a006002
0000060153fa8670 p_ctscs
R 7637 1 7637 7637 0 0x4a014000 00000600c9be4cf0
sac
R 7695 7637 7637 7637 0 0x4a014000 00000600c98b8cd8
ttymon
R 11035 1 11 11 0 0x4a004000
00000600cdd519b8 uce_agent.sh
R 15869 11035 11 11 0 0x4a004000 00000600b2b805e0
uce_agent.bin
Z 24884 1 24884 24884 100 0x4a004002 0000030597a799a0
oracle
Z 1449 1 1449 1449 100 0x4a004002 0000030597a28050
oracle
Z 18483 1 18483 18483 100 0x4a004002 0000030597a7a638
oracle
Z 5461 1 5461 5461 100 0x4a004002 0000030597a7d998
oracle
Z 28198 1 28198 28198 100 0x4a004002 0000030597a7c068
oracle
Z 21932 1 21932 21932 100 0x4a004002 0000030597a7cd00
oracle
Z 14770 1 14770 14770 100 0x4a004002 0000030597a37368
oracle
Z 8999 1 8999 8999 100 0x4a004002 0000030597aad938
oracle
[…]
Z 13641 1 13641 13641 100 0x4a004002 0000030597aa3280
oracle
Z 12707 1 12707 12707 100 0x4a004002 0000030597aa4018
oracle
>> More [<space>, <cr>, q, n, c, a] ?
A première vue Il semble y avoir beaucoup de processus « oracle ». Piste intéressante, j’investigue.
> ::ps !grep -c oracle
29684
Confirmation qu’il s’agit bien du contributeur « oracle ». J’essaye dans savoir un peu plus.
> ::ptree
00000000018b09c0 sched
00000600e4766018 zpool-oradg00
00000600b4821960 zpool-spool
00000600b4823290 zpool-dump
00000600b21b6ca8 zpool-asmdg00
00000600b21b9270 vmtasks
000006009bdb4008 fsflush
000006009bdb4ca0 pageout
000006009bdb5938 init
0000060146e6c0d0 p_ctscd
0000060153fa8670 p_ctscs
00000600c9be4cf0 sac
00000600c98b8cd8 ttymon
00000600cdd519b8 uce_agent.sh
00000600b2b805e0 uce_agent.bin
0000030597a799a0 oracle
0000030597a28050 oracle
0000030597a7a638 oracle
0000030597a7d998 oracle
0000030597a7c068 oracle
0000030597a7cd00 oracle
0000030597a37368 oracle
0000030597aad938 oracle
[…]
Tous les processus « oracle » ont comme père le processus init. Il s’agit vraisemblablement d’un nombre important de « sessions oracle » (et non pas une fork bomb). Je vérifie.
> ::ps -ft !grep oracle
Z 24884 1 24884 24884 100 0x4a004002 0000030597a799a0 oracleBASE
(LOCAL=NO)
Z 1449 1 1449 1449 100 0x4a004002 0000030597a28050 oracleBASE
(LOCAL=NO)
Z 18483 1 18483 18483 100 0x4a004002 0000030597a7a638 oracleBASE
(LOCAL=NO)
Z 5461 1 5461 5461 100 0x4a004002 0000030597a7d998 oracleBASE
(LOCAL=NO)
Z 28198 1 28198 28198 100 0x4a004002 0000030597a7c068 oracleBASE
(LOCAL=NO)
Z 21932 1 21932 21932 100 0x4a004002 0000030597a7cd00 oracleBASE
(LOCAL=NO)
Z 14770 1 14770 14770 100 0x4a004002 0000030597a37368 oracleBASE
(LOCAL=NO)
Z 8999 1 8999 8999 100 0x4a004002 0000030597aad938 oracleBASE
(LOCAL=NO)
Z 2874 1 2874 2874 100 0x4a004002 0000030597a7e630 oracleBASE
(LOCAL=NO)
Z 29899 1 29899 29899 100 0x4a004002 0000030597a88050 oracleBASE
(LOCAL=NO)
Z 26317 1 26317 26317 100 0x4a004002 0000030597a7f2c8 oracleBASE
(LOCAL=NO)
Z 23244 1 23244 23244 100 0x4a004002 0000030597a80cf8 oracleBASE
(LOCAL=NO)
Z 20412 1 20412 20412 100 0x4a004002 0000030597a81990 oracleBASE
(LOCAL=NO)
Z 16689 1 16689 16689 100 0x4a004002 0000030597a82628 oracleBASE
(LOCAL=NO)
[…]
Bingo ! J’ai un coupable… Un petit tour chez les DBA Oracle pour leur expliquer que l’incident survenu sur le serveur (indisponibilité) provient de chez eux.
<troll><mode Adrien> Encore les DBA, les nuls !! Un bon DBA est un DBA … </mode Adrien></troll>
J’ai dit quoi déjà : les apparences sont quelques fois trompeuses…
<troll> Adrien, calme me toi et lis la suite </troll>
En regardant d’un peu plus près le retour des commandes « ps », un premier élément me choque.
> ::ps -ft
[…]
Z 24884 1 24884 24884 100 0x4a004002 0000030597a799a0 oracleBASE
(LOCAL=NO)
Z 1449 1 1449 1449 100 0x4a004002 0000030597a28050 oracleBASE
(LOCAL=NO)
Z 18483 1 18483 18483 100 0x4a004002 0000030597a7a638 oracleBASE
(LOCAL=NO)
Z 5461 1 5461 5461 100 0x4a004002 0000030597a7d998 oracleBASE
(LOCAL=NO)
[…]
A première vue il s’agit de processus « zombie ». Strange… Combien de processus zombie pour cette base ? Existe-t-il d’autres processus zombie ?
> ::ps -ft !grep oracleBASE | grep -c ^Z
28773
> ::ps -ft !grep ^Z | grep -cv oracleBASE
469
Attention un processus zombie consomme une entrée dans la table des processus.
On a related note, the signal flow explains why zombie processes cannot be killed (any horror movie fan knows you can’t kill a zombie). A process must be executing in order to take delivery of a signal. A zombie process is, by definition, a process that has terminated. It exists only as a process table entry, with all of its execution state having been freed by the kernel (see preap(1) for cleaning up zombie processes).
En détaillant un peu les autres processus zombie un indice me choque rapidement.
> ::ps –ft !grep ^Z | grep –v BASE
Z 1 0 0 0 0 0x4a004000
000006009bdb5938 /sbin/init
Z 29265 1 29265 29265 100 0x4a004002 000003059798f2f8 oracle+ASM
(LOCAL=NO)
Z 17389 1 17389 17389 100 0x4a004002 000003059791c088 oracleXXX
(LOCAL=NO)
Z 10068 1 10068 10068 100 0x4a004002 00000305979172f8 oracleXXZ
(LOCAL=NO)
Z 8308 1 8308 8308 100 0x4a004002 0000030597924d10 oracleXYZ
(LOCAL=NO)
Z 6559 1 6559 6559 100 0x4a004002 0000030597930060 oracleZWX
(LOCAL=NO)
Z 1229 1 1229 1229 100 0x4a004002 00000305978e8100 oracleZSD
(LOCAL=NO)
Z 16366 1 16366 16366 100 0x4a004002 00000305977c0060 oracleWWW
(LOCAL=NO)
Z 2621 1 2621 2621 100 0x4a004002 0000030597713340 oracleQQQ
(LOCAL=NO)
Z 25811 1 25519 25519 100 0x4a004002 0000030597640d28 who am i
[…]
Le process « init » est dans l’état « zombie »… C’est assez surprenant !? Normalement un processus zombie est un processus terminé en attente d’un signal wait(2).
Regardless of which event causes the process to terminate, the kernel exit function is ultimately executed, freeing whatever resources have been allocated to the process, such as the address space mappings, open files, etc., and setting the process state to SZOMB, or the zombie state. A zombie process is one that has exited and that requires the parent process to issue a wait(2) system call to gather the exit status. The only kernel resource that a process in the zombie state is holding is the process table slot. Successful execution of a wait(2) call frees the process table slot. Orphaned processes are inherited by the init process solely for this purpose.
Mais s’agissant du processus init qui va lui envoyer le signal wait(2) ?
L’état du processus « init » semble inquiétant mais pour le moment, il n’existe pas encore de relation entre l’incident de fork et l’état du processus « init ». Y’a-t-il une information dans le buffer de messages concernant le process init ?
> ::msgbuf !grep init
NOTICE: core_log: init[1] core dumped: /var/core/core_myserver_init_0_0_1358854223_1
WARNING: init(1M) core dumped on signal 11: restarting automatically
WARNING: exec(/sbin/init) failed with errno 48.
WARNING: failed to restart init(1M) (err=48): system reboot required
Le processus init a eu un petit problème (signal SIGSEGV - Segmentation Fault) et n’a pas été réactivé correctement (exec failed – errno 48). Le problème du buffer de message c’est qu’il n’y a pas de timestamp. Du coup difficile de dire si il y a un rapport ou non avec mon incident « fork ».
Un petit passage par la log système est nécessaire.
Jan 22 12:30:24 myserver genunix: [ID 603404 kern.notice] NOTICE: core_log: init[1] core dumped:
/var/core/core_myserver_init_0_0_1358854223_1
Jan 22 12:30:24 myserver genunix: [ID 894729 kern.warning] WARNING: init(1M) core dumped on signal 11:
restarting automatically
Jan 22 12:30:24 myserver genunix: [ID 923222 kern.warning] WARNING: exec(/sbin/init) failed with errno
48.
Jan 22 12:30:24 myserver genunix: [ID 404865 kern.warning] WARNING: failed to restart init(1M) (err=48): system
reboot required
L’incident du « fork » se situe environ 35 minutes après l’incident du processus init… Quelle est la date de création de ces processus zombie ? Proviennent -ils d’avant l’incident du processus init ou pas ?
J’ai écrit un petit script pour obtenir le timestamp de création des processus (c’est pas très élégant mais ça fonctionne).
# cat /tmp/time_process_zombie
echo "::ps !grep ^Z" | mdb -k 0 | awk '{print $8}' > ps$$
while read proc
do
echo $proc | awk '{print $1}'
echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0
vmcore.0
done < ps$$
# cd /var/crash/myserver
# sh /tmp/bruno > liste_zombie
# cat /tmp/time_process_run
echo "::ps !grep ^R" | mdb -k 0 | awk '{print $8}' > ps$$
while read proc
do
echo $proc | awk '{print $1}'
echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0
vmcore.0
done < ps$$
# cd /var/crash/myserver
# sh /tmp/time_process_run > liste_run
Quelques observations après l’analyse des résultats :
- Seulement 3 processus créés après l’incident du processus « init » (bien entendu ces processus n’ont pas « init » comme père et celui-ci (leur père) n’est pas dans l’état zombie).
- Plus de 29300 processus zombie ont été créé à partir du 22 janvier 12:30:00.
- En date du 22 janvier, le premier processus zombie a démarré vers « 2013 Jan 22 12:05:33 ».
> 00000600dd4b99c8::ps -ft
S PID PPID PGID SID UID FLAGS
ADDR NAME
Z 11891 1 11891 11891 0 0x42000002 00000600dd4b99c8 /usr/lib/rcm/rcm_daemon
Il s’agit du deamon rcm_deamon. C’est quoi ce truc ? RCM « Reconfiguration Coordination Manager » est un framework qui manage la suppression automatique de composants du système.
The Reconfiguration Coordination Manager (RCM) is the framework that manages the dynamic removal of system components. By using RCM, you can register and release system resources in an orderly manner. You can use the new RCM script feature to write your own scripts to shut down your applications, or to cleanly release the devices from your applications during dynamic reconfiguration. The RCM framework launches a script automatically in response to a reconfiguration request, if the request impacts the resources that are registered by the script.
Une modification récente sur le système ? Mais oui… évidement maintenant qu’on en parle : il y a eu effectivement un changement de disque SCSI sur le châssis vers 12h00. Je vérifie rapidement l’heure de l’opération.
Jan 22 12:02:08 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:02:08 myserver Disconnected command timeout for Target 1
Jan 22 12:02:08 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:02:08 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:03:18 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:03:18 myserver Disconnected command timeout for Target 1
Jan 22 12:03:19 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:03:19 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:04:29 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:04:29 myserver Disconnected command timeout for Target 1
Jan 22 12:04:29 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:04:29 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:05:39 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:05:39 myserver Disconnected command timeout for Target 1
Jan 22 12:05:40 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:05:40 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:06:42 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:06:42 myserver wwn for target has changed
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1
(mpt0):
Jan 22 12:06:50 myserver Disconnected command timeout for Target 1
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.notice] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver mpt_flush_target discovered non-NULL cmd in slot 484, tasktype 0x3
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver Cmd (0x3005fa08e00) dump for Target 1 Lun 0:
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver cdb=[ 0x25 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 ]
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_flags=0x1c000 pkt_statistics=0x0 pkt_state=0x0
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_scbp=0x0 cmd_flags=0x860
Jan 22 12:06:53 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1/sd@1,0
(sd0):
Jan 22 12:06:53 myserver Corrupt label; wrong magic number
[…]
Jan 22 12:09:57 myserver genunix: [ID 408114 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0)
quiesced
[…]
Que dire de plus… Le changement physique du disque semble avoir « perturber » le système au point où le processus « init » segfault. Ce type d'incident ne se produit pas souvent du coup c'est difficile de savoir ce qui doit se produire. Dans mon cas, il semble y avoir eu création d’environ 29300 processus dans un statut bizarre (zombie).
Je remercie Yahya pour m’avoir challengé sur cet incident. Sans lui, je serais passé à côté de l'état zombie d'init et jamais je n'aurais penser à vérifier les dates de création des processus. Les apparences sont quelques fois trompeuses… n'oubliez pas !?
P.S. : Yahya est DBA Oracle...
