Ask Questions and Find Answers

0

Do you have any advice of what might be wrong in my Liferay installation? I think the following log message is the most relevant: The portal instance needs to be restarted to complete the installation of Liferay is packed inside Tomcat; and when I try to start it it starts starting just fine, it loggs messages in console and then, all the sudden it freezes. Logs stop and application is not responding.

We have a cluster of 16 servers all running Liferay Community Edition Portal 7.0.4 GA5 inside Tomcat inside Java 8 virtual machine inside RedHat Linux. All 16 servers have the same copy of jars and wars deployed. 15 out of those 16 work just fine. But this one freezes. Other applications on the server in question work just fine, so it is probably not the Operating System related.

Here are some logs for you:

1. The most interesthing log is error log taken from the standard out:

Thread dump for portal startup after waited 600000ms:


2022-12-13 12:32:21
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.231-b11 mixed mode):

"Attach Listener" #53 daemon prio=9 os_prio=0 tid=0x00007f89d0008800 nid=0x1734 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"com.liferay.portal.kernel.process.ProcessUtil-2" #52 daemon prio=1 os_prio=0 tid=0x00007f89b85c1000 nid=0x170b runnable [0x00007f8974c19000]
   java.lang.Thread.State: RUNNABLE

"com.liferay.portal.kernel.process.ProcessUtil-1" #51 daemon prio=1 os_prio=0 tid=0x00007f89b9304000 nid=0x170a runnable [0x00007f89776f5000]
   java.lang.Thread.State: RUNNABLE

"process reaper" #50 daemon prio=10 os_prio=0 tid=0x00007f89b85ab800 nid=0x1709 runnable [0x00007f89d80ae000]
   java.lang.Thread.State: RUNNABLE

"Java2D Disposer" #49 daemon prio=10 os_prio=0 tid=0x00007f8988190000 nid=0x14fe in Object.wait() [0x00007f8974d1a000]
   java.lang.Thread.State: WAITING (on object monitor)

"equinox telnet" #46 daemon prio=5 os_prio=0 tid=0x0000000001885800 nid=0x14f0 runnable [0x00007f8977ffe000]
   java.lang.Thread.State: RUNNABLE

"Portal Startup Monitoring Thread" #41 daemon prio=5 os_prio=0 tid=0x0000000001ff9000 nid=0x14c2 waiting on condition [0x00007f89774f3000]
   java.lang.Thread.State: WAITING (parking)

"SCR Component Actor" #40 daemon prio=5 os_prio=0 tid=0x0000000001fc3800 nid=0x14c1 in Object.wait() [0x00007f89775f4000]
   java.lang.Thread.State: WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/war" #38 daemon prio=5 os_prio=0 tid=0x0000000001d4b800 nid=0x14bf in Object.wait() [0x00007f89777f6000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/modules" #37 daemon prio=5 os_prio=0 tid=0x0000000001c84800 nid=0x14be in Object.wait() [0x00007f89778f7000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/shared" #36 daemon prio=5 os_prio=0 tid=0x0000000001c99000 nid=0x14bd in Object.wait() [0x00007f89779f8000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/marketplace" #35 daemon prio=5 os_prio=0 tid=0x0000000001c8c000 nid=0x14bc in Object.wait() [0x00007f8977af9000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/configs" #34 daemon prio=5 os_prio=0 tid=0x0000000001c9a000 nid=0x14bb in Object.wait() [0x00007f8977bfa000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"fileinstall-/opt/liferay/bundle/osgi/portal" #33 daemon prio=5 os_prio=0 tid=0x0000000001c92800 nid=0x14ba in Object.wait() [0x00007f8977cfb000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"Thread-6" #31 daemon prio=5 os_prio=0 tid=0x00007f8984001800 nid=0x14b8 waiting on condition [0x00007f8977dfc000]
   java.lang.Thread.State: WAITING (parking)

"Thread-5" #30 daemon prio=5 os_prio=0 tid=0x0000000001875800 nid=0x14b7 waiting on condition [0x00007f8977efd000]
   java.lang.Thread.State: WAITING (parking)

