jkrauss82 commented on PR #9153:
URL: https://github.com/apache/storm/pull/9153#issuecomment-5972249350
thanks for looking into this @GGraziadei
I don't have enough knowledge of the source and the actual inner working of
the various components using Curator to contribute meaningful to the discussion
regarding the scope of the PR. but I hope the logs below provide further
insight. happy to provide more if necessary.
also sharing this summary my local AI gave me regarding the log content,
just to provide further context as it includes the various relevant timestamps:
> 1. **`EndOfStreamException`** at `08:39:53.907` — socket closed by ZK
server, with the full stack trace from `ClientCnxnSocketNIO.doIO`
>
> 2. **Full `ConnectionLossException` stack trace** at `08:39:54.510`:
> - `SupervisorHeartbeat.run(SupervisorHeartbeat.java:165)`
> - `StormClusterStateImpl.supervisorHeartbeat`
> - `PaceMakerStateStorage.set_ephemeral_node`
> - `ClientZookeeper.existsNode`
> - `Curator RetryLoop.callWithRetry` — proving the retry loop **was
consulted**
> - `... 8 more`
>
> 3. **Process death** at `08:39:54.536` — `Utils.exitProcess(20)`
>
> 4. **Timeline context** showing:
> - ZK session established at `08:39:06` (RECONNECTED)
> - Socket closed at `08:39:53.907` (603ms before crash)
> - ConnectionState SUSPENDED at `08:39:54.489` (21ms before crash)
> - ConnectionLoss at `08:39:54.510`
> - `exitProcess` at `08:39:54.536` (629ms total)
>
> This confirms the retry loop was invoked but the underlying ZK operation
failed before `allowRetry()` could be called.
```
2026-09-29 08:38:44.753 o.a.s.h.HealthChecker EventTimer [INFO] The
supervisor healthchecks succeeded.
2026-09-29 08:38:42.214 o.a.s.s.o.a.c.f.s.ConnectionStateManager
Curator-ConnectionStateManager-0 [WARN] Session timeout has elapsed while
SUSPENDED. Injecting a session expiration. Elapsed ms: 36013. Adjusted session
timeout ms: 20000
2026-09-29 08:39:06.405 o.a.s.s.o.a.z.ClientCnxnSocket main-EventThread
[INFO] jute.maxbuffer value is 1048575 Bytes
2026-09-29 08:39:06.442 o.a.s.s.o.a.z.ClientCnxn main-EventThread [INFO]
zookeeper.request.timeout value is 0. feature enabled=false
2026-09-29 08:39:06.549 o.a.s.s.o.a.z.ZooKeeperTestable
Curator-ConnectionStateManager-0 [INFO] injectSessionExpiration() called
2026-09-29 08:39:06.550 o.a.s.s.o.a.z.ClientCnxn main-SendThread() [WARN]
Session 0x0 for server nimbus-node-2/<ZK-node-2-ip>:2181, Closing socket
connection. Attempting reconnect except it is a SessionExpiredException or
SessionTimeoutException.
java.io.IOException: Connection has already been closed and reconnection is
not allowed
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SendThread.changeZkState(ClientCnxn.java:991)
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SendThread.startConnect(ClientCnxn.java:1142)
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1200)
2026-09-29 08:39:06.551 o.a.s.s.o.a.c.ConnectionState main-EventThread
[WARN] Session expired event received
2026-09-29 08:39:06.552 o.a.s.s.o.a.z.ZooKeeper main-EventThread [INFO]
Initiating client connection,
connectString=nimbus-node-3:2181,nimbus-node-2:2181,nimbus-node-1:2181/zookeeper
sessionTimeout=20000
watcher=org.apache.storm.shade.org.apache.curator.ConnectionState@36fc05ff
2026-09-29 08:39:06.554 o.a.s.s.o.a.c.f.s.ConnectionStateManager
main-EventThread [INFO] State change: LOST
2026-09-29 08:39:06.561 o.a.s.s.o.a.z.ClientCnxnSocket main-EventThread
[INFO] jute.maxbuffer value is 1048575 Bytes
2026-09-29 08:39:06.577 o.a.s.s.o.a.z.ClientCnxn main-EventThread [INFO]
zookeeper.request.timeout value is 0. feature enabled=false
2026-09-29 08:39:06.732 o.a.s.s.o.a.z.ClientCnxn main-EventThread [INFO]
EventThread shut down for session: 0x0
2026-09-29 08:39:06.742 o.a.s.s.o.a.z.ClientCnxn main-EventThread [INFO]
EventThread shut down for session: 0x300ff9e3d430001
2026-09-29 08:39:06.862 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-1:2181) [INFO] Opening socket connection to server
nimbus-node-1/<ZK-node-1-ip>:2181.
2026-09-29 08:39:06.862 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-1:2181) [INFO] SASL config status: Will not attempt
to authenticate using SASL (unknown error)
2026-09-29 08:39:06.914 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-1:2181) [INFO] Socket connection established,
initiating session, client: /<supervisor-client-ip>:36856, server:
nimbus-node-1/<ZK-node-1-ip>:2181
2026-09-29 08:39:06.931 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-1:2181) [INFO] Session establishment complete on
server nimbus-node-1/<ZK-node-1-ip>:2181, session id = 0x300ff9e3d43024a,
negotiated timeout = 20000
2026-09-29 08:39:06.932 o.a.s.s.o.a.c.f.s.ConnectionStateManager
main-EventThread [INFO] State change: RECONNECTED
2026-09-29 08:39:53.911 o.a.s.d.s.t.SupervisorHealthCheck EventTimer [INFO]
Running supervisor healthchecks...
2026-09-29 08:39:53.911 o.a.s.h.HealthChecker EventTimer [INFO] The
supervisor healthchecks succeeded.
2026-09-29 08:39:53.907 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-1:2181) [WARN] Session 0x300ff9e3d43024a for server
nimbus-node-1/<ZK-node-1-ip>:2181, Closing socket connection. Attempting
reconnect except it is a SessionExpiredException or SessionTimeoutException.
EndOfStreamException: Unable to read additional data from server sessionid
0x300ff9e3d43024a, likely server has closed socket
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:77)
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:356)
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290)
2026-09-29 08:39:53.988 o.a.s.s.o.a.c.f.i.EnsembleTracker main-EventThread
[INFO] New config event received:
{server.2=nimbus-node-2:2888:3888:participant;0.0.0.0:2181,
server.1=nimbus-node-3:2888:3888:participant;0.0.0.0:2181,
server.3=nimbus-node-1:2888:3888:participant;0.0.0.0:2181, version=0}
2026-09-29 08:39:54.364 o.a.s.l.AsyncLocalizer AsyncLocalizer Task Executor
- 2 [INFO] Finish cleanup
2026-09-29 08:39:54.365 o.a.s.l.AsyncLocalizer AsyncLocalizer Task Executor
- 2 [INFO] Starting cleanup
2026-09-29 08:39:54.489 o.a.s.s.o.a.c.f.s.ConnectionStateManager
main-EventThread [INFO] State change: SUSPENDED
2026-09-29 08:39:54.510 o.a.s.d.s.DefaultUncaughtExceptionHandler HBTimer
[ERROR] Error when processing event
java.lang.RuntimeException:
org.apache.storm.shade.org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for /supervisors
at org.apache.storm.utils.Utils.wrapInRuntime(Utils.java:504)
at
org.apache.storm.zookeeper.ClientZookeeper.existsNode(ClientZookeeper.java:147)
at
org.apache.storm.zookeeper.ClientZookeeper.mkdirsImpl(ClientZookeeper.java:289)
at
org.apache.storm.zookeeper.ClientZookeeper.mkdirs(ClientZookeeper.java:70)
at
org.apache.storm.cluster.ZKStateStorage.set_ephemeral_node(ZKStateStorage.java:125)
at
org.apache.storm.cluster.PaceMakerStateStorage.set_ephemeral_node(PaceMakerStateStorage.java:79)
at
org.apache.storm.cluster.StormClusterStateImpl.supervisorHeartbeat(StormClusterStateImpl.java:531)
at
org.apache.storm.daemon.supervisor.timer.SupervisorHeartbeat.run(SupervisorHeartbeat.java:165)
at org.apache.storm.StormTimer$1.run(StormTimer.java:110)
at
org.apache.storm.StormTimer$StormTimerTask.run(StormTimer.java:226)
Caused by:
org.apache.storm.shade.org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for /supervisors
at
org.apache.storm.shade.org.apache.zookeeper.KeeperException.create(KeeperException.java:101)
at
org.apache.storm.shade.org.apache.zookeeper.KeeperException.create(KeeperException.java:53)
at
org.apache.storm.shade.org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1867)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl$3.call(ExistsBuilderImpl.java:247)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl$3.call(ExistsBuilderImpl.java:240)
at
org.apache.storm.shade.org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:88)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl.pathInForegroundStandard(ExistsBuilderImpl.java:240)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl.pathInForeground(ExistsBuilderImpl.java:235)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl.forPath(ExistsBuilderImpl.java:202)
at
org.apache.storm.shade.org.apache.curator.framework.imps.ExistsBuilderImpl.forPath(ExistsBuilderImpl.java:35)
at
org.apache.storm.zookeeper.ClientZookeeper.existsNode(ClientZookeeper.java:144)
... 8 more
2026-09-29 08:39:54.536 o.a.s.u.Utils HBTimer [ERROR] Halting process: Error
when processing an event
java.lang.RuntimeException: Halting process: Error when processing an event
at org.apache.storm.utils.Utils.exitProcess(Utils.java:527)
at
org.apache.storm.daemon.supervisor.DefaultUncaughtExceptionHandler.uncaughtException(DefaultUncaughtExceptionHandler.java:25)
at
org.apache.storm.StormTimer$StormTimerTask.run(StormTimer.java:253)
2026-09-29 08:39:56.670 o.a.s.u.Utils ShutdownHook-sleepKill-1s [INFO]
Halting after 1 seconds
2026-09-29 08:40:01.456 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-3:2181) [INFO] Opening socket connection to server
nimbus-node-3/<ZK-node-3-ip>:2181.
2026-09-29 08:40:02.931 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-3:2181) [INFO] SASL config status: Will not attempt
to authenticate using SASL (unknown error)
2026-09-29 08:40:14.005 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-3:2181) [WARN] Client session timed out, have not
heard from server in 57673ms for session id 0x300ff9e3d43024a
2026-09-29 08:40:14.500 o.a.s.s.o.a.c.f.s.ConnectionStateManager
Curator-ConnectionStateManager-0 [WARN] Session timeout has elapsed while
SUSPENDED. Injecting a session expiration. Elapsed ms: 20011. Adjusted session
timeout ms: 20000
2026-09-29 08:40:14.965 o.a.s.s.o.a.z.ZooKeeperTestable
Curator-ConnectionStateManager-0 [INFO] injectSessionExpiration() called
2026-09-29 08:40:16.967 o.a.s.s.o.a.z.ClientCnxn
main-SendThread(nimbus-node-3:2181) [WARN] Session 0x300ff9e3d43024a for server
nimbus-node-3/<ZK-node-3-ip>:2181, Closing socket connection. Attempting
reconnect except it is a SessionExpiredException or SessionTimeoutException.
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SessionTimeoutException:
Client session timed out, have not heard from server in 57673ms for session id
0x300ff9e3d43024a
at
org.apache.storm.shade.org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1252)
2026-09-29 08:40:20.908 o.a.s.d.s.Slot SLOT_6726 [WARN] SLOT 6726: HB is too
old 122000 > 120000 for topology: topology-a-76-1790230326
2026-09-29 08:40:21.187 o.a.s.d.s.Slot SLOT_6826 [WARN] SLOT 6826: HB is too
old 122000 > 120000 for topology: topology-h-376-1790234868
2026-09-29 08:40:23.729 o.a.s.s.o.a.c.ConnectionState main-EventThread
[WARN] Session expired event received
2026-09-29 08:40:24.995 o.a.s.d.s.Slot SLOT_6709 [WARN] SLOT 6709: HB is too
old 121000 > 120000 for topology: topology-f-26-1790229791
2026-09-29 08:40:25.071 o.a.s.d.s.Container SLOT_6826 [INFO] Killing
be2391fd-02e0-4034-af67-fa9114bb8b23-127.0.1.1:d49090d8-1538-4beb-aba1-cc6f0462b37b
2026-09-29 08:40:24.421 o.a.s.d.s.Slot SLOT_6706 [WARN] SLOT 6706: HB is too
old 174000 > 120000 for topology: topology-k-17-1790229697
2026-09-29 08:40:23.911 o.a.s.d.s.t.SupervisorHealthCheck EventTimer [INFO]
Running supervisor healthchecks...
2026-09-29 08:40:27.905 o.a.s.h.HealthChecker EventTimer [INFO] The
supervisor healthchecks succeeded.
2026-09-29 08:40:28.012 o.a.s.d.s.Slot SLOT_6708 [WARN] SLOT 6708: HB is too
old 129000 > 120000 for topology: topology-g-23-1790229761
2026-09-29 08:40:28.805 o.a.s.s.o.a.z.ZooKeeper main-EventThread [INFO]
Initiating client connection,
connectString=nimbus-node-3:2181,nimbus-node-2:2181,nimbus-node-1:2181/zookeeper
sessionTimeout=20000
watcher=org.apache.storm.shade.org.apache.curator.ConnectionState@36fc05ff
2026-09-29 08:40:32.373 o.a.s.d.s.Slot SLOT_6773 [WARN] SLOT 6773: HB is too
old 132000 > 120000 for topology: topology-c-217-1790231999
2026-09-29 08:40:30.663 o.a.s.d.s.Slot SLOT_6832 [WARN] SLOT 6832: HB is too
old 129000 > 120000 for topology: topology-i-394-1790235279
2026-09-29 08:40:30.682 o.a.s.d.s.Slot SLOT_6717 [WARN] SLOT 6717: HB is too
old 122000 > 120000 for topology: topology-j-50-1790230043
2026-09-29 08:40:30.682 o.a.s.d.s.Slot SLOT_6812 [WARN] SLOT 6812: HB is too
old 124000 > 120000 for topology: topology-e-335-1790234003
2026-09-29 08:40:50.664 o.a.s.s.o.a.c.f.s.ConnectionStateManager
Curator-ConnectionStateManager-0 [WARN] Session timeout has elapsed while
SUSPENDED. Injecting a session expiration. Elapsed ms: 36164. Adjusted session
timeout ms: 20000
2026-09-29 08:40:30.682 o.a.s.d.s.Slot SLOT_6720 [WARN] SLOT 6720: HB is too
old 130000 > 120000 for topology: topology-b-59-1790230141
2026-09-29 08:40:30.682 o.a.s.d.s.Slot SLOT_6803 [WARN] SLOT 6803: HB is too
old 124000 > 120000 for topology: topology-d-459-1790338504
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
