0 Replies Latest reply on Nov 22, 2017 10:34 AM by nicolas duminil

    Wildfly 10.1.0 - EAR deployment takes more then 3 minutes

    nicolas duminil Master

      Greetings,

       

      I have the following deployment script:

       

      #!/bin/bash

      WILDFLY_HOME=/opt/jboss/wildfly

      JBOSS_CLI=$WILDFLY_HOME/bin/jboss-cli.sh

       

      function wait_for_server() {

        until `$JBOSS_CLI -c ":read-attribute(name=server-state)" 2> /dev/null | grep -q running`; do

          sleep 1

        done

      }

       

      function wait_for_jdbc_connection() {

        until `$JBOSS_CLI -c "/subsystem=datasources/data-source=ExampleDS:test-connection-in-pool" 2> /dev/null | grep -q [true]`; do

          sleep 1

        done

      }

       

      echo $(date -u) "=> Starting WildFly server"

      $WILDFLY_HOME/bin/standalone.sh -b 0.0.0.0 -bmanagement 0.0.0.0 > /dev/null 2>&1 &

       

      echo $(date -u) "=> Waiting for the server to boot"

      wait_for_server

       

      echo $(date -u) "=> Removing data source ExampleDS, if any"

      $JBOSS_CLI -c "data-source remove --name=ExampleDS" > /dev/null 2>&1

      $JBOSS_CLI -c ":reload" > /dev/null 2>&1

       

      echo $(date -u) "=> Waiting for the server to reload"

      wait_for_server

       

      $JBOSS_CLI -c << EOF > /dev/null 2>&1

      /subsystem=datasources/jdbc-driver=h2:remove

      module add --name=com.oracle --resources=/opt/jboss/wildfly/customization/ojdbc6.jar --dependencies=javax.api,javax.transaction.api

      /subsystem=datasources/jdbc-driver=com.oracle:add(driver-name=com.oracle, driver-module-name=com.oracle, driver-xa-datasource-class-name=oracle.jdbc.xa.client.OracleXADataSource)

      data-source add --name=ExampleDS --driver-name=com.oracle --jndi-name=java:jboss/datasources/ExampleDS --connection-url=jdbc:oracle:thin:@172.19.0.2:1521:XE --user-name=nicolas --password=California1 --max-pool-size=25 --valid-connection-checker-class-name=org.jboss.jca.adapters.jdbc.extensions.oracle.OracleValidConnectionChecker, --stale-connection-checker-class-name=org.jboss.jca.adapters.jdbc.extensions.oracle.OracleStaleConnectionChecker, --exception-sorter-class-name=org.jboss.jca.adapters.jdbc.extensions.oracle.OracleExcectionSorter

      data-source  enable --name=ExampleDS

      /subsystem=infinispan/cache-container=oauth20:add(jndi-name="infinispan/oauth20-container", default-cache="clientid")

      /subsystem=infinispan/cache-container=oauth20/local-cache=clientid:add()

      /subsystem=infinispan/cache-container=oauth20/local-cache=clientid/component=transaction:write-attribute(name=mode, value="NONE")

      /subsystem=infinispan/cache-container=oauth20/local-cache=clientid/component=eviction:write-attribute(name=strategy, value="NONE")

      :reload

      EOF

      echo $(date -u) "=> Infinispan cache and Oracle data-source and driver correctly configured. Waiting for the server to reload"

      wait_for_server

      echo $(date -u) "=> Testing the new ExampleDS datasource"

      wait_for_jdbc_connection

      echo $(date -u) "=> ExampleDS datasource for Oracle test has succeeded"

      $WILDFLY_HOME/bin/add-user.sh nicolas California1$

      echo $(date -u) "=> Deploying customer-management.ear"

      $JBOSS_CLI -c "deploy ./wildfly/target/customer-management.ear"

      echo $(date -u) "=> customer-management.ear successfully deployed"

       

      It starts the server, replaces the H2 jdbc driver and the ExampleDS datasource for H2 by the Oracle 10g jdbc driver and the right ExampleDS datasource for Oracle. It also creates some Infinispan stuff and it reloads the server such that the modifications become current.

      Then it trie to test the newly created datasource and this test takes more then 1 minutes before it sicceeds. After that it tries to deploy an EAR and this deployment takes more then 3 minutes to succeed. here is the ouitput:

       

      [INFO] Wed Nov 22 14:40:33 UTC 2017 => Starting WildFly server

      [INFO] Wed Nov 22 14:40:33 UTC 2017 => Waiting for the server to boot

      [INFO] Wed Nov 22 14:40:36 UTC 2017 => Removing data source ExampleDS, if any

      [INFO] Wed Nov 22 14:40:37 UTC 2017 => Waiting for the server to reload

      [INFO] Wed Nov 22 14:40:39 UTC 2017 => Infinispan cache and Oracle data-source and driver correctly configured. Waiting for the server to reload

      [INFO] Wed Nov 22 14:40:41 UTC 2017 => Testing the new ExampleDS datasource

      [INFO] Wed Nov 22 14:41:41 UTC 2017 => ExampleDS datasource for Oracle test has succeeded

      [INFO] Added user 'nicolas' to file '/opt/jboss/wildfly/standalone/configuration/mgmt-users.properties'

      [INFO] Added user 'nicolas' to file '/opt/jboss/wildfly/domain/configuration/mgmt-users.properties'

      [INFO] Wed Nov 22 14:41:42 UTC 2017 => Deploying customer-management.ear

      [INFO] Wed Nov 22 14:44:45 UTC 2017 => customer-management.ear successfully deployed

      [INFO]  ---> 2ad491281d9b

      [INFO] Removing intermediate container b49cabcf972c

      [INFO] Successfully built 2ad491281d9b

      [INFO] Successfully tagged wfy10_oracle:latest

       

      I coloured in red the issues. The server.log file contains the following:

       

      ....

      2017-11-22 14:40:40,202 INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full 10.1.0.Final (WildFly Core 2.2.0.Final) started in 252ms - Started 352 of 645 services (458 services are lazy, passive or on-demand)

      2017-11-22 14:41:41,941 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (management-handler-thread - 1) IJ000604: Throwable while attempting to get a new connection: null: javax.resource.ResourceException: IJ031084: Unable to create connection

      ....

      Caused by: java.net.SocketTimeoutException: connect timed out

      ...

      2017-11-22 14:41:41,942 ERROR [org.jboss.as.controller.management-operation] (management-handler-thread - 1) WFLYCTL0013: Operation ("test-connection-in-pool") failed - address: ([

          ("subsystem" => "datasources"),

          ("data-source" => "ExampleDS")

      ]) - failure description: "WFLYJCA0040: failed to invoke operation: WFLYJCA0047: Connection is not valid"

      2017-11-22 14:41:43,039 INFO  [org.jboss.as.repository] (management-handler-thread - 6) WFLYDR0001: Content added at location /opt/jboss/wildfly/standalone/data/content/e1/a19d9030985cec1ed055db34280a20c7462f93/content

      2017-11-22 14:41:43,050 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-8) WFLYSRV0027: Starting deployment of "customer-management.ear" (runtime-name: "customer-management.ear")

      2017-11-22 14:41:43,086 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-3) WFLYSRV0207: Starting subdeployment (runtime-name: "customer-management-rest.war")

      2017-11-22 14:41:43,375 INFO  [org.jboss.as.jpa] (MSC service thread 1-7) WFLYJPA0002: Read persistence.xml for customers

      2017-11-22 14:41:43,414 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 68) WFLYJPA0010: Starting Persistence Unit (phase 1 of 2) Service 'customer-management.ear/customer-management-rest.war#customers'

      2017-11-22 14:41:43,418 INFO  [org.jboss.weld.deployer] (MSC service thread 1-1) WFLYWELD0003: Processing weld deployment customer-management.ear

      2017-11-22 14:41:43,430 INFO  [org.hibernate.jpa.internal.util.LogHelper] (ServerService Thread Pool -- 68) HHH000204: Processing PersistenceUnitInfo [

              name: customers

              ...]

      2017-11-22 14:41:43,476 INFO  [org.hibernate.validator.internal.util.Version] (MSC service thread 1-1) HV000001: Hibernate Validator 5.2.4.Final

      2017-11-22 14:41:43,501 INFO  [org.hibernate.Version] (ServerService Thread Pool -- 68) HHH000412: Hibernate Core {5.0.10.Final}

      2017-11-22 14:41:43,502 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 68) HHH000206: hibernate.properties not found

      2017-11-22 14:41:43,503 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 68) HHH000021: Bytecode provider name : javassist

      2017-11-22 14:41:43,507 WARN  [org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl] (ServerService Thread Pool -- 68) HHH000059: Defining hibernate.transaction.flush_before_completion=true ignored in HEM

      2017-11-22 14:41:43,535 INFO  [org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 68) HCANN000001: Hibernate Commons Annotations {5.0.1.Final}

      2017-11-22 14:41:43,577 INFO  [org.jboss.weld.deployer] (MSC service thread 1-7) WFLYWELD0003: Processing weld deployment customer-management-rest.war

      ....

      2017-11-22 14:42:43,939 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 69) IJ000604: Throwable while attempting to get a new connection: null: javax.resource.ResourceException: IJ031084: Unable to create connection

      ...

      Caused by: java.net.SocketTimeoutException: connect timed out

      ...

      2017-11-22 14:42:43,945 WARN  [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator] (ServerService Thread Pool -- 69) HHH000342: Could not obtain connection to query metadata : javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ExampleDS

      .....

      Caused by: java.net.SocketTimeoutException: connect timed out

      .....

      2017-11-22 14:43:44,331 ERROR [org.hibernate.hql.spi.id.IdTableHelper] (ServerService Thread Pool -- 69) Unable obtain JDBC Connection: java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ExampleDS

      .........

      Caused by: java.net.SocketTimeoutException: connect timed out

      ......

      2017-11-22 14:43:44,365 INFO  [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool -- 69) HHH000227: Running hbm2ddl schema export

      2017-11-22 14:44:44,420 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 69) IJ000604: Throwable while attempting to get a new connection: null: javax.resource.ResourceException: IJ031084: Unable to create connection

      ......

      Caused by: java.net.SocketTimeoutException: connect timed out

      ............

      2017-11-22 14:44:44,424 ERROR [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool -- 69) HHH000231: Schema export unsuccessful: java.sql.SQLException: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ExampleDS

      .......

      Caused by: java.net.SocketTimeoutException: connect timed out

      .........

      2017-11-22 14:44:44,426 INFO  [org.hibernate.tool.hbm2ddl.SchemaExport] (ServerService Thread Pool -- 69) HHH000230: Schema export complete

      2017-11-22 14:44:45,190 INFO  [org.jboss.resteasy.resteasy_jaxrs.i18n] (ServerService Thread Pool -- 70) RESTEASY002225: Deploying javax.ws.rs.core.Application: class fr.simplex_software.rest.CustomerManagementApp

      2017-11-22 14:44:45,212 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 70) WFLYUT0021: Registered web context: /customer-management

      2017-11-22 14:44:45,221 INFO  [org.jboss.as.server] (management-handler-thread - 6) WFLYSRV0010: Deployed "customer-management.ear" (runtime-name : "customer-management.ear")

       

      As one can see here above, between 14:41 and 14:44 there are several SocketTimeoutException, before the EAR deployment finally succeeds. I reckon this must be the socket use to communicate with the database (172.19.0.2:1521 in this case) which timeouts. But I don't understand why 'cause the Oracle database is started and available when every thing happens.

       

      I don't think it matters much but I have to say that this is ran in a docker container based on jboss/wildfly:10.1.0.Final image.

       

      Any suggestion ?

       

      Many thanks in advance.

       

      Nicolas