"CM Event Dispatcher" #28 daemon prio=5 os_prio=0 tid=0x000000000183b800 nid=0x14b5 in Object.wait() [0x00007f89c419b000]
   java.lang.Thread.State: WAITING (on object monitor)

"CM Configuration Updater" #27 daemon prio=5 os_prio=0 tid=0x00000000018a6800 nid=0x14b4 in Object.wait() [0x00007f89c4657000]
   java.lang.Thread.State: WAITING (on object monitor)

"Start Level: Equinox Container: 4023bd5b-d87a-001d-1ab8-f03d08a00709" #26 daemon prio=5 os_prio=0 tid=0x00007f89959f6000 nid=0x14ac in Object.wait() [0x00007f89c4758000]
   java.lang.Thread.State: WAITING (on object monitor)

"Bundle File Closer" #25 daemon prio=5 os_prio=0 tid=0x00007f89780b0800 nid=0x14ab in Object.wait() [0x00007f89c4551000]
   java.lang.Thread.State: WAITING (on object monitor)

"Refresh Thread: Equinox Container: 4023bd5b-d87a-001d-1ab8-f03d08a00709" #24 daemon prio=5 os_prio=0 tid=0x00007f8996540000 nid=0x14aa in Object.wait() [0x00007f89c48d3000]
   java.lang.Thread.State: WAITING (on object monitor)

"Framework Event Dispatcher: Equinox Container: 4023bd5b-d87a-001d-1ab8-f03d08a00709" #23 daemon prio=5 os_prio=0 tid=0x00007f899640b000 nid=0x14a9 in Object.wait() [0x00007f89c49d4000]
   java.lang.Thread.State: WAITING (on object monitor)

"Active Thread: Equinox Container: 4023bd5b-d87a-001d-1ab8-f03d08a00709" #21 prio=5 os_prio=0 tid=0x00007f8993fce000 nid=0x14a6 waiting on condition [0x00007f89c5ad5000]
   java.lang.Thread.State: TIMED_WAITING (parking)

"Tomcat JDBC Pool Cleaner[2070428996:1670930516054]" #20 daemon prio=5 os_prio=0 tid=0x00007f899c233800 nid=0x148c in Object.wait() [0x00007f89d8dda000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"localhost-startStop-1" #19 daemon prio=5 os_prio=0 tid=0x00007f899800c000 nid=0x1484 waiting on condition [0x00007f89d9ae5000]
   java.lang.Thread.State: WAITING (parking)

"Catalina-startStop-1" #18 daemon prio=5 os_prio=0 tid=0x00007f8a25eed800 nid=0x1483 waiting on condition [0x00007f89d9be7000]
   java.lang.Thread.State: WAITING (parking)

"NioBlockingSelector.BlockPoller-1" #17 daemon prio=5 os_prio=0 tid=0x00007f8a25edc000 nid=0x1482 runnable [0x00007f89f4189000]
   java.lang.Thread.State: RUNNABLE

"GC Daemon" #16 daemon prio=2 os_prio=0 tid=0x00007f8a25daa000 nid=0x1481 in Object.wait() [0x00007f89f44c8000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)

"AsyncFileHandlerWriter-1414644648" #15 daemon prio=5 os_prio=0 tid=0x00007f8a25913800 nid=0x147f waiting on condition [0x00007f89f4dfc000]
   java.lang.Thread.State: TIMED_WAITING (parking)

