[
https://issues.apache.org/jira/browse/NIFI-11841?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dheeraj Joshi updated NIFI-11841:
---------------------------------
Attachment: Logs.zip
> Nifi in cluster setup doesn't stop within the graceful shutdown period
> ----------------------------------------------------------------------
>
> Key: NIFI-11841
> URL: https://issues.apache.org/jira/browse/NIFI-11841
> Project: Apache NiFi
> Issue Type: Bug
> Components: Core Framework
> Affects Versions: 1.22.0
> Reporter: Dheeraj Joshi
> Priority: Major
> Attachments: Logs.zip, bootstrap.conf, nifi-app.log,
> nifi-bootstrap.log, nifi.properties, zookeeper.properties
>
>
> Bootstrap logs show the following logs when one of the nodes in a 3-node
> cluster is stopped
> {code:java}
> 2023-07-20 11:10:49,847 INFO [main] org.apache.nifi.bootstrap.Command
> Launched Apache NiFi with Process ID 18579
> 2023-07-20 11:10:50,475 INFO [NiFi Bootstrap Command Listener]
> org.apache.nifi.bootstrap.RunNiFi Apache NiFi now running and listening for
> Bootstrap requests on port 64739
> 2023-07-20 11:12:15,723 INFO [main] o.a.n.b.NotificationServiceManager
> Successfully loaded the following 0 services: []
> 2023-07-20 11:12:15,725 INFO [main] org.apache.nifi.bootstrap.RunNiFi
> Registered no Notification Services for Notification Type NIFI_STARTED
> 2023-07-20 11:12:15,725 INFO [main] org.apache.nifi.bootstrap.RunNiFi
> Registered no Notification Services for Notification Type NIFI_STOPPED
> 2023-07-20 11:12:15,725 INFO [main] org.apache.nifi.bootstrap.RunNiFi
> Registered no Notification Services for Notification Type NIFI_DIED
> 2023-07-20 11:12:15,750 INFO [main] org.apache.nifi.bootstrap.Command Apache
> NiFi has accepted the Shutdown Command and is shutting down now
> 2023-07-20 11:12:15,859 INFO [main] org.apache.nifi.bootstrap.Command NiFi
> PID [18579] shutdown in progress...
> 2023-07-20 11:12:17,896 INFO [main] org.apache.nifi.bootstrap.Command NiFi
> PID [18579] shutdown in progress...
> 2023-07-20 11:12:19,919 INFO [main] org.apache.nifi.bootstrap.Command NiFi
> PID [18579] shutdown in progress...{code}
> The shutdown in progress message gets repeated till
> {code:java}
> graceful.shutdown.seconds{code}
> is elapsed.
> Nifi app logs print socket exception during the shutdown but eventually shuts
> down the application server server
> {code:java}
> 2023-07-20 11:12:15,750 INFO [pool-2-thread-2]
> org.apache.nifi.BootstrapListener Received SHUTDOWN request from Bootstrap
> 2023-07-20 11:12:15,750 INFO [pool-2-thread-2] org.apache.nifi.NiFi
> Application Server shutdown started
> 2023-07-20 11:12:15,755 INFO [pool-2-thread-2]
> o.eclipse.jetty.server.AbstractConnector Stopped
> ServerConnector@2407a36c{HTTP/1.1, (http/1.1)}
> {127.0.0.1:8080}
> 2023-07-20 11:12:15,756 INFO [pool-2-thread-2]
> org.eclipse.jetty.server.session node0 Stopped scavenging
> 2023-07-20 11:12:15,769 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@7cfb8e98{nifi-error,/,null,STOPPED}
> {./work/nar/extensions/nifi-server-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-web-error-1.22.0.war}
> 2023-07-20 11:12:15,782 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@2aa5bd48{nifi-docs,/nifi-docs,null,STOPPED}
> {./work/nar/extensions/nifi-server-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-web-docs-1.22.0.war}
> 2023-07-20 11:12:15,798 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@133aacbe{nifi-content-viewer,/nifi-content-viewer,null,STOPPED}
> {./work/nar/extensions/nifi-server-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-web-content-viewer-1.22.0.war}
> 2023-07-20 11:12:15,803 INFO [pool-2-thread-2]
> o.a.n.w.c.ApplicationStartupContextListener Flow Service shutdown started
> 2023-07-20 11:12:15,803 INFO [pool-2-thread-2]
> o.a.n.c.c.node.NodeClusterCoordinator Status of 127.0.0.1:8080 changed from
> NodeConnectionStatus[nodeId=127.0.0.1:8080, state=CONNECTED, updateId=50] to
> NodeConnectionStatus[nodeId=127.0.0.1:8080, state=DISCONNECTED, Disconnect
> Code=Node was Shutdown, Disconnect Reason=Node was Shutdown, updateId=50]
> 2023-07-20 11:12:15,809 INFO [pool-2-thread-2]
> o.a.n.c.c.node.NodeClusterCoordinator Successfully notified other nodes that
> I am shutting down
> 2023-07-20 11:12:15,811 INFO [Curator-Framework-0]
> o.a.c.f.imps.CuratorFrameworkImpl backgroundOperationsLoop exiting
> 2023-07-20 11:12:15,813 INFO [RequestThrottler]
> o.a.zookeeper.server.ZooKeeperServer Submitting global closeSession request
> for session 0x10001c338080000
> 2023-07-20 11:12:15,815 INFO [Process Cluster Protocol Request-3]
> o.a.n.c.c.node.NodeClusterCoordinator Status of 127.0.0.1:8080 changed from
> NodeConnectionStatus[nodeId=127.0.0.1:8080, state=DISCONNECTED, Disconnect
> Code=Node was Shutdown, Disconnect Reason=Node was Shutdown, updateId=50] to
> NodeConnectionStatus[nodeId=127.0.0.1:8080, state=DISCONNECTED, Disconnect
> Code=Node was Shutdown, Disconnect Reason=Node was Shutdown, updateId=50]
> 2023-07-20 11:12:15,816 INFO [Process Cluster Protocol Request-3]
> o.a.n.c.p.impl.SocketProtocolListener Finished processing request
> 62a9da74-38d3-4bce-83a6-8f55aa7bec64 (type=NODE_STATUS_CHANGE, length=1184
> bytes) from localhost in 3 millis
> 2023-07-20 11:12:15,967 INFO [pool-2-thread-2]
> o.a.n.c.l.e.CuratorLeaderElectionManager
> CuratorLeaderElectionManager[stopped=true] stopped and closed
> 2023-07-20 11:12:15,967 INFO [pool-2-thread-2]
> o.a.n.c.c.h.AbstractHeartbeatMonitor Heartbeat Monitor stopped
> 2023-07-20 11:12:15,968 INFO [pool-2-thread-2]
> o.apache.nifi.controller.FlowController Initiated graceful shutdown of flow
> controller...waiting up to 10 seconds
> 2023-07-20 11:12:15,968 INFO [pool-2-thread-2]
> o.a.zookeeper.server.ZooKeeperServer shutting down
> 2023-07-20 11:12:15,968 INFO [pool-2-thread-2]
> o.a.zookeeper.server.RequestThrottler Shutting down
> 2023-07-20 11:12:15,968 INFO [RequestThrottler]
> o.a.zookeeper.server.RequestThrottler Draining request throttler queue
> 2023-07-20 11:12:15,969 INFO [RequestThrottler]
> o.a.zookeeper.server.RequestThrottler RequestThrottler shutdown. Dropped 0
> requests
> 2023-07-20 11:12:15,969 INFO [pool-2-thread-2]
> o.a.z.server.FinalRequestProcessor shutdown of request processor complete
> 2023-07-20 11:12:15,977 INFO [pool-2-thread-2]
> o.a.z.server.DatadirCleanupManager Shutting down purge task.
> 2023-07-20 11:12:16,072 INFO [pool-2-thread-2]
> o.apache.nifi.controller.FlowController Controller has been terminated
> successfully.
> 2023-07-20 11:12:16,083 INFO [pool-2-thread-2]
> o.apache.nifi.io.socket.SocketListener Socket Listener has been terminated
> successfully.
> 2023-07-20 11:12:16,084 INFO [pool-2-thread-2]
> o.a.n.w.c.ApplicationStartupContextListener Flow Service shutdown completed
> 2023-07-20 11:12:16,084 INFO [pool-2-thread-2]
> o.e.j.s.handler.ContextHandler._nifi_api Closing Spring root
> WebApplicationContext
> 2023-07-20 11:12:16,084 WARN [Cluster Socket Listener]
> o.apache.nifi.io.socket.SocketListener Failed to communicate with Unknown
> Host due to java.net.SocketException: Socket closed
> java.net.SocketException: Socket closed
> at java.base/sun.nio.ch.NioSocketImpl.endAccept(NioSocketImpl.java:689)
> at java.base/sun.nio.ch.NioSocketImpl.accept(NioSocketImpl.java:762)
> at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:675)
> at java.base/java.net.ServerSocket.platformImplAccept(ServerSocket.java:641)
> at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:617)
> at java.base/java.net.ServerSocket.implAccept(ServerSocket.java:574)
> at java.base/java.net.ServerSocket.accept(ServerSocket.java:532)
> at org.apache.nifi.io.socket.SocketListener$2.run(SocketListener.java:107)
> at java.base/java.lang.Thread.run(Thread.java:833)
> 2023-07-20 11:12:16,501 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@7c9beb51{nifi-api,/nifi-api,null,STOPPED}
> {./work/nar/extensions/nifi-server-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-web-api-1.22.0.war}
> 2023-07-20 11:12:16,709 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@3dfd7eaa{nifi,/nifi,null,STOPPED}
> {./work/nar/extensions/nifi-server-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-web-ui-1.22.0.war}
> 2023-07-20 11:12:16,719 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@418f0534{nifi-image-viewer,/nifi-image-viewer-1.22.0,null,STOPPED}
> {./work/nar/extensions/nifi-image-viewer-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-image-viewer-1.22.0.war}
> 2023-07-20 11:12:16,747 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@21f9c6ea{/nifi-update-attribute-ui-1.22.0,/nifi-update-attribute-ui-1.22.0,null,STOPPED}
> {./work/nar/extensions/nifi-update-attribute-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-update-attribute-ui-1.22.0.war}
> 2023-07-20 11:12:16,760 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@448ade1{nifi-standard-content-viewer,/nifi-standard-content-viewer-1.22.0,null,STOPPED}
> {./work/nar/extensions/nifi-standard-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-standard-content-viewer-1.22.0.war}
> 2023-07-20 11:12:16,805 INFO [pool-2-thread-2]
> o.e.jetty.server.handler.ContextHandler Stopped
> o.e.j.w.WebAppContext@5fe46d52{/nifi-jolt-transform-json-ui-1.22.0,/nifi-jolt-transform-json-ui-1.22.0,null,STOPPED}
> {./work/nar/extensions/nifi-standard-nar-1.22.0.nar-unpacked/NAR-INF/bundled-dependencies/nifi-jolt-transform-json-ui-1.22.0.war}
> 2023-07-20 11:12:16,808 INFO [pool-2-thread-2]
> org.apache.nifi.nar.NarAutoLoaderTask Stopping NAR Auto-loader
> 2023-07-20 11:12:16,808 INFO [pool-2-thread-2]
> org.apache.nifi.nar.NarAutoLoader NAR Auto-Loader stopped
> 2023-07-20 11:12:16,809 INFO [pool-2-thread-2]
> o.a.n.f.r.CompositeExternalResourceProviderService External Resource Provider
> Service is stopped
> 2023-07-20 11:12:16,809 INFO [pool-2-thread-2] org.apache.nifi.NiFi
> Application Server shutdown completed
> {code}
> Even though the Nifi app logs prints {{{}Application Server shutdown
> completed{}}}, the Java PID is still available and from the bootstrap code it
> looks like the stop command monitors the PID and since the PID is still
> available it keeps printing the {{Shutdown in }}{{progress}} logs
> There are no flows configured and running in the system, Its an empty system
> in which we see the issue
> Logs and configuration files are attached
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
