Yong-Hao Zou created ZOOKEEPER-4418:
---------------------------------------
Summary: Committing zxid 0x100000003 but next pending txn
0x100000002
Key: ZOOKEEPER-4418
URL: https://issues.apache.org/jira/browse/ZOOKEEPER-4418
Project: ZooKeeper
Issue Type: Bug
Components: server
Affects Versions: 3.7.0
Environment: Ubuntu 18.04
jdk8
Reporter: Yong-Hao Zou
The server exit with the following logs
{code:java}
// code placeholder
2021-11-23 17:02:45,602 [myid:] - INFO [main:QuorumPeerConfig@174] - Reading
configuration from: zoo2
2021-11-23 17:02:45,629 [myid:] - WARN [main:VerifyingFileFactory@65] - zoo2
is relative. Prepend ./ to indicate that you're sure!
2021-11-23 17:02:45,649 [myid:] - WARN [main:VerifyingFileFactory@65] - data2
is relative. Prepend ./ to indicate that you're sure!
2021-11-23 17:02:45,661 [myid:] - INFO [main:QuorumPeerConfig@444] -
clientPortAddress is 0.0.0.0:2182
2021-11-23 17:02:45,661 [myid:] - INFO [main:QuorumPeerConfig@448] -
secureClientPort is not set
2021-11-23 17:02:45,662 [myid:] - INFO [main:QuorumPeerConfig@464] -
observerMasterPort is not set
2021-11-23 17:02:45,662 [myid:] - INFO [main:QuorumPeerConfig@481] -
metricsProvider.className is
org.apache.zookeeper.metrics.impl.DefaultMetricsProvider
2021-11-23 17:02:45,790 [myid:2] - INFO [main:DatadirCleanupManager@78] -
autopurge.snapRetainCount set to 3
2021-11-23 17:02:45,790 [myid:2] - INFO [main:DatadirCleanupManager@79] -
autopurge.purgeInterval set to 0
2021-11-23 17:02:45,791 [myid:2] - INFO [main:DatadirCleanupManager@101] -
Purge task is not scheduled.
2021-11-23 17:02:45,806 [myid:2] - INFO [main:ManagedUtil@44] - Log4j 1.2 jmx
support found and enabled.
2021-11-23 17:02:46,060 [myid:2] - INFO [main:QuorumPeerMain@152] - Starting
quorum peer, myid=2
2021-11-23 17:02:46,144 [myid:2] - INFO [main:ServerMetrics@62] -
ServerMetrics initialized with provider
org.apache.zookeeper.metrics.impl.DefaultMetricsProvider@2a18f23c
2021-11-23 17:02:46,198 [myid:2] - INFO [main:DigestAuthenticationProvider@47]
- ACL digest algorithm is: SHA1
2021-11-23 17:02:46,199 [myid:2] - INFO [main:DigestAuthenticationProvider@61]
- zookeeper.DigestAuthenticationProvider.enabled = true
2021-11-23 17:02:46,213 [myid:2] - INFO [main:ServerCnxnFactory@169] - Using
org.apache.zookeeper.server.NIOServerCnxnFactory as server connection factory
2021-11-23 17:02:46,218 [myid:2] - WARN [main:ServerCnxnFactory@309] -
maxCnxns is not configured, using default value 0.
2021-11-23 17:02:46,221 [myid:2] - INFO [main:NIOServerCnxnFactory@652] -
Configuring NIO connection handler with 10s sessionless connection timeout, 2
selector thread(s), 24 worker threads, and 64 kB direct buffers.
2021-11-23 17:02:46,251 [myid:2] - INFO [main:NIOServerCnxnFactory@660] -
binding to port 0.0.0.0/0.0.0.0:2182
2021-11-23 17:02:46,268 [myid:2] - INFO [main:QuorumPeer@796] -
zookeeper.quorumCnxnTimeoutMs=-1
2021-11-23 17:02:46,280 [myid:2] - INFO [main:X509Util@77] - Setting -D
jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS
renegotiation
2021-11-23 17:02:46,285 [myid:2] - INFO [main:FileTxnSnapLog@124] -
zookeeper.snapshot.trust.empty : false
2021-11-23 17:02:46,294 [myid:2] - INFO [main:QuorumPeer@1739] - Local
sessions disabled
2021-11-23 17:02:46,297 [myid:2] - INFO [main:QuorumPeer@1750] - Local session
upgrading disabled
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1717] - tickTime set
to 200
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1761] -
minSessionTimeout set to 400
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1772] -
maxSessionTimeout set to 4000
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1797] - initLimit set
to 5
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1984] - syncLimit set
to 2
2021-11-23 17:02:46,299 [myid:2] - INFO [main:QuorumPeer@1999] -
connectToLearnerMasterLimit set to 0
2021-11-23 17:02:46,377 [myid:2] - INFO [main:ZookeeperBanner@42] -
2021-11-23 17:02:46,377 [myid:2] - INFO [main:ZookeeperBanner@42] - ______
_
2021-11-23 17:02:46,377 [myid:2] - INFO [main:ZookeeperBanner@42] - |___ /
| |
2021-11-23 17:02:46,377 [myid:2] - INFO [main:ZookeeperBanner@42] - / /
___ ___ | | __ ___ ___ _ __ ___ _ __
2021-11-23 17:02:46,378 [myid:2] - INFO [main:ZookeeperBanner@42] - / /
/ _ \ / _ \ | |/ / / _ \ / _ \ | '_ \ / _ \ | '__|
2021-11-23 17:02:46,378 [myid:2] - INFO [main:ZookeeperBanner@42] - / /__ |
(_) | | (_) | | < | __/ | __/ | |_) | | __/ | |
2021-11-23 17:02:46,378 [myid:2] - INFO [main:ZookeeperBanner@42] - /_____|
\___/ \___/ |_|\_\ \___| \___| | .__/ \___| |_|
2021-11-23 17:02:46,382 [myid:2] - INFO [main:ZookeeperBanner@42] -
| |
2021-11-23 17:02:46,382 [myid:2] - INFO [main:ZookeeperBanner@42] -
|_|
2021-11-23 17:02:46,382 [myid:2] - INFO [main:ZookeeperBanner@42] -
2021-11-23 17:02:46,391 [myid:2] - INFO [main:Environment@98] - Server
environment:zookeeper.version=3.7.0-e3704b390a6697bfdf4b0bef79e3da7a4f6bac4b,
built on 2021-03-17 09:46 UTC
2021-11-23 17:02:46,392 [myid:2] - INFO [main:Environment@98] - Server
environment:host.name=pc
2021-11-23 17:02:46,393 [myid:2] - INFO [main:Environment@98] - Server
environment:java.version=1.8.0_312
2021-11-23 17:02:46,393 [myid:2] - INFO [main:Environment@98] - Server
environment:java.vendor=Temurin
2021-11-23 17:02:46,393 [myid:2] - INFO [main:Environment@98] - Server
environment:java.home=/home/zyh/jdk8/jre
2021-11-23 17:02:46,393 [myid:2] - INFO [main:Environment@98] - Server
environment:java.class.path=/home/zyh/zookeeper/lib/zookeeper.jar:/home/zyh/zookeeper/lib/netty-handler-4.1.59.Final.jar:/home/zyh/zookeeper/lib/zookeeper-3.7.0.jar:/home/zyh/zookeeper/lib/commons-cli-1.4.jar:/home/zyh/zookeeper/lib/netty-transport-native-epoll-4.1.59.Final.jar:/home/zyh/zookeeper/lib/netty-transport-4.1.59.Final.jar:/home/zyh/zookeeper/lib/jetty-util-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/slf4j-log4j12-1.7.30.jar:/home/zyh/zookeeper/lib/jetty-io-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/jetty-server-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/netty-common-4.1.59.Final.jar:/home/zyh/zookeeper/lib/jackson-annotations-2.10.5.jar:/home/zyh/zookeeper/lib/jetty-http-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/netty-buffer-4.1.59.Final.jar:/home/zyh/zookeeper/lib/slf4j-api-1.7.30.jar:/home/zyh/zookeeper/lib/jetty-security-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/audience-annotations-0.12.0.jar:/home/zyh/zookeeper/lib/javax.servlet-api-3.1.0.jar:/home/zyh/zookeeper/lib/zookeeper-jute-3.7.0.jar:/home/zyh/zookeeper/lib/netty-transport-native-unix-common-4.1.59.Final.jar:/home/zyh/zookeeper/lib/simpleclient-0.9.0.jar:/home/zyh/zookeeper/lib/zookeeper-prometheus-metrics-3.7.0.jar:/home/zyh/zookeeper/lib/simpleclient_common-0.9.0.jar:/home/zyh/zookeeper/lib/metrics-core-4.1.12.1.jar:/home/zyh/zookeeper/lib/jetty-servlet-9.4.38.v20210224.jar:/home/zyh/zookeeper/lib/jline-2.14.6.jar:/home/zyh/zookeeper/lib/netty-codec-4.1.59.Final.jar:/home/zyh/zookeeper/lib/log4j-1.2.17.jar:/home/zyh/zookeeper/lib/netty-resolver-4.1.59.Final.jar:/home/zyh/zookeeper/lib/jackson-databind-2.10.5.1.jar:/home/zyh/zookeeper/lib/simpleclient_hotspot-0.9.0.jar:/home/zyh/zookeeper/lib/zookeeper.jar:/home/zyh/zookeeper/lib/snappy-java-1.1.7.7.jar:/home/zyh/zookeeper/lib/jackson-core-2.10.5.jar:/home/zyh/zookeeper/lib/simpleclient_servlet-0.9.0.jar:/home/zyh/zookeeper/lib/jetty-util-ajax-9.4.38.v20210224.jar:/home/zyh/zookeeper/conf
2021-11-23 17:02:46,393 [myid:2] - INFO [main:Environment@98] - Server
environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2021-11-23 17:02:46,394 [myid:2] - INFO [main:Environment@98] - Server
environment:java.io.tmpdir=/tmp
2021-11-23 17:02:46,394 [myid:2] - INFO [main:Environment@98] - Server
environment:java.compiler=<NA>
2021-11-23 17:02:46,395 [myid:2] - INFO [main:Environment@98] - Server
environment:os.name=Linux
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:os.arch=amd64
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:os.version=4.15.0-162-generic
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:user.name=zyh
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:user.home=/home/zyh
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:user.dir=/home/zyh/distributed-system-test/zookeeper_test/bin
2021-11-23 17:02:46,396 [myid:2] - INFO [main:Environment@98] - Server
environment:os.memory.free=463MB
2021-11-23 17:02:46,397 [myid:2] - INFO [main:Environment@98] - Server
environment:os.memory.max=7138MB
2021-11-23 17:02:46,397 [myid:2] - INFO [main:Environment@98] - Server
environment:os.memory.total=481MB
2021-11-23 17:02:46,397 [myid:2] - INFO [main:ZooKeeperServer@138] -
zookeeper.enableEagerACLCheck = false
2021-11-23 17:02:46,397 [myid:2] - INFO [main:ZooKeeperServer@151] -
zookeeper.digest.enabled = true
2021-11-23 17:02:46,397 [myid:2] - INFO [main:ZooKeeperServer@155] -
zookeeper.closeSessionTxn.enabled = true
2021-11-23 17:02:46,397 [myid:2] - INFO [main:ZooKeeperServer@1499] -
zookeeper.flushDelay=0
2021-11-23 17:02:46,398 [myid:2] - INFO [main:ZooKeeperServer@1508] -
zookeeper.maxWriteQueuePollTime=0
2021-11-23 17:02:46,398 [myid:2] - INFO [main:ZooKeeperServer@1517] -
zookeeper.maxBatchSize=1000
2021-11-23 17:02:46,399 [myid:2] - INFO [main:ZooKeeperServer@260] -
zookeeper.intBufferStartingSizeBytes = 1024
2021-11-23 17:02:46,417 [myid:2] - INFO [main:WatchManagerFactory@42] - Using
org.apache.zookeeper.server.watch.WatchManager as watch manager
2021-11-23 17:02:46,417 [myid:2] - INFO [main:WatchManagerFactory@42] - Using
org.apache.zookeeper.server.watch.WatchManager as watch manager
2021-11-23 17:02:46,418 [myid:2] - INFO [main:ZKDatabase@133] -
zookeeper.snapshotSizeFactor = 0.33
2021-11-23 17:02:46,418 [myid:2] - INFO [main:ZKDatabase@153] -
zookeeper.commitLogCount=500
2021-11-23 17:02:46,451 [myid:2] - INFO [main:QuorumPeer@2063] - Using
insecure (non-TLS) quorum communication
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@2069] - Port
unification disabled
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@179] -
multiAddress.enabled set to false
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@204] -
multiAddress.reachabilityCheckEnabled set to true
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@191] -
multiAddress.reachabilityCheckTimeoutMs set to 1000
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@2524] - QuorumPeer
communication is not secured! (SASL auth disabled)
2021-11-23 17:02:46,452 [myid:2] - INFO [main:QuorumPeer@2549] -
quorum.cnxn.threads.size set to 20
2021-11-23 17:02:46,465 [myid:2] - INFO [main:SnapStream@61] -
zookeeper.snapshot.compression.method = CHECKED
2021-11-23 17:02:46,466 [myid:2] - INFO [main:FileTxnSnapLog@479] -
Snapshotting: 0x0 to data2/version-2/snapshot.0
2021-11-23 17:02:46,472 [myid:2] - INFO [main:ZKDatabase@290] - Snapshot
loaded in 19 ms, highest zxid is 0x0, digest is 1371985504
2021-11-23 17:02:46,473 [myid:2] - INFO [main:QuorumPeer@1157] - currentEpoch
not found! Creating with a reasonable default of 0. This should only happen
when you are upgrading your installation
2021-11-23 17:02:46,487 [myid:2] - INFO [main:QuorumPeer@1177] - acceptedEpoch
not found! Creating with a reasonable default of 0. This should only happen
when you are upgrading your installation
2021-11-23 17:02:46,549 [myid:2] - INFO [main:QuorumPeer@2566] - Using 400ms
as the quorum cnxn socket timeout
2021-11-23 17:02:46,568 [myid:2] - INFO [main:QuorumCnxManager$Listener@924] -
Election port bind maximum retries is 3
2021-11-23 17:02:46,572 [myid:2] - INFO [main:FastLeaderElection@89] -
zookeeper.fastleader.minNotificationInterval=200
2021-11-23 17:02:46,573 [myid:2] - INFO [main:FastLeaderElection@91] -
zookeeper.fastleader.maxNotificationInterval=60000
2021-11-23 17:02:46,619 [myid:2] - INFO [main:ZKAuditProvider@42] - ZooKeeper
audit is disabled.
2021-11-23 17:02:46,629 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1066]
- 2 is accepting connections now, my election bind port: /127.0.1.1:3889
2021-11-23 17:02:46,631 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1430]
- LOOKING
2021-11-23 17:02:46,632 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):FastLeaderElection@945]
- New election. My id = 2, proposed zxid=0x0
2021-11-23 17:02:46,644 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34944
2021-11-23 17:02:46,677 [myid:2] - WARN
[QuorumConnectionThread-[myid=2]-1:QuorumCnxManager@401] - Cannot open channel
to 1 at election address /127.0.1.1:3888
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:607)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:384)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:458)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:46,689 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:2,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,694 [myid:2] - WARN [NIOWorkerThread-1:NIOServerCnxn@380]
- Close of session 0x0
java.io.IOException: ZooKeeperServer not running
at
org.apache.zookeeper.server.NIOServerCnxn.readLength(NIOServerCnxn.java:554)
at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:339)
at
org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:508)
at
org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:46,703 [myid:2] - INFO
[QuorumConnectionThread-[myid=2]-2:QuorumCnxManager@514] - Have smaller server
identifier, so dropping the connection: (myId:2 --> sid:3)
2021-11-23 17:02:46,704 [myid:2] - INFO
[QuorumConnectionThread-[myid=2]-1:QuorumCnxManager@514] - Have smaller server
identifier, so dropping the connection: (myId:2 --> sid:5)
2021-11-23 17:02:46,707 [myid:2] - INFO
[QuorumConnectionThread-[myid=2]-3:QuorumCnxManager@514] - Have smaller server
identifier, so dropping the connection: (myId:2 --> sid:4)
2021-11-23 17:02:46,715 [myid:2] - WARN
[SendWorker:3:QuorumCnxManager$SendWorker@1287] - Exception when using channel:
for id 3 my id = 2
java.net.SocketException: Broken pipe (Write failed)
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
at java.net.SocketOutputStream.write(SocketOutputStream.java:134)
at java.io.DataOutputStream.writeInt(DataOutputStream.java:198)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.send(QuorumCnxManager.java:1229)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:1280)
2021-11-23 17:02:46,723 [myid:2] - WARN
[SendWorker:3:QuorumCnxManager$SendWorker@1295] - Send worker leaving thread id
3 my id = 2
2021-11-23 17:02:46,723 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34954
2021-11-23 17:02:46,725 [myid:2] - WARN
[RecvWorker:3:QuorumCnxManager$RecvWorker@1403] - Interrupting SendWorker
thread from RecvWorker. sid: 3. myId: 2
2021-11-23 17:02:46,737 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34962
2021-11-23 17:02:46,738 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:5, n.state:LOOKING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,750 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34972
2021-11-23 17:02:46,750 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,754 [myid:2] - INFO
[QuorumConnectionThread-[myid=2]-2:QuorumCnxManager@514] - Have smaller server
identifier, so dropping the connection: (myId:2 --> sid:3)
2021-11-23 17:02:46,754 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34982
2021-11-23 17:02:46,756 [myid:2] - WARN
[SendWorker:3:QuorumCnxManager$SendWorker@1287] - Exception when using channel:
for id 3 my id = 2
java.net.SocketException: Broken pipe (Write failed)
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
at java.net.SocketOutputStream.write(SocketOutputStream.java:134)
at java.io.DataOutputStream.writeInt(DataOutputStream.java:198)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.send(QuorumCnxManager.java:1229)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:1280)
2021-11-23 17:02:46,756 [myid:2] - WARN
[RecvWorker:3:QuorumCnxManager$RecvWorker@1397] - Connection broken for id 3,
my id = 2
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:1385)
2021-11-23 17:02:46,759 [myid:2] - WARN
[RecvWorker:3:QuorumCnxManager$RecvWorker@1403] - Interrupting SendWorker
thread from RecvWorker. sid: 3. myId: 2
2021-11-23 17:02:46,756 [myid:2] - WARN
[RecvWorker:4:QuorumCnxManager$RecvWorker@1397] - Connection broken for id 4,
my id = 2
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:210)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:1385)
2021-11-23 17:02:46,763 [myid:2] - WARN
[RecvWorker:4:QuorumCnxManager$RecvWorker@1403] - Interrupting SendWorker
thread from RecvWorker. sid: 4. myId: 2
2021-11-23 17:02:46,764 [myid:2] - WARN
[SendWorker:3:QuorumCnxManager$SendWorker@1295] - Send worker leaving thread id
3 my id = 2
2021-11-23 17:02:46,765 [myid:2] - WARN
[SendWorker:4:QuorumCnxManager$SendWorker@1283] - Interrupted while waiting for
message on queue
java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
at
org.apache.zookeeper.util.CircularBlockingQueue.poll(CircularBlockingQueue.java:105)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:1448)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.access$900(QuorumCnxManager.java:99)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:1272)
2021-11-23 17:02:46,766 [myid:2] - WARN
[SendWorker:4:QuorumCnxManager$SendWorker@1295] - Send worker leaving thread id
4 my id = 2
2021-11-23 17:02:46,766 [myid:2] - WARN
[RecvWorker:1:QuorumCnxManager$RecvWorker@1403] - Interrupting SendWorker
thread from RecvWorker. sid: 1. myId: 2
2021-11-23 17:02:46,767 [myid:2] - WARN
[SendWorker:1:QuorumCnxManager$SendWorker@1295] - Send worker leaving thread id
1 my id = 2
2021-11-23 17:02:46,774 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:34986
2021-11-23 17:02:46,774 [myid:2] - WARN
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager@630] - Exception reading or
writing challenge
java.io.EOFException
at java.io.DataInputStream.readFully(DataInputStream.java:197)
at java.io.DataInputStream.readLong(DataInputStream.java:416)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.handleConnection(QuorumCnxManager.java:602)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.receiveConnection(QuorumCnxManager.java:555)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1080)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1034)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:46,777 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:35004
2021-11-23 17:02:46,803 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:4, n.state:LOOKING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,817 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,843 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:46,844 [myid:2] - WARN
[RecvWorker:1:QuorumCnxManager$RecvWorker@1397] - Connection broken for id 1,
my id = 2
java.io.IOException: Received packet with invalid packet: 0
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:1387)
2021-11-23 17:02:46,844 [myid:2] - WARN
[RecvWorker:1:QuorumCnxManager$RecvWorker@1403] - Interrupting SendWorker
thread from RecvWorker. sid: 1. myId: 2
2021-11-23 17:02:46,851 [myid:2] - WARN
[SendWorker:1:QuorumCnxManager$SendWorker@1283] - Interrupted while waiting for
message on queue
java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2088)
at
org.apache.zookeeper.util.CircularBlockingQueue.poll(CircularBlockingQueue.java:105)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:1448)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.access$900(QuorumCnxManager.java:99)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:1272)
2021-11-23 17:02:46,853 [myid:2] - WARN
[SendWorker:1:QuorumCnxManager$SendWorker@1295] - Send worker leaving thread id
1 my id = 2
2021-11-23 17:02:46,962 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:35016
2021-11-23 17:02:46,963 [myid:2] - WARN
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager@630] - Exception reading or
writing challenge
java.net.SocketException: Invalid argument (Read failed)
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
at java.io.DataInputStream.readFully(DataInputStream.java:195)
at java.io.DataInputStream.readLong(DataInputStream.java:416)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.handleConnection(QuorumCnxManager.java:602)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.receiveConnection(QuorumCnxManager.java:555)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1080)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1034)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:47,044 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@901]
- Peer state changed: following
2021-11-23 17:02:47,045 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1512]
- FOLLOWING
2021-11-23 17:02:47,049 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@127]
- leaderConnectDelayDuringRetryMs: 100
2021-11-23 17:02:47,049 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@128]
- TCP NoDelay set to: true
2021-11-23 17:02:47,049 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@129]
- learner.asyncSending = false
2021-11-23 17:02:47,049 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@130]
- learner.closeSocketAsync = false
2021-11-23 17:02:47,055 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):BlueThrottle@141]
- Weighed connection throttling is disabled
2021-11-23 17:02:47,056 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1300]
- minSessionTimeout set to 400
2021-11-23 17:02:47,057 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1309]
- maxSessionTimeout set to 4000
2021-11-23 17:02:47,058 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ResponseCache@45]
- getData response cache size is initialized with value 400.
2021-11-23 17:02:47,058 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ResponseCache@45]
- getChildren response cache size is initialized with value 400.
2021-11-23 17:02:47,059 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@109]
- zookeeper.pathStats.slotCapacity = 60
2021-11-23 17:02:47,060 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@110]
- zookeeper.pathStats.slotDuration = 15
2021-11-23 17:02:47,060 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@111]
- zookeeper.pathStats.maxDepth = 6
2021-11-23 17:02:47,060 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@112]
- zookeeper.pathStats.initialDelay = 5
2021-11-23 17:02:47,060 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@113]
- zookeeper.pathStats.delay = 5
2021-11-23 17:02:47,060 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@114]
- zookeeper.pathStats.enabled = false
2021-11-23 17:02:47,064 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1536]
- The max bytes for all large requests are set to 104857600
2021-11-23 17:02:47,064 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1550]
- The large request threshold is set to -1
2021-11-23 17:02:47,064 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):AuthenticationHelper@66]
- zookeeper.enforce.auth.enabled = false
2021-11-23 17:02:47,064 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):AuthenticationHelper@67]
- zookeeper.enforce.auth.schemes = []
2021-11-23 17:02:47,065 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@361]
- Created server with tickTime 200 minSessionTimeout 400 maxSessionTimeout
4000 clientPortListenBacklog -1 datadir data2/version-2 snapdir data2/version-2
2021-11-23 17:02:47,066 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@77]
- FOLLOWING - LEADER ELECTION TOOK - 433 MS
2021-11-23 17:02:47,068 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: following - discovery
2021-11-23 17:02:47,071 [myid:2] - WARN
[LeaderConnector-/127.0.1.1:2892:Learner$LeaderConnector@445] - Unexpected
exception, tries=0, remaining init limit=1000, connecting to /127.0.1.1:2892
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:607)
at org.apache.zookeeper.server.quorum.Learner.sockConnect(Learner.java:302)
at
org.apache.zookeeper.server.quorum.Learner$LeaderConnector.connectToLeader(Learner.java:419)
at
org.apache.zookeeper.server.quorum.Learner$LeaderConnector.run(Learner.java:377)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:47,172 [myid:2] - WARN
[LeaderConnector-/127.0.1.1:2892:Learner$LeaderConnector@445] - Unexpected
exception, tries=1, remaining init limit=899, connecting to /127.0.1.1:2892
java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:607)
at org.apache.zookeeper.server.quorum.Learner.sockConnect(Learner.java:302)
at
org.apache.zookeeper.server.quorum.Learner$LeaderConnector.connectToLeader(Learner.java:419)
at
org.apache.zookeeper.server.quorum.Learner$LeaderConnector.run(Learner.java:377)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2021-11-23 17:02:47,273 [myid:2] - INFO
[LeaderConnector-/127.0.1.1:2892:Learner$LeaderConnector@381] - Successfully
connected to leader, using address: /127.0.1.1:2892
2021-11-23 17:02:47,288 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: following - synchronization
2021-11-23 17:02:47,291 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@562]
- Getting a diff from the leader 0x0
2021-11-23 17:02:47,291 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@920]
- Peer state changed: following - synchronization - diff
2021-11-23 17:02:47,295 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@734]
- Learner received NEWLEADER message
2021-11-23 17:02:47,296 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1867]
- Dynamic reconfig is disabled, we don't store the last seen config.
2021-11-23 17:02:47,369 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@920]
- Peer state changed: following - synchronization
2021-11-23 17:02:47,381 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):CommitProcessor@491]
- Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
2021-11-23 17:02:47,381 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):CommitProcessor@452]
- Configuring CommitProcessor with 12 worker threads.
2021-11-23 17:02:47,382 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):FollowerRequestProcessor@59]
- Initialized FollowerRequestProcessor with
zookeeper.follower.skipLearnerRequestToNextProcessor as false
2021-11-23 17:02:47,386 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestThrottler@75]
- zookeeper.request_throttler.shutdownTimeout = 10000
2021-11-23 17:02:47,731 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:FOLLOWING; n.sid:4, n.state:LOOKING, n.leader:4,
n.round:0x2, n.peerEpoch:0x1, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,732 [myid:2] - INFO
[ListenerHandler-/127.0.1.1:3889:QuorumCnxManager$Listener$ListenerHandler@1071]
- Received connection request from /127.0.0.1:35042
2021-11-23 17:02:47,736 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:FOLLOWING; n.sid:3, n.state:LOOKING, n.leader:3,
n.round:0x2, n.peerEpoch:0x1, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,741 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:FOLLOWING; n.sid:3, n.state:LOOKING, n.leader:4,
n.round:0x2, n.peerEpoch:0x1, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,798 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@131]
- Exception when following the leader
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at java.io.DataInputStream.readInt(DataInputStream.java:387)
at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:96)
at
org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86)
at
org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:134)
at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:225)
at
org.apache.zookeeper.server.quorum.Learner.syncWithLeader(Learner.java:625)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:109)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1514)
2021-11-23 17:02:47,798 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@145]
- Disconnected from leader (with address: /127.0.1.1:2892). Was connected for
524ms. Sync state: false
2021-11-23 17:02:47,799 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@289]
- shutdown Follower
2021-11-23 17:02:47,799 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: looking
2021-11-23 17:02:47,799 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1560]
- PeerState set to LOOKING
2021-11-23 17:02:47,799 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1430]
- LOOKING
2021-11-23 17:02:47,799 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):FastLeaderElection@945]
- New election. My id = 2, proposed zxid=0x0
2021-11-23 17:02:47,801 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:2,
n.round:0x2, n.peerEpoch:0x1, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,804 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:3, n.state:FOLLOWING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,805 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,806 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:5, n.state:LEADING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,806 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:LOOKING; n.sid:1, n.state:FOLLOWING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,806 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@901]
- Peer state changed: following
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1512]
- FOLLOWING
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1300]
- minSessionTimeout set to 400
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1309]
- maxSessionTimeout set to 4000
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ResponseCache@45]
- getData response cache size is initialized with value 400.
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ResponseCache@45]
- getChildren response cache size is initialized with value 400.
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@109]
- zookeeper.pathStats.slotCapacity = 60
2021-11-23 17:02:47,807 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@110]
- zookeeper.pathStats.slotDuration = 15
2021-11-23 17:02:47,808 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:FOLLOWING; n.sid:1, n.state:FOLLOWING, n.leader:5,
n.round:0x1, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:47,813 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@111]
- zookeeper.pathStats.maxDepth = 6
2021-11-23 17:02:47,814 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@112]
- zookeeper.pathStats.initialDelay = 5
2021-11-23 17:02:47,814 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@113]
- zookeeper.pathStats.delay = 5
2021-11-23 17:02:47,814 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):RequestPathMetricsCollector@114]
- zookeeper.pathStats.enabled = false
2021-11-23 17:02:47,814 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1536]
- The max bytes for all large requests are set to 104857600
2021-11-23 17:02:47,814 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@1550]
- The large request threshold is set to -1
2021-11-23 17:02:47,815 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):AuthenticationHelper@66]
- zookeeper.enforce.auth.enabled = false
2021-11-23 17:02:47,815 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):AuthenticationHelper@67]
- zookeeper.enforce.auth.schemes = []
2021-11-23 17:02:47,815 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ZooKeeperServer@361]
- Created server with tickTime 200 minSessionTimeout 400 maxSessionTimeout
4000 clientPortListenBacklog -1 datadir data2/version-2 snapdir data2/version-2
2021-11-23 17:02:47,815 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@77]
- FOLLOWING - LEADER ELECTION TOOK - 16 MS
2021-11-23 17:02:47,815 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: following - discovery
2021-11-23 17:02:47,817 [myid:2] - INFO
[LeaderConnector-/127.0.1.1:2892:Learner$LeaderConnector@381] - Successfully
connected to leader, using address: /127.0.1.1:2892
2021-11-23 17:02:47,819 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: following - synchronization
2021-11-23 17:02:47,820 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@562]
- Getting a diff from the leader 0x0
2021-11-23 17:02:47,821 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@920]
- Peer state changed: following - synchronization - diff
2021-11-23 17:02:47,821 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@734]
- Learner received NEWLEADER message
2021-11-23 17:02:47,821 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@1867]
- Dynamic reconfig is disabled, we don't store the last seen config.
2021-11-23 17:02:47,824 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@920]
- Peer state changed: following - synchronization
2021-11-23 17:02:47,825 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):CommitProcessor@491]
- Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
2021-11-23 17:02:47,825 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):CommitProcessor@452]
- Configuring CommitProcessor with 12 worker threads.
2021-11-23 17:02:47,825 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):FollowerRequestProcessor@59]
- Initialized FollowerRequestProcessor with
zookeeper.follower.skipLearnerRequestToNextProcessor as false
2021-11-23 17:02:47,829 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):MBeanRegistry@110]
- Failed to register MBean InMemoryDataTree
2021-11-23 17:02:47,829 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):LearnerZooKeeperServer@104]
- Failed to register with JMX
javax.management.InstanceAlreadyExistsException:
org.apache.ZooKeeperService:name0=ReplicatedServer_id2,name1=replica.2,name2=Follower,name3=InMemoryDataTree
at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
at
com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
at
com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
at org.apache.zookeeper.jmx.MBeanRegistry.register(MBeanRegistry.java:106)
at
org.apache.zookeeper.server.quorum.LearnerZooKeeperServer.registerJMX(LearnerZooKeeperServer.java:102)
at
org.apache.zookeeper.server.ZooKeeperServer.startupWithServerState(ZooKeeperServer.java:709)
at
org.apache.zookeeper.server.ZooKeeperServer.startupWithoutServing(ZooKeeperServer.java:692)
at
org.apache.zookeeper.server.quorum.Learner.syncWithLeader(Learner.java:757)
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:109)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1514)
2021-11-23 17:02:47,870 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Learner@718]
- Learner received UPTODATE message
2021-11-23 17:02:47,870 [myid:2] - INFO
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):QuorumPeer@915]
- Peer state changed: following - broadcast
2021-11-23 17:02:48,009 [myid:2] - INFO
[WorkerReceiver[myid=2]:FastLeaderElection$Messenger$WorkerReceiver@390] -
Notification: my state:FOLLOWING; n.sid:4, n.state:LOOKING, n.leader:4,
n.round:0x2, n.peerEpoch:0x1, n.zxid:0x0, message format version:0x2, n.config
version:0x0
2021-11-23 17:02:48,113 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@172]
- Got zxid 0x100000001 expected 0x1
2021-11-23 17:02:48,114 [myid:2] - INFO [SyncThread:2:FileTxnLog@284] -
Creating new log file: log.100000001
2021-11-23 17:02:48,127 [myid:2] - INFO
[CommitProcessor:2:LearnerSessionTracker@116] - Committing global session
0x1000b301f680000
2021-11-23 17:02:48,155 [myid:2] - WARN
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):Follower@172]
- Got zxid 0x100000002 expected 0x100000003
2021-11-23 17:02:48,162 [myid:2] - WARN [SyncThread:2:FileTxnLog@275] -
Current zxid 4294967298 is <= 4294967298 for 1
2021-11-23 17:02:48,724 [myid:2] - ERROR
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):FollowerZooKeeperServer@104]
- Committing zxid 0x100000003 but next pending txn 0x100000002
2021-11-23 17:02:48,726 [myid:2] - ERROR
[QuorumPeer[myid=2](plain=[0:0:0:0:0:0:0:0]:2182)(secure=disabled):ServiceUtils@42]
- Exiting JVM with code 12
{code}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
