El servidor WAPT se bloquea constantemente

renaud.counhaye · 15 de octubre de 2019 - 15:19

Buen día,

Mi servidor Linux wapt 4.9.0-8-amd64 #1 SMP Debian 4.9.144-3.1 (2019-02-19) x86_64

Versión del servidor WAPT: 1.7.4
Versión del agente WAPT: 1.7.4.6143
Versión de la configuración WAPT: 1.7.4.6143

Suele fallar de forma esporádica y aleatoria, hasta el punto de bloquear el acceso a la consola (Error 504), el acceso web (Error 502) y las actualizaciones del cliente por tiempo de espera agotado.
En el servidor, encuentro el servicio wapttasks en estado de fallo.
● wapttasks.service cargado falló el script de inicio de WAPT Tasks

root@wapt # systemctl estado wapttasks
● wapttasks.service - Script de inicio de tareas WAPT
Cargado: cargado (/usr/lib/systemd/system/wapttasks.service; habilitado; valor predeterminado del proveedor: habilitado)
Activo: fallido (Resultado: código de salida) desde el martes 15/10/2019 15:00:05 CEST; hace 18 s Proceso: 611 ExecStart=/opt/wapt/bin/python /opt/wapt/waptserver/wapthuey.py waptenterprise.waptserver.wsus_tasks.huey PID principal: 611 (código=salió, estado=1/FAILURE)

15 oct. 15:00:04 wapt systemd[1]: wapttasks.service: La unidad entró en estado de error. 15 oct. 15:00:04 wapt systemd[1]: wapttasks.service: Falló con el resultado 'exit-code'. 15 oct. 15:00:05 wapt systemd[1]: wapttasks.service: Tiempo de espera del servicio expirado, se está programando el reinicio.
15 oct 15:00:05 wapt systemd[1]: Se detuvo el script de inicio de tareas WAPT.
15 oct. 15:00:05 wapt systemd[1]: wapttasks.service: La solicitud de inicio se repitió demasiado rápido. 15 oct. 15:00:05 wapt systemd[1]: Error al iniciar el script de inicio de WAPT Tasks. 15 oct. 15:00:05 wapt systemd[1]: wapttasks.service: La unidad entró en estado de error. 15 oct. 15:00:05 wapt systemd[1]: wapttasks.service: Error con el resultado 'exit-code'.

El servicio del servidor wapt se está ejecutando, pero si verifico su estado, obtengo una historia diferente:
[ ~ ] root@wapt # systemctl estado waptserver
● waptserver.service - Script de inicio del servidor WAPT
Cargado: cargado (/usr/lib/systemd/system/waptserver.service; habilitado; valor predeterminado del proveedor: habilitado)
Activo: activo (en ejecución) desde el viernes 20 de septiembre de 2019 a las 14:59:28 CEST; hace 3 semanas y 4 días. PID principal: 918 (Python)
Tareas: 1 (límite: 4915)
Grupo C: /system.slice/waptserver.service
└─918 /opt/wapt/bin/python /opt/wapt/waptserver/server.py

14 oct 21:00:05 wapt python[918]: 2019-10-14 21:00:05,820 ADVERTENCIA Sesión inválida Ninguna
14 oct 23:57:04 wapt python[918]: 2019-10-14 23:57:04,954 ADVERTENCIA Sesión inválida Ninguna
15 oct 08:51:02 wapt python[918]: 2019-10-15 08:51:02,071 ADVERTENCIA Sesión inválida Ninguna
15 oct 12:57:09 wapt python[918]: peewee 2019-10-15 12:57:09,728 ADVERTENCIA Conexión SocketIO rechazada para uuid, sid 07fe15 oct 12:57:09 wapt python[918]: 2019-10-15 12:57:09,728 ADVERTENCIA Conexión SocketIO rechazada para uuid, sid 07fe1be33bf15 oct 12:57:09 wapt python[918]: 2019-10-15 12:57:09,731 ADVERTENCIA Aplicación rechazó la conexión
15 oct 13:47:01 wapt python[918]: peewee 15/10/2019 13:47:01,889 CRÍTICO Error en Get_websocket_auth_token EWaptAuthentic 15 oct 13:47:01 wapt python[918]: 15/10/2019 13:47:01,889 CRÍTICO Error en Get_websocket_auth_token EWaptAuthenticationFa 15 oct 14:48:02 wapt python[918]: peewee 15/10/2019 14:48:02,176 CRÍTICO Error en Get_websocket_auth_token EWaptAuthentic 15 oct 14:48:02 wapt python[918]: 15/10/2019 14:48:02,176 CRÍTICO Error en Get_websocket_auth_token EWaptAuthenticationFa

