Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-28678

nuxeoctl shouldn't hang in strict mode

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Duplicate
    • Affects Version/s: 11.1-SNAPSHOT
    • Fix Version/s: 11.1
    • Component/s: Runtime

      Description

      In the case of a failure of Catalina because of some dependency missing Nuxeo exits but nuxeoctl may hang.

       

      # normal nuxeo component start
 2020-02-20T09:41:30,375 INFO  [OSGiRuntimeService] Nuxeo Platform Started
======================================================================
= Component Loading Status: Pending: 0 / Missing: 0 / Unstarted: 0 / Total: 694
======================================================================

# then
2020-02-20 09:41:36.337 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file
2020-02-20 09:41:36.340 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal Context [/nuxeo] startup failed due to previous errors
[25.590s][info][gc] GC(18) Pause Young (Normal) (G1 Evacuation Pause) 517M->124M(728M) 21.264ms
2020-02-20 09:41:38.363 SEVERE [main] org.apache.catalina.core.ContainerBase.startInternal A child container failed during start
	java.util.concurrent.ExecutionException: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost]]
		at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
		at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
		at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:916)
		at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.StandardService.startInternal(StandardService.java:421)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.startup.Catalina.start(Catalina.java:633)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.base/java.lang.reflect.Method.invoke(Method.java:566)
		at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:343)
		at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474)
	Caused by: org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost]]
		at org.apache.catalina.util.LifecycleBase.handleSubClassException(LifecycleBase.java:440)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:198)
		at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384)
		at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374)
		at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
		at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
		at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
		at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909)
		... 13 more
	Caused by: java.lang.IllegalStateException: Some contexts failed to start.
		at org.nuxeo.runtime.tomcat.NuxeoDeployer.checkFailures(NuxeoDeployer.java:83)
		at org.nuxeo.runtime.tomcat.NuxeoDeployer.lifecycleEvent(NuxeoDeployer.java:71)
		at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
		at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:193)
		... 19 more

      to get the cause you need to look at /opt/nuxeo/server/log/localhost.2020-02-20.log

      2020-02-20 09:09:37.360 SEVERE [main] org.apache.catalina.core.StandardContext.listenerStart Exception sending context initialized event to listener instance of class [org.jboss.seam.servlet.SeamListener]
	java.lang.RuntimeException: Could not create Component: esAdmin
		at org.jboss.seam.init.Initialization.addComponent(Initialization.java:1271)
		at org.jboss.seam.init.Initialization.installComponents(Initialization.java:1187)
		at org.jboss.seam.init.Initialization.init(Initialization.java:806)
		at org.jboss.seam.servlet.SeamListener.contextInitialized(SeamListener.java:36)
		at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4685)
		at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5146)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:717)
		at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:690)
		at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:705)
		at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:631)
		at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1831)
		at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
		at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
		at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
		at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
		at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:526)
		at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:425)
		at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1576)
		at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:309)
		at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
		at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:423)
		at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:366)
		at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:936)
		at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:841)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1384)
		at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1374)
		at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
		at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
		at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
		at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:909)
		at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:262)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.StandardService.startInternal(StandardService.java:421)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:930)
		at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
		at org.apache.catalina.startup.Catalina.start(Catalina.java:633)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.base/java.lang.reflect.Method.invoke(Method.java:566)
		at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:343)
		at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474)
	Caused by: java.lang.NoClassDefFoundError: Lcom/codahale/metrics/Timer;
		at java.base/java.lang.Class.getDeclaredFields0(Native Method)
		at java.base/java.lang.Class.privateGetDeclaredFields(Class.java:3062)
		at java.base/java.lang.Class.getDeclaredFields(Class.java:2249)
		at org.jboss.seam.Component.initMembers(Component.java:561)
		at org.jboss.seam.Component.<init>(Component.java:245)
		at org.jboss.seam.Component.<init>(Component.java:206)
		at org.jboss.seam.init.Initialization.addComponent(Initialization.java:1261)
		... 44 more
	Caused by: java.lang.ClassNotFoundException: com.codahale.metrics.Timer
		at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1365)
		at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
		... 51 more

      The nuxeo-launcher is still running:

      
"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1.01ms elapsed=1518.71s tid=0x00007f395428d000 nid=0xc7 waiting on condition  [0x00007f393c57e000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.2/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@11.0.2/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.2/Reference.java:213)"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.37ms elapsed=1518.71s tid=0x00007f395428f000 nid=0xc8 in Object.wait()  [0x00007f393c47d000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.2/Native Method)
	- waiting on <0x0000000627614730> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.2/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000627614730> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.2/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.2/Finalizer.java:170)"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.34ms elapsed=1518.71s tid=0x00007f3954297000 nid=0xc9 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=1180.44ms elapsed=1518.71s tid=0x00007f3954299000 nid=0xca waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=981.24ms elapsed=1518.71s tid=0x00007f395429b000 nid=0xcb waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task"Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=18.39ms elapsed=1518.71s tid=0x00007f395429d000 nid=0xcc runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE"Service Thread" #10 daemon prio=9 os_prio=0 cpu=0.14ms elapsed=1518.69s tid=0x00007f3954303800 nid=0xcd runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE"Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=2.89ms elapsed=1518.69s tid=0x00007f3954308000 nid=0xcf in Object.wait()  [0x00007f3924af3000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.2/Native Method)
	- waiting on <0x0000000627628fd0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.2/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000627628fd0> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@11.0.2/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@11.0.2/Thread.java:834)
	at jdk.internal.misc.InnocuousThread.run(java.base@11.0.2/InnocuousThread.java:134)"Log4j2-TF-2-Scheduled-1" #13 daemon prio=5 os_prio=0 cpu=0.99ms elapsed=1518.16s tid=0x00007f3954552800 nid=0xd1 waiting on condition  [0x00007f391dffe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.2/Native Method)
	- parking to wait for  <0x0000000627666028> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.2/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.2/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.2/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.2/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.2/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.2/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.2/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.2/Thread.java:834)"Log4j2-TF-4-Scheduled-2" #15 daemon prio=5 os_prio=0 cpu=0.17ms elapsed=1518.00s tid=0x00007f3954637800 nid=0xd9 waiting on condition  [0x00007f391d5ef000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.2/Native Method)
	- parking to wait for  <0x000000062763d630> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.2/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.2/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.2/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.2/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.2/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.2/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.2/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.2/Thread.java:834)"NuxeoProcessThread-0" #16 prio=5 os_prio=0 cpu=726.29ms elapsed=1517.84s tid=0x00007f39546b4000 nid=0xdb waiting on condition  [0x00007f391d1ed000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.2/Native Method)
	- parking to wait for  <0x00000006274db338> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.2/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.2/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.2/LinkedBlockingQueue.java:433)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.2/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.2/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.2/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.2/Thread.java:834)"DestroyJavaVM" #17 prio=5 os_prio=0 cpu=863.86ms elapsed=1517.84s tid=0x00007f3954011800 nid=0xc0 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

       

      Few improvements:

      • nuxeoctl should return in error
      • the error is weirdly reported, we should have something that says it is because of the sctrict mode that nuxeo cannot start
      • the cause of the error is not on the docker output, it is in its own directory/files which is hard to find

       

        Attachments

          Issue Links

          depends on

          Bug - A problem which impairs or prevents the functions of the product. NXP-28396 Make nuxeoctl console not blocking

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Resolved
          is related to

          Bug - A problem which impairs or prevents the functions of the product. NXP-28373 nuxeoctl hangs on failure with strict mode

          • Major - Major loss of function.
          • Resolved

          Improvement - An improvement or enhancement to an existing feature or task. NXP-20418 nuxeoctl start should be in strict mode by default

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Resolved

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 15 minutes
                  15m