Applications non fonctionnelles

rosanneQuily · January 14, 2021, 5:37pm

Bonjour,

toutes nos instances sont à nouveau en vrac ce matin …

j’ai du faire un vidage de cache global pour que ça fonctionne.

ci joint

2021-01-13 09:03:17,266 ERROR [com.simplicite.util.engine.CoreCache] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ERROR|08254|com.simplicite.util.engine.CoreCache|instantiateObject||Evénement: Class not found for CrbFopIndividu: checks definition and script compilation.
2021-01-13 09:03:17,265 WARN [com.simplicite.util.engine.DynamicClassLoader] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|WARN|system|com.simplicite.util.engine.DynamicClassLoader|loadClass||Evénement: Unable to load class: com.simplicite.objects.CrbForpro.CrbFopIndividu
2021-01-13 09:03:14,368 INFO [com.simplicite.util.Grant] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ICORED0001|public|com.simplicite.util.Grant|init||Info : public connected, session ID: 7D447EA7C58406DE5D6B4A58BE0284EE, timeout: 5 min , user agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:84.0) Gecko/20100101 Firefox/84.0
2021-01-13 09:03:14,238 INFO [com.simplicite.util.UserSession] LOGOUT|37662242D0AD90C7860F0C14B7612B14|SIVY22|20|0:00:20
2021-01-13 09:03:10,736 INFO [com.simplicite.util.Grant] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ICORED0001|public|com.simplicite.util.Grant|init||Info : public connected, session ID: 9445CA6DA72C016417B6363405CD0D11, timeout: 5 min , user agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.141 Safari/537.36
2021-01-13 09:03:10,733 WARN [com.simplicite.webapp.servlets.ui.JSONServlet] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|WARN|system|com.simplicite.webapp.servlets.ui.JSONServlet|service||Evénement: Service error
    java.lang.NullPointerException
     at com.simplicite.webapp.ObjectJson.metadata(ObjectJson.java:79)
     at com.simplicite.webapp.tools.JSONServletTool.businessObjectService(JSONServletTool.java:536)
     at com.simplicite.webapp.servlets.AbstractJSONServlet.service(AbstractJSONServlet.java:68)
     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:138)
     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:202)
     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
     at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
     at com.simplicite.tomcat.valves.APISessionValve.invoke(APISessionValve.java:192)
     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:888)
     at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
     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:830)

david · January 13, 2021, 9:22am

L’endroit où cette erreur se produit est très étrange (c’est un synchronize(obj) sur un objet sur lequel on vient juste de faire un getObject après avoir vérifié les droits) ce n’est donc sans doute pas la cause initiale du pb, merci de nous envoyer les logs complètes (Tomcat + Simplicite) depuis le dernier démarrage pour qu’on analyse ce qui a pu se passer avant.

francois · January 13, 2021, 9:35am

On a livré des petits correctifs hier en V4 mais rien qui peut faire ce genre de chose.

Je vois un “Class not found for CrbFopIndividu”

Problème de compilation des objets à un moment donné, votre clear-cache a visiblement pu rebuilder les classes.

Si l’objet est nul c’est que le cache a du mal se reconstruire. Il faut donc effectivement voir ce qui s’est passé lors de l’upgrade et faire de votre côté les vérifications de base : espace disque suffisant, un upgrade system/jdk … ?

Normalement on devrait voir les pb bas niveau dans les logs Tomcat (pas forcement simplicité qui reste un couche applicative).

david · January 13, 2021, 10:04am

Par acquis de conscience, outre les logs complètes, pourrait on voir ce que vous faites exactement dans vos hooks du SIM (/var/simplicite/hooks/pre|post-*.sh) ?

Ainsi que la configuration de votre SIM: sim config

L’idée est ici de savoir ce qui se passe exactement et dans quel ordre lors de vos upgrades

rosanneQuily · January 13, 2021, 10:16am

