Page History

Les fichiers de log du Poller sont situés dans le dossier /var/log/shinken/. Pour plus d'informations, consultez la page Fichiers Logs.

Logs spécifiques à ce démon au démarrage

Au démarrage et tous les jours à minuit, ce log indique la version ainsi que le numéro de patch cumulatif du démon., en plus des logs communs à tous les démons, le Poller indique l'état du logger optionnel d'exécution :

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ START-DAEMON ] Daemon[ LOGGERS versionCONFIGURATION is: XX.XX.XX-release.fr culmulative-patch-YY

Lors du démarrage du démon, une ligne est disponible:

] ---------------------------------------------------------
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ START-DAEMON ] [ LOGGERS TheCONFIGURATION daemon (version=02.08.01-release.fr) is now started as a daemon (detached from any shell) with pid=15412] Optional loggers activation :
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ SYSTEMSTART-DAEMON ] [ LOGGERS CONFIGURATION ]  - DISABLED : [ ]CHECK System resource number of open files is set to      (soft:1024       / hard:1024      ) (from parameter max_file_descriptor_limit)
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ SYSTEM           ] System resource number of processes/threads is set to (soft:unlimited  / hard:unlimited ) (set at system max values)

Avec comme informations principales:

• Sa version
• Son numéro de PID
• Ses limites systèmes en nombre de fichiers/socket ouvrables, et le nombre max de processus/threads

Gestion de la configuration

Premier chargement de la configuration

EXECUTION ]
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ START-DAEMON ] [ LOGGERS CONFIGURATION ] ---------------------------------------------------------

Ce logger peut être activé pour suivre l'exécution des commandes de vérification  ( voir la section Logs d'exécution des commandes de vérification ).

Au démarrage du démon, les lignes suivantes indiquent les limites systèmes qui sont appliquées :

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ SYSTEM           ] System resource number of open files is set to      (soft:1024       / hard:1024      ) (from parameter max_file_descriptor_limit)

Lorsque le Poller reçoit sa configuration pour la première fois, deux logs INFO sont affichés.

Le premier indiquant que nous rentrons dans la phase de chargement d'une nouvelle configuration.

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ 

SYSTEM 

          ] 

System resource number of processes/threads is set to (soft:unlimited  / hard:unlimited ) (set at system max values)

Avec comme informations principales:

• le nombre de fichiers/socket ouvrables,
• le nombre max de processus/threads.

Gestion de la configuration

Premier chargement de la configuration

Lorsque le Poller reçoit sa configuration pour la première fois, deux logs INFO sont affichés.

• Le premier indiquant que le Poller rentre dans la phase de chargement d'une nouvelle configuration.

  Code Block
  language js theme Confluence

• Le deuxième indiquant que nous avons reçu la configuration de l'Arbiter.

  Code Block
  theme Emacs
  [YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ CONFIGURATION ] The arbiter send us a new configuration: [configuration_uuid=configuration-uuid, arbiter=arbiter-name, architecture=architecture-name, date=YYYY-MM-DD HH:MM:SS]

Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est activée sur l'Arbiter:

Code BlockthemeEmacs

• [YYYY-MM-DD HH:MM:SS]

ERROR

• INFO : [ poller-name ] [ CONFIGURATION

Incompatible
daemon
version
:
Your
Arbiter
daemon
is
in

• ] ----- Loading the new configuration from the arbiter

• Le deuxième indiquant que le Poller a reçu la configuration de l'Arbiter.

  Code Block
  language js theme Confluence

  version [XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY]. Refusing this configuration.

  Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est désactivée sur l'Arbiter:

  Code Block
  theme Emacs
  [YYYY-MM-DD HH:MM:SS] WARNINGINFO : [ poller-name ] Incompatible daemon[ versionCONFIGURATION : Your Arbiter daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY].

Mise à jour de la configuration

• ] The arbiter send us a new configuration: [configuration_uuid=configuration-uuid, arbiter=arbiter-name, architecture=architecture-name, date=YYYY-MM-DD HH:MM:SS]

• Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est activée sur l'Arbiter:

  Code Block
  language js theme Confluence

Lorsqu'il y a une mise à jour de la configuration, deux logs en INFO sont affichés.

Le premier indiquant que nous rentrons dans la phase de chargement d'une nouvelle configuration.

Code BlockthemeEmacs

• [YYYY-MM-DD HH:MM:SS]

INFO

• ERROR : [ poller-name ] Incompatible

[

• daemon

CONFIGURATION

• version : Your Arbiter daemon is in version

] [ UPDATE ] ----- Loading a configuration update from the arbiter

• Le deuxième indiquant que nous avons reçu la configuration de l'Arbiter.

  Code Block
  theme Emacs
  [YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ CONFIGURATION ] [ UPDATE ] The arbiter send us a new configuration: [configuration_uuid=configuration-uuid, arbiter=arbiter-name, architecture=architecture-name, date=YYYY-MM-DD HH:MM:SS]