Reiniciar la máquina o detener y reiniciar Nginx, Waptserver y wapttasks resuelve el problema, pero no es lo ideal.
De hecho, incluso después de este procedimiento, wapttasks vuelve a fallar.

Gracias por leer, espero tener noticias suyas pronto y agradecería su ayuda si fuera posible. Que tenga un buen día.

Sep 20 14:59:19 wapt nginx[753]: nginx: [advertencia] "ssl_stapling" ignorado, certificado del emisor no encontrado
Sep 20 14:59:20 wapt nginx[836]: nginx: [advertencia] "ssl_stapling" ignorado, certificado del emisor no encontrado
Sep 20 14:59:20 wapt systemd[1]: nginx.service: Error al leer el PID del archivo /run/nginx.pid: Argumento no válido

Sep 20 14:59:23 wapt cron[850]: (CRON) INFO (Ejecutando trabajos @reboot)
Sep 20 14:59:24 wapt python[697]: #033[91mError al importar waptenterprise.waptserver.wsus_tasks.huey#033[0m
Sep 20 14:59:24 wapt python[697]: Traceback (most recent call last):
Sep 20 14:59:24 wapt python[697]: File "/opt/wapt/waptserver/wapthuey.py", line 37, in
20 sep 14:59:24 wapt python[697]: huey_consumer.consumer_main()
20 sep 14:59:24 wapt python[697]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 43, en consumer_main 20 sep 14:59:24 wapt python[697]: huey_instance = load_huey(args[0]) 20 sep 14:59:24 wapt python[697]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 18, en load_huey 20 sep 14:59:24 wapt python[697]: return load_class(path) Sep 20 14:59:24 wapt python[697]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/utils.py", línea 46, en load_class Sep 20 14:59:24 wapt python[697]: __import__(path) Sep 20 14:59:24 wapt python[697]: ImportError: No se encontró el módulo waptenterprise.waptserver.wsus_tasks
Sep 20 14:59:24 wapt systemd[1]: wapttasks.service: El proceso principal finalizó, código=exited, estado=1/FAILURE
Sep 20 14:59:24 wapt systemd[1]: wapttasks.service: La unidad falló y entró en estado.
20 sep 14:59:24 wapt systemd[1]: wapttasks.service: Falló con el resultado 'exit-code'.
20 sep 14:59:24 wapt systemd[1]: wapttasks.service: Tiempo de espera del servicio finalizado, programando reinicio.
20 sep 14:59:24 wapt systemd[1]: Script de inicio de WAPT Tasks detenido.
20 sep 14:59:24 wapt systemd[1]: Script de inicio de WAPT Tasks iniciado.
20 sep 14:59:25 wapt python[856]: #033[91mError al importar waptenterprise.waptserver.wsus_tasks.huey#033[0m
20 sep 14:59:25 wapt python[856]: Traceback (última llamada más reciente):
20 sep 14:59:25 wapt python[856]: Archivo "/opt/wapt/waptserver/wapthuey.py", línea 37, en
20 de septiembre 14:59:25 wapt python[856]: huey_consumer.consumer_main()
20 de septiembre 14:59:25 wapt python[856]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py
20 de septiembre 14:59:25 wapt python[856]: huey_consumer.consumer_main()
20 de septiembre 14:59:25 wapt python[856]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 43, en consumer_main
20 de septiembre 14:59:25 wapt python[856]: huey_instance = load_huey(args[0])
20 de septiembre 14:59:25 wapt python[856]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 18, en load_huey
20 de septiembre 14:59:25 wapt python[856]: return load_class(path)
20 de septiembre 14:59:25 wapt python[856]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/utils.py", línea 46, en load_class
20 de septiembre 14:59:25 wapt python[856]: __import__(path)
20 de septiembre 14:59:25 wapt python[856]: ImportError: No Módulo llamado waptenterprise.waptserver.wsus_tasks
20 de septiembre 14:59:25 wapt systemd[1]: wapttasks.service: El proceso principal salió, código=exited, estado=1/FAILURE
20 de septiembre 14:59:25 wapt systemd[1]: wapttasks.service: La unidad entró en estado de fallo.
20 de septiembre 14:59:25 wapt systemd[1]: wapttasks.service: Falló con el resultado 'exit-code'.
20 de septiembre 14:59:26 wapt systemd[1]: wapttasks.service: El tiempo de espera del servicio ha terminado, programando reinicio. 20 de septiembre 14:59:26
wapt systemd[1]: Script de inicio de WAPT Tasks detenido. 20 de septiembre 14:59:26
wapt systemd[1]: Script de inicio de WAPT Tasks iniciado.
20 de septiembre 14:59:26 wapt systemd[1]: Se iniciaron las actividades diarias de descarga de apt.