/var/simplicite/hooks/pre|post-*.sh => commande introuvable

Config de la sim :

david · January 13, 2021, 10:18am

C’était pas une commande mais un emplacement de fichiers => ls -alF /var/simplicite/hooks/

Les hooks du SIM sont des *.sh qui contiennent des customisations vis à vis du comportement standard du SIM, de mémoire vous en avez implémenté, nous voudrions savoir ce que vous y faites exactement.

rosanneQuily · January 13, 2021, 10:29am

effectivement, nous avons implémenté un crb-configure-autopatch.sh

david · January 13, 2021, 10:34am

OK dans quel(s) hooks ce script est il appelé ?
De mémoire il y avait d’autres choses dans ces hooks (genre des ajouts de JARs, etc)

Peut on avoir le contenu de tous les fichiers du répertoire hooks ? ce qu’on cherche ici à savoir c’est s’il y a quelque chose de nature à “perturber” le process d’upgrade et/ou plus généralement le fonctionnement de la plateforme. Peut être n’y a-t-il rien mais on voudrait en être sûr.

Peut on aussi avoir le contenu du fichier .simplicite de l’instance en question : sim sh moninstance puis cat .simplicite ? Ici l’objectif est de vérifier la manière dont est configurée le passage des patches sur cette instance

rosanneQuily · January 13, 2021, 10:34am

rosanneQuily · January 13, 2021, 10:36am

david · January 13, 2021, 10:38am

OK pour le .simplicite on est bien en mode “auto patch”

Pour les hooks du SIM il y en a plusieurs qui sont implémentés et qui sont sollicités pendant le process d’upgrade => il nous faudrait le contenu de ces scripts

rosanneQuily · January 13, 2021, 10:44am

les hook d’upgrade ?
pre-upgarde.sh est vide
post-upgarde.sh :

david · January 13, 2021, 10:51am

Le pre-start.sh est non vide lui aussi (cf les tailles de fichiers de votre ls) et celui-ci est aussi sollicité dans le process d’upgrade.

Sans le contenu de tous les hooks implémentés et des scripts crb-*.sh appelés dans ces hooks on ne sait toujours pas ce que ça fait exactement…

rosanneQuily · January 13, 2021, 10:56am

pre-start :

crb-configure-fullcalendar-libs.sh

crb-configure-jdbc-driver.sh

crb-configure-waf.sh

david · January 13, 2021, 11:09am

OK nous voulions vérifier qu’aucune “sollicitation” de la plateforme (genre des appels curl pour importer du paramérage ou autre) ne vient perturber le démarrage (et donc le chargement intial du cache). Ce n’est visiblement pas le cas, tant mieux.

Pour préciser : le mode auto-patch est “asynchrone” vis à vis du SIM, sur upgrade l’instance “rend la main” au SIM avant d’avoir fini son processus de démarrage et notamment son auto-patch, donc par exemple solliciter les services de l’instance dans le hook post-upgrade.sh ou le post-start.sh peut donc aboutir à des choses aléatoires et imprévisibles.

Donc pour avancer dans l’investigation il nous faut les logs complètes depuis le démarrage. Pas sous forme de copies d’écran ou par copier/coller textuels laborieux pour vous et risquant d’être incomplets => récupérez les fichiers complets par scp/sftp

rosanneQuily · January 13, 2021, 2:34pm

les fichiers de logs ont été envoyé par mail

david · January 13, 2021, 3:03pm

Dans le catalina.out il y a des :

13-Jan-2021 05:02:42.090 INFOS [http-nio-10023-exec-1] org.apache.coyote.http11.Http11Processor.service Erreur lors de l'analyse d'un en-tête de requête HTTP Note : les occurrences suivantes d'erreurs d'analyse de requête HTTP seront enregistrées au niveau DEBUG.
	java.lang.IllegalArgumentException: Caractère invalide trouvé dans le nom de méthode.  Les noms HTTP doivent être des "token".
		at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:417)
		at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:261)
		at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
		at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)
		at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
		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:830)

Rien à voir à priori avec Simplicité, c’est le connecteur HTTP Tomcat qui râle ici, mais je pense que vous devez faire des requêtes HTTP “atypiques” qu’il n’aime pas (“pings” de supervision peut être ?)

Dans le simplicite.log il y a:

a) des erreurs d’exécution Rhino:

2021-01-13 06:00:02,672 ERROR [com.simplicite.util.RhinoScriptInterpreter] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ECORESC002|system|com.simplicite.util.RhinoScriptInterpreter|CrbFopStagiaire.preSave||Erreur évaluation script: CrbFopStagiaire
org.mozilla.javascript.EcmaError: TypeError: Impossible dappeler la méthode "{1}" de {0} (CrbFopStagiaire#87) in CrbFopStagiaire at line number 87
line 82: 	if(this.getFieldValue("fopStagiaireDtSortie")!==""){
line 83: 		var tmpStgBilan=this.getGrant().getTmpObject("CrbFopStgBilan");
line 84: 		tmpStgBilan.resetFilters();
line 85: 		tmpStgBilan.getField("fopStgBilanStagiaire_fk").setFilter(this.getRowId());
line 86: 		var rows = tmpStgBilan.search();
error87: 		for (var k = 0; k < rows.size(); k++) {
line 88: 			var row=rows.get(k);
line 89: 			tmpStgBilan.setValues(row);
line 90: 			var id=tmpStgBilan.getRowId();

Comme c’est du Rhino, ca n’a sans doute pas d’impact sur le démarrage mais il y a un truc à regarder

b) des traces relatives à des classes Java non trouvées:

2021-01-13 06:00:02,830 WARN  [com.simplicite.util.engine.DynamicClassLoader] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|WARN|system|com.simplicite.util.engine.DynamicClassLoader|loadClass||Evénement: Unable to load class: com.simplicite.objects.CrbForpro.CrbFopSession
2021-01-13 06:00:02,830 ERROR [com.simplicite.util.engine.CoreCache] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ERROR|system|com.simplicite.util.engine.CoreCache|instantiateObject||Evénement: Class not found for CrbFopSession: checks definition and script compilation.
2021-01-13 06:00:02,830 WARN  [com.simplicite.util.engine.CoreCache] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|WARN|system|com.simplicite.util.engine.CoreCache|instantiateObject||Evénement: Designer can fix temporarily the object as a simple ObjectDB.
2021-01-13 06:00:02,831 WARN  [com.simplicite.util.engine.DynamicClassLoader] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|WARN|system|com.simplicite.util.engine.DynamicClassLoader|loadClass||Evénement: Unable to load class: com.simplicite.objects.CrbForpro.CrbFopSession
2021-01-13 06:00:02,833 ERROR [com.simplicite.util.Tool] SIMPLICITE|https://Prod-sim-2:10028/forpro|/forpro|ECORED0001|system|com.simplicite.util.Tool|streamToObject||Erreur Error during deserialization: com.simplicite.objects.CrbForpro.CrbFopSession
java.lang.ClassNotFoundException: com.simplicite.objects.CrbForpro.CrbFopSession
	at com.simplicite.util.engine.DynamicClassLoader.loadClass(DynamicClassLoader.java:71)
	at java.base/java.lang.Class.forName0(Native Method)
	at java.base/java.lang.Class.forName(Class.java:416)
	at com.simplicite.util.engine.DynamicObjectInputStream.resolveClass(DynamicObjectInputStream.java:26)
	at java.base/java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1941)
	at java.base/java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1827)
	at java.base/java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2115)
	at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1646)
	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:464)
	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:422)
	at com.simplicite.util.Tool.streamToObject(Tool.java:4955)
	at com.simplicite.util.Tool.bytesToObject(Tool.java:4942)
	at com.simplicite.util.engine.MemoryCache.cloneDefinition(MemoryCache.java:138)
	at com.simplicite.util.engine.ObjectLoader.getClone(ObjectLoader.java:121)
	at com.simplicite.util.engine.ObjectLoader.load(ObjectLoader.java:87)
	at com.simplicite.util.ObjectDirect.init(ObjectDirect.java:41)
	at com.simplicite.util.ObjectDB.init(ObjectDB.java:238)
	at com.simplicite.util.ObjectDB.load(ObjectDB.java:216)
	at com.simplicite.util.engine.CoreCache.instantiateObject(CoreCache.java:3631)
	at com.simplicite.util.engine.CoreCache.getObject(CoreCache.java:3564)
	at com.simplicite.util.engine.GrantManager.getObject(GrantManager.java:96)
	at com.simplicite.util.GrantDirect.getObject(GrantDirect.java:578)
	at com.simplicite.util.Grant.getObject(Grant.java:1886)
	at com.simplicite.util.Grant.getTmpObject(Grant.java:1998)
	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:567)
	at org.mozilla.javascript.MemberBox.invoke(MemberBox.java:138)
	at org.mozilla.javascript.NativeJavaMethod.call(NativeJavaMethod.java:226)
	at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1670)
	at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:1010)
	at org.mozilla.javascript.InterpretedFunction.exec(InterpretedFunction.java:124)
	at org.mozilla.javascript.Context.evaluateReader(Context.java:1296)
	at de.christophkraemer.rhino.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:229)
	at de.christophkraemer.rhino.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:255)
	at java.scripting/javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:233)
	at com.simplicite.util.ScriptedObjectDB.callFunction(ScriptedObjectDB.java:241)
	at com.simplicite.util.ScriptedObjectDB.callFunction(ScriptedObjectDB.java:214)
	at com.simplicite.util.ScriptedObjectDB.postSave(ScriptedObjectDB.java:630)
	at com.simplicite.util.engine.ObjectManager.save(ObjectManager.java:2955)

