title: Hadoop HA active NN keep crashing, and auto failover doesn't work
body: <p>I'm using hadoop 2.2.0 HA.
  Here is my configuration.</p>
  
  <p>core-site.xml</p>
  
  <pre><code>&lt;property&gt;
      &lt;name&gt;ha.zookeeper.quorum&lt;/name&gt;
      &lt;value&gt;zk01.bi.lietou.inc:2181,zk02.bi.lietou.inc:2181,zk03.bi.lietou.inc:2181&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;ipc.client.connect.timeout&lt;/name&gt;
      &lt;value&gt;20000&lt;/value&gt;
  &lt;/property&gt;
  </code></pre>
  
  <p>hdfs-site.xml</p>
  
  <pre><code>&lt;property&gt;
      &lt;name&gt;dfs.nameservices&lt;/name&gt;
      &lt;value&gt;lynxcluster&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.ha.namenodes.lynxcluster&lt;/name&gt;
      &lt;value&gt;nn1,nn2&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.namenode.rpc-address.lynxcluster.nn1&lt;/name&gt;
      &lt;value&gt;192.168.30.133:2020&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.namenode.rpc-address.lynxcluster.nn2&lt;/name&gt;
      &lt;value&gt;192.168.30.129:2020&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.namenode.http-address.lynxcluster.nn1&lt;/name&gt;
      &lt;value&gt;192.168.30.133:2070&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.namenode.http-address.lynxcluster.nn2&lt;/name&gt;
      &lt;value&gt;192.168.30.129:2070&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.namenode.shared.edits.dir&lt;/name&gt;
      &lt;value&gt;qjournal://192.168.30.134:8485;192.168.30.135:8485;192.168.30.136:8485/mycluster&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.client.failover.proxy.provider.lynxcluster&lt;/name&gt;
      &lt;value&gt;org.apache.hadoop.hdfs.server.namenode.ha.ConfiguredFailoverProxyProvider&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.ha.automatic-failover.enabled&lt;/name&gt;
      &lt;value&gt;true&lt;/value&gt;
  &lt;/property&gt;
  &lt;property&gt;
      &lt;name&gt;dfs.qjournal.write-txns.timeout.ms&lt;/name&gt;
      &lt;value&gt;6000000&lt;/value&gt;
  &lt;/property&gt;
  </code></pre>
  
  <p>192.168.30.129 is active NN, and 192.168.30.133 is standby NN.</p>
  
  <p>active NN get error when start log segment.</p>
  
  <pre><code>2015-09-26 22:09:06,044 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from 192.168.30.133
  2015-09-26 22:09:06,044 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs
  2015-09-26 22:09:06,044 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 522618707
  2015-09-26 22:09:06,179 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 16 Total time for transactions(ms): 7 Number of transactions batched in Syncs: 0 Number of syncs: 10 SyncTimes(ms): 670 2033 142
  2015-09-26 22:09:06,185 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizing edits file /data1/hadoop/name/current/edits_inprogress_0000000000522618707 -&gt; /data1/hadoop/name/current/edits_0000000000522618707-0000000000522618722
  2015-09-26 22:09:06,294 INFO org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Finalizingedits file /data2/hadoop/name/current/edits_inprogress_0000000000522618707 -&gt; /data2/hadoop/name/current/edits_0000000000522618707-0000000000522618722
  2015-09-26 22:09:06,307 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Starting log segment at 522618723
  2015-09-26 22:09:12,308 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 6001 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:13,310 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 7002 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:14,310 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 8003 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:15,312 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 9004 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:16,312 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 10005 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:17,313 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 11006 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:18,314 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 12007 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:19,315 INFO org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 13008 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:20,317 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 14009 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:21,317 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 15010 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:22,319 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 16011 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:23,319 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 17012 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:24,321 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 18013 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:25,321 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Waited 19014 ms (timeout=20000 ms) for a response for startLogSegment(522618723). Succeeded so far: [192.168.30.134:8485]
  2015-09-26 22:09:26,308 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: starting log segment 522618723 failed for required journal (JournalAndStream(mgr=QJM to [192.168.30.134:8485, 192.168.30.135:8485, 192.168.30.136:8485], stream=null))
  java.io.IOException: Timed out waiting 20000ms for a quorum of nodes to respond.
      at org.apache.hadoop.hdfs.qjournal.client.AsyncLoggerSet.waitForWriteQuorum(AsyncLoggerSet.java:137)
      at org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager.startLogSegment(QuorumJournalManager.java:387)
      at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.startLogSegment(JournalSet.java:91)
      at org.apache.hadoop.hdfs.server.namenode.JournalSet$2.apply(JournalSet.java:199)
      at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:352)
      at org.apache.hadoop.hdfs.server.namenode.JournalSet.startLogSegment(JournalSet.java:196)
      at org.apache.hadoop.hdfs.server.namenode.FSEditLog.startLogSegment(FSEditLog.java:1029)
      at org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:998)
      at org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1082)
      at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:5050)
      at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:832)
      at org.apache.hadoop.hdfs.protocolPB.NamenodeProtocolServerSideTranslatorPB.rollEditLog(NamenodeProtocolServerSideTranslatorPB.java:139)
      at org.apache.hadoop.hdfs.protocol.proto.NamenodeProtocolProtos$NamenodeProtocolService$2.callBlockingMethod(NamenodeProtocolProtos.java:11214)
      at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:585)
      at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:928)
      at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2048)
      at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2044)
      at java.security.AccessController.doPrivileged(Native Method) 
      at javax.security.auth.Subject.doAs(Subject.java:415)
      at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1491)
      at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2042)
  2015-09-26 22:09:26,312 INFO org.apache.hadoop.util.ExitUtil: Exiting with status 1
  2015-09-26 22:09:26,319 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:
  /************************************************************
  SHUTDOWN_MSG: Shutting down NameNode at lynx001-bi-30-129.liepin.inc/192.168.30.129
  ************************************************************/
  </code></pre>
  
  <p>After 129 shutting down, 133 was still in standby status.
  standby NN logs</p>
  
  <pre><code>2015-09-26 22:09:27,651 WARN org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Unable to trigger a roll of the active NN
  java.io.IOException: Failed on local exception: java.io.EOFException; Host Details : local host is: "lynx-bi-30-133.liepin.inc/192.168.30.133"; destination host is: "lynx001-bi-30-129.liepin.inc":2020;
      at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:764)
      at org.apache.hadoop.ipc.Client.call(Client.java:1351)
      at org.apache.hadoop.ipc.Client.call(Client.java:1300)
      at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
      at com.sun.proxy.$Proxy11.rollEditLog(Unknown Source)
      at org.apache.hadoop.hdfs.protocolPB.NamenodeProtocolTranslatorPB.rollEditLog(NamenodeProtocolTranslatorPB.java:139)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.triggerActiveLogRoll(EditLogTailer.java:268)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.access$600(EditLogTailer.java:61)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:310)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$200(EditLogTailer.java:279)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:296)
      at org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:456)
      at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:292)
  Caused by: java.io.EOFException
      at java.io.DataInputStream.readInt(DataInputStream.java:392)
      at org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:995)
      at org.apache.hadoop.ipc.Client$Connection.run(Client.java:891)
  </code></pre>
  
  <p>right before this error, it started to spill out</p>
  
  <pre><code>2015-09-26 22:03:00,941 ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:hadoop (auth:SIMPLE) cause:org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  2015-09-26 22:03:00,941 INFO org.apache.hadoop.ipc.Server: IPC Server handler 2 on 2020, call org.apache.hadoop.hdfs.protocol.ClientProtocol.getFileInfo from 192.168.30.131:35882Call#7495335 Retry#0: error: org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  2015-09-26 22:03:01,135 ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:hadoop (auth:SIMPLE) cause:org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  2015-09-26 22:03:01,135 INFO org.apache.hadoop.ipc.Server: IPC Server handler 45 on 2020, call org.apache.hadoop.hdfs.protocol.ClientProtocol.getFileInfo from 192.168.30.131:35886 Call#7495346 Retry#0: error: org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  2015-09-26 22:03:06,050 ERROR org.apache.hadoop.security.UserGroupInformation: PriviledgedActionException as:hadoop (auth:SIMPLE) cause:org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  2015-09-26 22:03:06,050 INFO org.apache.hadoop.ipc.Server: IPC Server handler 19 on 2020, call org.apache.hadoop.hdfs.protocol.ClientProtocol.getBlockLocations from 192.168.30.131:35891 Call#1 Retry#0: error: org.apache.hadoop.ipc.StandbyException: Operation category READ is not supported in state standby
  </code></pre>
  
  <p>JN logs</p>
  
  <pre><code>2015-09-26 22:09:44,395 WARN org.apache.hadoop.ipc.Server: IPC Server Responder, call org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocol.startLogSegment from 192.168.30.129:30015 Call#157803 Retry#0: output error
  2015-09-26 22:09:45,400 INFO org.apache.hadoop.ipc.Server: IPC Server handler 4 on 8485 caught an exception
  java.nio.channels.ClosedChannelException
      at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:265)
      at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:474)
      at org.apache.hadoop.ipc.Server.channelWrite(Server.java:2577)
      at org.apache.hadoop.ipc.Server.access$2200(Server.java:122)
      at org.apache.hadoop.ipc.Server$Responder.processResponse(Server.java:1011)
      at org.apache.hadoop.ipc.Server$Responder.doRespond(Server.java:1076)
      at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2104)
  </code></pre>
  
  <p>I've tried to increase the ipc timeout to 60s, but it doesn't work.</p>