Forum Linux.général systemd/journld ne capture pas tous les messages de la STDOUT

Posté par woffer 🐧 le 16 décembre 2015 à 14:52. Licence CC By‑SA.

Étiquettes :

déc.

2015

Bonjour à tous,

J'aimerai déléguer la gestion de mes logs à systemd/journald.
Donc, j'ai écrit un petit programme de test qui est une boucle infinie (ou pratiquement infinie) qui logue dans STDOUT un entier qui s'incrémente à chaque boucle.
C'est un programme en go (mais ça aurait pu être en C ou autre chose) :

package main

import (
    "fmt"
    "math"
    "time"
)

func main() {
    for i := uint64(0); i < math.MaxUint64; i++ {
        fmt.Println(i)
        time.Sleep(5 * time.Millisecond)
    }
}

Je le lance avec le fichier unit suivant:

[Unit]
Description=log testing
After=syslog.target network.target

[Service]
Type=simple
ExecStart=/tmp/log_testing
WorkingDirectory=/tmp/

[Install]
WantedBy=multi-user.target

Lorsque je lance le programme avec la commande suivante : systemctl start log_testing.service
Et que je regarde les log dans journald via : journalctl -u log_testing.service

Et bien il y a des log manquants :

déc. 15 16:34:32 ... log_testing[29722]: 0
déc. 15 16:34:32 ... log_testing[29722]: 1
déc. 15 16:34:32 ... log_testing[29722]: 2
déc. 15 16:34:32 ... log_testing[29722]: 3
déc. 15 16:34:32 ... log_testing[29722]: 4
déc. 15 16:34:32 ... log_testing[29722]: 5
déc. 15 16:34:32 ... log_testing[29722]: 6
déc. 15 16:34:32 ... log_testing[29722]: 7
déc. 15 16:34:32 ... log_testing[29722]: 8
déc. 15 16:34:32 ... log_testing[29722]: 9
déc. 15 16:34:32 ... log_testing[29722]: 10

... j'ai juste enlevé ces lignes pour ne pas trop surcharger (donc toutes les lignes sont présentes entre 10 et 995) ...

déc. 15 16:34:37 ... log_testing[29722]: 995
déc. 15 16:34:37 ... log_testing[29722]: 996
déc. 15 16:34:37 ... log_testing[29722]: 997
déc. 15 16:34:37 ... log_testing[29722]: 998
déc. 15 16:34:37 ... log_testing[29722]: 999
déc. 15 16:34:37 ... log_testing[29722]: 1000   
déc. 15 16:35:02 ... log_testing[29722]: 5841    <-- içi, ce n'est pas le numéro attendu (donc il manque les lignes de 1001 à 5841)
déc. 15 16:35:02 ... log_testing[29722]: 5842
déc. 15 16:35:02 ... log_testing[29722]: 5843
déc. 15 16:35:02 ... log_testing[29722]: 5844
déc. 15 16:35:02 ... log_testing[29722]: 5845
déc. 15 16:35:02 ... log_testing[29722]: 5846
déc. 15 16:35:02 ... log_testing[29722]: 5847

Il semblerait que systemd/journald capture les messages par tranche de 1000 messages.
Savez-vous si c'est configurable ?
Par avance merci

# il te manque un flush quelque part.

Posté par totof2000 le 16 décembre 2015 à 15:42. Évalué à 6. Dernière modification le 16 décembre 2015 à 15:46.

C'est pas un problème systemd, mais de bufferisation des IO. Regarde en go comment faire pour faire un println qui ne soit pas bufferisé.