• [XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY]. Refusing this configuration.

• Dans Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est activée désactivée sur l'Arbiter:

  Code Block
  language js theme Confluence theme Emacs
  [YYYY-MM-DD HH:MM:SS] ERRORWARNING : [ poller-name ] Incompatible daemon version : Your Arbiter daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY]. Refusing this configuration.

  Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est désactivée sur l'Arbiter:

  Code BlockthemeEmacs

Mise à jour de la configuration

Lorsqu'il y a une mise à jour de la configuration, deux logs en INFO sont affichés.

• Le premier indiquant que le Poller rentre dans la phase de chargement d'une nouvelle configuration.

  Code Block
  language js theme Confluence
  [YYYY-MM-DD HH:MM:SS]

WARNING

• INFO : [ poller-name ] [ CONFIGURATION

Incompatible
daemon
version
:
Your
Arbiter
daemon
is
in
version

• ] [

XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY].

Mise à jour des liens vers d'autres démons

• UPDATE ] ----- Loading a configuration update from the arbiter

• Le deuxième indiquant que le Poller a reçu la configuration de l'Arbiter.

  Code Block
  language js theme Confluence

Lorsque l'Arbiter détecte un changement de lien entre les démons, quatre logs en INFO seront affichés.

• Les deux premiers logs affichent le(les) lien(s) du(des) démon(s) supprimé(s).

• [YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ CONFIGURATION

• ]

• [

• UPDATE ]

• The

• arbiter

• send

• us

• a

• new configuration: [configuration_uuid=configuration-uuid, arbiter=arbiter-name, architecture=

• architecture-name

• , date=YYYY-MM-DD HH:MM:SS]

• Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est activée sur l'Arbiter:

  Code Block
  language js theme Confluence

• Les deux premiers logs affichent le(les) lien(s) du(des) démon(s) ajouté(s).

• [YYYY-MM-DD HH:MM:SS] ERROR

• : [ poller-name ]

• Incompatible daemon

• version

• :

• Your

• Arbiter

• daemon

• is

• in

• version

• [

Récupération des checks

Pour récupérer les checks a exécuter

• XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY]. Refusing this configuration.

• Dans le cas où le Poller n'est pas de la même version que l'Arbiter et que l'option *mismatch_version_error* est désactivée sur l'Arbiter:

  Code Block
  language js theme Confluence
  [YYYY-MM-

• Poller actif
  
  • Le Poller va demander au Scheduler.
  • Le Poller indique un temps de travail qu'il a de disponible ( en temps cpu ).
  • Le Scheduler lui donne des checks pour le temps disponible ( suivant le temps d’exécution moyen pour les checks constatés sur ce poller ). Il lui donne pour un temps inférieur ou égal au temps disponible.
  • Un log permet d'avoir le nombre de checks récupérés. Ce log s'affiche même si aucun check n'a été récupéré :

• DD HH:MM:SS]

• WARNING

• : [ poller-name ]

• Incompatible

• daemon version : Your Arbiter

• daemon

• is

• in

• version [

• XX.XX.XX-release.fr culmulative-patch-YY] while this daemon is in version [XX.XX.XX-release.fr culmulative-patch-YY].

Mise à jour des liens vers d'autres démons

Lorsque l'Arbiter détecte un changement de lien entre les démons, quatre logs en INFO seront affichés.

• Les deux premiers logs affichent le(les) lien(s) du(des) démon(s) supprimé(s).

• Poller passif
  • Le Scheduler demande au Poller le temps CPU disponible.
  • Le Scheduler lui envoie des checks à traiter pour le temps disponible ( suivant le temps d’exécution moyen pour les checks constatés sur ce Poller ). Il lui donne pour un temps inférieur ou égal au temps disponible.
  • Si des checks sont reçus, un log permet d'avoir le nombre de checks récupérés selon le temps de travail disponible sur le Poller :

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ CHECKSCONFIGURATION ] The arbiter asked us to remove daemons: 
[ scheduler-master ] [ RECEIVEDYYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] We[ receivedCONFIGURATION checks] todo- from thisREMOVED scheduler for 2.000s cpu time [received=1 check(s) for 0.317s cpu time]

Envoi des résultats de checks au Scheduler

