Project

General

Profile

Websocketd 100% CPU

Added by Fip Fip 27 days ago

Bonjour,

Nous intégrer à un ERP déjà existant, des boutons executant des requêtes API et Websocket.

Nous travaillons avec Wazo 18.03, nous recevons une centaine d'appels en simultané (jusqu'à 200) et nous avons une quarantaine d'agents qui utilise la solution.

Pour authentifier les agents avec le Websocket, nous utilisons le token des agents.
En effet, nous avons mis en place une remontée de fiche qui fait appel au Websocket. Nous nous apercevons que le processus monte à 100% de charge sur la partie CPU et ne répond plus. Nous sommes dans l'obligation de reboot le service.

Nous sommes obligé de reboot plusieurs fois par jours le processus Websocket?

Est-ce que quelqu'un à déjà rencontré le problème?

Merci d'avance pour votre aide.


Replies (34)

RE: Websocketd 100% CPU - Added by Sylvain Boily 26 days ago

Bonjour,

Y a t'il des logs qui pourraient aiguiller ? Comme ça j'ai pas de réponse à donner, il faudrait chercher un peu plus loin. Nous avons fait des changements depuis la 18.03 qui pourrait avoir un effet sur la performance mais nous n'avons pas de data pour le confirmer. Si vous étiez capable de nous donner un peu plus d'infos pour le reproduire simplement (genre un script), nous pourrions mettre en place des tests et faire évoluer le service en terme de performance.

Sylvain

RE: Websocketd 100% CPU - Added by Fip Fip 21 days ago

Bonjour,
Merci pour ce retour rapide.
Nous utilisons les websockets afin de récupérer les informations d'appels (Décrocher / Raccrocher) et l'API pour les actions TOIP (Appeler, Transférer, Raccrocher, Loguer et Déloguer un agent).

Explication du fonctionnement

1/ Voici le détail des actions utilisées coté DEV de notre coté pour que vous ayez une meilleure visibilité sur les requêtes exécutées :
-----------
Accès à l'ERP
=> API /token : Génère un token admin
=> API /token : Génère un token utilisateur
=> API /agents/by-id : Récupération du statut de l'agent
=> WS : L'agent se connecte au websocket.

L'agent reçois un appel et le décroche
WS => Le websocket capte l'action "décrocher" et déclenche la mise "En ligne" de l'agent :
=> Spécial : Met le statut à "En ligne" mais n'effectue pas d'action API
=> Remonter fiche via le n° appelant

L'agent est en ligne et raccroche l'appel
WS => Le websocket capte l'action "raccroche" et mets le statut "Connecté" de l'agent :
=> Spécial : Met le statut à "Connecté" mais n'effectue pas d'action API

Action : Se connecté (start)
=> API /agents/by-id : LogON de l'agent

Action : Se déconnecté (stop)
=> API /agents/by-id : LogOFF de l'agent

Action : Passer un appel
=> API /users : On met à jour le outgoing de l'utilisateur pour qu'il sorte avec le n° du client
=> API /users/me/calls : On passe l'appel

Action : Raccrocher
=> API /calls : Raccroche l'appel

Action : Transfert l'appel
=> API /users/me/calls : Recherche de l'appel en cours
- Non :
=> API /users : On met à jour le outgoing de l'utilisateur pour qu'il sorte avec le n° du client
=> API /users/me/calls : On passe l'appel
.
-> L'agent transfert l'appel
=> API /transfers : Transfert "complete"
-> L'agent annule l'appel
=> API /transfers : Transfert "delete"
=> API /calls : On raccroche l'appel
-> Non :
=> API /transfers : On transfert directement.

2/ Nous avons ajouté un système de mise en cache pour alléger le nombre de quêtes API /calls
> Ceci permet de réduire le nombre de requête mais n'a pas d'impact positif sur notre problématique

Problématiques observées

