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

Posté par  . Licence CC By‑SA.
1
16
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  . É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  . É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  . É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  . É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  . É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  . É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  . É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.

Suivre le flux des commentaires

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