4 Replies Latest reply on Oct 2, 2014 6:31 PM by psyclik

    Wildfly deployment abnormally long and crashes (should not)

    psyclik

      Hello!

       

      I'm having an issue regarding deployment speed of a project to wildlfy 8.1.0.

      I've been working on it for some time and it always deployed without problems, until this morning when it started taking ages to deploy.

       

      The bootstrap of wildfly itself is as fast as ever, the slowness starts at the hibernate phase of my project. After a while ( 5 to 10 minutes), it crashes. The exact same project (I reverted my code changes) deployed successfully in 4 secs this morning.

       

      I'm really wondering what is happening here as neither google, this forum, the bug tracker nor stackoverflow could provide any lead.

       

      The stacktrace mentions a war duplicate, but I'm positive I can't find any. Deployment is done through intelij idea.

       

      Here is the wildlfy stacktrace:

       

       

      @

      /Users/antoine/Workapps/wildfly-8.1.0.Final/bin/standalone.sh

      Detected server admin port: 9990

      Detected server http port: 8080

      JAVA_OPTS already set in environment; overriding default settings with values: -Xdebug -Xrunjdwp:transport=dt_socket,address=127.0.0.1:61321,suspend=y,server=n

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

       

       

        JBoss Bootstrap Environment

       

       

        JBOSS_HOME: /Users/antoine/Workapps/wildfly-8.1.0.Final

       

       

        JAVA: /Library/Java/JavaVirtualMachines/jdk1.8.0_11.jdk/Contents/Home/bin/java

       

       

        JAVA_OPTS:  -server -Xdebug -Xrunjdwp:transport=dt_socket,address=127.0.0.1:61321,suspend=y,server=n

       

       

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

       

       

      [2014-10-02 06:12:16,256] Artifact nexus:war: Server is not connected. Deploy is not available.

      Connected to the target VM, address: '127.0.0.1:61321', transport: 'socket'

      [0m18:12:17,340 INFO  [org.jboss.modules] (main) JBoss Modules version 1.3.3.Final

      [0m [0m18:12:18,069 INFO  [org.jboss.msc] (main) JBoss MSC version 1.2.2.Final

      [0m [0m18:12:18,149 INFO  [org.jboss.as] (MSC service thread 1-6) JBAS015899: WildFly 8.1.0.Final "Kenny" starting

      [0m [0m18:12:19,964 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS015888: Creating http management service using socket-binding (management-http)

      [0m [0m18:12:19,991 INFO  [org.xnio] (MSC service thread 1-5) XNIO version 3.2.2.Final

      [0m [0m18:12:20,006 INFO  [org.xnio.nio] (MSC service thread 1-5) XNIO NIO Implementation Version 3.2.2.Final

      [0m [0m18:12:20,055 INFO  [org.jboss.as.security] (ServerService Thread Pool -- 45) JBAS013171: Activating Security Subsystem

      [0m [33m18:12:20,057 WARN  [org.jboss.as.txn] (ServerService Thread Pool -- 46) JBAS010153: Node identifier property is set to the default value. Please make sure it is unique.

      [0m [0m18:12:20,077 INFO  [org.jboss.as.security] (MSC service thread 1-8) JBAS013170: Current PicketBox version=4.0.21.Beta1

      [0m [0m18:12:20,080 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 32) JBAS010280: Activating Infinispan subsystem.

      [0m [0m18:12:20,086 INFO  [org.jboss.as.jsf] (ServerService Thread Pool -- 38) JBAS012615: Activated the following JSF Implementations: [main]

      [0m [0m18:12:20,096 INFO  [org.jboss.as.naming] (ServerService Thread Pool -- 40) JBAS011800: Activating Naming Subsystem

      [0m [0m18:12:20,111 INFO  [org.wildfly.extension.io] (ServerService Thread Pool -- 31) WFLYIO001: Worker 'default' has auto-configured to 8 core threads with 64 task threads based on your 4 available processors

      [0m [0m18:12:20,155 INFO  [org.jboss.as.webservices] (ServerService Thread Pool -- 48) JBAS015537: Activating WebServices Extension

      [0m [0m18:12:20,182 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017502: Undertow 1.0.15.Final starting

      [0m [0m18:12:20,183 INFO  [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool -- 27) JBAS010403: Deploying JDBC-compliant driver class org.h2.Driver (version 1.3)

      [0m [0m18:12:20,184 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 47) JBAS017502: Undertow 1.0.15.Final starting

      [0m [0m18:12:20,212 INFO  [org.jboss.remoting] (MSC service thread 1-5) JBoss Remoting version 4.0.3.Final

      [0m [0m18:12:20,255 INFO  [org.jboss.as.connector.logging] (MSC service thread 1-7) JBAS010408: Starting JCA Subsystem (IronJacamar 1.1.5.Final)

      [0m [0m18:12:20,289 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-3) JBAS010417: Started Driver service with driver-name = h2

      [0m [0m18:12:20,803 INFO  [org.jboss.as.mail.extension] (MSC service thread 1-6) JBAS015400: Bound mail session [java:jboss/mail/Default]

      [0m [0m18:12:20,807 INFO  [org.jboss.as.naming] (MSC service thread 1-7) JBAS011802: Starting Naming Service

      [0m [0m18:12:21,059 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 47) JBAS017527: Creating file handler for path /Users/antoine/Workapps/wildfly-8.1.0.Final/welcome-content

      [0m [0m18:12:21,114 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) JBAS017525: Started server default-server.

      [0m [0m18:12:21,165 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-5) JBAS017531: Host default-host starting

      [0m [0m18:12:21,266 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-8) JBAS017519: Undertow HTTP listener default listening on /127.0.0.1:8080

      [0m [0m18:12:22,323 INFO  [org.jboss.as.server.deployment.scanner] (MSC service thread 1-8) JBAS015012: Started FileSystemDeploymentService for directory /Users/antoine/Workapps/wildfly-8.1.0.Final/standalone/deployments

      [0m [0m18:12:22,378 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-7) JBAS015876: Starting deployment of "nexus-1.0-SNAPSHOT.war" (runtime-name: "nexus-1.0-SNAPSHOT.war")

      [0m [0m18:12:22,378 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-1) JBAS015876: Starting deployment of "mysql-connector-java-5.1.29.jar" (runtime-name: "mysql-connector-java-5.1.29.jar")

      [0m [0m18:12:22,462 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2) JBAS010400: Bound data source [java:jboss/datasources/ExampleDS]

      [0m [0m18:12:22,787 INFO  [org.jboss.ws.common.management] (MSC service thread 1-6) JBWS022052: Starting JBoss Web Services - Stack CXF Server 4.2.4.Final

      [0m [0m18:12:22,916 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) JBAS010404: Deploying non-JDBC-compliant driver class com.mysql.jdbc.Driver (version 5.1)

      [0m [0m18:12:22,932 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) JBAS010417: Started Driver service with driver-name = mysql-connector-java-5.1.29.jar

      [0m [0m18:12:22,938 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-8) JBAS010400: Bound data source [java:/jdbc/nexus]

      [0m [0m18:12:22,938 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3) JBAS010400: Bound data source [java:/jdbc/fcl3]

      [0m [0m18:12:22,942 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2) JBAS010400: Bound data source [java:/jdbc/airports]

      [0m [0m18:12:22,944 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-6) JBAS010400: Bound data source [java:/jdbc/sushis]

      [0m [33m18:12:24,945 WARN  [org.jboss.as.server.deployment] (MSC service thread 1-1) JBAS015960: Class Path entry vaadin-server-7.2.0.beta1.jar in /content/nexus-1.0-SNAPSHOT.war/WEB-INF/lib/vaadin-cdi-1.0.0.alpha2.jar  does not point to a valid jar for a Class-Path reference.

      [0m [33m18:12:24,950 WARN  [org.jboss.as.server.deployment] (MSC service thread 1-1) JBAS015960: Class Path entry vaadin-shared-7.2.0.beta1.jar in /content/nexus-1.0-SNAPSHOT.war/WEB-INF/lib/vaadin-cdi-1.0.0.alpha2.jar  does not point to a valid jar for a Class-Path reference.

      [0m [33m18:12:24,951 WARN  [org.jboss.as.server.deployment] (MSC service thread 1-1) JBAS015960: Class Path entry android-json-0.0.20131108.vaadin1.jar in /content/nexus-1.0-SNAPSHOT.war/WEB-INF/lib/vaadin-cdi-1.0.0.alpha2.jar  does not point to a valid jar for a Class-Path reference.

      [0m [0m18:12:25,593 INFO  [org.jboss.as.jpa] (MSC service thread 1-1) JBAS011401: Read persistence.xml for jpaUnit

      [0m [0m18:12:25,828 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 50) JBAS011409: Starting Persistence Unit (phase 1 of 2) Service 'nexus-1.0-SNAPSHOT.war#jpaUnit'

      [0m [0m18:12:25,851 INFO  [org.hibernate.jpa.internal.util.LogHelper] (ServerService Thread Pool -- 50) HHH000204: Processing PersistenceUnitInfo [

        name: jpaUnit

        ...]

      [0m [0m18:12:26,120 INFO  [org.hibernate.Version] (ServerService Thread Pool -- 50) HHH000412: Hibernate Core {4.3.5.Final}

      [0m [0m18:12:26,131 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 50) HHH000206: hibernate.properties not found

      [0m [0m18:12:26,137 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 50) HHH000021: Bytecode provider name : javassist

      [0m [0m18:12:26,392 INFO  [org.jboss.weld.deployer] (MSC service thread 1-1) JBAS016002: Processing weld deployment nexus-1.0-SNAPSHOT.war

      [0m [0m18:12:26,499 INFO  [org.hibernate.validator.internal.util.Version] (MSC service thread 1-1) HV000001: Hibernate Validator 5.1.0.Final

      [0m [0m18:12:26,748 INFO  [org.jboss.weld.deployer] (MSC service thread 1-1) JBAS016005: Starting Services for CDI deployment: nexus-1.0-SNAPSHOT.war

      [0m [0m18:12:26,798 INFO  [org.jboss.weld.Version] (MSC service thread 1-1) WELD-000900: 2.1.2 (Final)

      [0m [0m18:12:26,881 INFO  [org.jboss.weld.deployer] (MSC service thread 1-8) JBAS016008: Starting weld service for deployment nexus-1.0-SNAPSHOT.war

      [0m [0m18:12:27,288 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 50) JBAS011409: Starting Persistence Unit (phase 2 of 2) Service 'nexus-1.0-SNAPSHOT.war#jpaUnit'

      [0m [0m18:12:27,873 INFO  [org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 50) HCANN000001: Hibernate Commons Annotations {4.0.4.Final}

      [0mConnected to server

      [2014-10-02 06:12:30,386] Artifact nexus:war: Artifact is being deployed, please wait...

      [0m18:12:36,514 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 50) HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect

      [0m [0m18:12:45,999 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool -- 50) HHH000397: Using ASTQueryTranslatorFactory

      [0m [0m18:16:29,376 INFO  [com.vaadin.cdi.internal.VaadinExtension] (MSC service thread 1-5) UIScopedContext registered

      [0m [33m18:16:32,000 WARN  [org.jboss.weld.Validator] (MSC service thread 1-5) WELD-001471: Interceptor method init defined on class com.adms.nexus.connector.AuthConnector is not defined according to the specification. It should not throw java.io.IOException, which is a checked exception.

      [0m [33m18:16:32,336 WARN  [org.jboss.weld.Validator] (MSC service thread 1-5) WELD-001471: Interceptor method init defined on class com.adms.ages.ui.vaadin.component.AbstractEntityForm is not defined according to the specification. It should not throw java.lang.IllegalAccessException, which is a checked exception.

      [0m [33m18:16:32,363 WARN  [org.jboss.weld.Validator] (MSC service thread 1-5) WELD-001471: Interceptor method init defined on class com.adms.ages.ui.vaadin.component.AbstractEntityForm is not defined according to the specification. It should not throw java.lang.InstantiationException, which is a checked exception.

      [0m [33m18:17:32,567 WARN  [org.jboss.weld.Validator] (MSC service thread 1-5) WELD-001471: Interceptor method init defined on class com.adms.ages.core.auth.DefaultAgesAuthConnector is not defined according to the specification. It should not throw java.io.IOException, which is a checked exception.

      [0m [0m18:18:28,141 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Initializing web context for path /nexus-1.0-SNAPSHOT

      [0m [0m18:18:28,154 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Discovering Vaadin UIs...

      [0m [0m18:18:28,178 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) 1 beans inheriting from UI discovered!

      [0m [0m18:18:28,204 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Available Vaadin UIs for CDI deployment [nexus]

      [0m [33m18:18:28,228 WARNING [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Vaadin related servlet is defined in deployment descriptor, automated deployment of VaadinCDIServlet is now disabled

      [0m [0m18:18:28,247 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Done deploying Vaadin UIs

      [0m [0m18:18:37,870 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Deploying javax.ws.rs.core.Application: class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,176 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding class resource com.adms.ages.connector.RoleConnector from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,211 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding class resource com.adms.nexus.connector.AuthConnector from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,250 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding class resource com.adms.nexus.connector.ConnectorsConnector from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,273 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding provider class com.adms.ages.utils.ResponseCorsFilter from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,298 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding class resource com.adms.ages.connector.AccountConnector from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:41,323 INFO  [org.jboss.resteasy.spi.ResteasyDeployment] (MSC service thread 1-6) Adding class resource com.adms.ages.connector.PersonConnector from Application class com.adms.nexus.connector.API$Proxy$_$$_WeldClientProxy

      [0m [0m18:18:53,424 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-6) JBAS017534: Registered web context: /nexus-1.0-SNAPSHOT

      [0m [0m18:18:57,027 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS018559: Deployed "nexus-1.0-SNAPSHOT.war" (runtime-name : "nexus-1.0-SNAPSHOT.war")

      [0m [0m18:18:57,138 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS018559: Deployed "mysql-connector-java-5.1.29.jar" (runtime-name : "mysql-connector-java-5.1.29.jar")

      [0m [0m18:18:58,765 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:9990/management

      [0m [0m18:18:58,876 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:9990

      [0m [0m18:18:58,985 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: WildFly 8.1.0.Final "Kenny" started in 402079ms - Started 351 of 410 services (99 services are lazy, passive or on-demand)

      [0m [31m18:19:00,648 ERROR [org.jboss.as.controller.management-operation] (management-handler-thread - 1) JBAS014613: Operation ("add") failed - address: ([("deployment" => "nexus-1.0-SNAPSHOT.war")]) - failure description: "JBAS014803: Duplicate resource [(\"deployment\" => \"nexus-1.0-SNAPSHOT.war\")]"

      [0m [0m18:19:03,466 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-6) JBAS017535: Unregistered web context: /nexus-1.0-SNAPSHOT

      [0m [0m18:19:03,612 INFO  [com.vaadin.cdi.internal.ContextDeployer] (MSC service thread 1-6) Context destroyed

      [0m [0m18:19:04,880 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 3) JBAS011410: Stopping Persistence Unit (phase 2 of 2) Service 'nexus-1.0-SNAPSHOT.war#jpaUnit'

      [0m [0m18:19:05,193 INFO  [org.jboss.weld.deployer] (MSC service thread 1-7) JBAS016009: Stopping weld service for deployment nexus-1.0-SNAPSHOT.war

      [0m [0m18:19:09,975 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 3) JBAS011410: Stopping Persistence Unit (phase 1 of 2) Service 'nexus-1.0-SNAPSHOT.war#jpaUnit'

      [0m [0m18:19:10,544 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-8) JBAS015877: Stopped deployment nexus-1.0-SNAPSHOT.war (runtime-name: nexus-1.0-SNAPSHOT.war) in 8151ms

      [0m [0m18:19:14,000 INFO  [org.jboss.as.server] (management-handler-thread - 7) JBAS018558: Undeployed "nexus-1.0-SNAPSHOT.war" (runtime-name: "nexus-1.0-SNAPSHOT.war")

      [0m[2014-10-02 06:19:19,946] Artifact nexus:war: Error during artifact deployment. See server log for details.

      [2014-10-02 06:19:19,950] Artifact nexus:war: java.lang.Exception: JBAS014803: Duplicate resource [("deployment" => "nexus-1.0-SNAPSHOT.war")]

        • 1. Re: Wildfly deployment abnormally long and crashes (should not)
          psyclik

          Testing on a fresh wildfly install, the deployment is still very slow, but succeeds in the end. The webapp remains *very* slow.

          Don't know if that helps, and honestly don't really know where to look.

          • 2. Re: Wildfly deployment abnormally long and crashes (should not)
            dmlloyd

            Is it possible for you to isolate exactly what changed between the fast and slow deployments?

            1 of 1 people found this helpful
            • 3. Re: Wildfly deployment abnormally long and crashes (should not)
              psyclik

              I looked at the local history, and found only changes that should be totally irrelevant (code formatting, comments update) or plain java code (no CDI nor JPA changes).

              Looking at the log, things start to slow down on when hibernate starts its annotation magic, exact lines are:

               

              [0m [0m23:32:16,263 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 12) JBAS011409: Starting Persistence Unit (phase 2 of 2) Service 'nexus-1.0-SNAPSHOT.war#jpaUnit'

              [0m [0m23:32:16,404 INFO  [org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 12) HCANN000001: Hibernate Commons Annotations {4.0.4.Final}

              [0m [0m23:32:20,259 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 12) HHH000400: Using dialect: org.hibernate.dialect.MySQL5Dialect

              [0m [0m23:32:30,571 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool -- 12) HHH000397: Using ASTQueryTranslatorFactory

               

              Funny thing is I don't have this speed problem when I build a war using maven and deploy it manually.

              • 4. Re: Wildfly deployment abnormally long and crashes (should not)
                psyclik

                Ok, got it.

                 

                I was absurdly stupid on this one. The problem came from misplaced method breakpoints and had nothing to do with wildfly.

                 

                Sorry for the noise .