Chargement des broks initiaux par un regenerator ( créateur d'objets des modules de broker ) et vérifier que c'est bien la même configuration charger entre les regenerators / Scheduler / Arbiter

Les logs suivants permettent de suivre le chargement de la configuration de supervision entre l'Arbiter les Schedulers jusqu'aux interfaces : webui / livestatus / livedata

Il existe 2 types d'identifiants de configuration (représentation de la configuration)

• configuration_uuid:  uuid de configuration totale générée par l'Arbiter
• configuration_part_id:  id de la partie de configuration géré par un Scheduler

Quand un module de broker avec un regenerator charge une nouvelle configuration :

[2020-05-15 16:29:49] INFO : [WebUI3] [ CONFIGURATION ] [ NEW ] [ REGENERATOR ] configuration part retrieved: [ configuration_part_id=configuration_part_id, scheduler=scheduler_name configuration_uuid=configuration_uuid, arbiter=arbiter_name date=creation_date ]

• configuration_part_id: id de la partie de configuration gérée par le Scheduler ( unique par Scheduler )
• scheduler_name: nom du Scheduler qui gère cette partie de la configuration
• configuration_uuid: uuid créée lors du démarrage de l'Arbiter qui correspond donc à l'id de la configuration gérée par l'Arbiter
• creation_date: date du démarrage de l'Arbiter
• arbiter_name: nom de l'Arbiter qui a créé cette configuration

[YYYY-MM-DD HH:MM:SS] INFO   : [WebUI3] [ CONFIGURATION ] [ NEW ] [ REGENERATOR ] configuration part retrieved : [ configuration_part_id=8, scheduler=scheduler-master configuration_uuid=fe5982b29bfb48cdadb35523799f7cec, arbiter=arbiter-master1 date=15-05-2020 16:13:40 ]

Quand un module de broker avec un regenerator rejette une configuration :

Dans le cas où la configuration d'un Scheduler est déjà gérée par un regenerator ( cas qui arrive si par exemple un module crash ), on redemande les broks initiaux.

Tous les modules vont recevoir la nouvelle configuration, mais ceux qui la gère déjà ne vont pas la recharger et vont loguer :

[YYYY-MM-DD HH:MM:SS] INFO : [WebUI3] [ CONFIGURATION ] [ NEW ] [ REGENERATOR ] No need to reload the configuration part because I already handle it [ configuration_part_id=configuration_part_id, scheduler=scheduler_name configuration_uuid=configuration_uuid, arbiter=arbiter_name date=creation_date ]

• configuration_part_id: id de la partie de configuration gérée par le Scheduler ( unique par Scheduler )
• scheduler_name: nom du Scheduler qui gère cette partie de la configuration
• configuration_uuid: uuid créée lors du démarrage de l'Arbiter qui correspond donc à l'id de la configuration gérée par l'Arbiter
• creation_date:  date du démarrage de l'Arbiter
• arbiter_name: nom de l'Arbiter qui a créé cette configuration

[YYYY-MM-DD HH:MM:SS] WARNING: [WebUI3] [ CONFIGURATION ] [ NEW ] [ REGENERATOR ] No need to reload the configuration part because I already handle it [ configuration_part_id=8, scheduler=scheduler-master configuration_uuid=fe5982b29bfb48cdadb35523799f7cec, arbiter=arbiter-master1 date=15-05-2020 16:13:40 ]

Temps de locks trop long entre la consommation des Broks et les requêtes des utilisateurs

Actuellement on ne sait pas consommer les broks, et répondre aux utilisateurs en même temps. On a donc une concurrence entre deux parties:

• Récupération et consommation des broks depuis le broker, et mise à jour des hôtes/checks/clusters (et tous les autres objets) depuis les informations des broks
• Réponses aux requêtes des utilisateurs ( parcours des hôtes, checks, clusters ... )

Un des principaux risques est une famine d'un des deux groupes d'actions:

• Si on ne fait qu'avaler des broks et ne jamais répondre aux utilisateurs, ceci va poser problème
• Symétriquement, si on ne fait que répondre aux utilisateurs, et jamais avaler des broks, on va avoir des informations périmées, voir, on ne finira jamais de consommer de nouvelles configurations

Le gestionnaire de lock essaie de partager au mieux le temps d'exécution entre les deux groupes, en cas de forte charge, des logs vont remonter les lenteurs observées

Quand on a trop de requêtes de lectures, et qu'elles ne rendent pas la main pendant plus de 30s aux broks, on aura un log suivant ( Brok BLOQUE par les requêtes ):

ERROR: [ ITEMS ACCESS ORDONNANCER ] [ LONG LOCK ] Broks management are waiting (1 thread) since 30s (> log error limit=30s) because HTTP resquests (20 threads) has the LOCK

Quand on a trop de consommation de Broks, et que les requêtes sont bloquées ( Requêtes utilisateurs BLOQUÉES par les Broks )

ERROR: [ ITEMS ACCESS ORDONNANCER ] [ LONG LOCK ] HTTP resquests are waiting (5 threads) since 30s (> log error limit=30s) because Broks management (1 thread) has the LOCK

Quand les requêtes en lecture mettent trop de temps à rendre la main au consommateur de Broks et que d'autres requêtes en lecture attendent de pouvoir s'exécuter depuis trop longtemps :

ERROR: [ ITEMS ACCESS ORDONNANCER ] [ LONG LOCK ] Still have 9 running tasks ongoing (HTTP resquests). => ( 1 ) Broks management and then ( 11 ) HTTP resquests are waiting since 30s (>= log error limit:30s)

Quand la consommation de Broks met trop de temps à rendre la main pour la gestion de requêtes en lecture, et que d'autres consommateurs attendent de s'exécuter depuis trop longtemps ( cas théorique, n'est pas supposé survenir en fonctionnement normal ) :

ERROR: [ ITEMS ACCESS ORDONNANCER ] [ LONG LOCK ] Still have 1 running tasks ongoing (Broks management). => ( 12 ) HTTP requests then ( 1 ) Broks management are waiting since 30s (>= log error limit:30s)

Gestion des broks

Information sur l'absorption des broks

Statistiques sur un traitement

Des broks on été traités, affichage de statistiques :

• nombre de broks traités
• temps d'attente du premier brok set
• nombre de brok set en retard récupérés, et le temps que ça a pris de les récupérer
• temps passé à dé-sérialiser les broks
• temps d'attente du lock avant de traiter les broks 
• temps passé pour traiter les broks 
• temps total
  
  

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI-6         ] [ MANAGE BROKS ] [PERF]  [ XXXX broks ] [ wait and get first set on queue=0.000s ] [ get 0 late sets on=0.000s ] [ unserialize=0.000s ] [ wait write lock=0.000s ] [ manage broks=0.000s ] [ total=0.000s ]

Nature des broks traités

Affichage du type des broks à traités

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI-6         ] [ MANAGE BROKS ] [PERF]                  => manage broks types : [brok_type_1=XXXX] [brok_type_2=XX] [...]

