WebSphere Liberty Profile blocking on Datasource lookup

Question

I'm trying to configure a datasource in IBM WebSphere Liberty Profile (16.0.0.3) and this is what I've done so far:

server.xml

<authData id="dbuser" password="{xor}blablabla" user="MY_USER"/>

<dataSource id="Oracle" isolationLevel="TRANSACTION_READ_COMMITTED" 
    jdbcDriverRef="OracleDriver" 
    jndiName="EPMS_DS" 
    recoveryAuthDataRef="dbuser" 
    type="javax.sql.ConnectionPoolDataSource">

    <properties.oracle databaseName="DBNAME" portNumber="1521" serverName="SERVERNAME"/>
</dataSource>

<jdbcDriver id="OracleDriver" 
    javax.sql.ConnectionPoolDataSource="oracle.jdbc.pool.OracleConnectionPoolDataSource" 
    libraryRef="shared-library"/>

web.xml

<resource-env-ref>
    <description>The Oracle DS</description>
    <resource-env-ref-name>jdbc/OracleDS</resource-env-ref-name>
    <resource-env-ref-type>javax.sql.DataSource</resource-env-ref-type>
</resource-env-ref>

ibm-web-bnd.xml

<resource-ref name="jdbc/OracleDS" binding-name="EPMS_DS">
    <authentication-alias name="dbuser" />
</resource-ref>

However, besides the application server is taking more than 2 minutes to startup, my application seems to freeze on the following instruction:

ctx = new InitialContext();
ctx.lookup("java:comp/env/jdbc/OracleDS");

The log doesn't show any errors, the last line it shows is an application's debug message indicating it is going to do a JNDI lookup.

I've also tried different configurations in server.xml, without <authData> and explicitly defining user and password on the datasource, but with identical results:

<dataSource id="Oracle" isolationLevel="TRANSACTION_READ_COMMITTED" jdbcDriverRef="OracleDriver" jndiName="EPMS_DS" type="javax.sql.ConnectionPoolDataSource">
    <properties.oracle URL="jdbc:oracle:thin:@SERVERNAME:1521:DBNAME" password="{xor}blablabla" user="MY_USER"/>
</dataSource>

Sadly, Liberty Profile doesn't seem to provide a way to test the DB connection, but everything seems correctly configured (I can assure the credentials are correct, as well as the server name and port). What am I missing here?

EDIT #1

Following njr's suggestion, I've performed a thread dump and here is a summary:

-  waiting on com.ibm.tx.jta.impl.EventSemaphore@737eaefc
-  waiting on com.ibm.ws.objectManager.FileLogOutput$FlushHelper@19d51071
-  waiting on com.ibm.ws.objectManager.FileLogOutput$NotifyHelper@2fa0da91
-  waiting on com.ibm.ws.objectManager.ObjectManagerState$CheckpointHelper@5b0919fc
-  waiting on com.ibm.ws.sib.msgstore.persistence.dispatcher.SpillDispatcher$DispatchingLock@1620db94
   (8 Occorrences, but different instances)
   ...
-  waiting on com.ibm.ws.threading.internal.BoundedBuffer$GetQueueLock@c8a05b6
   (56 Occorrences, but different instances)
   ...
-  waiting on java.lang.Object@4c1d5897
-  waiting on java.lang.ref.Reference$Lock@5448da4c
-  waiting on java.lang.ref.ReferenceQueue$Lock@f91b025
-  waiting on java.util.LinkedList@5b213416
-  waiting on java.util.LinkedList@6cb46e1f
-  waiting on java.util.TaskQueue@f50561c
   (14 Occorrences, but different instances)
   ...
-  waiting on java.util.concurrent.atomic.AtomicReference@5476d077
-  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4da17c93
-  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@513339c6
-  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@5dc2ae0f
-  waiting on org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@236970be
-  waiting on org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@6dfdd5
-  waiting on org.eclipse.osgi.framework.eventmgr.EventManager$EventThread@72ce4e1c
-  blocked on com.ibm.tx.jta.embeddable.impl.EmbeddableTMHelper@5748c911
-  blocked on com.ibm.tx.jta.embeddable.impl.EmbeddableTMHelper@5748c911

Can someone help me to interpret this?

EDIT #2

Here's where the complete stack trace of the blocked threads:

