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.