Savoir construire ses outils

Parfois, face à une situation nouvelle que je ne comprends pas, j’ai besoin de voir le problème sous un autre angle. Dans ces conditions, je suis content d’utiliser tous les outils que j’ai déjà. Et parfois, quand mes outils habituels ne sont pas adaptés, savoir fabriquer très vite un nouvel outil spécifique à la situation est très utile.

Voici le dernier exemple en date, où j’ai eu besoin de visualiser des événements sur un axe temporel pour les corréler et chercher des patterns.

Dans ma mission actuelle, nous avons eu besoin d’établir une connexion VPN entre un serveur applicatif et un serveur SMTP pour envoyer des emails. Et nous avons détecté que cette connexion était défectueuse régulièrement, car environ un email sur dix ne partait pas : le serveur applicatif n’arrivait pas à joindre le serveur SMTP.

Autre point important : sur ce projet on n’a pas encore pris le temps ni le budget de s’outiller sur l’analyse de logs, avec des outils du marché comme Datadog par exemple. Ces outils fonctionnent très bien et je les recommande, mais nous ne les avons pas encore sous la main, d’où cette démarche un peu plus rustique.

Voilà la démarche que j’ai suivie pour rendre visible les patterns de perte de connexion :

activer les logs de ping VPN
extraire des logs de ping les événements qui m’intéressent
dessiner un graph avec tous ces événements

Exploration des logs

Une connexion VPN, pour se maintenir, envoie à interval régulier des pings entre client et serveur. J’ai activé les logs de ces pings du point de vue de mon serveur applicatif. J’ai donc dans mes logs des pings envoyés et des pings reçus.

Ces logs sont très verbeux, ils contiennent beaucoup d’information. En plissant les yeux, on peut voir dans ces lignes des lignes ‘RECEIVED PING PACKET’ et ‘SENT PING’. On peut voire aussi des lignes ‘Inactivity timeout’ et ‘ping-restart’ : ce sont les lignes qui montrent le problème, le redémarrage fréquent de la connexion VPN qui causait les pertes d’emails.

2023-05-12 17:21:28.999239998 +0200 CEST [web-1] 2023-05-12 15:21:28 us=359574 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:21:28.999245803 +0200 CEST [web-1] 2023-05-12 15:21:28 us=364929 UDP READ [41] from [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:21:28.999246770 +0200 CEST [web-1] 2023-05-12 15:21:28 us=364965 TLS: tls_pre_decrypt, key_id=0, IP=[AF_INET]12.34.56.789:1194
2023-05-12 17:21:28.999247475 +0200 CEST [web-1] 2023-05-12 15:21:28 us=364984 PID_TEST [0] [SSL-0] [] 0:0 0:1 t=1683904888[0] r=[0,64,15,0,1] sl=[0,0,64,528]
2023-05-12 17:21:28.999248049 +0200 CEST [web-1] 2023-05-12 15:21:28 us=364993 RECEIVED PING PACKET
2023-05-12 17:21:39.000111417 +0200 CEST [web-1] 2023-05-12 15:21:38 us=479455 TLS: tls_pre_encrypt: key_id=0
2023-05-12 17:21:39.000143400 +0200 CEST [web-1] 2023-05-12 15:21:38 us=479527 SENT PING
2023-05-12 17:21:39.000152558 +0200 CEST [web-1] 2023-05-12 15:21:38 us=479567 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:21:49.001203807 +0200 CEST [web-1] 2023-05-12 15:21:48 us=710285 TLS: tls_pre_encrypt: key_id=0
2023-05-12 17:21:49.001231283 +0200 CEST [web-1] 2023-05-12 15:21:48 us=710359 SENT PING
2023-05-12 17:21:49.001235143 +0200 CEST [web-1] 2023-05-12 15:21:48 us=710413 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:21:59.002236188 +0200 CEST [web-1] 2023-05-12 15:21:58 us=745173 TLS: tls_pre_encrypt: key_id=0
2023-05-12 17:21:59.002246836 +0200 CEST [web-1] 2023-05-12 15:21:58 us=745261 SENT PING
2023-05-12 17:21:59.002287152 +0200 CEST [web-1] 2023-05-12 15:21:58 us=745302 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:22:09.003668616 +0200 CEST [web-1] 2023-05-12 15:22:08 us=957512 TLS: tls_pre_encrypt: key_id=0
2023-05-12 17:22:09.003689111 +0200 CEST [web-1] 2023-05-12 15:22:08 us=957579 SENT PING
2023-05-12 17:22:09.003693708 +0200 CEST [web-1] 2023-05-12 15:22:08 us=957618 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:22:20.004539495 +0200 CEST [web-1] 2023-05-12 15:22:19 us=79677 TLS: tls_pre_encrypt: key_id=0
2023-05-12 17:22:20.004544393 +0200 CEST [web-1] 2023-05-12 15:22:19 us=79749 SENT PING
2023-05-12 17:22:20.004545188 +0200 CEST [web-1] 2023-05-12 15:22:19 us=79805 UDP WRITE [41] to [AF_INET]12.34.56.789:1194: P_DATA_V2 kid=0 DATA len=40
2023-05-12 17:22:29.005460487 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327448 [OpenVPN-Server-mon-serveur-vpn.com] Inactivity timeout (--ping-restart), restarting
2023-05-12 17:22:29.005472487 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327506 PID packet_id_free
2023-05-12 17:22:29.005495216 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327605 PID packet_id_free
2023-05-12 17:22:29.005500324 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327617 PID packet_id_free
2023-05-12 17:22:29.005501491 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327624 PID packet_id_free
2023-05-12 17:22:29.005552612 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327640 PID packet_id_free
2023-05-12 17:22:29.005555228 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327647 PID packet_id_free
2023-05-12 17:22:29.005555749 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327654 PID packet_id_free
2023-05-12 17:22:29.005556455 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327661 PID packet_id_free
2023-05-12 17:22:29.005568587 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327672 TCP/UDP: Closing socket
2023-05-12 17:22:29.005569472 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327690 PID packet_id_free
2023-05-12 17:22:29.005574817 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327709 SIGUSR1[soft,ping-restart] received, process restarting
2023-05-12 17:22:29.005575207 +0200 CEST [web-1] 2023-05-12 15:22:28 us=327727 Restart pause, 5 second(s)

On peut déjà en tirer des informations mais ce n’est pas très pratique : dans l’exemple il y a une ou deux minutes de logs, et pour mon problème j’ai besoin d’analyser un bon quart d’heure pour chercher des patterns.

Transformation des logs

J’ai commencé par extraire les événements qui m’intéressent avec rg (un genre de grep) et à les structurer pour isoler le timestamp.

Isoler les envois de pings :

$ rg 'SENT PING' logs
99694:2023-05-12 17:20:53.995533501 +0200 CEST [web-1] 2023-05-12 15:20:53 us=775530 SENT PING
99697:2023-05-12 17:21:03.996518529 +0200 CEST [web-1] 2023-05-12 15:21:03 us=991544 SENT PING
99739:2023-05-12 17:21:18.998396048 +0200 CEST [web-1] 2023-05-12 15:21:18 us=82178 SENT PING
99833:2023-05-12 17:21:28.999163512 +0200 CEST [web-1] 2023-05-12 15:21:28 us=359535 SENT PING
99840:2023-05-12 17:21:39.000143400 +0200 CEST [web-1] 2023-05-12 15:21:38 us=479527 SENT PING
99843:2023-05-12 17:21:49.001231283 +0200 CEST [web-1] 2023-05-12 15:21:48 us=710359 SENT PING
99846:2023-05-12 17:21:59.002246836 +0200 CEST [web-1] 2023-05-12 15:21:58 us=745261 SENT PING
99849:2023-05-12 17:22:09.003689111 +0200 CEST [web-1] 2023-05-12 15:22:08 us=957579 SENT PING
99852:2023-05-12 17:22:20.004544393 +0200 CEST [web-1] 2023-05-12 15:22:19 us=79749 SENT PING
99894:2023-05-12 17:22:34.006820819 +0200 CEST [web-1] 2023-05-12 15:22:33 us=328337 SENT PING
99992:2023-05-12 17:22:44.007459739 +0200 CEST [web-1] 2023-05-12 15:22:43 us=490301 SENT PING
99995:2023-05-12 17:22:54.008443004 +0200 CEST [web-1] 2023-05-12 15:22:53 us=684270 SENT PING

Extraire le timestamp avec cut (on délimite sur les espaces et on prend les deux premiers champs) :

$ rg 'SENT PING' logs | cut -d' ' -f1-2
2023-05-12 17:20:53.995533501
2023-05-12 17:21:03.996518529
2023-05-12 17:21:18.998396048
2023-05-12 17:21:28.999163512
2023-05-12 17:21:39.000143400
2023-05-12 17:21:49.001231283
2023-05-12 17:21:59.002246836
2023-05-12 17:22:09.003689111
2023-05-12 17:22:20.004544393
2023-05-12 17:22:34.006820819
2023-05-12 17:22:44.007459739
2023-05-12 17:22:54.008443004

Ajouter le marqueur ‘ >’ (pour signifier “envoyé”) en fin de ligne, et envoyer le résultat dans un fichier “sent” (ici avec tee pour visualiser le résultat en même temps) :

$ rg 'SENT PING' logs | cut -d' ' -f1-2 | rg '$' -r ' >' | tee sent
2023-05-12 17:20:53.995533501 >
2023-05-12 17:21:03.996518529 >
2023-05-12 17:21:18.998396048 >
2023-05-12 17:21:28.999163512 >
2023-05-12 17:21:39.000143400 >
2023-05-12 17:21:49.001231283 >
2023-05-12 17:21:59.002246836 >
2023-05-12 17:22:09.003689111 >
2023-05-12 17:22:20.004544393 >
2023-05-12 17:22:34.006820819 >
2023-05-12 17:22:44.007459739 >
2023-05-12 17:22:54.008443004 >

Faire la même chose avec les pings reçus :

$ rg 'RECEIVED PING' logs | cut -d' ' -f1-2 | rg '$' -r ' < Received' | tee received
2023-05-12 17:20:12.991392556 < Received
2023-05-12 17:21:28.999248049 < Received
2023-05-12 17:22:44.007432531 < Received
2023-05-12 17:22:54.008453476 < Received

Et les redémarrages de session VPN :

$ rg '12 17:.*Inactivity timeout' logs | cut -d' ' -f1-2 | rg '$' -r ' * Restart !!' | tee restart
2023-05-12 17:21:13.997629899 * Restart !!
2023-05-12 17:22:29.005460487 * Restart !!

Ensuite on peut joindre les fichiers avec cat et les trier (par date puisque c’est le début de ligne) dans un fichier “history”::

$ cat received sent restarts | sort > history
$ cat history
2023-05-12 17:20:53.995533501 >
2023-05-12 17:21:03.996518529 >
2023-05-12 17:21:13.997629899 * Restart !!
2023-05-12 17:21:18.998396048 >
2023-05-12 17:21:28.999163512 >
2023-05-12 17:21:28.999248049 < Received
2023-05-12 17:21:39.000143400 >
2023-05-12 17:21:49.001231283 >
2023-05-12 17:21:59.002246836 >
2023-05-12 17:22:09.003689111 >
2023-05-12 17:22:20.004544393 >
2023-05-12 17:22:29.005460487 * Restart !!
2023-05-12 17:22:34.006820819 >
2023-05-12 17:22:44.007432531 < Received
2023-05-12 17:22:44.007459739 >
2023-05-12 17:22:54.008443004 >
2023-05-12 17:22:54.008453476 < Received

C’est déjà plus lisible, on peut maintenant commencer à corréler et voir des patterns. En plissant les yeux, on peut voir que les pings envoyés sont beaucoup plus fréquents que les pings reçus.

On peut voir aussi que le redémarrage de 17h22 survient une minute et une seconde après le dernier ping reçu : ça correspond à notre configuration VPN : envoyez-vous des pings toutes les 10 secondes, et redémarrez si vous n’avez pas de nouvelles après 1 mn. Mais j’avais envie de voir ces infos sur un graph pendant une longue période pour mieux confirmer mes intuitions.

Affichage dans un graph

Ça tombe bien, ça fait longtemps que j’avais envie d’explorer l’aspect visuel de Smalltalk, un petit langage qui contient tout ce qu’il faut pour générer des images et les afficher out of the box (petit, en effet : 30 Mo le zip avec la VM, la lib standard, toutes les sources, et un IDE puissant intégré !).

J’ai donc exploré un peu et j’ai trouvé une classe RSChart qui pouvait afficher des RSLinePlot et des RSScatterPlot. Dans les commentaires de la classe il y a même tout ce qu’il faut pour démarrer.

En explorant quelques minutes de plus, j’ai trouvé comment ajouter des marqueurs, et en peu de temps j’avais ce résultat à partir de mes logs, exactement ce dont j’avais besoin :

On peut voir qu’il y a effectivement un pattern super régulier : mon client VPN reçoit des pings du serveur pendant quelques dizaines de secondes, ne reçoit pas les pings du serveur pendant une minute et redémarre. Et ainsi de suite.

En réfléchissant un peu, j’ai pu faire l’hypothèse qu’il y avait une autre machine qui utilisait la même configuration. Quand le serveur voyait cette autre machine arriver, il lui se mettait à lui envoyer les pings et mon serveur ne les recevait plus. Ma connexion redémarre, le serveur m’envoie les pings, (donc l’autre machine ne les reçoit plus et redémarre), et ainsi de suite, à toi, à moi, etc.

Et bingo, j’avais bien utilisé la même conf VPN sur deux de mes serveurs qui se volaient la vedette à chacun leur tour 🤦. Problème enfin résolu ! 🎉

Conclusion

Pour résumer, bien connaître GNU core-utils et un langage de programmation un peu visuel permet de se fabriquer ses propres outils spécifiques rapidement et à peu de frais, à tel point que je ne “capitalise” pas sur ces outils, je n’en fait surtout pas une librairie. Je conserve quelques snippets pour me rappeler rapidement les détails, et je me reconstruis un outil vite fait à chaque fois, en jetant parfois un œil à un de mes vieux snippets.

Annexe

Version awk

On peut aussi faire toute la phase d’exploration de logs en une seule ligne de awk :

$ awk <logs '/SENT PING/ { print $1 $2 " >" } ; /RECEIVED PING/ { print $1 $2 " < Received"} ; /Inactivity/ { print $1 $2 " * Restart !!" }'
2023-05-1217:20:43.994461854 >
2023-05-1217:20:53.995533501 >
2023-05-1217:21:03.996518529 >
2023-05-1217:21:13.997629899 * Restart !!
2023-05-1217:21:18.998396048 >
2023-05-1217:21:28.999163512 >
2023-05-1217:21:28.999248049 < Received
2023-05-1217:21:39.000143400 >
2023-05-1217:21:49.001231283 >
2023-05-1217:21:59.002246836 >
2023-05-1217:22:09.003689111 >
2023-05-1217:22:20.004544393 >
2023-05-1217:22:29.005460487 * Restart !!
2023-05-1217:22:34.006820819 >
2023-05-1217:22:44.007432531 < Received
2023-05-1217:22:44.007459739 >
2023-05-1217:22:54.008443004 >
2023-05-1217:22:54.008453476 < Received

Code du graph en Pharo Smalltalk

Si vous connaissez Ruby, une bonne partie de Smalltalk va vous paraître familière : les collections, les blocks de code, et le paradigme "tout est message".

Exemple de graph qui affiche une sinusoïde :

x := -3.14 to: 3.14 by: 0.1.
y := x sin.

c := RSChart new.
c addPlot: (RSLinePlot new x: x y: y).
c addDecoration: (RSChartTitleDecoration new title: 'hello'; fontSize: 20).
c addDecoration: (RSXLabelDecoration new title: 'My X Axis'; fontSize: 12).
c addDecoration: (RSYLabelDecoration new title: 'My Y Axis'; fontSize: 15).
c show

Voilà tout le code écrit à l’arrache pour le graph des redémarrages. Ça tient en une vingtaine de lignes :

file := FileSystem disk workingDirectory
        / 'Developer/project/history'.
lines := file contents lines allButFirst: 8.

c := RSChart new.

y := 1.
xS := (lines select: [ :each | each endsWith: ' >' ]) collect: [ :line |
        (DateAndTime fromString: (line first: 23)) asUnixTime ].
c addPlot:
    (RSScatterPlot new x: xS y: (OrderedCollection new: xS size withAll: y)).

y := 1.5.
xRc := (lines select: [ :each | each endsWith: 'Received' ]) collect: [ :line |
        (DateAndTime fromString: (line first: 23)) asUnixTime ].
c addPlot:
    (RSScatterPlot new x: xRc y: (OrderedCollection new: xRc size withAll: y)).

((lines select: [ :each | each endsWith: 'Restart !!' ]) collect: [ :line |
     (DateAndTime fromString: (line first: 23)) asUnixTime ]) do: [ :value |
    c addDecoration: (RSXMarkerDecoration new value: value) ].

c addDecoration: (RSHorizontalTick new labelConversion: [ :value |
      (DateAndTime fromUnixTime: value) asTime ]).
c addDecoration: (RSXLabelDecoration new
      title: 'Heure';
      fontSize: 12).

c padding: 0 @ 80.
c show

Le site de Pharo Smalltalk, qui permet de faire tourner ce code out of the box : https://pharo.org/

Blog