Plugin <pluginName> not found

[yblatti]

Plusieurs utilisateurs rencontrent encore le problème de plugins non trouvé, et doivent relancer les traitements.

[yblatti]

NB : Le bug #195 n'a pas pu être reproduit chez ASIT ni chez ArxIT (Testé sur Centos + OpenJDK8, Win Server 2012 R2 + Oracle JDK 7, Windows Server 2019 + OpenJDK8 et Win 10 + OpenJDK8).
Un notification admin sur l'erreur a été ajoutée par contre.

[yblatti]

Lié à #213 car les mécaniques de chargement dynamique de classe / plugin ont été revues sur les version "modernes" de java.

[yblatti]

Se produit toujours en v2.0+

[maltaesousa]

De notre côté ça s'est reproduit uniquement après un redémarrage de l'application dans Tomcat. Avant ça se produisait plus souvent même si on touchait pas à Tomcat.

[rbovard]

Si l'on arrive vraiment pas à trouver comment corriger ce bug, une piste serait peut-être d'aussi envoyer les notifications d'erreurs "Plugin not found" aux administrateurs, parce que là seul l'opérateur les reçoit mais il ne peut que redémarrer la tâche qui plantera toujours.

[yblatti]

Non reproduit sur Linux

Je n'arrive pas à le reproduire sur un environnement de debug Linux.
J'ai pourtant essayé de le pousser dans ses retranchements (100 produits en entrée au démarrage, ajouté des délais artificiels, etc).

Je vois que tous ceux qui sont concernés utilisent des environnements Windows, il doit donc y avoir un composante environnementale. Je n'ai pour l'instant pas d'environnement de dev/debug sur Windows.

Premières commandes ?

Chez presque tout le monde, cela concerne les premières commandes après un redémarrage (daily de nuit, une fois le dimanche, etc). J'oriente donc mes recherches vers les initialisations.

Ma piste

Bien que je n'arrive pas à le reproduire sur mon environnement, je me suis attaqué à la lecture du code et des logs, et j'ai peut-être une piste, basé sur le log suivant. (Disclaimer : je ne suis pas développeur java!)

On y voit deux threads concurrent, au démarrage de l'application. Ils sont colorés ici :

+ pool-3-thread-2 en vert
! pool-3-thread-1 en orange

06:15:32.529 8941 [main] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Setting the servlet context.
06:15:32.535 8947 [main] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Setting the servlet context.
+ 07:47:58.198 5554610 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Getting task processor FME2017.
+ 07:47:58.198 5554610 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Instantiating the task processor discoverer.
+ 07:47:58.198 5554610 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Assembling an array of task processors JAR URLs.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-reject-2.0.1-RELEASE.jar
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Getting task processor FME2017.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting task processor plugin FME2017.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting all plugins.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Fetching all the plugins.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Initializing the service loader.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting the task processors class loader,
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - The class loader is not instantiated. Creating a new instance.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-reject-2.0.1-RELEASE.jar.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - No additional JAR URLs set. Using the default class loader.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-fmeserver-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-fmeserver-2.0.1-RELEASE.jar.
! 07:47:58.213 5554625 [pool-3-thread-1] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Task processors plugins discoverer initialized with 0 plugins.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-archive-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-archive-2.0.1-RELEASE.jar.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-email-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-email-2.0.1-RELEASE.jar.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-validation-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-validation-2.0.1-RELEASE.jar.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-fmedesktop-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-fmedesktop-2.0.1-RELEASE.jar.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Found task processor plugin JAR D:\Applications\Tomcat9.0.68\webapps\extract##2.0.1-RELEASE\WEB-INF\classes\task_processors\extract-task-remark-2.0.1-RELEASE.jar
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - The URL of the task processor plugin JAR is file:/D:/Applications/Tomcat9.0.68/webapps/extract%23%232.0.1-RELEASE/WEB-INF/classes/task_processors/extract-task-remark-2.0.1-RELEASE.jar.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.i.TaskProcessorDiscovererWrapper - Setting the task processors JAR URLs.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Defining the URLs of the JAR files possibly containing task processors plugins.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - 7 JAR URLs set.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Reinitializing the class loader so that it is reinstantiated with new URLs when next used.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Reinitializing the cached plugins so they are fetched again when next used.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting task processor plugin FME2017.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting all plugins.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Fetching all the plugins.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Initializing the service loader.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Getting the task processors class loader,
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - The class loader is not instantiated. Creating a new instance.
+ 07:47:58.213 5554625 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Instantiating a class loader with 7 additional JAR URLs.
+ 07:47:58.229 5554641 [pool-3-thread-2] DEBUG c.a.e.p.TaskProcessorsDiscoverer - Task processor found. Attempting instantiation.

Les deux threads utilisent en même temps le bean taskProcessorDiscoverer (de type TaskProcessorDiscovererWrapper) pour trouver un plugin de tâche. Pour rappel, un Spring Bean a par défaut un scope singletonet par conséquent une seule instance qui sera injectée par le container IOC.

