Erreur 500 (websockets ?)

guithel · September 25, 2020, 9:12am

Bonjour, nous avons une erreur 500 qui apparaît aléatoirement.

version : Simplicité version4.0 patch level P24Built on2020-09-24 17:50 (revision 15c2ad3ac2a6ccc48119d5620f806db14ba59f15)Database levelP24

Nous avonc du mal à reproduire le problème. Il semble cependant que le problème pourrait être lié aux websockets :

En cliquant sur obj 1 :1 dans la console du navigateur nous voyons comme réponse :

<!doctype html><html lang="fr"><head><title>État HTTP 500 – Erreur interne du serveur</title><style type="text/css">body {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b {color:white;background-color:#525D76;} h1 {font-size:22px;} h2 {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>État HTTP 500 – Erreur interne du serveur</h1><hr class="line" /><p><b>Type</b> Rapport d'exception</p><p><b>message</b> La session WebSocket [15] a été fermée et aucune méthode (à part close()) ne peut être appelée sur une session fermée</p><p><b>description</b> Le serveur a rencontré une erreur interne qui l'a empêché de satisfaire la requête.</p><p><b>exception</b></p><pre>java.lang.IllegalStateException: La session WebSocket [15] a été fermée et aucune méthode (à part close()) ne peut être appelée sur une session fermée
        org.apache.tomcat.websocket.WsSession.checkState(WsSession.java:871)
        org.apache.tomcat.websocket.WsSession.getBasicRemote(WsSession.java:434)
        com.simplicite.webapp.websockets.Events.pushLog(Events.java:165)
        com.simplicite.util.AppLog.warning(AppLog.java:512)
        com.simplicite.util.AppLog.log(AppLog.java:234)
        com.simplicite.util.AppLog.log(AppLog.java:192)
        com.simplicite.util.AppLog.warning(AppLog.java:500)
com.simplicite.webapp.servlets.AbstractJSONServlet.service(AbstractJSONServlet.java:102)
        javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
        org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        com.simplicite.webapp.filters.RewriteFilter.doFilter(RewriteFilter.java:77)
        com.simplicite.webapp.filters.AbstractFilter.doFilter(AbstractFilter.java:37)
       com.simplicite.webapp.filters.AuthMethodFilter.doFilter(AuthMethodFilter.java:137)
        com.simplicite.webapp.filters.AbstractFilter.doFilter(AbstractFilter.java:37)
</pre><p><b>note</b> La trace complète de la cause mère de cette erreur est disponible dans les fichiers journaux de ce serveur.</p><hr class="line" /><h3>Apache Tomcat/9.0.38</h3></body></html>

Il n’ya pas plus d’info dans les logs tomcat, et j’ai l’impression qu’il ya parfois des pics d’utilisation de cpu.

Je suis bien conscient que cette description est vague, mais auriez-vous une piste d’investigation, ou est-il possible d’agmenter le niveau de logging ?

Merci d’avance,
Guillaume

guithel · September 25, 2020, 9:28am

Le problème vient de se reproduire :

Nous avons dans les logs tomcat

25-Sep-2020 11:15:31.113 GRAVE [http-nio-10588-exec-10] org.apache.tomcat.websocket.pojo.PojoEndpointBase.onClose Echec lors de l'appel de la mÃ©thode onClose du point de terminaison POJO de type [com.simplicite.webapp.websockets.ui.Events]
	java.lang.reflect.InvocationTargetException
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.base/java.lang.reflect.Method.invoke(Method.java:566)
		at org.apache.tomcat.websocket.pojo.PojoEndpointBase.onClose(PojoEndpointBase.java:103)
		at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:556)
		at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:534)
		at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:354)
		at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:296)
		at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:133)
		at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:82)
		at org.apache.tomcat.websocket.server.WsFrameServer.doOnDataAvailable(WsFrameServer.java:171)
		at org.apache.tomcat.websocket.server.WsFrameServer.notifyDataAvailable(WsFrameServer.java:151)
		at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:148)
		at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54)
		at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
		at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
		at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
		at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
		at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
		at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
		at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
		at java.base/java.lang.Thread.run(Thread.java:834)
	Caused by: java.lang.IllegalStateException: Le message ne sera pas envoyÃ© parce que la session WebSocket a Ã©tÃ© fermÃ©e
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:439)
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:311)
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:251)
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:192)
		at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37)
		at com.simplicite.webapp.websockets.Events.pushLog(Events.java:165)
		at com.simplicite.util.AppLog.debug(AppLog.java:426)
		at com.simplicite.util.AppLog.log(AppLog.java:239)
		at com.simplicite.util.AppLog.log(AppLog.java:192)
		at com.simplicite.util.AppLog.log(AppLog.java:349)
		at com.simplicite.webapp.websockets.AbstractWebsocket.log(AbstractWebsocket.java:296)
		at com.simplicite.webapp.websockets.AbstractWebsocket.onClose(AbstractWebsocket.java:107)
		at com.simplicite.webapp.websockets.AbstractWebsocket.onCloseHandler(AbstractWebsocket.java:267)
		at com.simplicite.webapp.websockets.ui.Events.onCloseHandler(Events.java:62)
		... 23 more