Exemple de log

L'absorption des broks a pris du retard

En cas de forte charge sur le serveur, ou lorsque des requêtes HTTP durent trop longtemps, le module peut prendre du retard sur la gestion des broks.

L'algorithme d'absorption des broks peut être paramétré via les paramètres webui_broks_getter_XXX du fichier de configuration du Module WebUI

Le mode de rattrapage pour récupérer les broks en retard s'active

Activation du rattrapage des broks en retard, on prend un brok set supplémentaire à traiter, on affiche :

• le nombre de broks dans le brok set 
• le temps passé pour récupérer le brok set sur la queue
• le nombre actuel de broks à traiter
• le nombre maximal de broks qu'on peut récupérer avant de les traiter
• le nombre de brok set encore en attente
  
  

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI-6         ] [ MANAGE BROKS ] [PERF] [LATE BROKS SETS]  Getting brok set with XX broks in 0.000s [time for read queue size=0.000s]. Total broks to process= XXX/max:XXXX. Broks sets in queue: X.

Le mode rattrapage a suffisamment de broks à traiter 

Rattrapage des broks en retard en cours, on a atteint/dépassé le nombre maximal de broks à récupérer, on les traite : 

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI-6         ] [ MANAGE BROKS ] [PERF] [LATE BROKS SETS] Late brok taken => limit reach : XX / limit: XXXXXX.

Après avoir traiter des broks, il en reste encore trop en attente

Après avoir traiter des broks, il reste trop de brok set en attente, on garde le lock et on continue l'absorption des broks en retard :

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI-6         ] [ MANAGE BROKS ] [PERF] Broks sets in queue after manage broks is XX. We keep the lock and continue the brok managing.

Demande des broks initiaux lors du redémarrage d'un module externe du Broker

Lors du redémarrage d'un module externe du broker, une demande est envoyée par le Broker aux Schedulers pour récupérer de nouveaux broks initiaux ( une demande par Scheduler ).

[YYYY-MM-DD HH:MM:SS] INFO   : [ broker-master ] [ GET BROKS        ] [ NEED DATA ] [ scheduler-name ] I ask for a initial broks generation to the scheduler with new daemon incarnation {u'shard_id': XXXX, u'configuration_incarnation_uuid': UUID} (old incarnation was {})

Les logs du module MongoDB

Erreurs

Si le module MongoDB n'arrive pas à se connecter à la base mongo définit dans son fichier cfg :

[YYYY-MM-DD HH:MM:SS] ERROR  : [ WebUI           ] Mongodb Module: Error : [ WebUI            ] [ MONGODB          ]   - mongo connection failure to 192.168.1.87:27017

Les logs du module event-manager-reader

Erreurs

Dans le cas où un utilisateur demande une requête trop grande aux events ( en tapant un filtre trop large dans le nom, matchant plus de 50000 host/checks/clusters ), alors la WebUI va générer un log de WARNING affirmant que la recherche est trop large, et que MongoDB risque de refuser la requête si elle est effectuée avec des uuids. Elle sera donc fait avec des regexp côté base de données, ce qui est très lent.

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI ] [ event_container ] [ FAST-SEARCH ] [user=admin] [filter=type:check^^host~host_name:BiBi] The filter match too much uuids to query mongodb (101 > 100000) we must fallback to the slower regexp based query.

