Les fichiers de log du Scheduler sont situés dans le dossier /var/log/shinken/. Pour plus d'informations, consultez la page Fichiers Logs.
Au démarrage et tous les jours à minuit, ce log indique la version ainsi que le numéro de patch cumulatif du démon.
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] Daemon version 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 : [ scheduler-name ] [START-DAEMON] The daemon (version=02.08.02-release.fr) is now started as a daemon (detached from any shell) with pid=15412 [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SYSTEM ] 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 : [ scheduler-name ] [ SYSTEM ] System resource number of processes/threads is set to (soft:unlimited / hard:unlimited ) (set at system max values) |
Avec comme informations principales:
S'il écoute sur toutes les interfaces:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [schedulerdeamon] The daemon listens on all network interfaces. |
S'il écoute sur une interface précise:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [schedulerdeamon] The daemon listens on the IP_INTERFACE:PORT_INTERFACE network interface. |
Les logs suivants permettent de suivre le chargement de la configuration de supervision entre l'Arbiter et les Schedulers jusqu'aux interfaces : webui / livestatus / livedata.
Il existe 2 types d'identifiants de configuration ( représentation de la configuration ).
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The arbiter send us a new configuration: [ configuration_part_id=configuration_part_id, configuration_uuid=configuration_uuid, arbiter=arbiter_name, architecture=architecture_name, date=creation_date] |
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-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 scheduler n'est pas de la même version que l'arbiter et que l'option *mismatch_version_error* est désactivé sur l'arbiter:
[YYYY-MM-DD HH:MM:SS] WARNING : [ scheduler-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]. |
Le log suivant apparaît si le Scheduler n'a pas fini de charger sa configuration est qu'il reçoit une demande de statut
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [scheduler][0] Someone asks to get the raw stats (deamon Health) but the scheduler is not initialized |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The configuration [ shard_id=shard_id, scheduler=scheduler, configuration_uuid=configuration_uuid, arbiter=arbiter_name, architecture=architecture, date=creation_date, active=active] was loaded in [loading_time]s |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The configuration [shard_id=256, scheduler=scheduler-master, configuration_uuid=c6e6edef648246c290ac252d623719f3, arbiter=arbiter-master, architecture=Shinken-groy-dev-02-07, date=09-06-2021 15:30:06, active=True] was loaded in [0.00109791755676]s |
Les modules de Broker ont besoin des Broks dit "initiaux" afin d'avoir une image complète des éléments de supervision (hôtes, checks, mais aussi timeperiod et commandes). Quand une nouvelle configuration est chargée par le scheduler, le Broker le détecte et demande une génération des broks initiaux. Ceci est visible par la log suivant:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ REGISTERING ] [ broker-master ] The Broker is registering for initial broks generation. ( Currently 1 registered ) |
La génération va commencer.
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ TIMING ] Generating initial broks for configuration [shard_id=256, scheduler=scheduler-name, configuration_uuid=60b36ae8df5f4090bd7ef5d576ee1a15, arbiter=arbiter-name, architecture=architecture-name, date=26-08-2022 16:13:27, active=True] (currently have 36 hosts and 463 services) |
Pendant ce temps, d'autres demandes vont se rajouter à la première si on a plusieurs Brokers.
Une fois la génération finie, on aura le log suivant:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ DONE ] [ Elapsed time=0.042s ] 241 initial broks are generated for 2 brokers: [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ DONE ] - broker-master [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ DONE ] - broker-secondary |
Et les Brokers seront prévenus qu'ils peuvent désormais revenir télécharger les broks:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ DONE ] [ broker-master ] The broker is warned that the generation is done and can be GET. [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ INITIAL BROKS ] [ GENERATING ] [ DONE ] [ broker-secondary] The broker is warned that the generation is done and can be GET. |
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 ]
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The scheduler-distant has not yet received any configuration from Arbiter. |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The scheduler-distant change it's configuration from configuration_uuid to new_configuration_uuid |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The scheduler-distant change it's configuration from 6ddbcbd9260e40d9a8a48e1eabc875a5 to 32ab5f3457fb4c3fbe2415d873ae199e |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ CONFIGURATION ] The scheduler-distant received a new configuration (uuid=073c072c6d524b38bb4c08b1fdfa7f89) |
La commande shinken-scheduler-export-data invoquée depuis le serveur de l'Arbiter permet de questionner les Schedulers pour extraire des données sur les éléments supervisés.
Lorsque cette commande est utilisée, les logs qui suivent permettent de voir la nature de la réponse faite par un Scheduler.
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ EXPORT DATA ] full export of XXX elements in X.XXXs from Arbiter IP〖XXX.XXX.XXX.XXX〗 |
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ EXPORT DATA ] anonymous export of XXX elements in X.XXXs from Arbiter IP〖XXX.XXX.XXX.XXX〗 |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ EXPORT DATA ] Request from Arbiter IP〖XXX.XXX.XXX.XXX〗fails. Scheduler is not ready (initialisation ongoing) |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ EXPORT DATA ] Request from Arbiter IP〖XXX.XXX.XXX.XXX〗fails. Scheduler is not ready (waiting for configuration) |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ EXPORT DATA ] Request from Arbiter IP〖XXX.XXX.XXX.XXX〗fails. Export is disabled by configuration parameter 〖scheduler__export_data__enabled〗 |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ EXPORT DATA ] Request from Arbiter IP〖XXX.XXX.XXX.XXX〗fails. The scheduler〖scheduler__export_data__password〗parameter is missing or void, that is forbidden for not anonymous request |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ EXPORT DATA ] Request from Arbiter IP〖XXX.XXX.XXX.XXX〗fails. Access token is not valid |
Les périodes de maintenance ont une incohérence entre non identifiée qui consiste à ce qu'une période de maintenance va être démarrée deux fois, ce qui va poser soucis lors de son arrêt (l'hôte/check sera dans un état incohérent). Pour l'instant, nous n'avons pas trouvé la source de l'incohérence, mais nous avons mis des protections pour les éviter et corriger.
Au chargement de la rétention, on aura une entrée "ERROR":
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-name ] [ DOWNTIME-INCOHERENCY ] The host Linux has bad downtime values (saved number of downtime=1, actual=0). We are fixing the values. Please report it to the support. |
Lors du second démarrage de la période de maintenance:
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-name ] [ DOWNTIME-INCOHERENCY ] The downtime [Downtime id=1596532528600972 active=active type=fixed start=Tue Aug 4 11:16:06 2020 - end=Tue Aug 4 12:15:06 2020] on moi got activated twice. This is a bug and MUST be reported to support for investigation. Thanks. |
Dans les deux cas, il faut récupérer les logs du Scheduler, et les donner en analyse au support Shinken.
Lorsque le Receiver envoie des commandes externes au Scheduler, il est possible que ce dernier n'ait pas reçu de configuration de la part de l'Arbiter et qu'il ne soit pas en capacité d'exécuter ces commandes. Dans ce cas-là, nous renvoyons cette entrée :
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ BUS COMMANDS ] Get external commands (like recheck, set acknowledge, etc) from the Receiver receiver-master but i am not ready. Waiting for configuration from Arbiter. |
Dans le cas où, les commandes ont pu être exécutées :
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ BUS COMMANDS ] Running 200 external commands (like recheck, set acknowledge, etc) received from the Receiver receiver-master |
Les commandes externes différentes des mise à jour de statut sont également listées :
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ EXTERNAL COMMAND ] received command [ COMMAND_NAME ] on [ ELEMENT ] with args [ OPTIONAL_PARAMETERS ] |
Les valeurs les plus courantes pour COMMAND_NAME sont les suivantes :
| COMMAND_NAME | Type d'élément | Action | |
|---|---|---|---|
| check | Définit une prise en compte sur un check | |
| check | Supprime une prise en compte sur un check | |
| check | Définit une période de maintenance sur un check | |
| check | Supprime une période de maintenance sur un check | |
| check | Force l'exécution de la vérification du statut d'un check | |
| host | Définit une prise en compte sur un hôte | |
| host | Supprime une prise en compte sur un hôte | |
| host | Définit une période de maintenance sur un hôte | |
| host | Supprime une période de maintenance sur un hôte | |
| host | Force l'exécution de la vérification du statut d'un hôte |
[2023-03-30 14:10:28] INFO : [ scheduler-supdesup2 ] [ EXTERNAL COMMAND ] received command [ Check acknowledge ] on [ Int-II - CLOUD - int-google-1/Load Average SSH ] with args [ 2,True,True,bmourgues,En cours de résolution ] |
[2023-03-30 14:12:18] INFO : [ scheduler-supdesup2 ] [ EXTERNAL COMMAND ] received command [ Check acknowledge deletion ] on [ Int-II - CLOUD - int-google-1/Load Average SSH ] with args [ ] |
[2023-03-30 14:13:30] INFO : [ scheduler-supdesup2 ] [ EXTERNAL COMMAND ] received command [ Create check downtime ] on [ Int-II - CLOUD - int-google-1/Load Average SSH ] with args [ 1680178443,1680181983,True,0,0,bmourgues,Mise à jour en cours ] |
[2023-03-30 14:15:42] INFO : [ scheduler-supdesup2 ] [ EXTERNAL COMMAND ] received command [ Delete check downtime ] on [ Downtime id=1680178410781868 active=active type=fixed start=Thu Mar 30 14:14:03 2023 - end=Thu Mar 30 15:13:03 2023 on Int-II - CLOUD - int-google-1/Load Average SSH ] with args [ ] |
[2023-03-30 11:01:04] INFO : [ scheduler-supdesup2 ] [ EXTERNAL COMMAND ] received command [ Schedule immediate check ] on [ Int-II - FRANCE - integration-1/Broker - broker-france-webui - Memory consumption ] with args [ 1680166864 ] |
Quand le broker demande les broks au Scheduler, ce dernier va avoir dans ses logs:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ GIVE BROKS ] [ broker-master ] Sending 5 broks (1.3kB) |
Si on se retrouve dans un cas où la limite du broks_packet_size est atteinte (sur les broks initiaux par exemple), on va avoir la ligne suivante:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ GIVE BROKS ] [ broker-master3 ] Sending 2588 broks (413.4kB) [chunk, still 1698 to send] |
En cas de problème de communication, il se peut qu'un paquet de broks soit perdu, dans ce cas, une réémission est faite pour éviter cette perte, on aura un WARNING suivant:
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ GIVE BROKS ] [ broker-master ] Packet number did mismatch "100d0ccf12de4665bf04f2150dcc97d5" != "0ca27bc3ea5440358c1194b5b7c3b4f4" : Re-sending broks (6.3kB) |
Dans la boucle du Scheduler, les logs ci-dessous permettent de connaître le temps d'exécution passé pour chaque action.
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] [ === Loop start === ] [ Loop number=7885 ] ===-===-===-===-===-===-===-===-===-===-===-===-=== [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] took [ 0.005 ]s to schedule checks, consume results and create broks [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] took [ 0.005 ]s to update items context ( downtimes, acknowledge, flapping, root_problems, business values ) [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] took [ 0.005 ]s to clean data ( cache, zombies, proxy, stats, notifications list ) [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] took [ 0.005 ]s to check environment and update stats ( satellite_thread, time, retention, orphan, modules ) [YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ SCHEDULER TIME ] [ === Loop stop === ] [ Loop number=7884 ] [PERF] [ 0.082 ]s |
Afin d'avoir toutes les informations de DEBUG sur les performances du Scheduler (boucle principale), il faut le lancer avec:
SHINKEN_LOG_SCHEDULER_RECURRENT_TIMES_FLAG=1 /etc/init.d/shinken-scheduler -d start |
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] WARNING : [ LOGGER ] [YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] ---------------------------------------------------------------------------------------------------- [YYYY-MM-DD HH:MM:SS] WARNING : [ LOGGER ] [ WRITING ] The log writes time 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 ] |
Dans le cas où le Scheduler détecte que des objets d'exécution de checks ne sont pas bien nettoyés dans l'index de lancement ( par rapport au temps ).
Ceci peut résulter en deux logs d'ERROR :
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-name ] [ SCHEDULING ] [ JOB-EXECUTION FAST INDEX ] The check XXXX is zombie without being cleaned (name=YYYY, was indexed at SSSSSS). Please report to your support. |
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-name ] [ JOB-EXECUTION FAST INDEX ] [ SCHEDULING ] [ JOB-EXECUTION FAST INDEX ] [PERF: lock aquired in 0.000s, done in 0.001s] Did remove 9 forgotten execution from 2 past seconds indexed (total number of seconds inside=63). |
Cette situation ne devrait pas être présente, donc nous vous conseiller d'activer des logs de debug plus détaillé concernant ce mécanisme via la variable d'environnement SHINKEN_LOG_SCHEDULER_JOB_EXECUTION_FAST_INDEX_FLAG
SHINKEN_LOG_SCHEDULER_JOB_EXECUTION_FAST_INDEX_FLAG=1 /etc/init.d/shinken-scheduler -d restart |
Nous vous conseillons de fournir ces logs détaillés à votre support pour analyse.
Sur des installations datant d'avant la 02.03.03-U01, des objets "notifications" pouvaient rester indéfiniment en mémoire dans le Scheduler, mais sans être lancés.
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [RETENTION] [myhost] The notification [Notification 557481183 status:scheduled command:VOID ref:unknown t_to_go:Tue Feb 2 07:49:19 2021 (creation=Fri Apr 28 02:19:56 2017) (is_master=False) (on myhost)] was detected as invalid (bug from old code), and was dropped. |
[YYYY-MM-DD HH:MM:SS] WARNING: [ scheduler-name ] [ NOTIFICATION ] The notification for NOM DE L'HOTE OU DU CHECK was not send because notification_period NOM DE LA PERIODE DE TEMPS do not provide a date in the next 366 days ( either in the past or nothing is defined, or days are excluded ). |
Ce log sera affiché qu'une fois par jour au max par éléments afin d'évité de stature les logs.
Si le démon n'arrive pas à charger les données de rétention, il va potentiellement perdre des données comme les notifications actuelles, les downtimes ou les acknowledge, ce qui est très visible pour les utilisateurs.
En l'état, on préfère tuer le démon afin qu'un spare puisse prendre le relai et fonctionner normalement.
Quand un scheduler s'arrête pour cette raison, il loggue:
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-master ] [ RETENTION ] Failed to load the retention data. Shutting down daemon: we prefer to shut the daemon and leave a spare take the role instead of start and loose data like notifications or downtimes. |
Afin d'éviter un crash du Scheduler après le chargement d'une mauvaise rétention avec un check ou un hôte qui possède trop de vérifications, on ignore les vérifications et on log le message suivant :
[YYYY-MM-DD HH:MM:SS] ERROR : [ scheduler-name ] [ RETENTION ] [ ANALYSE ] [ CHECKS_IN_PROGRESS ] [ monhote/check The check have too much executions (503 > warning limit=100). This can be a bug, please contact your support with a backup of your retention for verification. [ uuid=b3e7d3307d2211eca52d080027940ca8-f9c118de7d2311ec80c7080027940ca8 ] |
Si, suite à une demande du support, l'option pour forcer l'étalement des checks a été activée, le log suivant apparaîtra lors du premier chargement d'une configuration par le Scheduler:
[YYYY-MM-DD HH:MM:SS] INFO : [ scheduler-name ] [ MAINTENANCE ] [ CHECK SPREAD OUT ] Scheduler will force all check spread out |