Eric Boumendil

Outil d’import de fichiers syslog vers une base PostgreSql

3 février 2024 // soho

N’ayant pas trouvé d’outil, gratuit, pour importer des fichiers syslog dans une base de données, j’ai développé le mien.

Les suites type Elastic sont bien trop riches et gourmandes en ressources pour mes besoins.

Pour quel usage ?

Mon réseau local est constitué de quelques équipements qui génèrent classiquement des messages syslog. Ces équipements sont principalement un pare-feu (pfSense), un NAS de marque QNAP, un switch managé. Les fichiers syslog sont stockés sur le NAS.

Suite à des incidents mineurs mais répétés au cours du mois dernier sur mon réseau WAN (perte d’accès Internet pendant quelques secondes à quelques minutes, et très rarement plusieurs heures!), j’ai voulu avoir une idée plus précise de l’ampleur et du rythme de ces incidents qui apparaissent bien dans mes logs. Peu pratique à faire efficacement à partir de centaines de fichiers textes. Ayant décidé de changer de fournisseur d’accès Internet, je voulais être en mesure de comparer l’avant et l’après grâce à ces logs.

Sur un système Linux standard, il aurait probablement été possible de configurer un « pont » avec rsyslog pour écrire vers une base de données. Cependant j’utilise le serveur syslog de mon NAS QNAP, qui est très peu configurable. Je souhaite rester « standard » et ne pas toucher directement à son système (une distribution Linux propriétaire très allégée) pour m’éviter des problèmes de maintenance lors des mises à jour régulières.

Mon programme, SyslogFilesToSql (GitHub), surveille la rotation (rollover) des fichiers syslog. Le serveur syslog de mon NAS crée un nouveau fichier syslog dès que le fichier courant atteint une certaine limite en taille (1 Mo ou 10 Mo par exemple). SyslogFilesToSql importe dans une base PostgreSql l’intégralité du fichier après rotation (autrement dit le fichier courant « syslog » n’est pas lu en temps réel, on attend qu’il soit renommé par exemple « syslog_2024_02_03 »). Pour plus d’efficacité, l’import est effectué via la commande COPY au format binaire. Pour que les requêtes SQL soient rapides, j’ai égalemement partitionné la table de stockage des messages syslog en fonction de la date de chaque message (partitionnement dynamique en fonction des dates des messages, avec nombre de jours, ou partitions, maximum). Une fois importés, les fichiers du NAS sont compressés. Sur le NAS, j’ai un job planifié pour supprimer les plus anciens fichiers « syslog_*.gz » après un délai d’archivage.

Une fois les données en base, il est facile de les requêter. Par exemple, dans mon cas avec pfSense, les pertes de connectivité du réseau WAN sont surveillés par un service « dpinger ». On peut les identifier via cette requête SQL:


SELECT created_on, severity, host, app, msg
	FROM v_syslog_msg
    WHERE 
	created_on::date BETWEEN '2024-01-01' AND '2024-01-31'
	AND app = ('dpinger') 
	AND severity = 'Warning'
	AND msg LIKE '%WAN_DHCP% Alarm latency%'
	ORDER BY created_on DESC


"created_on"	"severity"	"host"	"app"	"msg"
"2024-01-19 18:23:40"	"Warning"	"redacted"	"dpinger"	"dpinger[56431]: WAN_DHCP redacted: Alarm latency 8370us stddev 1198us loss 53%"
"2024-01-19 18:22:46"	"Warning"	"redacted"	"dpinger"	"dpinger[65737]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
"2024-01-19 18:21:35"	"Warning"	"redacted"	"dpinger"	"dpinger[44219]: WAN_DHCP redacted: Alarm latency 8222us stddev 488us loss 53%"
"2024-01-18 00:36:43"	"Warning"	"redacted"	"dpinger"	"dpinger[18465]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
"2024-01-18 00:36:39"	"Warning"	"redacted"	"dpinger"	"dpinger[62420]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
"2024-01-18 00:35:58"	"Warning"	"redacted"	"dpinger"	"dpinger[88887]: WAN_DHCP redacted: Alarm latency 8412us stddev 677us loss 52%"
"2024-01-17 17:52:31"	"Warning"	"redacted"	"dpinger"	"dpinger[7114]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
"2024-01-17 17:52:27"	"Warning"	"redacted"	"dpinger"	"dpinger[94122]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
"2024-01-17 17:51:26"	"Warning"	"redacted"	"dpinger"	"dpinger[93206]: WAN_DHCP redacted: Alarm latency 9869us stddev 3911us loss 51%"
"2024-01-16 18:46:17"	"Warning"	"redacted"	"dpinger"	"dpinger[89635]: WAN_DHCP redacted: Alarm latency 0us stddev 0us loss 100%"
[...]

J’ai tronqué les résultats pour l’esthétique de cette page (et remplacé les informations privées par « redacted »). J’ai eu bien plus d’alertes que cela, en l’espace d’un mois.

