La semaine dernière, après un redémarrage de mon firewall tournant sous OpenBSD, j’ai pu constater une forte utilisation du CPU par le démon de journalisation des paquets réseaux : pflogd.
Le but de cet article est d’analyser le problème avec les outils que nous avons sous la main et de proposer une solution pour éviter ce genre de désagrément.
Ne perdons plus de temps, et voyons la sortie de la commande top quelques minutes après le redémarrage du serveur :
$ top -b -o time
load averages: 1.69, 0.82, 0.35 firewall 13:54:10
30 processes: 1 running, 28 idle, 1 on processor
CPU states: 0.6% user, 0.0% nice, 95.0% system, 1.0% interrupt, 3.4% idle
Memory: Real: 17M/42M act/tot Free: 74M Swap: 0K/128M used/tot
PID USERNAME PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
27673 _pflogd 58 0 640K 316K run - 3:00 98.88% pflogd
13154 root 2 0 420K 296K sleep select 0:01 0.00% vmware-guestd
13249 root 2 0 1824K 4180K sleep select 0:00 0.00% snmpd
29048 root 2 0 732K 1192K idle select 0:00 0.00% sshd
6201 jaax 2 0 3212K 1960K sleep select 0:00 0.00% sshd
7766 jaax 18 0 996K 1840K idle pause 0:00 0.00% zsh
24443 root 2 0 3232K 2476K idle netio 0:00 0.00% sshd
12901 root 2 0 1712K 2076K sleep poll 0:00 0.00% systat
2332 root 18 0 1040K 1868K idle pause 0:00 0.00% zsh
31170 jaax 2 0 3388K 1956K sleep select 0:00 0.00% sshd
2452 root 2 0 3404K 2504K idle netio 0:00 0.00% sshd
17843 root 18 0 984K 1864K idle pause 0:00 0.00% zsh
4236 jaax 18 0 968K 1876K idle pause 0:00 0.00% zsh
1551 _syslogd 2 0 524K 692K sleep poll 0:00 0.00% syslogd
9572 root 2 0 1456K 2020K sleep poll 0:00 0.00% bacula-fd
6727 root 18 0 524K 476K sleep pause 0:00 0.00% ksh
1 root 10 0 544K 300K idle wait 0:00 0.00% init
25826 _ntp 2 0 752K 920K idle poll 0:00 0.00% ntpd
La sortie de la commande top montre une forte utilisation du CPU par le processus pflogd, PID 27673.
Dans un autre terminal, la commande vmstat donne la sortie suivante :
$ vmstat 2 10 procs memory page disks traps cpu r b w avm fre flt re pi po fr sr sd0 vn0 int sys cs us sy id 1 0 0 16328 76692 73 0 0 0 0 0 27 0 29 57400 49 3 96 1 1 0 0 16332 76528 29 0 0 0 0 0 14 0 13 53722 31 5 95 0 1 0 0 16332 76464 18 0 0 0 0 0 12 0 23 51511 31 5 95 0 1 0 0 16332 76304 18 0 0 0 0 0 13 0 38 52656 33 7 93 0 1 0 0 16332 76432 19 0 0 0 0 0 20 0 26 80600 33 5 95 0 1 0 0 16332 76368 18 0 0 0 0 0 23 0 17 99014 29 3 97 0 1 0 0 16332 76832 25 0 0 0 0 0 25 0 28 105198 35 0 100 0 1 0 0 16332 76640 18 0 0 0 0 0 25 0 16 104762 32 0 100 0 1 0 0 16332 76392 18 0 0 0 0 0 26 0 16 105555 32 0 100 0 1 0 0 16332 76904 19 0 0 0 0 0 25 0 16 105507 33 1 99 0
La première chose que l’on constate, c’est qu’il y a bien un processus dans la file d’attente d’exécutuion. Mais ce qu’il faut surtout noter, c’est le nombre important d’appels systèmes qui est fait.
Enquêtons sans plus attendre sur ce processus pour essayer de comprendre ce qui se passe.
Utilisons la commande ktrace pour tracer les intéractions entre le noyau et pflogd. La trace est sauvegardée dans le fichier ktrace.out.
# Activation du traçage $ ktrace -p 27673 # Attendons quelques minutes ... # Désactivation du traçage $ ktrace -cp 27673
Pour l’écriture de cet article, j’ai pris le temps d’écrire un script shell qui permet d’identifier et de compter les appels systèmes effectués à partir d’un fichier de trace.
La trace précédente montre un nombre important d’appels systèmes de type E/S.
Vous commencez à comprendre ce qu’il se passe au démarrage du serveur ?
En effet, on dirait bien que le processus pflogd lit le fichier de journalisation.
Continuons quand même notre analyse et essayons d’identifier le descripteur de fichier utilisé par les deux appels systèmes.
$ kdump -f /tmp/ktrace.out -tc | egrep 'CALL .* lseek' | tail -1 27673 pflogd CALL lseek(0x4,0,0x3609d77,0,0)
Maintenant que nous connaissons le descripteur de fichier (0×4), voyons de quel fichier il s’agit.
$ fstat -p 27673 | awk ' $4 == 4 { print $0 } '
_pflogd pflogd 27673 4 /var 26640 -rw------- rw 383711002
Le fichier en question possède le numéro d’inode 26640.
$ find / -inum 26640 -ls 26640 749728 -rw------- 1 root wheel 383731462 Jun 29 16:57 /var/log/pflog
Et voilà, nous connaissons le fichier même si on aurait pu s’en douter étant donné que le processus pflogd est responsable de la journalisation des paquets de PF.
Donc au final, à chaque fois que le serveur sera redémarré ou que le moteur de filtrage Packet Filter sera désactivé/activé, la charge du serveur augmentera car il y aura lecture du fichier de journalisation.
Pour éviter ce genre de désagrément, la solution est de configurer la rotation des logs de PF.
Extrait de mon fichier de configuration de newsyslog :
$ cat /etc/newsyslog.conf [...] /var/log/pflog 600 31 * @T0001 ZB "pkill -HUP -u root -U root -t - -x pflogd"
Si vous avez des remarques ou juste pour dire un petit « merci », laissez un commentaire.