转载请注明:@ni掌柜 nileader@gmail.com

 问题描述

    公司之前进行了几次机房容灾演习中,经常是模拟一个机房挂掉的场景,把一个机房的网络切掉,使得这个机房内部网络通信正常,与外部的网络不通。在容灾演习过程中,我们发现ZK的客户端应用中出现大量类似这样的日志:

  1. An exception was thrown while closing send thread for ession 0x for server null, unexpected error, closing socket connection and attempting  

从这个日志中,红色部分出现的是null。当时看到这个情况,觉得,正常情况正在,这个地方应用出现的是那个被隔离的机房中部署的ZK的机器IP的,但是这里出现的是null,非常困惑。

    具体描述也可以在这里查看:https://issues.apache.org/jira/browse/ZOOKEEPER-1480

 问题定位

    看了下3.4.3及其以前版本的ZooKeeper代码,发现问题出在这里,日志打印的逻辑在这里:

  1. catch (Throwable e) {  
  2.     if (closing) {  
  3.         if (LOG.isDebugEnabled()) {  
  4.             // closing so this is expected  
  5.             LOG.debug("An exception was thrown while closing send thread for session 0x"  
  6.                     + Long.toHexString(getSessionId())  
  7.                     + " : " + e.getMessage());  
  8.         }  
  9.         break;  
  10.     } else {  
  11.         // this is ugly, you have a better way speak up  
  12.         if (e instanceof SessionExpiredException) {  
  13.             LOG.info(e.getMessage() + ", closing socket connection");  
  14.         } else if (e instanceof SessionTimeoutException) {  
  15.             LOG.info(e.getMessage() + RETRY_CONN_MSG);  
  16.         } else if (e instanceof EndOfStreamException) {  
  17.             LOG.info(e.getMessage() + RETRY_CONN_MSG);  
  18.         } else if (e instanceof RWServerFoundException) {  
  19.             LOG.info(e.getMessage());  
  20.         } else {  
  21.             LOG.warn(  
  22.                     "Session 0x"  
  23.                             + Long.toHexString(getSessionId())  
  24.                             + " for server "  
  25.                             + clientCnxnSocket.getRemoteSocketAddress()  
  26.                             + ", unexpected error"  
  27.                             + RETRY_CONN_MSG, e);  
  28.         }  

可以看到,在打印日志过程,是通过clientCnxnSocket.getRemoteSocketAddress() 来获取当前连接的服务器地址的,那再来看下这个方法:

  1. /** 
  2.      * Returns the address to which the socket is connected. 
  3.      * @return ip address of the remote side of the connection or null if not connected 
  4.      */ 
  5.     @Override 
  6.     SocketAddress getRemoteSocketAddress() { 
  7.         // a lot could go wrong here, so rather than put in a bunch of code 
  8.         // to check for nulls all down the chain let's do it the simple 
  9.         // yet bulletproof way 
  10.         try { 
  11.             return ((SocketChannel) sockKey.channel()).socket() 
  12.                     .getRemoteSocketAddress(); 
  13.         } catch (NullPointerException e) { 
  14.             return null
  15.         } 
  16.     /** 
  17.      * Returns the address of the endpoint this socket is connected to, or 
  18.      * <code>null</code> if it is unconnected. 
  19.      * @return a <code>SocketAddress</code> reprensenting the remote endpoint of this 
  20.      *         socket, or <code>null</code> if it is not connected yet. 
  21.      * @see #getInetAddress() 
  22.      * @see #getPort() 
  23.      * @see #connect(SocketAddress, int) 
  24.      * @see #connect(SocketAddress) 
  25.      * @since 1.4 
  26.      */ 
  27.     public SocketAddress getRemoteSocketAddress() { 
  28.       if (!isConnected()) 
  29.         return null
  30.       return new InetSocketAddress(getInetAddress(), getPort()); 

所以,现在基本就可以定位问题了,如果服务器端非正常关闭socket连接(例如容灾演习的时候把机房网络切断),那么getRemoteSocketAddress这个方法就会返回null了,也就是日志中为什么出现null的原因了。 

 问题解决

    这个日志输出对于开发人员来说非常重要,在排查问题过程中可以清楚的定位当时是哪台服务器出现问题,但是这里一旦输出null,那么将无从下手。这里我做了一些改进,确保出现问题的时候,客户端能够输出当前出现问题的服务器IP。在这里下载补丁:https://github.com/downloads/nileader/taokeeper/getCurrentZooKeeperAddr_for_3.4.3.patch

    首先是给org.apache.zookeeper.client.HostProvider类添加两个接口,分别用于获取“当前地址列中正在使用的地址序号”和获取“所有地址列表”。关于ZooKeeper客户端地址列表获取和随机原理,具体可以查看这个文章《ZooKeeper客户端地址列表的随机原理》。

  1. public interface HostProvider { 
  2.     …… …… 
  3.     /**  
  4.      * Get current index that is connecting or connected.  
  5.      * @see ZOOKEEPER-1480:https://issues.apache.org/jira/browse/ZOOKEEPER-1480 
  6.      * */ 
  7.     public int getCurrentIndex(); 
  8.     /** 
  9.      * Get all server address that config when use zookeeper client. 
  10.      * @return List  
  11.      * @see ZOOKEEPER-1480:https://issues.apache.org/jira/browse/ZOOKEEPER-1480 
  12.      */ 
  13.     public List<InetSocketAddress> getAllServerAddress(); 
  14.      

 其次是修改org.apache.zookeeper.ClientCnxn类中日志输出逻辑:

  1. /** 
  2.          * Get current zookeeper addr that client is connected or connecting.<br> 
  3.          * Note:The method will return null if can't not get host ip. 
  4.          * */ 
  5.         private InetSocketAddress getCurrentZooKeeperAddr(){ 
  6.             try { 
  7.                 InetSocketAddress addr = null
  8.                 ifnull == hostProvider || null == hostProvider.getAllServerAddress() ) 
  9.                     return addr; 
  10.                 int index = hostProvider.getCurrentIndex(); 
  11.                 if ( index >= 0  ) { 
  12.                     addr = hostProvider.getAllServerAddress().get( index ); 
  13.                 } 
  14.                 return addr; 
  15.             } catch ( Exception e ) { 
  16.                 return null
  17.             } 
  18.         } 
  19. …… …… 
  20.         //get current ZK host to log 
  21.         InetSocketAddress addr = getCurrentZooKeeperAddr(); 
  22.          
  23.         LOG.warn( 
  24.             "Session 0x" 
  25.                     + Long.toHexString(getSessionId()) 
  26.                     + " for server ip: " + addr + ", detail conn: " 
  27.                     + clientCnxnSocket.getRemoteSocketAddress() 
  28.                     + ", unexpected error" 
  29.                     + RETRY_CONN_MSG, e);