Je voulais aussi connaître la durée de ces incidents. Je n’ai malheureusement pas directement cette information dans les logs de pfSense, avec ma configuration spécifique. En revanche, ma configuration spécifique me permet d’approximer cette durée avec une analyse un peu plus élaborée des logs. Pour expliquer en détail comment, j’ai besoin de décrire en partie comment mon réseau est configuré:

En simplifiant, la partie WAN de mon réseau (accès à Internet) est composée d’une passerelle (gateway) nommée « WAN_DHCP » qui est la passerelle principale, connectée à ma box Internet (anciennement SFR, puis plus récemment Orange), et de deux passerelles virtuelles « VPN1_WAN » et « VPN2_WAN » qui sont des clients OpenVPN. Ces deux dernières étant regroupées en un groupe de passerelles nommé « VPN_WAN_Group ». Cela permet de faire du load-balancing et du failover: quand les deux clients OpenVPN sont opérationnels, les connexions sortantes sont réparties entre les deux clients; quand un client n’est plus opérationnel, les connexions sortantes passent par le client restant. Les deux clients OpenVPN me permettent de chiffrer et d’anonymiser (au moins en partie) mon trafic Internet. Je n’ai aucune activité qui nécessite spécialement de cacher mon trafic, mais j’aime compliquer la vie du ciblage marketing et les autres formes de tracking; j’utilise aussi le très efficace pfBlockerNg de pfSense, mais l’ajout d’un VPN d’un pays étranger ajoute une belle surcouche: par exemple les publicités qui ne sont pas bloquées par pfBlockerNg sont dans une langue que je ne comprends pas (dans mon cas, en langue germanique dont je ne comprends pas un mot), ainsi même mon subconscient y est moins sensible!

Dans pfSense, il est possible de surveiller la connectivité de chaque passerelle pour le failover. Le failover n’a d’intérêt que si l’on a plus d’une passerelle, sinon pfSense désactive l’unique passerelle utilisable, ce qui aurait généralement pour effet de rallonger le temps de rétablissement de la connectivité (à cause de la surcouche de pfSense). De ce fait, « WAN_DHCP » est surveillé, mais n’a pas de failover. C’est pourquoi je n’ai dans mes logs que des alertes de type « WAN_DHCP Alarm latency […] » (sans début et fin d’incident). En revanche, comme j’ai un groupe « VPN_WAN_Group » avec mes deux clients OpenVPN, les logs sont plus précis et indiquent quand un client est défaillant, et sorti du groupe, et quand il est de nouveau opérationnel, et réintégré au groupe. Par exemple: 


SELECT created_on, severity, host, app, msg FROM v_syslog_msg 
	WHERE 
        created_on::date BETWEEN '2024-01-01' AND '2024-01-31'
        AND
        (
	        (app = 'rc.gateway_alarm' AND msg LIKE '%Gateway alarm: WAN_DHCP%')
	        OR 
	        (app IN ('php-fpm', 'php-cgi') AND msg LIKE '%VPN_WAN_Group%')
        )
	ORDER BY created_on ASC


"created_on"	"severity"	"host"	"app"	"msg"
"2023-12-29 16:03:33"	"Informational"	"redacted"	"rc.gateway_alarm"	"rc.gateway_alarm[2328]: >>> Gateway alarm: WAN_DHCP (Addr:redacted Alarm:down RTT:0ms RTTsd:0ms Loss:100%)"
"2023-12-29 16:03:35"	"Error"	"redacted"	"php-fpm"	"php-fpm[98063]: /rc.filter_configure_sync: MONITOR: VPN1_WAN has packet loss, omitting from routing group VPN_WAN_Group"
"2023-12-29 16:03:35"	"Error"	"redacted"	"php-fpm"	"php-fpm[98063]: /rc.filter_configure_sync: MONITOR: VPN2_WAN has packet loss, omitting from routing group VPN_WAN_Group"
"2023-12-29 16:04:22"	"Error"	"redacted"	"php-fpm"	"php-fpm[68513]: /rc.filter_configure_sync: MONITOR: VPN1_WAN is available now, adding to routing group VPN_WAN_Group"
"2023-12-29 16:04:24"	"Error"	"redacted"	"php-fpm"	"php-fpm[88619]: /rc.newwanip: MONITOR: VPN2_WAN is available now, adding to routing group VPN_WAN_Group"
[...]

Mon idée a donc été de faire un petit script basé sur la sortie de la requête SQL précédente, pour estimer une durée approximative de chaque incident qui répond aux conditions suivantes: VPN1_WAN, VPN2_WAN et WAN_DHCP défaillants dans la même fenêtre temporelle. Je teste cette dernière condition sur WAN_DHCP pour éviter de comptabiliser un incident au cas où les deux clients OpenVPN seraient défaillants sans que ce soit lié à une perte de connectivité à Internet proprement dit.

