[
https://issues.apache.org/jira/browse/ZOOKEEPER-3800?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17102372#comment-17102372
]
maoling commented on ZOOKEEPER-3800:
------------------------------------
Attach the new changed logs as follow:
{code:java}
2020-05-08 16:18:32,090 [myid:1] - INFO [main:Environment@98] - Server
environment:java.compiler=<NA>
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.name=Mac OS X
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.arch=x86_64
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.version=10.13.6
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:user.name=maoling
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:user.home=/Users/maoling
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:user.dir=/data/software/zookeeper/zookeeper-three/bin
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.memory.free=914MB
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.memory.max=981MB
2020-05-08 16:18:32,091 [myid:1] - INFO [main:Environment@98] - Server
environment:os.memory.total=981MB
2020-05-08 16:18:32,091 [myid:1] - INFO [main:ZooKeeperServer@128] -
zookeeper.enableEagerACLCheck = false
2020-05-08 16:18:32,091 [myid:1] - INFO [main:ZooKeeperServer@136] -
zookeeper.digest.enabled = true
2020-05-08 16:18:32,091 [myid:1] - INFO [main:ZooKeeperServer@140] -
zookeeper.closeSessionTxn.enabled = true
2020-05-08 16:18:32,092 [myid:1] - INFO [main:ZooKeeperServer@1446] -
zookeeper.flushDelay=0
2020-05-08 16:18:32,092 [myid:1] - INFO [main:ZooKeeperServer@1455] -
zookeeper.maxWriteQueuePollTime=0
2020-05-08 16:18:32,092 [myid:1] - INFO [main:ZooKeeperServer@1464] -
zookeeper.maxBatchSize=1000
2020-05-08 16:18:32,092 [myid:1] - INFO [main:ZooKeeperServer@244] -
zookeeper.intBufferStartingSizeBytes = 1024
2020-05-08 16:18:32,096 [myid:1] - INFO [main:WatchManagerFactory@42] - Using
org.apache.zookeeper.server.watch.WatchManager as watch manager
2020-05-08 16:18:32,096 [myid:1] - INFO [main:WatchManagerFactory@42] - Using
org.apache.zookeeper.server.watch.WatchManager as watch manager
2020-05-08 16:18:32,096 [myid:1] - INFO [main:ZKDatabase@132] -
zookeeper.snapshotSizeFactor = 0.33
2020-05-08 16:18:32,096 [myid:1] - INFO [main:ZKDatabase@152] -
zookeeper.commitLogCount=500
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@2001] - Using
insecure (non-TLS) quorum communication
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@2007] - Port
unification disabled
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@174] -
multiAddress.enabled set to false
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@199] -
multiAddress.reachabilityCheckEnabled set to true
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@186] -
multiAddress.reachabilityCheckTimeoutMs set to 1000
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@2462] - QuorumPeer
communication is not secured! (SASL auth disabled)
2020-05-08 16:18:32,108 [myid:1] - INFO [main:QuorumPeer@2487] -
quorum.cnxn.threads.size set to 20
2020-05-08 16:18:32,115 [myid:1] - INFO [main:SnapStream@61] -
zookeeper.snapshot.compression.method = CHECKED
2020-05-08 16:18:32,139 [myid:1] - INFO [main:FileSnap@85] - Reading snapshot
../../zkdata3/version-2/snapshot.fabb00006fde
2020-05-08 16:18:37,392 [myid:1] - INFO [main:DataTree@1730] - The digest in
the snapshot has digest version of 2, , with zxid as 0xfabb00007feb, and digest
value as 2327489191295519
2020-05-08 16:18:37,871 [myid:1] - INFO [main:FileTxnSnapLog@363] - 21199 txns
loaded in 276 ms
2020-05-08 16:18:37,873 [myid:1] - INFO [main:ZKDatabase@289] - Snapshot
loaded in 5765 ms, highest zxid is 0xfabb0000c2ad, digest is 2327348253450434
2020-05-08 16:18:37,876 [myid:1] - INFO [main:Server@359] -
jetty-9.4.24.v20191120; built: 2019-11-20T21:37:49.771Z; git:
363d5f2df3a8a28de40604320230664b9c793c16; jvm 1.8.0_191-b12
2020-05-08 16:18:39,703 [myid:1] - INFO [main:DefaultSessionIdManager@333] -
DefaultSessionIdManager workerName=node0
2020-05-08 16:18:39,704 [myid:1] - INFO [main:DefaultSessionIdManager@338] -
No SessionScavenger set, using defaults
2020-05-08 16:18:39,706 [myid:1] - INFO [main:HouseKeeper@140] - node0
Scavenging every 600000ms
2020-05-08 16:18:39,710 [myid:1] - WARN [main:ConstraintSecurityHandler@757] -
[email protected]@345965f2{/,null,STARTING} has
uncovered http methods for path: /*
2020-05-08 16:18:39,711 [myid:1] - INFO [main:ContextHandler@825] - Started
o.e.j.s.ServletContextHandler@345965f2{/,null,AVAILABLE}
2020-05-08 16:18:39,713 [myid:1] - INFO [main:AbstractConnector@330] - Started
ServerConnector@146044d7{HTTP/1.1,[http/1.1]}{0.0.0.0:8083}
2020-05-08 16:18:39,714 [myid:1] - INFO [main:Server@399] - Started @8357ms
2020-05-08 16:18:39,714 [myid:1] - INFO [main:JettyAdminServer@182] - Started
AdminServer on address 0.0.0.0, port 8083 and command URL /commands
2020-05-08 16:18:39,715 [myid:1] - INFO [main:QuorumPeer@2504] - Using 10000ms
as the quorum cnxn socket timeout
2020-05-08 16:18:39,720 [myid:1] - INFO [main:QuorumCnxManager$Listener@923] -
Election port bind maximum retries is 3
2020-05-08 16:18:39,723 [myid:1] - INFO [main:FastLeaderElection@88] -
zookeeper.fastleader.minNotificationInterval=200
2020-05-08 16:18:39,724 [myid:1] - INFO [main:FastLeaderElection@90] -
zookeeper.fastleader.maxNotificationInterval=60000
2020-05-08 16:18:39,727 [myid:1] - INFO [main:ZKAuditProvider@42] - ZooKeeper
audit is disabled.
2020-05-08 16:18:39,728 [myid:1] - ERROR
[ListenerHandler-/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1093]
- Exception while listening to address /127.0.0.1:3888
java.net.BindException: Address already in use (Bind failed)
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387)
at java.net.ServerSocket.bind(ServerSocket.java:375)
at java.net.ServerSocket.bind(ServerSocket.java:329)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.createNewServerSocket(QuorumCnxManager.java:1134)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1064)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1033)
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)
2020-05-08 16:18:39,732 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):QuorumPeer@1371]
- LOOKING
2020-05-08 16:18:39,733 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):FastLeaderElection@944]
- New election. My id = 1, proposed zxid=0xfabb0000c2ad
2020-05-08 16:18:39,741 [myid:1] - INFO
[WorkerReceiver[myid=1]:FastLeaderElection$Messenger$WorkerReceiver@389] -
Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1,
n.round:0x1, n.peerEpoch:0xfabc, n.zxid:0xfabb0000c2ad, message format
version:0x2, n.config version:0x0
2020-05-08 16:18:39,747 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-2:QuorumCnxManager@400] - Cannot open channel
to 3 at election address /127.0.0.1:23888
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:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:383)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:457)
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)
2020-05-08 16:18:39,750 [myid:1] - INFO
[QuorumConnectionThread-[myid=1]-1:QuorumCnxManager@513] - Have smaller server
identifier, so dropping the connection: (myId:1 --> sid:2)
2020-05-08 16:18:39,946 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):FastLeaderElection@979]
- Notification time out: 400
2020-05-08 16:18:39,947 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-1:QuorumCnxManager@400] - Cannot open channel
to 3 at election address /127.0.0.1:23888
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:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:383)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:457)
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)
2020-05-08 16:18:39,947 [myid:1] - INFO
[QuorumConnectionThread-[myid=1]-3:QuorumCnxManager@513] - Have smaller server
identifier, so dropping the connection: (myId:1 --> sid:2)
2020-05-08 16:18:40,351 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):FastLeaderElection@979]
- Notification time out: 800
2020-05-08 16:18:40,352 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-1:QuorumCnxManager@400] - Cannot open channel
to 3 at election address /127.0.0.1:23888
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:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:383)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:457)
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)
2020-05-08 16:18:40,352 [myid:1] - INFO
[QuorumConnectionThread-[myid=1]-3:QuorumCnxManager@513] - Have smaller server
identifier, so dropping the connection: (myId:1 --> sid:2)
2020-05-08 16:18:40,731 [myid:1] - ERROR
[ListenerHandler-/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1093]
- Exception while listening to address /127.0.0.1:3888
java.net.BindException: Address already in use (Bind failed)
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387)
at java.net.ServerSocket.bind(ServerSocket.java:375)
at java.net.ServerSocket.bind(ServerSocket.java:329)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.createNewServerSocket(QuorumCnxManager.java:1134)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1064)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1033)
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)
2020-05-08 16:18:41,154 [myid:1] - INFO
[QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):FastLeaderElection@979]
- Notification time out: 1600
2020-05-08 16:18:41,154 [myid:1] - WARN
[QuorumConnectionThread-[myid=1]-1:QuorumCnxManager@400] - Cannot open channel
to 3 at election address /127.0.0.1:23888
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:589)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:383)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:457)
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)
2020-05-08 16:18:41,154 [myid:1] - INFO
[QuorumConnectionThread-[myid=1]-3:QuorumCnxManager@513] - Have smaller server
identifier, so dropping the connection: (myId:1 --> sid:2)
2020-05-08 16:18:41,733 [myid:1] - ERROR
[ListenerHandler-/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1093]
- Exception while listening to address /127.0.0.1:3888
java.net.BindException: Address already in use (Bind failed)
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387)
at java.net.ServerSocket.bind(ServerSocket.java:375)
at java.net.ServerSocket.bind(ServerSocket.java:329)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.createNewServerSocket(QuorumCnxManager.java:1134)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1064)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1033)
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)
2020-05-08 16:18:42,735 [myid:1] - ERROR
[ListenerHandler-/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1112]
- Leaving listener thread for address 127.0.0.1:3888 after 3 errors. Use
zookeeper.electionPortBindRetry property to increase retry count.
2020-05-08 16:18:42,736 [myid:1] - INFO
[QuorumPeerListener:QuorumCnxManager$Listener@979] - Leaving listener
2020-05-08 16:18:42,737 [myid:1] - ERROR
[QuorumPeerListener:QuorumCnxManager$Listener@981] - As I'm leaving the
listener thread, I won't be able to participate in leader election any longer:
127.0.0.1:3888
2020-05-08 16:18:42,740 [myid:1] - ERROR [QuorumPeerListener:ServiceUtils@42] -
Exiting JVM with code 14
{code}
> improve the log printing the address when QuorumCnxManager#ListenerHandler's
> port binds
> ----------------------------------------------------------------------------------------
>
> Key: ZOOKEEPER-3800
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-3800
> Project: ZooKeeper
> Issue Type: Improvement
> Reporter: maoling
> Assignee: Nishanth Entoor
> Priority: Minor
> Labels: pull-request-available
> Fix For: 3.7.0
>
> Time Spent: 0.5h
> Remaining Estimate: 0h
>
>
> 1.
> {code:java}
> LOG.error("Exception while listening", e);{code}
>
> At least, the log should print the address to help me find what port has
> conflicted in my host
> 2. The stack trace is following:
>
> {code:java}
> 2020-04-17 18:49:24,757 [myid:1] - INFO [main:ZKAuditProvider@42] -
> ZooKeeper audit is disabled.
> 2020-04-17 18:49:24,758 [myid:1] - ERROR
> [ListenerHandler-/127.0.0.1:3888:QuorumCnxManager$Listener$ListenerHandler@1093]
> - Exception while listening
> java.net.BindException: Address already in use (Bind failed)
> at java.net.PlainSocketImpl.socketBind(Native Method)
> at
> java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387)
> at java.net.ServerSocket.bind(ServerSocket.java:375)
> at java.net.ServerSocket.bind(ServerSocket.java:329)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.createNewServerSocket(QuorumCnxManager.java:1134)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.acceptConnections(QuorumCnxManager.java:1064)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener$ListenerHandler.run(QuorumCnxManager.java:1033)
> 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)
> 2020-04-17 18:49:24,764 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):QuorumPeer@1371]
> - LOOKING
> 2020-04-17 18:49:24,765 [myid:1] - INFO
> [QuorumPeer[myid=1](plain=[0:0:0:0:0:0:0:0]:2183)(secure=disabled):FastLeaderElection@944]
> - New election. My id = 1, proposed zxid=0xfab000000002
> {code}
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