Les log des appels de performances

Note : ces log sont désactivé par défaut voir la page : Activation/Désactivation des parties de log pour les activer

[YYYY-MM-DD HH:MM:SS] INFO   : [ WebUI           ] [ UI MANAGEMENT    ] [ QUERY ] [ PERF ] [ NOM_DE_L'APPEL        ] [ user UUID= UUID_DE_L'UTILISATEUR_QUI_A_FAIT_LA_REQUETE ] [ start= 15:18:48  end= 15:18:48  Total= 0.000s  { lock wait= 0.000s  running time= 0.000s } ]

log de performance de la liste

Note ce log s'affichera en DEBUG par défaut et en WARNING si l'appel à la liste prend plus de 1s :

[YYYY-MM-DD HH:MM:SS] WARNING : [ WebUI           ]  [ CP Server Thread-74    ] [ user= 30067cfe5adf11e59a28080027f08538 ] [ get_data_visualisation_list ] [ PERF ] [ 0.007s ] elements:[ in broker= 54 filtered= 54 total= 54 in page= 54 ] page:[ 1 / 1 ] filter:[  ] sort:[  ]

log de performance du conteneur d'événements

Note ce log s'affichera en DEBUG par défaut et en WARNING si la requête au conteneur d'événements prend plus de 30s

[2021-04-08 13:34:47] WARNING: [ WebUI           ] [ event-manager-reader ] [ user=30067cfe5adf11e59a28080027f08538 ] [ get_events ] [ PERF ] [ 31.064s ] 100 events returned with filter:[{"filter0":"type:host","filter1":"event_since:latest|3600~type:check~realm:All"}]

Erreurs lors du lancement du module WebUI

Le port de la WebUI est déjà ouvert

Si une autre WebUI utilise déjà le port ( sûrement un problème de configuration ), alors on aura les WARNING suivants:

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 1/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use
[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 2/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 3/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 4/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 5/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 6/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 7/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 8/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

[YYYY-MM-DD HH:MM:SS] WARNING: [ WebUI2 ] [TRY 9/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

Puis lors du dernier essai une ERROR (le module s'arrête):

[YYYY-MM-DD HH:MM:SS] ERROR : [ WebUI2 ] [ CRASH - INSIDE MODULE PROCESS ] [TRY 10/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

Enfin l'erreur sera rapportée par le Broker qui va s'assurer que le module est éteint, et tenter de le relancer plus tard:

[YYYY-MM-DD HH:MM:SS] ERROR : [ broker-master ] [ MODULES-MANAGER ] [ MODULE-INSTANCE-CRASH ] [ WebUI2 ] [ module_type=webui ] The module WebUI2 just stopped. Last ERROR received:

[YYYY-MM-DD HH:MM:SS] ERROR : [ broker-master ] [ MODULES-MANAGER ] [ MODULE-INSTANCE-CRASH ] [ WebUI2 ] [ module_type=webui ] [TRY 10/10] The webui named [WebUI2] can not start because the address 0.0.0.0:7767 is already in use

Erreurs issues d'un problème de changement dans le code de la WebUI (problème de DEV), ou d'une installation cassée si chez un client

Si le fichier index.html est cassé chez un client, ou qu'un développeur a changé ce fichier sans faire attention, on aura des erreurs spécifiques.

Si le fichier index.html est manquant:

[YYYY-MM-DD HH:MM:SS] ERROR : [ WebUI2 ] [ CRASH - INSIDE MODULE PROCESS ] The file /var/lib/shinken/modules/webui/htdocs/ui/index.html is missing: there is a critical error with your installation. Please open a ticket to your support.

Si le fichier index.html n'a pas les bons droits (l'utilisateur shinken ne peux pas l'ouvrir):

[YYYY-MM-DD HH:MM:SS] ERROR : [ WebUI2 ] [ CRASH - INSIDE MODULE PROCESS ] Cannot open the file /var/lib/shinken/modules/webui/htdocs/ui/index.html with the error "ERROR": there is a critical error with your installation. Please open a ticket to your support.

Si le fichier index.html n'a pas la bonne variable ( soit erreur du DEV, soit le fichier du client a été modifié pour une raison )

[YYYY-MM-DD HH:MM:SS] ERROR : [ WebUI2 ] [ CRASH - INSIDE MODULE PROCESS ] The __shinken_lang__ variable was not found in the file /var/lib/shinken/modules/webui/htdocs/ui/index.html: there is a critical error with your installation. Please open a ticket to your support.

Erreurs de paramétrage

Si certains paramètres sont mal définis, la WebUI ne peux pas démarrer et va s'arrêter sur une erreur critique, qui sera affichée dans le check du Broker ainsi que dans le healthcheck.

Si son paramètre lang n'est pas dans la liste autorisé ( fr, en ), on aura l'erreur suivante:

[YYYY-MM-DD HH:MM:SS] ERROR : [ WebUI ] [ CRASH - INSIDE MODULE PROCESS ] For the parameter "lang" the value "XXX" is not allowed. Values can be : "fr, en"