: [name=scheduler1-name] [shard_id= XXX] [uri=http://scheduler_address:port/] 

• Les deux premiers logs affichent le(les) lien(s) du(des) démon(s) ajouté(s).

• Poller actif
  • Une fois les commandes exécutées, le Poller envoie les résultats au Scheduler.
  • Un log permet d'avoir le nombre de résultats de checks envoyés au Scheduler et le temps mis pour être envoyé.

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ CHECKS RESULTS ] [scheduler-master] [ PUSHED ] 1 check's result(s) sends to this scheduler in [0.043]s CONFIGURATION ] The arbiter send us new daemons: 
[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ CONFIGURATION ] + ADDED scheduler : [name=scheduler2-name] [shard_id= XXX] [uri=http://scheduler_address:port/]

Récupération des checks

Pour récupérer les checks a exécuter

• Poller actif
  
  • Le Poller va demander au Scheduler.
  • Le Poller indique un temps de travail qu'il a de disponible ( en temps cpu ).
  • Le Scheduler lui donne des checks pour le temps disponible ( suivant le temps d’exécution moyen pour les checks constatés sur ce poller ). Il lui donne pour un temps inférieur ou égal au temps disponible.
  • Un
  Poller passif
  • Une fois les checks exécutés, le Poller stocke les résultats en attendant que le Scheduler vienne les récupérer.
  • A chaque tour de boucle du Scheduler, ce dernier demande au Poller s'il a des résultats de checks disponibles.
    
  • Si des résultats sont disponibles, un log permet d'avoir le nombre de résultats checks donnés au Scheduler.récupérés. Ce log s'affiche même si aucun check n'a été récupéré :

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ CHECKS RESULTS    ] [ scheduler-master ] [ GIVENGET ] 1Requesting check's resultchecks todo from this scheduler for 2.000s cpu time [received=3 check(s) givenfor to0.039s answer scheduler request

Surcharge serveur en activité disque, ralentissant l'écriture des logs

cpu time]

• Poller passif
  • Le Scheduler demande au Poller le temps CPU disponible.
  • Le Scheduler lui envoie des checks à traiter pour le temps disponible ( suivant le temps d’exécution moyen pour les checks constatés sur ce Poller ). Il lui donne pour un temps inférieur ou égal au temps disponible.
  • Si des checks sont reçus, un log permet d'avoir le nombre de checks récupérés selon le temps de travail disponible sur le Poller :

Si le serveur hébergeant le démon est surchargé en termes d'IO disques sur le volume qui héberge le fichier de log, alors ce dernier va mettre du temps à s'écrire et va ralentir tout le démon. Il faut alors si c'est faisable isoler le volume des disques sur un disque moins chargé pour ne pas ralentir le démon.

En cas de soucis, vous aurez dans les logs l'entrée suivante:

[YYYY-MM-DD HH:MM:SS] WARNINGINFO   : [ LOGGERpoller-name ]
[YYYY-MM-DD HH:MM:SS] WARNING : [ CHECKS ] [ scheduler-master ] [ LOGGERRECEIVED ] ----------------------------------------------------------------------------------------------------
[YYYY-MM- We received checks todo from this scheduler for 2.000s cpu time [received=1 check(s) for 0.317s cpu time]

Envoi des résultats de checks au Scheduler

• Poller actif
  • Une fois les commandes exécutées, le Poller envoie les résultats au Scheduler.
  • Un log permet d'avoir le nombre de résultats de checks envoyés au Scheduler et le temps mis pour être envoyé.

[YYYY-MM-DD HH:MM:SS] WARNINGINFO :  : [ LOGGERpoller-name ] [ WRITINGCHECKS RESULTS ] [scheduler-master] [ PUSHED ] 1 check's result(s) sends to this scheduler in [0.043]s

• Poller passif
  • Une fois les checks exécutés, le Poller stocke les résultats en attendant que le Scheduler vienne les récupérer.
  • A chaque tour de boucle du Scheduler, ce dernier demande au Poller s'il a des résultats de checks disponibles.
    
  • Si des résultats sont disponibles, un log permet d'avoir le nombre de résultats checks renvoyés au Scheduler.

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-name ] [ CHECKS RESULTS ] [scheduler-master] [ GIVEN ] 1 check's result(s) given to answer scheduler request

Surcharge serveur en activité disque, ralentissant l'écriture des logs

Si le serveur hébergeant le démon est surchargé en termes d'IO disques sur le volume qui héberge le fichier de log, alors ce dernier va mettre du temps à s'écrire et va ralentir tout le démon. Il faut alors si c'est faisable isoler le volume des disques sur un disque moins chargé pour ne pas ralentir le démon.

En cas de soucis, il sera écrit les lignes suivantes :

[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ]
[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] The log write times is very high (1.87s). Please look at your log disk performance.
[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] [ WRITING ] The log write times is very high (1.87s). Please look at your log disk performance.
[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] ----------------------------------------------------------------------------------------------------
[YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ]

Logs concernant les checks de vérifications Shinken

Quand un check de supervision du démon est fait, on va avoir plusieurs entrées dans les logs qui concernent des données que le démon garde sur diverses statistiques.

Un log permet d'avoir le temps pris sur le calcul des dernières commandes en timeout:

[YYYY-MM-DD HH:MM:SS] DEBUG : [ poller-name ] [ STATS         ] Compute "Checks in timeouts" stats : 0.000s in a total of 2048 commands in timeouts

Un log permet d'avoir le temps de calcul concernant les ranges d'exécution des checks/notifications en fonction du temps (<100ms, <400ms, etc):