Voici ce que nous constatons lors des fortes charges (200 appels, 40 agent en File d'attente) :
1/ l'API passe de 0.5sec de temps de réponse à 10-15 secondes lors de l’exécution d'une requête API /calls
2/ Le Websocket envois les informations d'appels en passant de 0.5sec à 60 secondes (augmente crescendo )

> La seule solution de contournement validée est le redémarrage du service Websocket WAZO qui permet de récupérer un fonctionnement correcte en attendant la prochaine charge.

Diagnostic
1/ Analyse des fichiers de configuration
Nous avons passé en revue les fichiers de configuration des modules Asterisk, Xivo, WAZO, Mongooseim, AMQP dans le but d'identifier des limites fixes sur le nombre de requêtes ou la taille du flux.
> Nous n'avons pas identifié de brides qui expliqueraient le comportement actuel.

2/ Analyse des logs
De nombreuses erreurs sont présentes dans les logs de ces différents modules mais difficile de savoir si elles sont causées par notre problématiques de "saturation/délais" ou par ce redémarrage "forcé" du web socket.
Voici quelques exemples :

  1. fichier : /var/log/xivo-ctid-ng.log =========================

2019-06-21 09:52:27,649 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 09:52:30,459 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 09:52:30,627 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 09:52:54,132 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 09:52:54,213 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 10:22:44,990 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 14:20:26,322 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 14:22:56,365 [23078] (ERROR) (ari.client): Event listener threw exception
2019-06-21 14:22:56,504 [23078] (ERROR) (ari.client): Event listener threw exception

  1. ZOOM sur une des erreurs ###

Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/ari/client.py", line 109, in __run
callback(msg_json, *args, **kwargs)
File "/usr/lib/python2.7/dist-packages/ari/client.py", line 224, in extract_objects
event_cb(obj, event, *args, **kwargs)
File "/usr/lib/python2.7/dist-packages/xivo_ctid_ng/plugins/transfers/stasis.py", line 119, in stasis_start
self.stasis_start_pubsub.publish(app_action, (channel, event))
File "/usr/lib/python2.7/dist-packages/xivo/pubsub.py", line 44, in publish
self.publish_one(callback, message)
File "/usr/lib/python2.7/dist-packages/xivo/pubsub.py", line 52, in publish_one
self._exception_handler(callback, message, e)
File "/usr/lib/python2.7/dist-packages/xivo/pubsub.py", line 49, in publish_one
callback(message)
File "/usr/lib/python2.7/dist-packages/xivo_ctid_ng/plugins/transfers/stasis.py", line 135, in transfer_recipient_answered
transfer_bridge.addChannel(channel=channel.id)
File "/usr/lib/python2.7/dist-packages/ari/model.py", line 43, in decorator
raise e
HTTPError: 400 Client Error: Bad Request for url: http://localhost:5039/ari/bridges/18fd9432-dc6f-4a34-978a-1f71239d7a93/addChannel?channel=1561124641.31292

=====================

  1. Fichier :/var/log/xivo-ctid.log

=============

2019-06-21 19:02:17,264 [22711] (ERROR) (xivo_cti.task): Unexpected exception raised while running task
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/xivo_cti/task.py", line 31, in run
self._function(*self._args)
File "/usr/lib/python2.7/dist-packages/xivo_cti/services/user/manager.py", line 137, in _on_new_presence
self.set_presence(user_id, user_uuid, auth_token, presence)
File "/usr/lib/python2.7/dist-packages/xivo_cti/services/user/manager.py", line 140, in set_presence
user_profile = self.dao.user.get_cti_profile_id(user_id)
File "/usr/lib/python2.7/dist-packages/xivo_cti/dao/user_dao.py", line 157, in get_cti_profile_id
return int(user['cti_profile_id'])
TypeError: int() argument must be a string or a number, not 'NoneType'

======================

Conclusion

Nous n'avons aujourd'hui plus de solution à court terme pour solutionner cette problématique.

1/ Avez-vous connaissance de certaines limites sur les modules de la solution Asterisk/XIVO/Mongo/AMQP/WAZO ?

2/ Ces erreurs vous parlent-elles ?

Merci d'avance pour votre aide

RE: Websocketd 100% CPU - Added by Sylvain Boily 20 days ago

Bonjour,

Merci pour ce retour très détaillé, nous allons en discuter en interne. Pour info MongoseIM n'est plus dans Wazo, ni xivo-ctid. On a changé pas mal de chose depuis la 18.03.

Sylvain

RE: Websocketd 100% CPU - Added by Fip Fip 20 days ago

Bonjour,

Merci, dans ce cas nous attendons votre retour.
Avez-vous un schéma fonctionnel qui détail l'utilisation des paquets et modules pour cette version 18.03 de Wazo ?

Nous n'avons pas trouvé de document précis qui détaille le cheminement d'un flux pour les accès aux API et Websocket.

Merci.

RE: Websocketd 100% CPU - Added by Sylvain Boily 20 days ago

La documentation pour le futur est maintenant sur http://developers.wazo.io. Nous avons commencé des schémas.

RE: Websocketd 100% CPU - Added by Fip Fip 20 days ago

Merci c'est schéma sont très intéressant.
Le point comment que je vois entre les Websocket et l'API est le bus RabbitMQ, à voir si cela est également valable en 18.03.

Le seul message récurrent que nous avons dans les logs RabbitMQ est de ce type :

=WARNING REPORT==== 1-Jul-2019::09:26:25 ===
closing AMQP connection <0.19891.4> (127.0.0.1:60860 -> 127.0.0.1:5672):
client unexpectedly closed TCP connection

RE: Websocketd 100% CPU - Added by Sylvain Boily 20 days ago

Oui les schémas ne sont pas valides pour 18.03 mais pour les dernières versions 19.08 et plus.

RE: Websocketd 100% CPU - Added by Fip Fip 18 days ago

Voici quelques éléments supplémentaires concernant notre analyse actuelle.

Nous avons regardé de prêt la partie RabbitMQ qui semble utilisée en tant que broker central sur toute la solution.
Il apparaît que lors des problématiques Websocket et API, nous atteignons entre 200 et 400 messages / secondes et certains messages restent en status UNACKED.

La capture ci-joint illustre l'un de ces PIC.
Lors des problématiques de ralentissements nous avons ces status UNACKED de manière régulière (toutes les 10 minutes, 50 messages UNACKED ).
L'un des channels principal qui présente ces statuts UNACKED est connecté sur le module "Wazo-call-logd".

RE: Websocketd 100% CPU - Added by Sylvain Boily 18 days ago

Est-ce que vous avez essayé d'arrêter ce service pour tester s'il est vraiment en cause ? Les logs ne seront pas perdu, ils vont se refaire à partir d'une cron.
Nous avons planifier de discuter de ce retour à notre prochaine itération pour voir si les versions récentes sont aussi impactés par ce problème de charge.

RE: Websocketd 100% CPU - Added by Fip Fip 18 days ago

Ce module est utilisé uniquement pour la gestion des logs ?

Cela n'aura aucun impact sur les requêtes API dans la section Calls et Mecalls ?

RE: Websocketd 100% CPU - Added by Sylvain Boily 18 days ago

Ce service offre les APIs pour aller chercher les infos dans le CDR. Cela va couper toutes actions autour des journaux d'appels ainsi que leur génération temporairement.

RE: RE: Websocketd 100% CPU - Added by Fip Fip 18 days ago

Je pense qu'une sécurité Interne relance le service "Wazo-call-logd".
Où doit-on désactiver le service pour empêcher ce redémarrage automatique ?

Cédric.

RE: Websocketd 100% CPU - Added by Sylvain Boily 18 days ago

Oui c'est monit qui surveille les processus.

monit unmonitor wazo-call-logd ou xivo-call-logd je ne sais plus le nom en 18.03.

RE: Websocketd 100% CPU - Added by Fip Fip 17 days ago

Malheureusement la désactivation du processus n'a pas eu d'effets positif sur les ralentissements.

La suite de notre diag nous a amené à surveiller 2 channels sur RabbitMQ.
Le premier est en publish et collecte jusqu'à 500 messages/seconde en provenance de xivo-amid.
Le seconde est en deliver et envoie ces 500 messages vers xivo-websocketd.

Le service de Websocket semble saturer et passer à 100% de CPU des que l'on dépasse les 300m/s de manière constant.

Existe-t-il un moyen de filtrer les messages envoyés par xivo-amid ?

Merci par avance de votre retour.

RE: Websocketd 100% CPU - Added by Sylvain Boily 17 days ago

Si tu essaies d'enlever des messages, tu auras potentiellement des choses qui ne marcheront plus.

On va creuser cette partie nombre de messages vers websocket.

Une solution temporaire pourrait être de sortir websocketd de ton serveur et de le mettre sur une machine plus puissante dédié.

RE: Websocketd 100% CPU - Added by Sylvain Boily 17 days ago

Et aussi de changer le reverse proxy nginx vers ce websocket. Cela sera transparent pour l'utilisateur final.

RE: Websocketd 100% CPU - Added by Sébastien Duthil 17 days ago

Salut,

il se passe quoi si tu systemctl stop mongooseim? Celui-ci est lié à wazo-websocketd et a tendance à lui pomper un peu trop de ressources, alors j'aimerais voir si ça vient de lui.
De la même manière, il se passe quoi si tu systemctl stop xivo-amid? Ça devrait arrêter le flot de messages qui proviennent de xivo-amid, j'aimerais déterminer si xivo-websocketd continue de prendre 100% CPU pendant longtemps ou s'il revient à la normale? Car s'il reste à 100%, ça indique une boucle infinie.

Oublie pas de systemctl start les services que tu éteins après :)

