Log4j Shutdown Starts Before Status Check Finishes

Issue:

When trying to start Fusion or Zookeeper, I see the following error message about the shutdown hook:

$ bin/zookeeper start

Starting zookeeper.....

Successfully started zookeeper on port 9983 (process ID 24448)

$ bin/zookeeper status

zookeeper is running on port 9983 (process ID 24448)

2017-11-17 16:41:21,562 agent service-monitor ERROR Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED

      at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113)

      at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:273)

      at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:256)

      at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:216)

      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:145)

      at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41)

      at org.apache.logging.log4j.LogManager.getContext(LogManager.java:182)

      at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:103)

      at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43)

      at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42)

      at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)

      at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)

      at org.zeroturnaround.exec.stream.slf4j.Slf4jStream.ofCaller(Slf4jStream.java:85)

      at org.zeroturnaround.process.UnixProcess.isAlive(UnixProcess.java:26)

      at com.lucidworks.apollo.supervisor.ProcessLivenessDetector.getState(ProcessLivenessDetector.java:46)

      at com.lucidworks.apollo.supervisor.LocalRunningService$MonitorThread.run(LocalRunningService.java:791)

      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)

      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)

      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)

      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

      at java.lang.Thread.run(Thread.java:748) 

Environment:

Fusion

Resolution:

When starting zookeeper, you may see a successful start message.  But checking the status, the error will show immediately.  You will need to edit the agent-log4j2.xml file on each server and then restart the Agent process on each as well.

• First check to determine if zookeeper is actually running with the ‘ruok’ command.

  • echo ruok | nc localhost 9983

• Navigate to your agent-log4j2.xml file which is located in the $FUSION-HOME/conf directory and edit the Configuration section to add the shutdownHook disable (it should be the second line in the file)

            <Configuration status="WARN" monitoringInterval="120" shutdownHook="disable">

• Restart the agent

  • bin/fusion restart agent

• After making this change on all of the servers, try starting zookeeper again.  If the error remains, then you’ll need to check that there is no AgentMain process hanging around.  If it exists, remove it.

  • To remove the Agent process, you can check by doing the following:

    • Run ‘jps’ to find the AgentMain java process ID, or you can do ‘ps -ef | grep AgentMain’

• kill -9 <pid>

          (Here using the jps output above, you’d use ‘kill -9 57623’)

• After removing the AgentMain, then try starting zookeeper or fusion again and it should start without the previous error.

NOTE:  There is an internal JIRA, APOLLO-11615, opened to address this issue.

Cause: