[
https://issues.apache.org/jira/browse/ZOOKEEPER-790?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12890512#action_12890512
]
Travis Crawford commented on ZOOKEEPER-790:
-------------------------------------------
I tested this patch on a build with the following, applied in the listed order:
3.3.1 release + ZOOKEEPER-744.patch + ZOOKEEPER-790-3.3.patch
Looks good!
{code}
2010-07-20 23:43:34,229 - INFO [Thread-2545:nioserverc...@1516] - Closed
socket connection for client /10.209.21.181:53743 (no session established for
client)
2010-07-20 23:43:34,659 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@639] -
EndOfStreamException: Unable to read additional data from client sessionid
0x129d3fcb5a6f60d, likely client has closed socket
2010-07-20 23:43:34,660 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1516] - Closed socket
connection for client /10.209.21.204:59727 which had sessionid 0x129d3fcb5a6f60d
2010-07-20 23:43:34,684 - INFO [ProcessThread:-1:preprequestproces...@385] -
Processed session termination for sessionid: 0x329d3fcb6594e53
2010-07-20 23:52:14,522 - INFO [main:quorumpeercon...@90] - Reading
configuration from: /etc/zookeeper/conf/zoo.cfg
2010-07-20 23:52:14,529 - INFO [main:quorumpeercon...@287] - Defaulting to
majority quorums
2010-07-20 23:52:14,540 - INFO [main:quorumpeerm...@119] - Starting quorum peer
2010-07-20 23:52:14,562 - INFO [main:nioservercnxn$fact...@149] - binding to
port 0.0.0.0/0.0.0.0:2181
2010-07-20 23:52:14,578 - INFO [main:quorump...@818] - tickTime set to 2000
2010-07-20 23:52:14,579 - INFO [main:quorump...@829] - minSessionTimeout set
to -1
2010-07-20 23:52:14,579 - INFO [main:quorump...@840] - maxSessionTimeout set
to -1
2010-07-20 23:52:14,579 - INFO [main:quorump...@855] - initLimit set to 10
2010-07-20 23:52:14,798 - INFO [main:files...@82] - Reading snapshot
/data/zookeeper/version-2/snapshot.2500197ee5
2010-07-20 23:52:15,660 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.45.76:57030
2010-07-20 23:52:15,661 - INFO [Thread-1:quorumcnxmanager$liste...@436] - My
election bind port: 3888
2010-07-20 23:52:15,663 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@644] - Exception
causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not
running
2010-07-20 23:52:15,664 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1516] - Closed socket
connection for client /10.209.45.76:57030 (no session established for client)
2010-07-20 23:52:15,670 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:quorump...@620] - LOOKING
2010-07-20 23:52:15,672 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@649] - New election. My id
= 1, Proposed zxid = 158915472832
2010-07-20 23:52:15,674 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@689] - Notification: 1,
158915472832, 1, 1, LOOKING, LOOKING, 1
2010-07-20 23:52:15,674 - INFO [WorkerSender Thread:quorumcnxmana...@162] -
Have smaller server identifier, so dropping the connection: (2, 1)
2010-07-20 23:52:15,675 - INFO [WorkerSender Thread:quorumcnxmana...@162] -
Have smaller server identifier, so dropping the connection: (3, 1)
2010-07-20 23:52:15,676 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@689] - Notification: 2,
158915472832, 5, 1, LOOKING, LOOKING, 2
2010-07-20 23:52:15,676 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@689] - Notification: 3,
158915472832, 5, 1, LOOKING, LOOKING, 2
2010-07-20 23:52:15,676 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@711] - Updating proposal
2010-07-20 23:52:15,677 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@799] - Notification: 3,
158915472832, 5, 1, LOOKING, FOLLOWING, 2
2010-07-20 23:52:15,677 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@689] - Notification: 3,
158915472832, 5, 1, LOOKING, LOOKING, 3
2010-07-20 23:52:15,879 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:quorump...@642] - FOLLOWING
2010-07-20 23:52:15,885 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lear...@72] -
TCP NoDelay set to: true
2010-07-20 23:52:15,893 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:zookeeper.version=3.3.1-942149, built on 05/07/2010 17:14 GMT
2010-07-20 23:52:15,893 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:host.name=sjc1k029.twitter.com
2010-07-20 23:52:15,894 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.version=1.6.0_16
2010-07-20 23:52:15,894 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.vendor=Sun Microsystems Inc.
2010-07-20 23:52:15,894 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.home=/usr/java/jdk1.6.0_16/jre
2010-07-20 23:52:15,894 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.class.path=/etc/zookeeper/conf::/usr/local/zookeeper/../zookeeper-*.jar:/usr/local/zookeeper/../lib/*.jar:/usr/local/zookeeper/../src/java/lib/*.jar:/usr/local/zookeeper/jline-0.9.94.jar:/usr/local/zookeeper/log4j-1.2.15.jar:/usr/local/zookeeper/zookeeper-3.3.2-dev.jar
2010-07-20 23:52:15,895 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.library.path=/usr/java/jdk1.6.0_16/jre/lib/amd64/server:/usr/java/jdk1.6.0_16/jre/lib/amd64:/usr/java/jdk1.6.0_16/jre/../lib/amd64:/usr/java/packages/lib/amd64:/lib:/usr/lib
2010-07-20 23:52:15,895 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.io.tmpdir=/tmp
2010-07-20 23:52:15,895 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:java.compiler=<NA>
2010-07-20 23:52:15,896 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:os.name=Linux
2010-07-20 23:52:15,896 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:os.arch=amd64
2010-07-20 23:52:15,896 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:os.version=2.6.18-164.6.1.el5
2010-07-20 23:52:15,897 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:user.name=root
2010-07-20 23:52:15,897 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:user.home=/root
2010-07-20 23:52:15,897 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:environm...@97] - Server
environment:user.dir=/
2010-07-20 23:52:15,899 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:zookeeperser...@151] - Created server with
tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir
/data/zookeeper/txlog/version-2 snapdir /data/zookeeper/version-2
2010-07-20 23:52:15,911 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lear...@285]
- Getting a snapshot from leader
2010-07-20 23:52:16,152 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lear...@315]
- Setting leader epoch 26
2010-07-20 23:52:16,166 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:filetxnsnap...@208] - Snapshotting: 260000195d
2010-07-20 23:52:16,200 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.21.181:49189
2010-07-20 23:52:16,200 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1314] - Processing
stat command from /10.209.21.181:49189
2010-07-20 23:52:16,203 - INFO [Thread-6:nioserverc...@1516] - Closed socket
connection for client /10.209.21.181:49189 (no session established for client)
2010-07-20 23:52:16,446 - WARN [QuorumPeer:/0:0:0:0:0:0:0:0:2181:follo...@116]
- Got zxid 0x260000195e expected 0x1
2010-07-20 23:52:16,446 - INFO [SyncThread:1:filetxn...@197] - Creating new
log file: log.260000195e
2010-07-20 23:52:19,205 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.21.181:49192
2010-07-20 23:52:19,205 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1314] - Processing
stat command from /10.209.21.181:49192
2010-07-20 23:52:19,206 - INFO [Thread-7:nioservercnxn$statcomm...@1167] -
Stat command output
2010-07-20 23:52:19,208 - INFO [Thread-7:nioserverc...@1516] - Closed socket
connection for client /10.209.21.181:49192 (no session established for client)
2010-07-20 23:52:20,562 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.44.180:47281
2010-07-20 23:52:20,564 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@782] - Client
attempting to establish new session at /10.209.44.180:47281
2010-07-20 23:52:20,574 - INFO [CommitProcessor:1:nioserverc...@1661] -
Established session 0x129f245a01c0000 with negotiated timeout 10000 for client
/10.209.44.180:47281
2010-07-20 23:52:20,581 - INFO [CommitProcessor:1:preprequestproces...@69] -
zookeeper.skipACL=="yes", ACL checks will be skipped
2010-07-20 23:52:20,586 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@639] -
EndOfStreamException: Unable to read additional data from client sessionid
0x129f245a01c0000, likely client has closed socket
2010-07-20 23:52:20,587 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1516] - Closed socket
connection for client /10.209.44.180:47281 which had sessionid 0x129f245a01c0000
2010-07-20 23:52:20,826 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.48.78:52838
2010-07-20 23:52:20,827 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@782] - Client
attempting to establish new session at /10.209.48.78:52838
2010-07-20 23:52:20,829 - INFO [CommitProcessor:1:nioserverc...@1661] -
Established session 0x129f245a01c0001 with negotiated timeout 10000 for client
/10.209.48.78:52838
2010-07-20 23:52:20,832 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@639] -
EndOfStreamException: Unable to read additional data from client sessionid
0x129f245a01c0001, likely client has closed socket
2010-07-20 23:52:20,833 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1516] - Closed socket
connection for client /10.209.48.78:52838 which had sessionid 0x129f245a01c0001
2010-07-20 23:52:22,210 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.21.181:49197
2010-07-20 23:52:22,210 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@1314] - Processing
stat command from /10.209.21.181:49197
2010-07-20 23:52:22,211 - INFO [Thread-8:nioservercnxn$statcomm...@1167] -
Stat command output
2010-07-20 23:52:22,227 - INFO [Thread-8:nioserverc...@1516] - Closed socket
connection for client /10.209.21.181:49197 (no session established for client)
2010-07-20 23:52:22,551 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioservercnxn$fact...@256] -
Accepted socket connection from /10.209.45.104:42183
2010-07-20 23:52:22,552 - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@782] - Client
attempting to establish new session at /10.209.45.104:42183
2010-07-20 23:52:22,554 - INFO [CommitProcessor:1:nioserverc...@1661] -
Established session 0x129f245a01c0002 with negotiated timeout 10000 for client
/10.209.45.104:42183
2010-07-20 23:52:22,560 - WARN
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:nioserverc...@639] -
EndOfStreamException: Unable to read additional data from client sessionid
0x129f245a01c0002, likely client has closed socket
{code}
> Last processed zxid set prematurely while establishing leadership
> -----------------------------------------------------------------
>
> Key: ZOOKEEPER-790
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-790
> Project: Zookeeper
> Issue Type: Bug
> Components: quorum
> Affects Versions: 3.3.1
> Reporter: Flavio Paiva Junqueira
> Assignee: Flavio Paiva Junqueira
> Priority: Blocker
> Fix For: 3.3.2, 3.4.0
>
> Attachments: ZOOKEEPER-790-3.3.patch, ZOOKEEPER-790.patch,
> ZOOKEEPER-790.patch, ZOOKEEPER-790.patch, ZOOKEEPER-790.travis.log.bz2
>
>
> The leader code is setting the last processed zxid to the first of the new
> epoch even before connecting to a quorum of followers. Because the leader
> code sets this value before connecting to a quorum of followers
> (Leader.java:281) and the follower code throws an IOException
> (Follower.java:73) if the leader epoch is smaller, we have that when the
> false leader drops leadership and becomes a follower, it finds a smaller
> epoch and kills itself.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