Exemple : https://gobyexample.com/writing-files : il y a un appel à sync ou flush. Je ne connais pas suffisamment go pour te répondre plus précisément, mais c'est un classique dans tous les langages.
- [^] # Re: il te manque un flush quelque part.
  
  Posté par woffer 🐧 le 16 décembre 2015 à 20:06. Évalué à 2.
  
  Je viens de demander à la liste de golang nuts https://groups.google.com/forum/#!topic/golang-nuts/0n8EkqakuTc
  D'après eux, c'est dû à un mécanisme d'anti-flooding genre 1000 msg par minute.
  
  Savez-vous où je peux trouver ce genre de configuration pour journald/systemd ?
  - [^] # Re: il te manque un flush quelque part.
    
    Posté par woffer 🐧 le 16 décembre 2015 à 20:30. Évalué à 1.
    
    Après une rechercher rapide, je pense que c'est la cause de mon pb :
    http://www.freedesktop.org/software/systemd/man/journald.conf.html#RateLimitInterval=
    
    J'essayerai d'ici la fin de semaine et je vous tiens au courant si ça corrige ou pas le pb.
    - [^] # Re: il te manque un flush quelque part.
      
      Posté par NeoX le 16 décembre 2015 à 21:03. Évalué à 3.
      
      D'après eux, c'est dû à un mécanisme d'anti-flooding genre 1000 msg par minute.
      
      facile a tester, envoi ton compteur 1 fois / secondes
      en une minute ca n'en fera que 60 ;)
    - [^] # Re: il te manque un flush quelque part.
      
      Posté par woffer 🐧 le 19 décembre 2015 à 12:34. Évalué à 1.
      
      Après une rechercher rapide, je pense que c'est la cause de mon pb :
      http://www.freedesktop.org/software/systemd/man/journald.conf.html#RateLimitInterval=
      
      J'essayerai d'ici la fin de semaine et je vous tiens au courant si ça corrige ou pas le pb.
      
      Le problème vient bien du mécanisme d'anti-flooding qui limite à 1000 messages par tranche de 30s (c'est la configuration par défaut).
      Il suffit juste de mettre la clef RateLimitBurst à 0 (sous Archlinux) dans le fichier /etc/system/journald.conf et de redémarrer journald. Et cela fonctionne.
      
      Ce n'est donc pas un problème venant de go.
      - [^] # Re: il te manque un flush quelque part.
        
        Posté par totof2000 le 19 décembre 2015 à 14:07. Évalué à 4. Dernière modification le 19 décembre 2015 à 14:08.
        
        Bon à savoir, merci pour le retour.
        
        Par contre systemd devrait peut-être être plus loquace sur ce sujet et logguer un truc du style "plus de 1000 messages reçus de xxxx durant la dernière mn, je blackliste". Ca éviterait certainement de se prendre la tête pendant des heures à chercher à comprendre ce qui se passe (surtout que ça doit etre un détail d'implémetation parmi tant d'autres caché au fin fond de la doc, ou peut-être même pas documenté).
        
        [^] # Re: il te manque un flush quelque part.
        
        Posté par ookaze le 21 décembre 2015 à 09:51. Évalué à 1.
        
        Par contre systemd devrait peut-être être plus loquace sur ce sujet et logguer un truc du style "plus de 1000 messages reçus de xxxx durant la dernière mn, je blackliste". Ca éviterait certainement de se prendre la tête pendant des heures à chercher à comprendre ce qui se passe (surtout que ça doit etre un détail d'implémetation parmi tant d'autres caché au fin fond de la doc, ou peut-être même pas documenté).
        
        Je trouve amusant de lire une telle réponse à un post qui cite le man de journald. Une réponse à priori négative comme quoi ce "détail d'implémentation", qui est en fait une protection parfaitement voulue et demandée, n'est peut-être pas documenté. Cette option est non seulement documentée, mais possède plusieurs options de contrôle qui lui sont propres.
        Un minimum d'expérience en administration pousse tout de suite vers du "rate limiting", mais surtout, envoyer autant de messages par secondes ne me paraît pas très sain si le seul objectif est de tester que les logs partent bien dans le journal. Si l'objectif était autre, j'ai dû rater cette information.
        En fait, journald se comporte comme les autres daemons de log, mais comme le résultat est plus simple à consulter avec journald, on repère vite des choses qui passaient inaperçues auparavant.
        
        [^] # Re: il te manque un flush quelque part.
        
        Posté par totof2000 le 21 décembre 2015 à 10:27. Évalué à 2. Dernière modification le 21 décembre 2015 à 10:28.
        
        Je persiste, il manque un message dans les logs (ou alors il existe et le PI ne l'a pas vu). Quand tu te retrouves à perdre des messages, tu ne vas pas forcément penser à ce genre de limitation. D'ailleurs, tu risques même de ne pas te rendre compte dans un premier temps que tu perds des logs, autrement qu'en faisant un test tel que le PI l'a fait. Et quand je parle de "un détail d'implémetation parmi tant d'autres caché au fin fond de la doc", mes propos sont peut-être mal choisis.Il est vrai que c'est indiqué dans le man de journald : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=journald.conf&ampsect=5 Par contre, lorsque tu vas voir le man de journald, tu te rends compte que tu as également de la doc systemd là : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=journalctl&ampsect=1, là : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd&ampsect=1, là : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd-journald.service&ampsect=8, là : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd.journal-fields&ampsect=7 et là : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd-system.conf&ampsect=5. Ca commence à faire beaucoup de doc à parcourir, et quand tu te trouves confronté à ce genre de problème, ça fait beaucoup à lire. Ton analyse peut d'ailleurs être faussée par d'autres choses que tu pourrais trouver bizarre et qui se passent autour. Tandis que si tu vois dans tes logs que tel process emet plus de X messages à la minute et qu'il est blacklisté, déjà tu sais que tu perds des logs (ce qui en soi est une information importante), et surtout tu sais pourquoi.
        
        En fait, journald se comporte comme les autres daemons de log, mais comme le résultat est plus simple à consulter avec journald, on repère vite des choses qui passaient inaperçues auparavant.
        
        Si les autres systèmes de log n'indiquent pas qu'ils blacklistent des process parce qu'ils recoivent trop de message de leur part, c'est également une erreur (pour le coup, ce n'est pas systemd ens soi que je critique, mais le principe de ne pas logger une information importante).

Suivre le flux des commentaires

Note : les commentaires appartiennent à celles et ceux qui les ont postés. Nous n’en sommes pas responsables.