20 de septiembre 14:59:26 wapt systemd[1]: apt-daily.timer: Añadiendo 1 h 59 min 42,052407 s de tiempo aleatorio.
20 de septiembre 14:59:26 wapt systemd[1]: apt-daily.timer: Añadiendo 1 h 23 min 1,241385 s de tiempo aleatorio.
20 de septiembre 14:59:27 wapt python[874]: #033[91mError al importar waptenterprise.waptserver.wsus_tasks.huey#033[0m
20 de septiembre 14:59:27 wapt python[874]: Traceback (última llamada más reciente):
20 de septiembre 14:59:27 wapt python[874]: Archivo "/opt/wapt/waptserver/wapthuey.py", línea 37, en
20 sep 14:59:27 wapt python[874]: huey_consumer.consumer_main()
20 sep 14:59:27 wapt python[874]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 43, en consumer_main 20 sep 14:59:27 wapt python[874]: huey_instance = load_huey(args[0])
20 sep 14:59:27 wapt python[874]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/bin/huey_consumer.py", línea 18, en load_huey 20 sep 14:59:27 wapt python[874]: return load_class(path)
Sep 20 14:59:27 wapt python[874]: Archivo "/opt/wapt/lib/python2.7/site-packages/huey/utils.py", línea 46, en load_class
Sep 20 14:59:27 wapt python[874]: __import__(path)
Sep 20 14:59:27 wapt python[874]: ImportError: No se encontró el módulo waptenterprise.waptserver.wsus_tasks
Sep 20 14:59:27 wapt systemd[1]: wapttasks.service: El proceso principal finalizó, código=exited, estado=1/FAILURE
Sep 20 14:59:27 wapt systemd[1]: wapttasks.service: La unidad falló y entró en estado.
20 sep 14:59:27 wapt systemd[1]: wapttasks.service: Falló con el resultado 'exit-code'.
20 sep 14:59:27 wapt systemd[1]: wapttasks.service: Tiempo de espera del servicio finalizado, programando reinicio.
20 sep 14:59:27 wapt systemd[1]: Script de inicio de WAPT Tasks detenido.
20 sep 14:59:27 wapt systemd[1]: Script de inicio de WAPT Tasks iniciado.
Sep 20 14:59:27 wapt python[903]: #033[91mError al importar waptenterprise.waptserver.wsus_tasks.huey#033[0m
Sep 20 14:59:27 wapt python[903]: Traceback (última llamada más reciente):

ep 20 15:00:10 wapt peewee 2019-09-20 15:00:10,626 CRITICAL Get_websocket_auth_token falló EWaptAuthenticationFailure(u"Error en la verificación de firma de la solicitud: Falló la verificación de firma SSL para el certificado {'commonName': u'1591875c-95e0-433c-b448-38427397885d', 'organizationName': u'Microsoft'} emitido por 1591875c-95e0-433c-b448-38427397885d",)
Sep 20 15:00:10 wapt python[918]: 2019-09-20 15:00:10,626 CRITICAL Get_websocket_auth_token failed EWaptAuthenticationFailure(u"Request signature verification failed: SSL signature verification failed for certificate {'commonName': u'1591875c-95e0-433c-b448-38427397885d', 'organizationName': u'Microsoft'} issued by 1591875c-95e0-433c-b448-38427397885d",)
Sep 20 15:00:17 wapt peewee 2019-09-20 15:00:17,724 CRITICAL Get_websocket_auth_token falló EWaptAuthenticationFailure('No se proporcionó uuid',)
Sep 20 15:00:17 wapt python[918]: 2019-09-20 15:00:17,724 CRITICAL Get_websocket_auth_token falló EWaptAuthenticationFailure('No se proporcionó uuid',)
Sep 20 15:01:10 wapt peewee 2019-09-20 15:01:10,684 CRITICAL Get_websocket_auth_token falló EWaptAuthenticationFailure(u"La verificación de la firma de la solicitud falló: la verificación de la firma SSL falló para el certificado {'commonName': u'1591875c-95e0-433c-b448-38427397885d', 'organizationName': u'Microsoft'} emitido por 1591875c-95e0-433c-b448-38427397885d",)
Sep 20 15:01:10 wapt python[918]: 2019-09-20 15:01:10,684 CRITICAL Get_websocket_auth_token falló EWaptAuthenticationFailure(u"La verificación de la firma de la solicitud falló: la verificación de la firma SSL falló para el certificado {'commonName': u'1591875c-95e0-433c-b448-38427397885d', 'organizationName': u'Microsoft'} emitido por 1591875c-95e0-433c-b448-38427397885d",)
Sep 20 15:01:17 wapt peewee 2019-09-20 15:01:17,871 CRITICAL Get_websocket_auth_token failed EWaptAuthenticationFailure('No uuid provided',)
Sep 20 15:01:17 wapt python[918]: 2019-09-20 15:01:17,871 CRITICAL Get_websocket_auth_token failed EWaptAuthenticationFailure('No uuid provided',)