"oneagentperiodiceventsmanaged" #12 daemon prio=5 os_prio=0 tid=0x00007f8a08001000 nid=0x1471 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"oneagentautosensor" #11 daemon prio=5 os_prio=0 tid=0x00007f89a8001000 nid=0x1470 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"oneagentsubpathsender" #10 daemon prio=5 os_prio=0 tid=0x00007f8a04001000 nid=0x146f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"oneagentperiodicrequests" #9 daemon prio=5 os_prio=0 tid=0x00007f8a0c001000 nid=0x146d runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007f8a25774000 nid=0x147d runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f8a25769000 nid=0x147c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f8a25767000 nid=0x147b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f8a25765000 nid=0x147a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f8a25762800 nid=0x1479 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f8a2571b800 nid=0x1478 in Object.wait() [0x00007f8a18600000]
   java.lang.Thread.State: WAITING (on object monitor)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f8a25715000 nid=0x1477 in Object.wait() [0x00007f8a18701000]
   java.lang.Thread.State: WAITING (on object monitor)

"main" #1 prio=5 os_prio=0 tid=0x00007f8a244ce800 nid=0x1467 waiting on condition [0x00007f8a2885f000]
   java.lang.Thread.State: WAITING (parking)

"VM Thread" os_prio=0 tid=0x00007f8a246fd000 nid=0x1476 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f8a24524800 nid=0x1472 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f8a24526800 nid=0x1473 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f8a24528800 nid=0x1474 runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f8a2452a000 nid=0x1475 runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f8a25777000 nid=0x147e waiting on condition

JNI global references: 693

I had to truncate logs to be able to post here.

I am really not that good at interpreting the thread dump so if you can see what is going on here? It appears to me that Liferay is waiting for something to happen what never happens.