/extract/src/main/java/ch/asit_asso/extract/context/ContextListener.java

    /**
     * Initializes the object that finds the available plugins to carry process data orders.
     *
     * @return the task processor plugins finder bean
     */
    @Bean
    public TaskProcessorDiscovererWrapper taskProcessorDiscoverer() {
        TaskProcessorDiscovererWrapper taskProcessorDiscoverer = new TaskProcessorDiscovererWrapper();
        taskProcessorDiscoverer.setApplicationLanguage(this.applicationLanguage);
        taskProcessorDiscoverer.setServletContext(this.servletContext);

        return taskProcessorDiscoverer;
    }

/extract/src/main/java/ch/asit_asso/extract/plugins/implementation/TaskProcessorDiscovererWrapper.java

    /**
     * Gets the current instance of the task processor discoverer and initializes it for the current context if
     * necessary.
     *
     * @return the current task processor discoverer
     */
    private TaskProcessorsDiscoverer getTaskProcessorDiscoverer() {

        if (this.taskProcessorDiscoverer == null) {
            this.logger.debug("Instantiating the task processor discoverer.");
            this.taskProcessorDiscoverer = TaskProcessorsDiscoverer.getInstance();
            this.taskProcessorDiscoverer.setApplicationLanguage(this.applicationLanguage);
            URL[] jarUrlsArray = this.getJarUrls();

            if (jarUrlsArray != null) {
                this.logger.debug("Setting the task processors JAR URLs.");
                this.taskProcessorDiscoverer.setJarUrls(jarUrlsArray);
            } else {
                this.taskProcessorDiscoverer.setJarUrls(new URL[]{});
                this.logger.warn("The returned JAR URLs was null. Using the default system class loader.");
            }
        }

        return this.taskProcessorDiscoverer;
    }

On y voit un appel à TaskProcessorsDiscoverer.getInstance(), qui retourne un singleton et est thread safe (synchronized).

    /**
     * Creates a new instance of the task processor plugin discoverer. This constructor should not be called directly
     * (singleton).
     */
    private TaskProcessorsDiscoverer() {
        this.arePluginsInitialized = false;
    }



    /**
     * Gets the current instance of the connector discoverer and creates it first if necessary.
     * // NOTE yblatti : ce commentaire est faux ! connector -> task
     *
     * @return the task processor discoverer
     */
    public static synchronized TaskProcessorsDiscoverer getInstance() {

        if (TaskProcessorsDiscoverer.discoveryService == null) {
            TaskProcessorsDiscoverer.discoveryService = new TaskProcessorsDiscoverer();
        }

        return TaskProcessorsDiscoverer.discoveryService;
    }

Zoom sur getTaskProcessorDiscoverer

J'ai annoté getTaskProcessorDiscoverer avec ma suspicion :

/extract/src/main/java/ch/asit_asso/extract/plugins/implementation/TaskProcessorDiscovererWrapper.java

    private TaskProcessorsDiscoverer getTaskProcessorDiscoverer() {

        if (this.taskProcessorDiscoverer == null) {
            this.logger.debug("Instantiating the task processor discoverer.");
            this.taskProcessorDiscoverer = TaskProcessorsDiscoverer.getInstance();
            // #### 
            // #### A partir d'ici taskProcessorDiscoverer est défini, par conséquent un deuxième appel à 
            // #### getTaskProcessorDiscoverer ne rentre plus dans le if, 
            // #### mais aucun jar n'a été ajouté via setJarUrls.
            // #### Le deuxième appel utiliserai donc this.taskProcessorDiscoverer sans liste de jars.
            // #### 
            this.taskProcessorDiscoverer.setApplicationLanguage(this.applicationLanguage);
            URL[] jarUrlsArray = this.getJarUrls();

            if (jarUrlsArray != null) {
                this.logger.debug("Setting the task processors JAR URLs.");
                this.taskProcessorDiscoverer.setJarUrls(jarUrlsArray);
            } else {
                this.taskProcessorDiscoverer.setJarUrls(new URL[]{});
                this.logger.warn("The returned JAR URLs was null. Using the default system class loader.");
            }
            // #### 
            // #### C'est seulement à partir d'ici qu'un deuxième appel est safe !!!
            // #### 
        }

        return this.taskProcessorDiscoverer;
    }

Ma proposition

Je propose donc de rendre getTaskProcessorDiscoverer() thread safe en ajoutant synchronized :

    private synchronized TaskProcessorsDiscoverer getTaskProcessorDiscoverer() {

J'ai l’impression que c'est une adaptation sans danger, même si elle se fait à fins exploratoires.

D'ailleurs, si elle semble correcte, on pourrait aussi l'ajouter à la découverte des plugins de connecteurs, bien qu'on ait jamais rencontré le problème à ma connaissance :

    private synchronized ConnectorDiscoverer getConnectorDiscoverer() {

Mais pourquoi Windows ?

Tout cela ne dit pas pourquoi on ne rencontre cela que sur les infras Windows.
J'imagine que cela dépend des implémentations sous-jacentes d'accès aux ressources (vu qu'on va parcourir les dossiers et lire la liste des jars...). Les blocages doivent différer, ou le temps d'accès au ressources, ce qui change le risque de collisions.

[yblatti]

Remonté pour avis chez arxit : FS#23401