Ce script m’a permis d’estimer que la plupart des pertes de connexion Internet que j’ai eu ont duré entre une et deux minutes. Je suppose que c’est approximativement le délai de redémarrage ou de re-synchronization de ma box Internet (celle de SFR). Et qu’il y a eu 3 incidents majeurs en un mois avec une coupure plus longue. Je n’ai pas de précision de durée sur ces 3 grosses coupures car j’utilise dans ce cas une connexion de secours en 5G, que je dois brancher manuellement sur pfSense, en remplacement de la connexion WAN de ma box Internet, car je fais tourner pfSense sur un mini pc qui n’est équipé que de deux interfaces réseau physiques – une pour le WAN et une pour le LAN (je rappelle que c’est un réseau domestique, avec des moyens raisonnablement limités).

Mon programme SyslogFilesToSql tourne dans un cluster mono-noeud MicroK8S sur un mini PC (j’ai aussi testé k3s et les deux fonctionnent, je n’ai pas d’avis sur la question). Le répertoire des fichiers syslog du NAS est monté via un volume NFS. Le mode de fonctionnement du programme fait qu’on peut le couper et le lancer ponctuellement (il rattrapera son retard au prochain lancement). Un exemple de manifeste de déploiement pour Kubernetes est inclu dans le dépôt GitHub de SyslogFilesToSql.

Depuis que j’ai changé de fournisseur, SFR à Orange, je n’ai pas eu de nouvel incident. C’était donc dans mon cas utile de changer. Je précise que cet article n’a pas pour but de dire qu’Orange est mieux que SFR, cela dépend probablement de beaucoup de facteurs dont, essentiellement je pense, votre localisation géographique.

SyslogDecode pour le parsing

Pour le parsing proprement dit des fichiers, j’ai utilisé la librairie SyslogDecode. Celle-ci présente l’avantage de supporter beaucoup de variantes de messages Syslog. Je ne pense pas qu’elle soit parfaite, mais nul doute qu’elle est beaucoup mieux que ce que j’aurai pu implémenter en peu de temps pour ce projet personnel.

Bugs propres aux implémentations de serveur Syslog

J’ai eu la « chance » de tester mon programme à partir d’un stock de plus de 200 fichiers syslog, et plus de 2 Go de messages (car il se trouve aussi que j’avais ponctuellement augmenté la verbosité de certains services de pfSense), avec un volume de messages importants au passage à la nouvelle année 2024.

Cela m’a permis de découvrir un bug intéressant: des dates incohérentes peuvent être écrites par le serveur syslog géré par le NAS QNAP. Voici un échantillon plus parlant:


<30>1 2023-12-31T23:59:55+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:3] info: Verified that unsigned response is INSECURE
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:3] info: resolving redacted. AAAA IN
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:3] info: resolving redacted. AAAA IN
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:1] info: resolving redacted. A IN
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:1] info: resolving redacted A IN
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:3] info: reply from  redacted#53
<30>1 2024-12-31T23:59:57+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:3] info: query response was nodata ANSWER
<30>1 2024-01-01T00:00:00+01:00 10.15.50.1 unbound 47362 - - unbound[47362]: [47362:2] info: resolving redacted. PTR IN

On peut voir plusieurs messages avec une date d’un an dans le futur « 2024-12-31 ».

Après quelques recherches, je pense que ce bug est dû au fait que le serveur syslog du NAS écrit ses fichiers au format plus récent RFC 5424, où l’année est incluse dans la date, et que pfSense génère ses messages au format RFC 3164, où l’année n’est pas incluse dans la date. Le serveur ajoute simplement l’année courante à la date incomplète. Lors du changement d’année, en cas de volume important de messages ou si l’heure système n’est pas parfaitement synchronisée entre le serveur syslog et ses clients, on obtient ce résultat incohérent.

Bien que non observé en pratique dans mon cas, l’inverse semble être tout autant possible, à savoir un serveur syslog légèrement en retard, qui aurait alors écrit la date « 2023-01-01 » au lieu de « 2024-01-01 ».

J’ai donc implémenté une correction des dates lors de l’import, si l’un de ces deux cas de figure se produit au sein d’un même fichier à importer. J’ai d’ailleurs dû modifier SyslogDecode pour utiliser le type DateTimeOffset à la place du type DateTime pour les timestamps des messages, et pour ne pas normaliser les heures en UTC. Cela simplifiait beaucoup la correction à effectuer (comme nous avons à Paris une heure de décalage par rapport à UTC, la date incorrecte « 2023-01-01 00:00:00 » du second cas de figure était normalisée en « 2022-12-31 23:00:00 »).

Je suppose que ce « bug » est présent dans de nombreux systèmes syslog où les deux normes RFC 3164 et RFC 5424 cohabitent. C’est sans conséquence quand c’est du texte dans un fichier, mais cela était beaucoup plus gênant une fois importé en base de données (avec en plus la gestion des tables partitionnées par date).

Dépôt SyslogFilesToSql sur GitHub: https://github.com/eric-b/syslog-files-to-sql

← 
 →