1. Second most interesting log is the catalina log taken durring server boot. In here you can see all what was happening before server froze:

    29-Nov-2022 15:48:58.762 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.0.32
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Feb 2 2016 19:34:53 UTC
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.0.32.0
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-862.3.3.el7.x86_64
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/java/jdk1.8.0_231-amd64/jre
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_231-b11
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
    29-Nov-2022 15:48:58.764 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32
    29-Nov-2022 15:48:58.765 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32
    29-Nov-2022 15:48:58.765 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/opt/liferay/bundle/tomcat/conf/logging.properties
    29-Nov-2022 15:48:58.765 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
    29-Nov-2022 15:48:58.765 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dfile.encoding=UTF8
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.net.preferIPv4Stack=true
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.loader.WebappClassLoader.ENABLE_CLEAR_REFERENCES=false
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Duser.timezone=GMT
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx3072m
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -DLIFERAY_LOGS=/opt/liferay/logs
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttps.proxyHost=192.168.255.60
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttps.proxyPort=8080
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttp.proxyHost=192.168.255.60
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttp.proxyPort=8080
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dhttp.nonProxyHosts=localhost|127.0.0.1|11.220.10.*|11.220.11.*|11.220.11.*|11.220.11.*|11.220.11.*|11.220.11.*|11.220.11.*|11.220.11.*
    29-Nov-2022 15:48:58.766 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=/opt/liferay/bundle/tomcat/endorsed
    29-Nov-2022 15:48:58.767 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/opt/liferay/bundle/tomcat
    29-Nov-2022 15:48:58.767 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/opt/liferay/bundle/tomcat
    29-Nov-2022 15:48:58.767 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/opt/liferay/bundle/tomcat/temp
    29-Nov-2022 15:48:58.767 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -agentpath:/opt/dynatrace/oneagent/agent/lib64/liboneagentloader.so=loglevelcon=none,tenant=c36be366-d0cd-5d68-a746-328377dac62a,tenanttoken=ozhtrfDimuukoPl,server=https://11.220.19.2:8443/communication;https://11.220.19.3:8443/communication
    29-Nov-2022 15:48:58.767 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
    29-Nov-2022 15:48:58.930 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
    29-Nov-2022 15:48:58.945 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
    29-Nov-2022 15:48:58.949 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 533 ms
    29-Nov-2022 15:48:58.974 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service Catalina
    29-Nov-2022 15:48:58.974 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.0.32
    29-Nov-2022 15:48:58.983 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor /opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32/conf/Catalina/localhost/ROOT.xml
    13-Dec-2022 11:21:57.350 INFO [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log No Spring WebApplicationInitializer types detected on classpath
    Loading jar:file:/opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32/webapps/ROOT/WEB-INF/lib/portal-impl.jar!/system.properties
    Loading jar:file:/opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32/webapps/ROOT/WEB-INF/lib/portal-impl.jar!/system.properties
    Loading jar:file:/opt/liferay/liferay-ce-portal-7.0-ga5/tomcat-8.0.32/webapps/ROOT/WEB-INF/lib/portal-impl.jar!/portal.properties
    Loading file:/opt/liferay/liferay-ce-portal-7.0-ga5/portal-ext.properties
    log4j:WARN No such property [conversionPattern] in net.logstash.log4j.JSONEventLayoutV1.
    [Target Platform Indexer][main] INFO osgi.logging.org_eclipse_osgi - ServiceEvent REGISTERED {org.eclipse.osgi.service.security.TrustEngine}={service.ranking=-2147483648, osgi.signedcontent.trust.engine=org.eclipse.osgi, service.id=24, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    [Target Platform Indexer][main] INFO osgi.logging.org_eclipse_osgi - ServiceEvent REGISTERED {org.eclipse.osgi.signedcontent.SignedContentFactory}={service.id=25, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    [Target Platform Indexer][main] INFO osgi.logging.org_eclipse_osgi - ServiceEvent REGISTERED {org.eclipse.osgi.service.debug.DebugOptionsListener}={service.ranking=2147483647, listener.symbolic.name=org.eclipse.osgi, service.pid=0.org.eclipse.osgi.internal.debug.Debug, service.vendor=Eclipse.org - Equinox, service.id=26, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    [Target Platform Indexer][main] INFO osgi.logging.org_eclipse_osgi - ServiceEvent REGISTERED {org.eclipse.osgi.service.debug.DebugOptionsListener}={service.ranking=2147483647, listener.symbolic.name=org.eclipse.osgi, service.pid=0.org.eclipse.osgi.container.ModuleContainer, service.vendor=Eclipse.org - Equinox, service.id=27, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    [Target Platform Indexer][Framework stop] INFO osgi.logging.org_eclipse_osgi - ServiceEvent UNREGISTERING {com.liferay.portal.app.license.AppLicenseVerifier}={version=1.0.0, service.id=22, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    [Target Platform Indexer][Framework stop] INFO osgi.logging.org_eclipse_osgi - ServiceEvent UNREGISTERING {org.osgi.framework.hooks.resolver.ResolverHookFactory}={service.id=23, service.bundleid=0, service.scope=singleton}[Target Platform Indexer]
    13-Dec-2022 11:22:31.648 INFO [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log Initializing Spring root WebApplicationContext

Nothing too special here either. Only interesting thing about this log is that it ends after the line saying that it is initializing the spring root.

1. In the Liferay log the most interesthing record i could find is:

    {"@timestamp":"2022-11-29T15:49:42.300Z","source_host":"127.0.0.1","file":"LPKGArtifactInstaller.java","method":"_logRestartRequired","level":"INFO","line_number":"127","thread_name":"fileinstall-\/opt\/liferay\/bundle\/osgi\/marketplace","@version":1,"logger_name":"com.liferay.marketplace.deployer.internal.LPKGArtifactInstaller","message":"The portal instance needs to be restarted to complete the installation of \/opt\/liferay\/liferay-ce-portal-7.0-ga5\/osgi\/marketplace\/Liferay Marketplace.lpkg","class":"com.liferay.marketplace.deployer.internal.LPKGArtifactInstaller","mdc":{}}

I am not allowed to attach the whole log file here.

Here what is interesting is that, toward the end of the log, it says that portal needs to be restarted to complete the installation. What is interesting is that whenever Tomcat is restarted the exact same logs are generated with this message that it needs to be restarted.

After these logs logging stops in total and no log entry is written to logs unless we restart the server.

This will not fix itself if we wait, we did not notice this problem for more than 6 months and durring those 6 months nothing was logged into logs. So, it is completely frozen.

Any idea? How to proceed into debugging this problem?