D’après le stacktrace, visiblement on est dans le contexte d’un appel de classe Java depuis du script Rhino

@francois, peut être un pb d’ “oeuf et de poule” entre Rhino et du Java ?

rosanneQuily · January 14, 2021, 7:01am

bonjour,

même pb ce matin qu’hier … je dois vider le cache de toutes les instances.

francois · January 14, 2021, 8:33am

Bonjour Rosanne,

D’après les logs à 6h du matin il y a une tache qui travaille sur un objet en Rhino, qui invoque un objet Java dont la classe n’a pas été remise dans le class-loader (suite surement à un pb de clear-cache suite à upgrade de 2h). Les objets ne pouvant être instanciés ça génère des NPE.

Sur la question d’oeuf et de poule entre du code Rhino/Java, je ne vois pas pourquoi un clear-cache à 8h fonctionnerait mieux qu’un à 2h du matin. Les 2 cohabitent très bien, les problèmes seraient plus sur un objet à héritage qui mélangerait Rhino et Java, fortement déconseillé.

A titre préventif, il va falloir arrêter l’auto-upgrade de nuit le temps de trouver la cause de votre problème. Et tester le process d’auto-upgrade depuis une serveur de test/recette qu’on puisse analyser à chaud le comportement avec vos scripts SIM.

Et pour ne pas chercher des pb parasites au niveau applicatif, il faudrait aussi nous envoyer les logs d’une autre instance ou application pour comparer.

Avez vous changé qq choses sur les serveurs ?

rosanneQuily · January 14, 2021, 8:39am

nous n’avons rien changé sur les serveurs. Nos 7 sim sont concernées.

Sur la question Rhino/java, j’ai comme un doute. L’application Gestion des ressources a ce pb alors que les scripts sont tous en rhino. je n’ai encore rien migré en java.

c’est l’upgrade de la nuit du 12 au 13 qui a généré ce pb.

je vous envoie les logs d’une autre appli par mail.