[YYYY-MM-DD HH:MM:SS] DEBUG : [ poller-name ] [ STATS         ] Compute "Checks per CPU running time" : 0.000s (on a total of 2048 checks)

Un log permet d'avoir le temps de calcul pour avoir les 5 commandes les plus longues en temps CPU:

[YYYY-MM-DD HH:MM:SS] DEBUG : [ poller-name ] [ STATS         ] top5 execution time 0.003s (loop over 1 ranges and 343 elements)

Un dernier log permet d'avoir le temps complet du calcul des statistiques du démon:

• Sur une partie commune à tous les démons (version, chemins, etc.)
• Sur la partie qui concerne uniquement ce qui concerne ce démon, donc sont inclus ici les temps précédents
• Il est affiché en :
  • DEBUG: si le temps de calcul est inférieur à la valeur du paramètre display_statistics_compute_time_if_higher du démon.
  • INFO: si le temps de calcul est supérieur ou égal au paramètre display_statistics_compute_time_if_higher du démon.

[YYYY-MM-DD HH:MM:SS] DEBUG : [ poller-name ] [ STATS         ] Daemon stats were computed in 0.020s (0.001 for daemon common part, 0.020 for poller 
part)

En cas d'affichage INFO on met un petit morceau en plus sur comment gérer le niveau de log:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ STATS         ] Daemon stats were computed in 0.004s (0.000 for daemon common part, 0.004 for poller part) (NOTE: log is displayed in INFO because 0.004 is higher than display_statistics_compute_time_if_higher=1ms in the daemon cfg)

Le démon nettoie ses structures de statistiques toutes les 5minutes, ce qui sera vu par la ligne de log suivante:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ STATS        ] Clean checks in timeouts structure in 0.000s (before clean: 0 commands in timeouts, after clean: 0)

Suivi des lancement de sondes par les workers et de leur performances

Les Workers arrivent à lancer toutes leurs sondes ou se limitent

On peut savoir si les workers manquent de disponibilité CPU/RAM/Load average en suivant les logs.

Si on a manqué de performance ce tour (CPU, RAM ou load average trop élevé, indiqué), alors on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ ALL WORKERS ] [ MISSING RESSOURCE ] Must launch: 2 checks  ( Expected CPU Time: 1.318s ) => Launched: 1/2 checks => Wait 0.530s CPU/Memory availability

Sinon ils ont pu tout lancer, on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ ALL WORKERS ] Launched all 2/2 checks  (  Expected CPU Time: 1.318s )

PROBLEME: Un worker n'arrive pas à lancer ses checks

Si le worker n'a pas réussi à lancer de check pendant plus de 5 seconds on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] WARNING : [ poller-name ] [worker-fork] [WORKER_ID] is full since 〖X〗. It has 〖Y〗 checks pending.

ou : 

• WORKER_ID : est l'id du worker
• X : est la durée depuis lequel le worker n'a pas lancer de checks 
• Y : est le nombre de checks à lancer

Le total des sondes et leurs performances au sein du poller

On peut suivre les sondes au sein du Poller via le log suivant, pour les checks provenant des Schedulers & Synchronizers (cumulés, pour l'instant on n’a pas l'information sur toute la chaine du Poller):

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-master   ] [ PERFS ] [ FOR SCHEDULERS/SYNCHRONIZERS ] [ THIS TURN   ] [ Daemon ]       [ Waiting to be push to workers ]    8 checks, Expected CPU Time: 1.06s
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-master   ] [ PERFS ]                                  [ THIS TURN   ] => [ Workers ]   [ New launch =  9 checks, Expected CPU Time: 1.10s ] [ Executing =  6 checks, Expected CPU Time: 1.601s ] [ Just finished =  7 checks, Consumed CPU Time: 0.62s, +0.03s from Expected CPU Time ]
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-master   ] [ PERFS ]                                  [ THIS TURN   ] [ Daemon ]       [ Waiting to be returned ]          6 checks, Consumed CPU Time: 1.06s

Avec:

• Expected CPU Time= temps CPU pur ( sans les appels réseaux et autres sleep ) qu'on a mesuré en moyenne sur ce check
• Consumed CPU Time= vrai temps CPU mesuré sur CE dernier lancement
• +0.03s from Expected CPU Time = différence de temps CPU ( en + ou en - ) qu'on a eu par rapport à leurs exécutions moyennes passées
• Waiting to be push to workers = dans le processus maitre, avant d'être envoyé aux workers
• New launch = dans le worker, en attente d'être lancé
• Executing  = dans le worker, en cours d'exécution ( lancé ce tour, ou un tout d'avant )
• Just finished = fini dans ce tour-ci
• Waiting to be returned = dans le process maitre, en attente d'être renvoyés vers les Schedulers/Synchronizers