RE: Websocketd 100% CPU - Added by Fip Fip 15 days ago

Bonjour,

Merci pour ces axes de réflexions.
Le Websocket étant mono thread, le changer de machine ne changera certainement pas grand chose car nous sommes déjà sur un coeur à 3Ghz.

La désactivation du service Mongooseim a eu pour effet de désactiver complètement les remontées d'info du Websocket, nous avons du le redémarrer afin de rétablir la production.
==> Es-ce normal si Mongooseim n'est plus utilisé dans wazo ?

Nous pourrons essayer de "systemctl stop xivo-amid" demain matin pour vérifier le comportement du Websocket.
Mais je ne pense pas qu'il s'agisse d'une boucle infinie car lors des charges moyennes, le websocket s'emballe puis fini par redescendre en charge dans les 30 secondes qui suivent. Alors qu'en forte charge, il passe à 100% et fini par délayer les messages à plus de 60 secondes.

Pour information, nous avons également essayé de nous passer du Websocket en activant un contrôle régulier de l'état des états d'appels (Appels API Calls / mecalls toutes les 3 secondes). Ce fonctionnement a eu pour effet de générer prêt de 100 appels aux API par minutes et rendu totalement inopérant l'API et donc la solution de contrôle d'appel globale.

RE: Websocketd 100% CPU - Added by Fip Fip 14 days ago

