Uploaded image for project: 'PUBLIC - Liferay Portal Community Edition'
  1. PUBLIC - Liferay Portal Community Edition
  2. LPS-100951

Threadlock waiting for DDMStructureManager service

    Details

      Description

      Steps to Reproduce:

      1. Execute database upgrade from previous version (So far, this has only been seen on upgrade automation - database attached)
      2. Start portal

      Expected Result:
      Server always fully starts after upgrade.

      Actual Result:
      Server sometimes fails to start with:

           [exec] 20:52:59,237 ERROR [liferay/document_library_raw_metadata_processor-1][ServiceProxyFactory:273] Service "com.liferay.dynamic.data.mapping.kernel.DDMStructureManager" is unavailable in 600000 milliseconds while setting field "_ddmStructureManager" for class "com.liferay.dynamic.data.mapping.kernel.DDMStructureManagerUtil", will retry...
           [exec] 20:53:00,623 ERROR [main][ServiceProxyFactory:273] Service "com.liferay.dynamic.data.mapping.kernel.DDMStructureManager" is unavailable in 600000 milliseconds while setting field "_ddmStructureManager" for class "com.liferay.dynamic.data.mapping.kernel.DDMStructureManagerUtil", will retry...
           [exec] 21:02:59,237 ERROR [liferay/document_library_raw_metadata_processor-1][ServiceProxyFactory:273] Service "com.liferay.dynamic.data.mapping.kernel.DDMStructureManager" is unavailable in 600000 milliseconds while setting field "_ddmStructureManager" for class "com.liferay.dynamic.data.mapping.kernel.DDMStructureManagerUtil", will retry...
           [exec] 21:03:00,625 ERROR [main][ServiceProxyFactory:273] Service "com.liferay.dynamic.data.mapping.kernel.DDMStructureManager" is unavailable in 600000 milliseconds while setting field "_ddmStructureManager" for class "com.liferay.dynamic.data.mapping.kernel.DDMStructureManagerUtil", will retry...
         [delete] Deleting: /opt/dev/projects/github/liferay-portal/jps_output
         [delete] Deleting: /opt/dev/projects/github/liferay-portal/jstack_output
      [stopwatch] [run.batch.test.action: 32:13.962 sec]
           [echo] The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test-batch.xml:370: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test-batch.xml:1319: /opt/dev/projects/github/liferay-portal/build-test-batch.xml:1323: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test-tomcat.xml:48: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test-tomcat.xml:60: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:11151: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:11404: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:3706: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:3821: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:4463: The following error occurred while executing this line:
           [echo] /opt/dev/projects/github/liferay-portal/build-test.xml:4590: Unable to find startup message after 30 minutes.
           [echo] 2019-09-03 21:12:11
           [echo] Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):
           [echo] 
           [echo] "Attach Listener" #148 daemon prio=9 os_prio=0 tid=0x00007f3f4c001000 nid=0x508 waiting on condition [0x0000000000000000]
           [echo]    java.lang.Thread.State: RUNNABLE
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "liferay/scheduler_dispatch-11" #147 daemon prio=5 os_prio=0 tid=0x00007f3ec000f800 nid=0x30b waiting on condition [0x00007f3e3c2ef000]
           [echo]    java.lang.Thread.State: TIMED_WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x000000009d1d4db0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
           [echo] 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
           [echo] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
           [echo] 	at com.liferay.portal.kernel.concurrent.TaskQueue.poll(TaskQueue.java:196)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor._getTask(ThreadPoolExecutor.java:541)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor.access$500(ThreadPoolExecutor.java:37)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:669)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "liferay/scheduler_dispatch-8" #144 daemon prio=5 os_prio=0 tid=0x00007f3ec000a800 nid=0x7edc waiting on condition [0x00007f3e3e3f2000]
           [echo]    java.lang.Thread.State: TIMED_WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x000000009d1d4db0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
           [echo] 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
           [echo] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
           [echo] 	at com.liferay.portal.kernel.concurrent.TaskQueue.poll(TaskQueue.java:196)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor._getTask(ThreadPoolExecutor.java:541)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor.access$500(ThreadPoolExecutor.java:37)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:669)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "liferay/scheduler_dispatch-6" #139 daemon prio=5 os_prio=0 tid=0x00007f3ec000e000 nid=0x7b71 waiting on condition [0x00007f3e7e2f5000]
           [echo]    java.lang.Thread.State: TIMED_WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x000000009d1d4db0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
           [echo] 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
           [echo] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
           [echo] 	at com.liferay.portal.kernel.concurrent.TaskQueue.poll(TaskQueue.java:196)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor._getTask(ThreadPoolExecutor.java:541)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor.access$500(ThreadPoolExecutor.java:37)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:669)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "elasticsearch[_g3Vltb][flush][T#1]" #134 daemon prio=5 os_prio=0 tid=0x00007f3e48016000 nid=0x7924 waiting on condition [0x00007f3e7daed000]
           [echo]    java.lang.Thread.State: WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x0000000093fd3ae0> (a org.elasticsearch.common.util.concurrent.EsExecutors$ExecutorScalingQueue)
           [echo] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "elasticsearch[_g3Vltb][management][T#2]" #124 daemon prio=5 os_prio=0 tid=0x00007f3e38004800 nid=0x7759 waiting on condition [0x00007f3e37efd000]
           [echo]    java.lang.Thread.State: TIMED_WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x0000000093fd35c0> (a org.elasticsearch.common.util.concurrent.EsExecutors$ExecutorScalingQueue)
           [echo] 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:734)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.poll(LinkedTransferQueue.java:1277)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "elasticsearch[_g3Vltb][write][T#1]" #123 daemon prio=5 os_prio=0 tid=0x00007f3f7622e000 nid=0x774a waiting on condition [0x00007f3e37cfb000]
           [echo]    java.lang.Thread.State: WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x0000000093fd2f68> (a java.util.concurrent.LinkedTransferQueue)
           [echo] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
           [echo] 	at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
           [echo] 	at org.elasticsearch.common.util.concurrent.SizeBlockingQueue.take(SizeBlockingQueue.java:165)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
           [echo] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "liferay/adaptive_media_processor-1" #119 daemon prio=5 os_prio=0 tid=0x00007f3f126c2000 nid=0x7745 waiting on condition [0x00007f3e37ffe000]
           [echo]    java.lang.Thread.State: WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x000000008bc88238> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
           [echo] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
           [echo] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
           [echo] 	at com.liferay.portal.kernel.concurrent.TaskQueue.take(TaskQueue.java:257)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor._getTask(ThreadPoolExecutor.java:545)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor.access$500(ThreadPoolExecutor.java:37)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:669)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
           [echo] 
           [echo]    Locked ownable synchronizers:
           [echo] 	- None
           [echo] 
           [echo] "liferay/document_library_raw_metadata_processor-1" #118 daemon prio=5 os_prio=0 tid=0x00007f3f126c1000 nid=0x7744 waiting on condition [0x00007f3e3c1ed000]
           [echo]    java.lang.Thread.State: TIMED_WAITING (parking)
           [echo] 	at sun.misc.Unsafe.park(Native Method)
           [echo] 	- parking to wait for  <0x000000009f7602c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
           [echo] 	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
           [echo] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2163)
           [echo] 	at com.liferay.portal.kernel.util.ServiceProxyFactory$AwaitServiceInvocationHandler.invoke(ServiceProxyFactory.java:247)
           [echo] 	at com.sun.proxy.$Proxy898.getClassStructures(Unknown Source)
           [echo] 	at com.liferay.dynamic.data.mapping.kernel.DDMStructureManagerUtil.getClassStructures(DDMStructureManagerUtil.java:106)
           [echo] 	at com.liferay.portlet.documentlibrary.util.RawMetadataProcessorImpl.saveMetadata(RawMetadataProcessorImpl.java:165)
           [echo] 	at com.liferay.document.library.kernel.util.RawMetadataProcessorUtil.saveMetadata(RawMetadataProcessorUtil.java:113)
           [echo] 	at com.liferay.portlet.documentlibrary.messaging.RawMetadataProcessorMessageListener.doReceive(RawMetadataProcessorMessageListener.java:34)
           [echo] 	at com.liferay.portal.kernel.messaging.BaseMessageListener.receive(BaseMessageListener.java:26)
           [echo] 	at com.liferay.portal.kernel.messaging.InvokerMessageListener.receive(InvokerMessageListener.java:74)
           [echo] 	at com.liferay.portal.kernel.messaging.SerialDestination$1.run(SerialDestination.java:58)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask._runTask(ThreadPoolExecutor.java:752)
           [echo] 	at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:664)
           [echo] 	at java.lang.Thread.run(Thread.java:745)
      

      Full log: https://testray.liferay.com/reports/production/logs/test-1-16/1567540184352/test-portal-acceptance-pullrequest(master)/4645/functional-upgrade-tomcat90-mysql57-jdk8/2/0/jenkins-console.txt.gz

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                victor.ware Victor Ware
                Reporter:
                victor.ware Victor Ware
                Participants of an Issue:
                Recent user:
                Jason Pince
              • Votes:
                0 Vote for this issue
                Watchers:
                0 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Days since last comment:
                  11 weeks ago

                  Packages

                  Version Package
                  7.2.X
                  7.2.1 CE GA2
                  Master