25-Sep-2020 11:15:31.114 GRAVE [http-nio-10588-exec-10] org.apache.tomcat.websocket.pojo.PojoEndpointBase.onError Echec de l'appel de la mÃ©thode onError du point de terminaison POJO pour le type [com.simplicite.webapp.websockets.ui.Events]
	java.lang.reflect.InvocationTargetException
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.base/java.lang.reflect.Method.invoke(Method.java:566)
		at org.apache.tomcat.websocket.pojo.PojoEndpointBase.onError(PojoEndpointBase.java:130)
		at org.apache.tomcat.websocket.pojo.PojoEndpointBase.handleOnOpenOrCloseError(PojoEndpointBase.java:90)
		at org.apache.tomcat.websocket.pojo.PojoEndpointBase.onClose(PojoEndpointBase.java:108)
		at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:556)
		at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:534)
		at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:354)
		at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:296)
		at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:133)
		at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:82)
		at org.apache.tomcat.websocket.server.WsFrameServer.doOnDataAvailable(WsFrameServer.java:171)
		at org.apache.tomcat.websocket.server.WsFrameServer.notifyDataAvailable(WsFrameServer.java:151)
		at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:148)
		at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54)
		at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
		at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
		at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
		at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
		at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
		at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
		at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
		at java.base/java.lang.Thread.run(Thread.java:834)
	Caused by: java.lang.IllegalStateException: La terminaison distante est dans l'Ã©tat [TEXT_FULL_WRITING] ce qui est invalide pour la mÃ©thode appelÃ©e
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.checkState(WsRemoteEndpointImplBase.java:1243)
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.textStart(WsRemoteEndpointImplBase.java:1205)
		at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:191)
		at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37)
		at com.simplicite.webapp.websockets.Events.pushLog(Events.java:165)
		at com.simplicite.util.AppLog.debug(AppLog.java:426)
		at com.simplicite.util.AppLog.log(AppLog.java:239)
		at com.simplicite.util.AppLog.log(AppLog.java:192)
		at com.simplicite.util.AppLog.log(AppLog.java:349)
		at com.simplicite.webapp.websockets.AbstractWebsocket.log(AbstractWebsocket.java:296)
		at com.simplicite.webapp.websockets.AbstractWebsocket.onError(AbstractWebsocket.java:117)
		at com.simplicite.webapp.websockets.AbstractWebsocket.onErrorHandler(AbstractWebsocket.java:284)
		at com.simplicite.webapp.websockets.ui.Events.onErrorHandler(Events.java:74)
		... 25 more

Suivi du message suivant qui se répète en boucle :