LargeThreadPool-thread-148 [217] (BLOCKED)
   com.ibm.tx.jta.embeddable.impl.EmbeddableTMHelper.start line: 63
   com.ibm.tx.jta.util.TxTMHelper.start line: 461
   com.ibm.tx.util.TMHelper.start line: 74
   com.ibm.tx.jta.util.TxTMHelper.checkTMState line: 500
   com.ibm.tx.util.TMHelper.checkTMState line: 116
   com.ibm.tx.jta.impl.TranManagerSet.registerResourceInfo line: 270
   com.ibm.ws.transaction.services.TransactionManagerService.registerResourceInfo line: 260
   com.ibm.ejs.j2c.ConnectionManager.registerXAResourceInfo line: 2537
   com.ibm.ejs.j2c.ConnectionManager.<init> line: 509
   com.ibm.ejs.j2c.ConnectionManagerServiceImpl.getConnectionManager line: 407
   com.ibm.ejs.j2c.ConnectionManagerServiceImpl.getConnectionManager line: 54
   com.ibm.ws.jca.cm.AbstractConnectionFactoryService.createResource line: 146
   com.ibm.ws.injectionengine.osgi.internal.IndirectJndiLookupObjectFactory.createResourceWithFilter line: 346
   com.ibm.ws.injectionengine.osgi.internal.IndirectJndiLookupObjectFactory.createResource line: 319
   com.ibm.ws.injectionengine.osgi.internal.IndirectJndiLookupObjectFactory.getObjectInstance line: 133
   com.ibm.ws.injectionengine.osgi.internal.IndirectJndiLookupObjectFactory.getObjectInstance line: 99
   com.ibm.wsspi.injectionengine.InjectionBinding.getInjectionObjectInstance line: 1556
   com.ibm.wsspi.injectionengine.InjectionBinding.getInjectionObject line: 1433
   com.ibm.wsspi.injectionengine.InjectionBinding.getInjectionObject line: 1389
   com.ibm.ws.injectionengine.osgi.internal.naming.InjectionJavaColonHelper.getObjectInstance line: 116
   com.ibm.ws.jndi.url.contexts.javacolon.internal.JavaURLContext.lookup line: 333
   com.ibm.ws.jndi.url.contexts.javacolon.internal.JavaURLContext.lookup line: 371
   org.apache.aries.jndi.DelegateContext.lookup line: 161
   javax.naming.InitialContext.lookup line: 417
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController.jndiLookupUsed line: 264
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController.checkConfiguration line: 115
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController.<init> line: 95
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController.<init> line: 51
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController$SingletonHolder.<clinit> line: 81
   pt.sibs.epms.persistence.utils.EntityManagerFactoryController.getInstance line: 88
   pt.sibs.epms.util.logging.LoggerConfiguration.<clinit> line: 33
   pt.sibs.epms.ecc.renderer.HtmlFormRenderer.<clinit> line: 25
   java.lang.Class.forName0 line: not available [native method]
   java.lang.Class.forName line: 348
   com.ibm.ws.webcontainer.osgi.webapp.WebApp.addClassToHandlesTypesStartupSet line: 1104
   com.ibm.ws.webcontainer.osgi.webapp.WebApp.scanForHandlesTypesClasses line: 1038
   com.ibm.ws.webcontainer.webapp.WebApp.initializeServletContainerInitializers line: 2493
   com.ibm.ws.webcontainer.webapp.WebApp.initialize line: 1037
   com.ibm.ws.webcontainer.webapp.WebApp.initialize line: 6545
   com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.startWebApp line: 466
   com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.createRunnableHandler line: 264
   com.ibm.ws.webcontainer.osgi.DynamicVirtualHost.createRunnableHandler line: 329
   com.ibm.ws.http.internal.VirtualHostImpl.discriminate line: 251
   com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready line: 301
   com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination line: 471
   com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest line: 405
   com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest line: 285
   com.ibm.ws.http.channel.internal.inbound.HttpICLReadCallback.complete line: 66
   com.ibm.ws.channel.ssl.internal.SSLReadServiceContext$SSLReadCompletedCallback.complete line: 1777
   com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete line: 504
   com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO line: 574
   com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun line: 929
   com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run line: 1018
   java.util.concurrent.ThreadPoolExecutor.runWorker line: 1142
   java.util.concurrent.ThreadPoolExecutor$Worker.run line: 617
   java.lang.Thread.run line: 745

And the second thread:

LargeThreadPool-thread-3 [33] (BLOCKED)
   com.ibm.tx.jta.embeddable.impl.EmbeddableTMHelper.start line: 63
   com.ibm.tx.jta.util.TxTMHelper.start line: 461
   com.ibm.tx.util.TMHelper.start line: 74
   com.ibm.tx.jta.util.TxTMHelper.checkTMState line: 500
   com.ibm.tx.util.TMHelper.checkTMState line: 116
   com.ibm.tx.jta.impl.TranManagerSet.begin line: 167
   com.ibm.ejs.csi.TranStrategy.beginGlobalTx line: 593
   com.ibm.ejs.csi.Required.preInvoke line: 56
   com.ibm.ejs.csi.TransactionControlImpl.preInvoke line: 222
   com.ibm.ejs.container.EJSContainer.preInvokeActivate line: 3176
   com.ibm.ejs.container.EJSContainer.EjbPreInvoke line: 2576
   com.ibm.ejs.container.TimedObjectWrapper.invokeCallback line: 84
   com.ibm.ejs.container.TimerNpRunnable.doWork line: 196
   com.ibm.ejs.container.TimerNpRunnable.run line: 103
   java.util.concurrent.Executors$RunnableAdapter.call line: 511
   java.util.concurrent.FutureTask.run line: 266
   java.util.concurrent.ThreadPoolExecutor.runWorker line: 1142
   java.util.concurrent.ThreadPoolExecutor$Worker.run line: 617
   java.lang.Thread.run line: 745

Edit #3

The thread that is WAITING and, apparently, blocking the other two threads:

LargeThreadPool-thread-38 [103] (WAITING)
   java.lang.Object.wait line: not available [native method]
   java.lang.Object.wait line: 502
   com.ibm.tx.jta.impl.EventSemaphore.waitEvent line: 71
   com.ibm.tx.jta.impl.RecoveryManager.waitForReplayCompletion line: 1273
   com.ibm.tx.jta.impl.TxRecoveryAgentImpl.initiateRecovery line: 413
   com.ibm.ws.recoverylog.spi.RecoveryDirectorImpl.directInitialization line: 751
   com.ibm.ws.recoverylog.spi.RecoveryDirectorImpl.driveLocalRecovery line: 1240
   com.ibm.ws.recoverylog.spi.RecLogServiceImpl.start line: 125
   com.ibm.tx.jta.embeddable.impl.EmbeddableTMHelper.start line: 130
   com.ibm.tx.jta.util.TxTMHelper.start line: 461
   com.ibm.tx.util.TMHelper.start line: 74
   com.ibm.tx.jta.util.TxTMHelper.checkTMState line: 500
   com.ibm.tx.util.TMHelper.checkTMState line: 116
   com.ibm.tx.jta.impl.TranManagerSet.begin line: 167
   com.ibm.ws.transaction.services.TransactionManagerService.begin line: 281
   com.ibm.ws.concurrent.persistent.internal.PersistentExecutorImpl$PollingTask.run line: 2239

Not sure if it is related, but ffdc is showing the following exception:

------Start of DE processing------ = [09-11-2016 14:41:09:006 GMT]
Exception = com.ibm.ws.recoverylog.spi.LogIncompatibleException
Source = com.ibm.ws.recoverylog.spi.LogHandle
probeid = 326
Stack Dump = com.ibm.ws.recoverylog.spi.LogIncompatibleException
    at com.ibm.ws.recoverylog.spi.LogFileHandle.fileOpen(LogFileHandle.java:522)
    at com.ibm.ws.recoverylog.spi.LogHandle.openLog(LogHandle.java:324)
    at com.ibm.ws.recoverylog.spi.MultiScopeRecoveryLog.openLog(MultiScopeRecoveryLog.java:602)at com.ibm.ws.recoverylog.spi.RecoveryLogImpl.openLog(RecoveryLogImpl.java:77)
    at com.ibm.tx.jta.impl.RecoveryManager.run(RecoveryManager.java:1835)
    at java.lang.Thread.run(Thread.java:745)

Answer 1

In your Edit #3, the thread that is waiting in

com.ibm.tx.jta.impl.RecoveryManager.waitForReplayCompletion

will have spawned another recoveryManager thread who's role is to access the transaction log files in your flesystem. That other thread Should do the minimal amount of file processing necessary before signalling to the waiting thread that it may continue. Can you see another thread with a stack containing

com.ibm.tx.jta.impl.RecoveryManager.run ?

I am concerned about the LogIncompatibleException. It suggests that the transaction log files on your filesystem are corrupt. This should not cause the server to hang and I believe you've hit a product defect.

If you need to make progress quickly, it may be appropriate in your scenario to delete the transaction log files. Please note that this is something we only suggest to customers with extreme care as the transaction logs ensure the integrity of distributed transactions. In a production environment we'd generally recommend that such action is only taken under the guidance of IBM Level 3 Service. But in a test/evaluation scenario it can be applicable.

The Liberty transaction log info is stored in the /wlp/usr/servers//tranlog directory. If appropriate the tranlog and partnerlog subdirectories may be deleted and the server restarted.