Et les mêmes informations, mais sur une moyenne d'une minute glissantes:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-master ] [ PERFS ] [ FOR SCHEDULERS/SYNCHRONIZERS ] [ 1min AVERAGE ] [ Daemon ] [ Waiting to be push to workers ] 14.42 checks/s, Expected CPU Time: 2.11s
[YYYY-MM-DD HH:MM:SS] INFO : [ poller-master ] [ PERFS ] [ 1min AVERAGE ] => [ Workers ] [ New launch = 5.98 checks/s, Expected CPU Time: 0.91s ] [ Executing = 5.10 checks/s, Expected CPU Time: 0.933s ] [ Just finished = 5.78 checks/s, Consumed CPU Time (total): 1.35s, +0.00s from Expected CPU Time ]
[YYYY-MM-DD HH:MM:SS] WARNINGINFO : [ poller-master ] [ PERFS ] [ 1min AVERAGE ] [ Daemon ] [ LOGGER ]

Logs concernant les checks de vérifications Shinken

Waiting to be returned ] 5.80 checks/s, Consumed CPU Time: 0.88s  

Note: on doit avoir des valeurs sensiblement équivalentes entre les valeurs suivantes:

• New launch
• Just finished
• Waiting to be returned

Et ils représentent le débit du Poller.

Logs de chargement des modules

Les démons ont une phase de chargement des modules qui est décrite dans la page GLOBAL - Les logs de gestion des modules - chapitre [ MODULES-MANAGER ]

Échanges entre le processus principal et les Workers

Suivi des actions en cours

Dans le démon (boucle principale)

Le log suivant indique

• le nombre d'actions présentes dans le démon principal
• le nombre d'actions traitées sur ce tour de boucle ainsi que le nombre total d'actions présentes par Worker
• le nombre total d'actions en cours de gestion (démon + Workers)

Quand un check de supervision du démon est fait, on va avoir plusieurs entrées dans les logs qui concernent des données que le démon garde sur diverses statistiques.

[YYYY-MM-DD HH:MM:SS] DEBUG : [ poller-name ] [ STATS         ] Compute "Checks in timouts" stats : 0.000s in a total of 2048 commands in timeouts

Un log permet d'avoir le temps de calcul concernant les ranges d'exécution des checks/notifications en fonction du temps (<100ms, <400ms, etc):

[YYYY-MM-DD HH:MM:SS] DEBUGINFO : [ poller-namemaster ] [ STATS ] action in main daemon to be dispatched to workers: [ XX ] Compute "Checks per CPU running time" : 0.000s (on a total of 2048 checks)

Un log permet d'avoir le temps de calcul pour avoir les 5 commandes les plus longues en temps CPU:

, distribution by worker [ WORKER XX: XX done this turn / XX total pending ] [ WORKER XX: XX done this turn / XX total pending ] total: [ XX ] 

Dans un Worker

Le log suivant indique le nombre d'actions présentes dans le Worker, ainsi qu'une estimation du temps CPU nécessaire à leur exécution

[YYYY-MM-DD HH:MM:SS] DEBUGINFO : [ poller-namemaster ] [WORKER STATSXX][COMMAND         TO PROCESS] top5 execution time 0.003s (loop over 1 ranges and 343 elements)

Un dernier log permet d'avoir le temps complet du calcul des statistiques du démon:

Worker load_todo_actions : X.XXX nb_action : XX

Problème temporaire de réception de résultats depuis les workers

Si un worker est surchargé, le log WARNING suivant sera généré, indiquant qu'il met trop de temps à retourner ses résultats :

• Sur une partie commune à tous les démons (version, chemins, etc.)
• Sur la partie qui concerne uniquement ce qui concerne ce démon, donc sont inclus ici les temps précédents
• Il est affiché en :
  • DEBUG: si le temps de calcul est inférieur à la valeur du paramètre display_statistics_compute_time_if_higher du démon.
  • INFO: si le temps de calcul est supérieur ou égal au paramètre display_statistics_compute_time_if_higher du démon.

[YYYY-MM-DD HH:MM:SS] DEBUGWARNING : [ poller-name ] [ STATS         ] Daemon stats were computed in 0.020s (0.001 for daemon common part, 0.020 for poller 
part)The worker 2 reception did fail this turn (IOError), skip to the next turn to receive more.

• Si ces logs WARNING sont sporadiques, ils ne sont pas un problème, les résultats sont juste récupérés à la seconde suivante.
• Si ces logs WARNING sont constants, ceci signifie que le worker est saturé.

Log de performance de la boucle du Poller

Les logs suivants permettent de suivre le temps d'exécution de la boucle principale du Poller

En cas d'affichage INFO on met un petit morceau en plus sur comment gérer le niveau de log:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ STATSPOLLER         ] Daemon stats were computed in 0.004s (0.000 for daemon common part, 0.004 for poller part) (NOTE: log is displayed in INFO because 0.004 is higher than display_statistics_compute_time_if_higher=1ms in the daemon cfg)

Le démon nettoie ses structures de statistiques toutes les 5minutes, ce qui sera vu par la ligne de log suivante:

TIME ] [ === Loop start === ] [ Loop number=XXX   ] ===-===-===-===-===-===-===-===-===-===-===-===-===
[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ STATSPOLLER TIME ] [ === Loop stop  === ] Clean[ checksLoop innumber=XXX timeouts structure in 0.000s (before clean: 0 commands in timeouts, after clean: 0)

Suivi des lancement de sondes par les workers et de leur performances

Les Workers arrivent à lancer toutes leurs sondes ou se limitent

Performance des boucles des Workers

Le log suivant permet de suivre l'activité de chaque Worker et de s'assurer que chacun continue de tourner

On peut savoir si les workers manquent de disponibilité CPU/RAM/Load average en suivant les logs.

Si on a manqué de performance ce tour (CPU, RAM ou load average trop élevé, indiqué), alors on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name ] [ ALLPOLLER WORKERSTIME ] [ MISSING RESSOURCEWORKERS ] MustLast launch:activity 2[ checks  ( Expected CPU TimeWORKER X: 1X.318sXXXs )ago, =>WORKER LaunchedY: 1/2 checks => Wait 0.530s CPU/Memory availability

Sinon ils ont pu tout lancer, on aura le log suivant:

Y.YYYs ago]

Un Worker est lent

Quand le tour de boucle d'un Worker n'a pas fini avant un certain délai, le log suivant signale la lenteur observée

[YYYY-MM-DD HH:MM:SS] INFOWARNING : [ poller-name ] [ ALL WORKERS POLLER TIME ] [ WORKER X ] Launchedis all 2/2 checks  (  Expected CPU Time: 1.318s )slow, last tick was X.XXXs ago, over limit of X.XXXs

Un Worker est en retard

Quand le tour de boucle d'un Worker prend beaucoup trop de temps, le log suivant signale le retard observé

Si le worker n'a pas réussi à lancer de check pendant plus de 5 seconds on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] WARNINGERROR : [ poller-name ] [worker-fork POLLER TIME ] [ WORKER_ID X ] is late, last fulltick sincewas 〖X〗X.XXXs Itago, hasover 〖Y〗limit checksof pendingX.

ou : 

• WORKER_ID : est l'id du worker
• X : est la durée depuis lequel le worker n'a pas lancer de checks 
• Y : est le nombre de checks à lancer

PROBLEME: Un worker n'arrive pas à lancer ses checks

Si le worker n'a pas réussi à lancer de check pendant plus de 5 seconds on aura le log suivant:

[YYYY-MM-DD HH:MM:SS] WARNING : [ poller-name ] [worker-fork] [WORKER_ID] is full since 〖X〗. It has 〖Y〗 checks pending.

ou : 

• WORKER_ID : est l'id du worker
• X : est la durée depuis lequel le worker n'a pas lancer de checks 
• Y : est le nombre de checks à lancer

Le total des sondes et leurs performances au sein du poller

Logs d'exécution des commandes de vérification

Gestion du logger

L'activation ou la désactivation du logger optionnel se fait via l'utilisation d'une commande curl depuis le shell.

Les paramètres requis sont :

• POLLER_IP : l'adresse IP ou le nom du serveur où tourne le Poller (ou localhot si le shell est lancé sur le serveur du Poller directement ) ,
• POLLER_PORT : le port du Poller,
• POLLER_PROTOCOLE :
  • https si le protocole HTTPS a été activé sur le démon ( voir le paramètre use_ssl  dans le fichier /etc/shinken/daemons/pollerd.ini du démon ),
  • http sinon,
• LOGGER_ID : l'identifiant du logger, soit :
  • CHECK_EXECUTION pour les commandes de vérification.

Le résultat de cette commande renvoie un document JSON.

Activation du logger

curl -s -k "POLLER_PROTOCOLE://POLLER_IP:POLLER_PORT/set_log_enable?logger_id=LOGGER_ID&enable=1"

curl -s -k "http://localhost:7771/set_log_enable?logger_id=CHECK_EXECUTION&enable=1"

La commande doit renvoyer la sortie :

{"message": "logger [Shinken] [CHECK EXECUTION CONTROL] is enabled"}

Log d'activation du logger

Quand le logger est activé, le log suivant est généré :

On peut suivre les sondes au sein du Poller via le log suivant, pour les checks provenant des Schedulers & Synchronizers (cumulés, pour l'instant on n’a pas l'information sur toute la chaine du Poller):

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-master   ] [ PERFS ] [ FOR SCHEDULERS/SYNCHRONIZERS ] [ THIS TURN   ] [ Daemon ]       [ Waiting to be push to workers ]    8 checks, Expected CPU Time: 1.06s
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-mastername ] [ INFO-DAEMON ] [ LOGGERS PERFSCONFIGURATION ]  - ENABLING  : [ XXXX EXECUTION ]

[2025-11-06 16:45:36] INFO   : [ poller-master ] [ INFO-DAEMON ] [ LOGGERS CONFIGURATION ]  - ENABLING  : [ CHECK EXECUTION ]