Bonjour,

Nous avons réalisé le test ce matin de désactiver le service xivo-amid lors de notre problématique de Websoket.

Après arrêt du service xivo-amid, le websocket reste chargé à 100% pendant 90 secondes et le délais de transmission était de 30-40 seconde durant toutes ces 90 secondes.
Puis le processus est redescendu d'un coup à 0% stoppant la remontée d'information vers les clients WSS.

===================
Après analyse des messages AMQP transitant dans la queue vers le Websocket, il apparaît que pour un simple appel entrant 50 messages AMQP sont transmis alors que seulement 2 semblent nous intéresser coté Websocket (Routing keys : calls.call.updated | ou status dans le payload).

Est-il possible de filtrer les messages en autorisant uniquement les caractéristique ci-dessus ? (filtrer en deliver vers le Websocket par exemple)
==> Sans causer d'impact sur le fonctionnement de WAZO bien entendu.

RE: Websocketd 100% CPU - Added by Sébastien Duthil 14 days ago

Merci pour les infos.

Les 50 messages AMQP envoyés pour un appel sont normaux, ce sont les messages remontés par Asterisk, via l'AMI, qui sont retransmis à RabbitMQ par xivo-amid. Malheureusement websocketd est abonné à tous les événements sans exception, donc il les reçoit aussi.

La solution la plus simple est de patcher xivo-websocketd pour qu'il ignore les messages venant de l'AMI. Voir le patch joint.

Pour l'appliquer:

patch -p1 -d /usr/lib/python3/dist-packages/ < drop-ami-events.patch
systemctl restart xivo-websocketd

Pour le retirer:

patch -R -p1 -d /usr/lib/python3/dist-packages/ < drop-ami-events.patch
systemctl restart xivo-websocketd

Le patch ne devrait pas avoir d'impact sur le fonctionnement interne de Wazo. Par contre, comme le patch est obligé de lister les routing keys possibles, ça se peut que j'en aie oublié, alors s'il vous manque des messages dans la Websocket, ça peut venir de là.

RE: Websocketd 100% CPU - Added by Sébastien Duthil 14 days ago

Concernant MongooseIM, il est toujours utilisé dans Wazo 18.03. Le comportement que tu observes est donc normal, lorsque tu éteins MongooseIM, xivo-websocketd refuse de démarrer. Je n'étais pas sur de ce comportement alors je t'ai demandé d'essayer quand même. MongooseIM a été retiré en version 19.04.

RE: Websocketd 100% CPU - Added by Fip Fip 14 days ago

Merci beaucoup pour cette réactivité.

Nous allons appliquer le patch des que possible pour valider son fonctionnement dans notre contexte.

RE: Websocketd 100% CPU - Added by Fip Fip 13 days ago

Bonjour,

Nous avons appliqué le patch ce matin et malheureusement nous rencontrons toujours ce problème de saturation du Websocket.
Nous essayons de travailler sur les abonnements / routing keys pour l'alléger encore.

Autre indicateur que nous avions mise en place sur le système est le temps de réponse de l'API sur une requête Calls.
En temps normal nous somme à moins d'une seconde alors que dans les périodes à problèmes nous montons à plus de 10-15 secondes.
Je ne sais pas à quel niveau (d'un point de vue architecture) cela est lié avec le Websocket...

RE: Websocketd 100% CPU - Added by Sébastien Duthil 13 days ago

Bon, on va sortir les grands moyens pour essayer de trouver d'où ça vient :)

Peux-tu rouler xivo-websocketd dans un profileur Python, comme décrit dans la doc?

Fais-le tourner un peu, idéalement fais-le monter à 100% CPU pendant quelques dizaines de secondes puis envoie nous le fichier de profiling, s'il te plait.

RE: Websocketd 100% CPU - Added by Fip Fip 12 days ago

J'ai essayé de rouler "Xivo-websocketd" mais j'obtiens ces erreurs.
J'ai essayé via les 2 méthodes proposées mais je n'ai pas trouvé de section spécifique pour xivo-websocketd.

Il manque peut être une dépendance ?

###python -m cProfile -o websocketd.profile /usr/bin/xivo-websocketd -f
Traceback (most recent call last):
File "/usr/lib/python2.7/runpy.py", line 174, in run_module_as_main
"
_main__", fname, loader, pkg_name)
File "/usr/lib/python2.7/runpy.py", line 72, in _run_code
exec code in run_globals
File "/usr/lib/python2.7/cProfile.py", line 199, in <module>
main()
File "/usr/lib/python2.7/cProfile.py", line 192, in main
runctx(code, globs, None, options.outfile, options.sort)
File "/usr/lib/python2.7/cProfile.py", line 49, in runctx
prof = prof.runctx(statement, globals, locals)
File "/usr/lib/python2.7/cProfile.py", line 140, in runctx
exec cmd in globals, locals
File "/usr/bin/xivo-websocketd", line 5, in <module>
from xivo_websocketd.bin.main import main
ImportError: No module named xivo_websocketd.bin.main

====================
###twistd p websocketd.profile --profiler=cprofile --savestats -no --python=/usr/bin/xivo-websocketd
Unhandled Error
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 648, in run
runApp(config)
File "/usr/lib/python2.7/dist-packages/twisted/scripts/twistd.py", line 25, in runApp
_SomeApplicationRunner(config).run()
File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 379, in run
self.application = self.createOrGetApplication()
File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 444, in createOrGetApplication
application = getApplication(self.config, passphrase)
--
<exception caught here> ---
File "/usr/lib/python2.7/dist-packages/twisted/application/app.py", line 455, in getApplication
application = service.loadApplication(filename, style, passphrase)
File "/usr/lib/python2.7/dist-packages/twisted/application/service.py", line 411, in loadApplication
passphrase)
File "/usr/lib/python2.7/dist-packages/twisted/persisted/sob.py", line 223, in loadValueFromFile
eval(codeObj, d, d)
File "/usr/bin/xivo-websocketd", line 5, in <module>
from xivo_websocketd.bin.main import main
exceptions.ImportError: No module named xivo_websocketd.bin.main

Failed to load application: No module named xivo_websocketd.bin.main

(1-25/34)