16 de octubre de 2019 - 11:56

Buen día,
De hecho, la pregunta plantea dos problemas

Actualmente, el servicio WaptTasks solo gestiona la descarga de actualizaciones de Windows y podría no ser relevante para usted. Si experimenta un error, probablemente se deba a la ausencia de los módulos de Python correspondientes a la versión Enterprise. Sin embargo, esto no debería afectar a las demás funciones de Wapt.

El servicio waptserver es el culpable. Si recibes un error 504 (tiempo de espera de la puerta de enlace agotado) en la consola, pero el servicio waptserver parece estar ejecutándose, se trata de un problema interno del proceso waptserver, como un interbloqueo.
El proceso waptserver es de un solo subproceso, con un sistema multitarea cooperativo ("greenlet") para mantener activos un gran número de sockets TCP (web) (las máquinas conectadas). Si el servicio waptserver fuera multiproceso, dedicaría más tiempo a cambiar de contexto mientras esperaba datos en los sockets que a trabajar. Sin embargo, esto podría generar una vulnerabilidad de interbloqueo.
Tenemos otros tres clientes (con un número significativo de estaciones de trabajo conectadas) que experimentan este problema de bloqueo de forma intermitente, y el análisis aún no ha arrojado resultados concluyentes. La causa más probable es un bloqueo en las transacciones de la base de datos, en este contexto de multitarea colaborativa
Reiniciar el servicio waptserver es suficiente para resolver la situación, por lo que, como solución temporal, hemos instalado un temporizador de vigilancia en un trabajo cron en estos clientes que hace ping al servicio waptserver (https://waptserver/ping) y lo reinicia si hay un error. Algo así:

wget -q -O - http://127.0.0.1:8080/ping --no-check-certificate | grep "WAPT Server running" || (echo Reiniciar; systemctl restart waptserver)

No es ideal, pero es útil mientras se esperan más investigaciones

16 de octubre de 2019 - 12:14

Hola Renaud,

renaud.counhaye escribió: ↑15 de oct. de 2019 - 15:19 ...
Tiende a fallar esporádica y aleatoriamente, hasta el punto de bloquear el acceso a la consola (Error 504), el acceso web (Error 502) y las actualizaciones del cliente con un tiempo de espera agotado.
En el servidor, encuentro el servicio wapttasks en un estado de fallo
...
Reiniciar la máquina o detener y luego reiniciar Nginx, Waptserver y wapttasks resuelve el problema, pero no es lo ideal ...
De hecho, incluso después de esta solución, wapttasks vuelve a su estado de fallo.

Gracias por tu detallada publicación. Como mencionó Hubert, ya nos encontramos con el problema que nos informaron. Parece que tenemos un problema de interbloqueo, probablemente relacionado con PostgreSQL. ¿Podrías ejecutar el siguiente comando la próxima vez que encuentres un interbloqueo en tu servidor WAPT como root?

sudo -u postgres psql wapt
SELECT nombre_dato, nombre_uso, dirección_cliente, inicio_xact, inicio_consulta, cambio_estado, estado, consulta FROM pg_stat_activity;

y envíame el resultado por mensaje privado (dcardon AT tranquil DOT it).

Saludos,

Denis