[ 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.