You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@zookeeper.apache.org by "Yong-Hao Zou (Jira)" <ji...@apache.org> on 2021/11/23 09:42:00 UTC
[jira] [Created] (ZOOKEEPER-4418) Committing zxid 0x100000003 but next pending txn 0x100000002
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)