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 . Ă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 đ§ . Ă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 đ§ . Ă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 . ĂvaluĂ©Â Ă Â 3.
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 đ§ . ĂvaluĂ©Â Ă Â 1.
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 . Ă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 . ĂvaluĂ©Â Ă Â 1.
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 . Ă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&sect=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&sect=1, lĂ : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd&sect=1, lĂ : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd-journald.service&sect=8, lĂ : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd.journal-fields&sect=7 et lĂ : http://www.dsm.fordham.edu/cgi-bin/man-cgi.pl?topic=systemd-system.conf&sect=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.
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.