25-Sep-2020 11:15:41.248 GRAVE [http-nio-10588-exec-4] org.apache.catalina.core.StandardWrapperValve.invoke "Servlet.service()" pour la servlet [Logs] a gÃ©nÃ©rÃ© une exception
	java.lang.IllegalStateException: La session WebSocket [c] a Ã©tÃ© fermÃ©e et aucune mÃ©thode (Ã  part close()) ne peut Ãªtre appelÃ©e sur une session fermÃ©e
		at org.apache.tomcat.websocket.WsSession.checkState(WsSession.java:871)
		at org.apache.tomcat.websocket.WsSession.getBasicRemote(WsSession.java:434)
		at com.simplicite.webapp.websockets.Events.pushLog(Events.java:165)
		at com.simplicite.util.AppLog.debug(AppLog.java:426)
		at com.simplicite.util.AppLog.log(AppLog.java:239)
		at com.simplicite.util.AppLog.log(AppLog.java:192)
		at com.simplicite.util.AppLog.debug(AppLog.java:401)
		at com.simplicite.webapp.tools.ServletTool.setHTTPHeaders(ServletTool.java:329)
		at com.simplicite.webapp.tools.ServletTool.setHTTPHeadersForHTML(ServletTool.java:173)
		at com.simplicite.webapp.servlets.ui.LogsServlet.service(LogsServlet.java:61)
		at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at com.simplicite.webapp.filters.RewriteFilter.doFilter(RewriteFilter.java:77)
		at com.simplicite.webapp.filters.AbstractFilter.doFilter(AbstractFilter.java:37)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at com.simplicite.webapp.filters.AuthMethodFilter.doFilter(AuthMethodFilter.java:137)
		at com.simplicite.webapp.filters.AbstractFilter.doFilter(AbstractFilter.java:37)
		at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
		at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
		at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:188)
		at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
		at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
		at com.simplicite.tomcat.valves.APISessionValve.invoke(APISessionValve.java:191)
		at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
		at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
		at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
		at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
		at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
		at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
		at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
		at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
		at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
		at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
		at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
		at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
		at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
		at java.base/java.lang.Thread.run(Thread.java:834)

david · September 25, 2020, 12:59pm

Les websockets sont parfois très sensibles à la configuration de la “tuyauterie” (reverse proxies, firewall, routeurs, etc.).

Si vous ne vous en servez pas (elles servent actuellement essentiellement à remonter les logs serveur dans la console du navigateur) vous pouvez les inhiber totalement en ajoutant un -Dserver.websocket=false aux options de démarrage de la JVM de Tomcat

guithel · September 28, 2020, 7:18am

Bonjour,

Merci. Je voudrais essayer mais je ne sais pas comment passer les arguments “-D…”. J’ai tenté d’ajouter

export JAVA_OPTS="$JAVA_OPTS -Dserver.websocket=false"

dans le run.sh mais je n’ai pas l’impression que la config soit prise en compte :

Merci d’avance,

Guillaume

david · September 28, 2020, 8:21am

On parle d’une instance gérée sur un SIM ?

guithel · September 28, 2020, 8:26am

oui on parle bien d’une instance sur un sim

david · September 28, 2020, 8:34am

Dans ce cas vous devez modifier le script de démarrage /etc/init.d/tomcat-moninstance pour ajouter le -D en question.

Attention ce script de démarrage est régénéré à chaque upgrade donc pour rendre cette modif permanente vous devez l’implémenter dans les hooks ad hoc post-create.sh, post-upgrade.sh, …

Le SIM n’a pas de mécanisme simplifié à base de var d’env pour ajouter des options de démarrage arbitraires additionnelles à la JVM. On va regarder pour les ajouter pour que ça soit plus simple (il suffira alors de mettre la valeur dans le .simplicite de l’instance)

david · September 28, 2020, 8:39am

OK c’est fait vous pourrez désormais ajouter une variable dans le .simplicite de votre instance:

(...)
SERVICE_JDK_OPTS="-D..."
(...)

Sinon vous pouvez le faire pour toutes les instances en mettant:

(...)
APPS_JDK_OPTS="-D..."
(...)

dans le /var/simplicite/config.sh.

La prise en compte de ces variables ne se fera qu’après un upgrade des instances. Et bien entendu après avoir mis à jour le SIM via un sim refresh puisqu’on vient juste de pousser l’évolution.

david · September 28, 2020, 9:21am

ERRATUM

En fait le APPS_JDK_OPTS est positionné au niveau des versions, il ne faut donc pas le surcharger dans le /var/simplicite/config.sh

Par contre il est désormais possible d’ajouter des options en écrivant:

SERVICE_JDK_OPTS="$APPS_JDK_OPTS -D..."

Dans le .simplicite de l’instance.

guithel · September 28, 2020, 9:56am

Le paramètre est bien passé

Le problème étant aléatoire je ne peux pas vous confirmer qu’il est résolu pour l’instant, mais je ne vois plus l’erreur en question dans les logs.

Merci,

Guillaume

david · September 28, 2020, 10:04am

Normalement ça inhibe totalement l’usage des websockets.
Mais bon ça veut dire plus de logs serveur remontées dans la console du navigateur non plus…

L’idéal reste quand mêle de regarder dans votre config reseau/proxies/… ce qui pourrait nuire aux websockets (timeout, limites de volumes, …)