Désactivation du logger

curl -s -k "POLLER_PROTOCOLE://POLLER_IP:POLLER_PORT/set_log_enable?logger_id=LOGGER_ID&enable=0"

curl -s -k "http://localhost:7771/set_log_enable?logger_id=CHECK_EXECUTION&enable=0"

La commande doit renvoyer la sortie :

{"message": "logger [Shinken] [CHECK EXECUTION CONTROL] is disabled"}

Log de désactivation du logger

Quand le logger est désactivé, le log suivant est généré :

        [ THIS TURN   ] => [ Workers ]   [ New launch =  9 checks, Expected CPU Time: 1.10s ] [ Executing =  6 checks, Expected CPU Time: 1.601s ] [ Just finished =  7 checks, Consumed CPU Time: 0.62s, +0.03s from Expected CPU Time ]
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-mastername   ] [ PERFSINFO-DAEMON ] [ LOGGERS CONFIGURATION ]  -  DISABLING : [ XXXX EXECUTION         ]

[2025-11-06 16:58:23] INFO       : [ poller-master ] [ INFO-DAEMON ] [ THISLOGGERS TURNCONFIGURATION ]  ]- [DISABLING Daemon: ][ CHECK EXECUTION ]

État du logger

curl -s   [ Waiting to be returned ]          6 checks, Consumed CPU Time: 1.06s-k "POLLER_PROTOCOLE://POLLER_IP:POLLER_PORT/get_log_info?logger_id=LOGGER_ID"

curl -s -k "http://localhost:7771/get_log_info?logger_id=CHECK_EXECUTION"

La commande doit renvoyer une sortie du style :

[{"id": "CHECK_EXECUTION", "name": "[Shinken] [CHECK EXECUTION CONTROL]", "enable": true}]

Logs d'exécution

Exécution normale

Lorsqu'une commande s'exécute, et que le logger d'exécution a été activé, les logs suivants sont générés.

Si la commande termine avec un code de terminaison compris entre 1 et 3  ( inclus ), Shinken considère que la commande a fonctionné correctement ( voir la page Les Sondes, section "Code retour" ).

Avec:

• Expected CPU Time= temps CPU pur ( sans les appels réseaux et autres sleep ) qu'on a mesuré en moyenne sur ce check
• Consumed CPU Time= vrai temps CPU mesuré sur CE dernier lancement
• +0.03s from Expected CPU Time = différence de temps CPU ( en + ou en - ) qu'on a eu par rapport à leurs exécutions moyennes passées
• Waiting to be push to workers = dans le processus maitre, avant d'être envoyé aux workers
• New launch = dans le worker, en attente d'être lancé
• Executing  = dans le worker, en cours d'exécution ( lancé ce tour, ou un tout d'avant )
• Just finished = fini dans ce tour-ci
• Waiting to be returned = dans le process maitre, en attente d'être renvoyés vers les Schedulers/Synchronizers

Et les mêmes informations, mais sur une moyenne d'une minute glissantes:

[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-master ] [ PERFSWORKER X ] [ FORXXXXX SCHEDULERS/SYNCHRONIZERSEXECUTION ] [ 1min AVERAGEDONE ] [ DaemonUUID ] [ Waiting to be push to workersCOMMAND ] 14.42 checks/s, Expected CPU Time: 2.11s: CHEMIN_DE_LA_COMMANDE ...
[YYYY-MM-DD HH:MM:SS] INFO   : [ WORKER poller-masterX ] [ PERFSXXXXX EXECUTION ] [ 1min AVERAGEDONE ] => [ WorkersUUID ] [ NewSTATUS launch] =: 5.98 checks/s, Expected CPU Time: 0.91s ] [ Executing = 5.10 checks/s, Expected CPU Time: 0.933s ] [ Just finished = 5.78 checks/s, Consumed CPU Time (total): 1.35s, +0.00s from Expected CPU Time ]RESULTAT D'EXÉCUTION
[YYYY-MM-DD HH:MM:SS] INFO   : [ WORKER X ] [ XXXXX EXECUTION ] [ DONE ] [ UUID ] [ RESULT ] : SORTIE GÉNÉRÉE LIGNE 1
[YYYY-MM-DD HH:MM:SS] INFO   : [ poller-masterWORKER X ] [ XXXXX PERFSEXECUTION ] [ 1min AVERAGEDONE ] [ DaemonUUID ] [ Waiting to be returned RESULT ] 5.80 checks/s, Consumed CPU Time: 0.88s  

Note: on doit avoir des valeurs sensiblement équivalentes entre les valeurs suivantes:

• New launch
• Just finished
• Waiting to be returned

Et ils représentent le débit du Poller.

Logs de chargement des modules

Les démons ont une phase de chargement des modules qui est décrite dans la page GLOBAL - Les logs de gestion des modules - chapitre [ MODULES-MANAGER ]

Échanges entre le processus principal et les Workers

Suivi des actions en cours

Dans le démon (boucle principale)

Le log suivant indique

• le nombre d'actions présentes dans le démon principal
• le nombre d'actions traitées sur ce tour de boucle ainsi que le nombre total d'actions présentes par Worker
• le nombre total d'actions en cours de gestion (démon + Workers)

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-master ] [ STATS ] action in main daemon to be dispatched to workers: [ XX ], distribution by worker [ WORKER XX: XX done this turn / XX total pending ] [ WORKER XX: XX done this turn / XX total pending ] total: [ XX ] 

Dans un Worker

Le log suivant indique le nombre d'actions présentes dans le Worker, ainsi qu'une estimation du temps CPU nécessaire à leur exécution

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-master ] [WORKER XX][COMMAND TO PROCESS] Worker load_todo_actions : X.XXX nb_action : XX

Problème temporaire de réception de résultats depuis les workers

Exécution en erreur

Les commandes de vérification dont le code de terminaison n'est pas compris entre 0 et 3 ( inclus )  sont considérées comme non fonctionnelles ( voir la page Les Sondes, section "Code retour" ).

Il se peut que si un worker est chargé, il mette trop de temps à nous renvoyer un résultat, dans ce cas on aura le log WARNING suivant:

[YYYY-MM-DD HH:MM:SS] ERROR WARNING : [ WORKER X ] [ poller-name XXXXX EXECUTION ] [ ERROR ] The[ workerUUID 2] reception[ didCOMMAND fail] this turn (IOError), skip to the next turn to receive more.

La vérification du bon fonctionnement des workers est faite lors de l'envoi des checks, donc en cas de problème worker mort il sera détecté.

• Si ces logs WARNING sont sporadiques, ils ne sont pas un problème, les résultats sont juste récupérés à la seconde suivante
• Si ces logs WARNING sont constants, ceci signifie que le worker est surchargé, et alors le mécanisme de surcharge doit être activé également

Log de performance de la boucle du Poller

Les logs suivants permettent de suivre le temps d'exécution de la boucle principale du Poller

: CHEMIN_DE_LA_COMMANDE ...
[YYYY-MM-DD HH:MM:SS] ERROR  : [ WORKER X ] [ XXXXX EXECUTION ] [ ERROR ] [ UUID ] [ STATUS ] : RESULTAT D'EXÉCUTION
[YYYY-MM-DD HH:MM:SS] ERROR INFO : [ WORKER poller-nameX ] [ POLLERXXXXX TIMEEXECUTION ] [ ===ERROR Loop] start[ ===UUID ] [ RESULT Loop] number=XXX: SORTIE GÉNÉRÉE ] ===-===-===-===-===-===-===-===-===-===-===-===-===LIGNE 1
[YYYY-MM-DD HH:MM:SS] ERROR INFO : [ WORKER X ] [ XXXXX EXECUTION ] [ ERROR ] [ poller-name ] [ POLLER TIME UUID ] [ RESULT ] : SORTIE GÉNÉRÉE LIGNE 2

[2025-11-06 18:12:03] ERROR  : [ WORKER 2        ] [ ===CHECK LoopEXECUTION stop] [ ===ERROR ] [ Loop16049b9c632040b7822b80cb934c36ff number=XXX] [ COMMAND ] [PERF] [  X.XXX ]s

Performance des boucles des Workers

Le log suivant permet de suivre l'activité de chaque Worker et de s'assurer que chacun continue de tourner

[YYYY-MM-DD HH:MM:SS] INFO : [ poller-name: /usr/bin/bash ...
[2025-11-06 18:12:03] ERROR  : [ WORKER 2        ] [ POLLERCHECK TIMEEXECUTION ] [ WORKERSERROR ] Last activity [ WORKER16049b9c632040b7822b80cb934c36ff X: X.XXXs ago, WORKER Y: Y.YYYs ago]

Un Worker est en retard

Quand le tour de boucle d'un Worker n'a pas fini avant un certain délai, le log suivant signale la lenteur observée

[YYYY-MM-DD HH:MM:SS] WARNING] [ STATUS ] : 8 (ERROR)
[2025-11-06 18:12:03] ERROR  : [ poller-nameWORKER ]2 [ POLLER TIME ] [ WORKER X ] is[ slow,CHECK lastEXECUTION tick] was[ X.XXXs ago, over limit of X.XXXs

Un Worker est lent

Quand le tour de boucle d'un Worker prend beaucoup trop de temps, le log suivant signale le retard observé

[YYYY-MM-DD HH:MM:SS] ERROR : [ poller-nameERROR ] [ 16049b9c632040b7822b80cb934c36ff ] [ RESULT ] : failed to
[2025-11-06 18:12:03] ERROR  : [ WORKER 2        ] [ POLLERCHECK TIMEEXECUTION ] [ WORKER XERROR ] is[ late,16049b9c632040b7822b80cb934c36ff last] tick[ wasRESULT X.XXXs ago, over limit of X.XXXs] : execute on this system