ZooKeeper timeout exception

ZooKeeper timeout exceptions include two types: 1) client readTimeout causing connection loss; 2) server session timeout sessionTimeout causing client connection failure

Client readTimeout causes connection loss

The readTimeout of the ZooKeeper client cannot be set; its value is calculated based on the session timeout.The calculation rules are:

  1. Before the client has completed the connection (that is, before the server has finished creating the client session and notified the client of the Watcher.Event.KeeperState.SyncConnected message)
    At this point readTimeout sets the sessionTimeout * 2/3 (that is, the session Timeout parameter value in ZooKeeper.ZooKeeper(String, int, Watcher) for the client.
    Refer to line 430 of the ZooKeeper source org.apache.zookeeper.ClientCnxn:

        readTimeout = sessionTimeout * 2 / 3
  2. When the client has finished connecting
    readTimeout * 2/3 sessionTimeout * negotiated between client and server.
    Refer to line 1405 of ZooKeeper source org.apache.zookeeper.ClientCnxn:

        readTimeout = negotiatedSessionTimeout * 2 / 3

When the client does not receive the packet sent by the server within the readTimeout time, the connection will be lost. Refer to line 1288 of ZooKeeper source code org.apache.zookeeper.ClientCnxn, as shown below

   to = readTimeout - clientCnxnSocket.getIdleRecv();
   if (to <= 0) {
        String warnInfo;
        warnInfo = "Client session timed out, have not heard from server in "
            + clientCnxnSocket.getIdleRecv() + "ms"
            + " for sessionid 0x" + Long.toHexString(sessionId);
        LOG.warn(warnInfo);
        throw new SessionTimeoutException(warnInfo);
    }

When a connection loss occurs:

  1. The client's request operation will throw an org.apache.zookeeper.KeeperException.ConnectionLossException exception
  2. Client-registered Watchers will also receive Watcher.Event.KeeperState.Disconnected notifications

However, session timeouts generally do not occur at this time, and the ZooKeeper client will perform an automatic reconnection the next time it performs the requested operation, and then the operation request will be executed after the reconnection is successful.Therefore, the next operation request is usually not a problem.

Server-side session timeout sessionTimeout causes client connections to fail

The client's session timeout sessionTimeout is determined by the client and the server through negotiation.The ZooKeeper client submits a client-set session timeout when establishing a connection with the server (referred to below as clientSessionTimeout)
The ZooKeeper service side has two configuration items: the minimum timeout (minSessionTimeout) and the maximum timeout (maxSessionTimeout), which have default values of twice and 20 times tickTime, respectively (which can also be set through zoo.cfg).
The final negotiated session timeout sessionTimeout calculation rule is as follows:

if (clientSessionTimeout < minSessionTimeout) {
    sessionTimeout = minSessionTimeout;
} else if (clientSessionTimeout > maxSessionTimeout) {
    sessionTimeout = maxSessionTimeout;
} else {
    sessionTimeout = clientSessionTimeout;
}

The ZooKeeper service buckets all client connections by session timeout, and the coordinates of each bucket in the bucket are the point at which the next session of the client session will time out detection (modeled by the maximum number of buckets in buckets, so the next session timeout detection point for all clients will fall at a point not exceeding the maximum number of buckets).Referring to the ZooKeeper service side source {@link org.apache.zookeeper.server.ExpiryQueue}, when a client performs a request operation (such as a reuse session Id and a session Password re-establish connection request), the service side checks whether the session timed out, if a session timeout occurs:

  1. The server will respond to the error code org.apache.zookeeper.KeeperException.Code.SESSIONEXPIRED for session timeout in response to the client's operation request
  2. When the client receives the error code for the server response, it throws the org.apache.zookeeper.KeeperException.SessionExpiredException exception
  3. Client-registered Watchers will also receive Watcher.Event.KeeperState.Expired notifications

In this case, the client needs to actively re-create the connection (that is, re-create the ZooKeeper instance object) and then retry the operation with the new connection.

Be careful

  1. Connection loss exception, an error detected and proactively thrown by ZooKeeper client
  2. Session timeout exception is notified to the client by the ZooKeeper server after it detects the client's session timeout

How to simulate the occurrence of readTimeout?

Simply add a debug breakpoint to the line of code that executes the requested operation before ZooKeeper executes the operation request and allow the debug breakpoint to stay between (readTimeout, session Timeout) to simulate the loss of connection.
For example, a tickTime setting of 2 seconds on the ZooKeeper server side would result in minSessionTimeout=4 seconds and maxSessionTimeout=40 seconds on the ZooKeeper server side. If a client requests a session timeout of 9 seconds when establishing a connection, the final negotiated session timeout would be 9 seconds (because 9 seconds is greater than 4 seconds and less than 40 seconds).Thus, readTimeout = 9 * 2 / 3 = 6 seconds.As long as the debug breakpoint stays between (6 seconds, 9 seconds) at the code where the ZooKeeper client executes the request, connection loss occurs.

How do I simulate session timeouts?

Simply add a debug breakpoint to the line of code that executes the operation and let the debug breakpoint stay longer than sessionTimeout before ZooKeeper executes the operation request to simulate a session timeout.
For example, a tickTime setting of 2 seconds on the ZooKeeper server side would result in minSessionTimeout=4 seconds and maxSessionTimeout=40 seconds on the ZooKeeper server side. If a client requests a session timeout of 9 seconds when establishing a connection, the final negotiated session timeout would be 9 seconds (because 9 seconds is greater than 4 seconds and less than 40 seconds).As long as the debug breakpoint stays longer than 9 seconds at the code where the ZooKeeper client executes the request, a session timeout occurs.

Test Code

package org.setamv.jsetamv.thirdparty.zookeeper.official;

import java.util.concurrent.Callable;
import org.apache.zookeeper.CreateMode;
import org.apache.zookeeper.KeeperException.ConnectionLossException;
import org.apache.zookeeper.KeeperException.SessionExpiredException;
import org.apache.zookeeper.WatchedEvent;
import org.apache.zookeeper.Watcher;
import org.apache.zookeeper.Watcher.Event.KeeperState;
import org.apache.zookeeper.ZooDefs.Ids;
import org.apache.zookeeper.ZooKeeper;
import org.apache.zookeeper.data.Stat;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * The following demonstrates timeout exception handling for ZooKeeper clients.
 * <p>ZooKeeper There are two types of timeout exceptions: 1) the client's readTimeout causes the connection to be lost; 2) the client's session timeout causes the required connection to fail.
 * <p><p><b>readTimeout on client causes connection loss </b>
 * <p>ZooKeeper The readTimeout of the client cannot be set and its value is calculated based on the session timeout.The calculation rule is: <ul>
 *     <li>When the client has not completed the connection (that is, the server has not finished creating the client session and has not notified the client of the {@link KeeperState#SyncConnected} message),
 *          readTimeout Session Timeout * 2/3 (that is, the value of the session Timeout parameter in {@link ZooKeeper#ZooKeeper(String, int, Watcher)} set for the client.<br/>
 *          Refer to line 430 of the ZooKeeper source {@link org.apache.zookeeper.ClientCnxn}: <pre>
 *              readTimeout = sessionTimeout * 2 / 3
 *          </pre></li>
 *     <li>When the client is connected, readTimeout negotiates sessionTimeout * 2/3 for both the client and the server.<br/>
 *          Refer to line 1405 of the ZooKeeper source {@link org.apache.zookeeper.ClientCnxn}: <pre>
 *              readTimeout = negotiatedSessionTimeout * 2 / 3
 *          </pre></li>
 * </ul>
 * When the client does not receive any packets sent by the server within the readTimeout time, the connection will be lost. Refer to line 1208 of the ZooKeeper source {@link org.apache.zookeeper.ClientCnxn}, as shown below <pre>
 *     if (to <= 0) {
 *          String warnInfo;
 *          warnInfo = "Client session timed out, have not heard from server in "
 *              + clientCnxnSocket.getIdleRecv() + "ms"
 *              + " for sessionid 0x" + Long.toHexString(sessionId);
 *          LOG.warn(warnInfo);
 *          throw new SessionTimeoutException(warnInfo);
 *      }
 * </pre>
 * At this time: <ul>
 *     <li>Client's request operation will throw {@link ConnectionLossException} exception </li>
 *     <li>Watcher registered by client will also receive {@link KeeperState#Disconnected} notification </li>
 * </ul>
 * However, session timeouts generally do not occur at this time, and the ZooKeeper client will perform an automatic reconnection the next time it performs the requested operation, and then the operation request will be executed after the reconnection is successful.Therefore, the next operation request is usually not a problem.<br/>
 *
 *
 * <p><p><b>Client session timeout sessionTimeout causes required connection failures </b>
 * <p>The client's session timeout sessionTimeout is determined by the client and the server through negotiation.<br/>
 * ZooKeeper When a client establishes a connection with a server, it submits a client-set session timeout (pronounced clientSessionTimeout below)<br/>
 * ZooKeeper The server side has two configuration items: the minimum timeout (minSessionTimeout) and the maximum timeout (maxSessionTimeout).
 * Their default values are twice as large as tickTimed and 20 times larger, respectively (which can also be set by zoo.cfg).<br/>
 * The final negotiated session timeout sessionTimeout calculation rule is as follows: <pre>
 *     if (clientSessionTimeout < minSessionTimeout) {
 *         sessionTimeout = minSessionTimeout;
 *     } else if (clientSessionTimeout > maxSessionTimeout) {
 *         sessionTimeout = maxSessionTimeout;
 *     } else {
 *         sessionTimeout = clientSessionTimeout;
 *     }
 * </pre>
 * When the client executes the requested operation, the server checks to see if the session timed out, and if the session timed out occurs: <ul>
 *     <li>The server will respond to the client's operation request with the error code {@link org.apache.zookeeper.KeeperException.Code#SESSIONEXPIRED}</li>for session timeout
 *     <li>Client will throw {@link SessionExpiredException} exception </li>
 *     <li>Watcher registered by client will also receive {@link KeeperState#Expired} notification </li>
 * </ul>
 * In this case, the client needs to actively re-create the connection (that is, re-create the {@link ZooKeeper} instance object) and then retry the operation with the new connection.
 *
 * <p><p><b>Note </b><br/>
 * 1,Connection loss exception, detected and proactively thrown by ZooKeeper client <br/>
 * 2,Session timeout exception is notified to the client by the ZooKeeper server after it detects the client's session timeout
 *
 * <p><p><b>How to simulate the occurrence of readTimeout?</b><br/>
 * Simply add a debug breakpoint to the line of code that executes the operation and allow the debug breakpoint to stay between (readTimeout, session Timeout) before ZooKeeper only wants to manipulate the request to simulate the loss of connection.<br/>
 * For example, a tickTime setting of 2 seconds on the ZooKeeper server side would result in minSessionTimeout=4 seconds and maxSessionTimeout=40 seconds on the ZooKeeper server side, and if the session requested by the client to establish a connection would time out of 9 seconds.
 * The session timeout for final negotiation will be 9 seconds (because 9 seconds is greater than 4 seconds and less than 40 seconds).Thus, readTimeout = 9 * 2 / 3 = 6 seconds.<br/>
 * As long as the debug breakpoint stays between (6 seconds, 9 seconds) at the code where the ZooKeeper client executes the request, connection loss occurs.
 *
 * <p><p><b>How do I simulate session timeouts?</b><br/>
 * Simply add a debug breakpoint to the line of code that executes the operation and allow the debug breakpoint to stay longer than sessionTimeout before ZooKeeper only wants to operate on the request to simulate a session timeout.<br/>
 * For example, if the tickTime setting on the ZooKeeper server is 9 seconds, the minSessionTimeout on the ZooKeeper server is 4 seconds, and the maxSessionTimeout is 40 seconds. If the client establishes a connection, the requested session timeout is 9 seconds.
 * The session timeout for final negotiation will be 9 seconds (because 9 seconds is greater than 4 seconds and less than 40 seconds).<br/>
 * As long as the debug breakpoint stays longer than 9 seconds at the code where the ZooKeeper client executes the request, a session timeout occurs.
 */
public class ZooKeeperTimeoutHandleUsage {

    private static final Logger LOG = LoggerFactory.getLogger(ZooKeeperTimeoutHandleUsage.class);

    private volatile int counter = 0;

    private int sessionTimeout = 9000;

    private ZooKeeper zooKeeper;

    public ZooKeeperTimeoutHandleUsage() {
        zooKeeper = ZooKeeperUtil.buildInstance(sessionTimeout);
    }

    public static void main(String[] args) throws Exception {
        ZooKeeperTimeoutHandleUsage usage = new ZooKeeperTimeoutHandleUsage();
        usage.rightUsage();
    }

    /**
     * ZooKeeper Packaging of operations, mainly for retries with lost connections and session timeouts
     */
    public <V> V wrapperOperation(String operation, Callable<V> command) {
        int seq = ++counter;
        int retryTimes = 0;
        while (retryTimes <= 3) {
            try {
                LOG.info("[{}]Ready to perform action:{}", seq, operation);
                V result = command.call();
                LOG.info("[{}]{}Success", seq, operation);
                return result;
            } catch (ConnectionLossException e) {
                // Connection lost exception, try again.Because the ZooKeeper client will reconnect automatically
                LOG.error("[" + seq + "]" + operation + "Failed!Prepare to retry", e);
            } catch (SessionExpiredException e) {
                // Client session timed out, re-establish client connection
                LOG.error("[" + seq + "]" + operation + "Failed!Session timed out, ready to recreate session and retry operation", e);
                zooKeeper = ZooKeeperUtil.buildInstance(sessionTimeout);
            } catch (Exception e) {
                LOG.error("[" + seq + "]" + operation + "Failed!", e);
            } finally {
                retryTimes++;
            }
        }
        return null;
    }

    public Watcher existsWatcher = new Watcher() {
        @Override
        public void process(WatchedEvent event) {
            ZooKeeperUtil.logWatchedEvent(LOG, event);
            if (KeeperState.SyncConnected == event.getState() && null != event.getPath()) {
                registerExistsWatcher(event.getPath());
            }
        }
    };

    public void registerExistsWatcher(String path) {
        try {
            zooKeeper.exists(path, existsWatcher);
        } catch (Exception e) {
            throw new RuntimeException(e);
        }
    }

    public void rightUsage() throws Exception {
        String path = ZooKeeperUtil.usagePath("/right-usage");
        String data = "demonstrate right usage of zookeeper client";

        registerExistsWatcher(path);

        // Create Node
        String realPath = wrapperOperation("Create Node", () -> {
            return zooKeeper.create(path, data.getBytes(), Ids.OPEN_ACL_UNSAFE, CreateMode.PERSISTENT_SEQUENTIAL);
        });

        Long startTime = System.currentTimeMillis();
        // Set a breakpoint in the line below and leave it to simulate connection loss or session timeout (assuming session timeout is 9 seconds)
        // If you stay between sessionTimeout * 2/3 = 6 seconds and sessionTimeout = 9 seconds, connection loss will occur
        // If you stay longer than sessionTimeout = 9 seconds, a session timeout will occur
        LOG.info("simulation ZooKeeper Client and server lose network connection{}Seconds.", (System.currentTimeMillis() - startTime) / 1000);

        // Get node data
        wrapperOperation("Get node data", () -> {
            return zooKeeper.getData(realPath, false, new Stat());
        });

        // Get node data
        wrapperOperation("Set Node Data", () -> {
            return zooKeeper.setData(realPath, (data + "-a").getBytes(), -1);
        });

        // Get node data
        wrapperOperation("Get node data", () -> {
            return zooKeeper.getData(realPath, false, new Stat());
        });
    }
}

public class ZooKeeperUtil {
    /**
     * Build ZooKeeper client instance with specified timeout
     * @param sessionTimeout
     * @return
     */
    public static ZooKeeper buildInstance(int sessionTimeout) {
        final CountDownLatch connectedSemaphore = new CountDownLatch(1);

        Watcher watcher = (watchedEvent) -> {
            ZooKeeperUtil.logWatchedEvent(LOG, watchedEvent);
            connectedSemaphore.countDown();
        };

        ZooKeeper zooKeeper;
        try {
            zooKeeper = new ZooKeeper(SERVERS, sessionTimeout, watcher);
            connectedSemaphore.await();
        } catch (Exception e) {
            throw new RuntimeException(e);
        }
        return zooKeeper;
    }
}    

Connection Lost Automatic Reconnection Presentation Log

The ZooKeeper server sets tickTime=2 seconds, the session timeout included in the client's request to establish a connection is 9 seconds, and the breakpoint stays for 6 seconds. The following logs appear (Note: >>>>>>>>>>>>>>>>>>>>> Description is not the content of the logs, it is the description of the logs)

>>>>>>>>>>>>>>>>[Note) Some logs started earlier, ignored
... 
10:10:18:858 [main] INFO  ZooKeeper - Initiating client connection, connectString=192.168.199.130:2181 sessionTimeout=9000 watcher=org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperUtil$$Lambda$1/1661081225@243c4f91
10:10:18:862 [main] DEBUG ClientCnxn - zookeeper.disableAutoWatchReset is false
10:10:19:024 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Opening socket connection to server 192.168.199.130/192.168.199.130:2181. Will not attempt to authenticate using SASL (unknown error)
10:10:19:026 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Socket connection established to 192.168.199.130/192.168.199.130:2181, initiating session
10:10:19:028 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Session establishment request sent on 192.168.199.130/192.168.199.130:2181

>>>>>>>>>>>>>>>>[Note) The following log shows that the session timeout for final negotiation is 9000 milliseconds, or 9 seconds
10:10:19:033 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Session establishment complete on server 192.168.199.130/192.168.199.130:2181, sessionid = 0x1000000ceb80034, negotiated timeout = 9000
10:10:19:035 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=SyncConnected, eventType=None, path=null
10:10:19:042 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 1,3  replyHeader:: 1,542,-101  request:: '/usage/right-usage,T  response::  
10:10:19:045 [main] INFO  ZooKeeperTimeoutHandleUsage - [1]Ready to perform action: Create node
10:10:19:055 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 2,1  replyHeader:: 2,543,0  request:: '/usage/right-usage,#64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e74,v{s{31,s{'world,'anyone}}},2  response:: '/usage/right-usage0000000031 
10:10:19:055 [main] INFO  ZooKeeperTimeoutHandleUsage - [1]Node Creation Successful

>>>>>>>>>>>>>>>>[Description) Client received at 6541 ms No messages were received from the server in time (because debug Breakpoint stay causes)
10:10:25:595 [main-SendThread(192.168.199.130:2181)] WARN  ClientCnxn - Client session timed out, have not heard from server in 6541ms for sessionid 0x1000000ceb80034
10:10:25:596 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Client session timed out, have not heard from server in 6541ms for sessionid 0x1000000ceb80034, closing socket connection and attempting reconnect

>>>>>>>>>>>>>>>>[Description) Here is the debug Stay for 6 seconds to simulate logs of client and server disconnected for 6 seconds
10:10:25:596 [main] INFO  ZooKeeperTimeoutHandleUsage - simulation ZooKeeper Client and server lost network connection for 6 seconds.
10:10:25:609 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Ready to perform action: Get node data
10:10:25:707 [main-EventThread] INFO  ZooKeeperTimeoutHandleUsage - Received[watched event], state=Disconnected, eventType=None, path=null
10:10:25:709 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=Disconnected, eventType=None, path=null

>>>>>>>>>>>>>>>>[Description) Retry operation after connection loss
10:10:25:727 [main] ERROR ZooKeeperTimeoutHandleUsage - [2]Failed to get node data!Prepare to retry
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /usage/right-usage0000000031
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1215)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1244)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.lambda$rightUsage$1(ZooKeeperTimeoutHandleUsage.java:169)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.wrapperOperation(ZooKeeperTimeoutHandleUsage.java:113)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.rightUsage(ZooKeeperTimeoutHandleUsage.java:168)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.main(ZooKeeperTimeoutHandleUsage.java:101)
10:10:25:727 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Ready to perform action: Get node data

>>>>>>>>>>>>>>>>[Description) The following log shows ZooKeeper The client automatically reconnected before retrying the operation
10:10:27:700 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Opening socket connection to server 192.168.199.130/192.168.199.130:2181. Will not attempt to authenticate using SASL (unknown error)
10:10:27:701 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Socket connection established to 192.168.199.130/192.168.199.130:2181, initiating session
10:10:27:703 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Session establishment request sent on 192.168.199.130/192.168.199.130:2181
10:10:27:706 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Session establishment complete on server 192.168.199.130/192.168.199.130:2181, sessionid = 0x1000000ceb80034, negotiated timeout = 9000

>>>>>>>>>>>>>>>>[Description) ZooKeeper Client Auto Reconnect Successful
10:10:27:707 [main-EventThread] INFO  ZooKeeperTimeoutHandleUsage - Received[watched event], state=SyncConnected, eventType=None, path=null
10:10:27:707 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=SyncConnected, eventType=None, path=null

>>>>>>>>>>>>>>>>[Description) The retry operation was performed successfully and a reply packet was received from the server
10:10:27:710 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 3,101  replyHeader:: 3,543,0  request:: 543,v{},v{'/usage/right-usage},v{}  response:: null
10:10:27:723 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 4,4  replyHeader:: 4,543,0  request:: '/usage/right-usage0000000031,F  response:: #64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e74,s{543,543,1573956619409,1573956619409,0,0,0,0,43,0,543} 
10:10:27:729 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Getting node data succeeded
10:10:27:730 [main] INFO  ZooKeeperTimeoutHandleUsage - [3]Ready to perform action: Set node data
10:10:27:736 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 5,5  replyHeader:: 5,544,0  request:: '/usage/right-usage0000000031,#64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e742d61,-1  response:: s{543,544,1573956619409,1573956628091,1,0,0,0,45,0,543} 
10:10:27:736 [main] INFO  ZooKeeperTimeoutHandleUsage - [3]Setting node data succeeded
10:10:27:737 [main] INFO  ZooKeeperTimeoutHandleUsage - [4]Ready to perform action: Get node data
10:10:27:740 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80034, packet:: clientPath:null serverPath:null finished:false header:: 6,4  replyHeader:: 6,544,0  request:: '/usage/right-usage0000000031,F  response:: #64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e742d61,s{543,544,1573956619409,1573956628091,1,0,0,0,45,0,543} 
10:10:27:740 [main] INFO  ZooKeeperTimeoutHandleUsage - [4]Getting node data succeeded

Re-create the presentation log for the session after it has timed out

The ZooKeeper server sets tickTime=2 seconds, the session timeout included in the client's request to establish a connection is 9 seconds, and the breakpoint stays for about 10 seconds. The following logs appear (Note: >>>>>>>>>>>>>>>>>>> Description) is not the log content, it is the description of the logs)

>>>>>>>>>>>>>>>>[Comment) Startup log omitted
....
10:26:11:516 [main] INFO  ZooKeeper - Initiating client connection, connectString=192.168.199.130:2181 sessionTimeout=9000 watcher=org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperUtil$$Lambda$1/1661081225@243c4f91
10:26:11:519 [main] DEBUG ClientCnxn - zookeeper.disableAutoWatchReset is false
10:26:11:699 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Opening socket connection to server 192.168.199.130/192.168.199.130:2181. Will not attempt to authenticate using SASL (unknown error)
10:26:11:704 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Socket connection established to 192.168.199.130/192.168.199.130:2181, initiating session
10:26:11:707 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Session establishment request sent on 192.168.199.130/192.168.199.130:2181

>>>>>>>>>>>>>>>>[Note) The following log shows that the session timeout for final negotiation is 9000 milliseconds, or 9 seconds
10:26:11:723 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Session establishment complete on server 192.168.199.130/192.168.199.130:2181, sessionid = 0x1000000ceb80035, negotiated timeout = 9000
10:26:11:726 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=SyncConnected, eventType=None, path=null
10:26:11:738 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80035, packet:: clientPath:null serverPath:null finished:false header:: 1,3  replyHeader:: 1,546,-101  request:: '/usage/right-usage,T  response::  
10:26:11:741 [main] INFO  ZooKeeperTimeoutHandleUsage - [1]Ready to perform action: Create node
10:26:11:749 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80035, packet:: clientPath:null serverPath:null finished:false header:: 2,1  replyHeader:: 2,547,0  request:: '/usage/right-usage,#64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e74,v{s{31,s{'world,'anyone}}},2  response:: '/usage/right-usage0000000032 
10:26:11:749 [main] INFO  ZooKeeperTimeoutHandleUsage - [1]Node Creation Successful

>>>>>>>>>>>>>>>>[Description) Received Client at 10136 ms No messages were received from the server in time (because debug Breakpoint stay causes)
10:26:21:884 [main-SendThread(192.168.199.130:2181)] WARN  ClientCnxn - Client session timed out, have not heard from server in 10136ms for sessionid 0x1000000ceb80035
10:26:21:885 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Client session timed out, have not heard from server in 10136ms for sessionid 0x1000000ceb80035, closing socket connection and attempting reconnect

>>>>>>>>>>>>>>>>[Description) Here is the debug Stay for 10 seconds to simulate logs of client and server disconnected for 6 seconds
10:26:21:884 [main] INFO  ZooKeeperTimeoutHandleUsage - simulation ZooKeeper The client and server lost their network connection for 10 seconds.
10:26:21:888 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Ready to perform action: Get node data
10:26:22:000 [main] ERROR ZooKeeperTimeoutHandleUsage - [2]Failed to get node data!Prepare to retry

>>>>>>>>>>>>>>>>[Description) The client first triggered a connection loss exception (which was detected before the session timeout exception because the connection loss exception was proactively detected by the client and the session timeout had to wait until the client's next operation before the server notified the client when it detected a session timeout)
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss for /usage/right-usage0000000032
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1215)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1244)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.lambda$rightUsage$1(ZooKeeperTimeoutHandleUsage.java:169)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.wrapperOperation(ZooKeeperTimeoutHandleUsage.java:113)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.rightUsage(ZooKeeperTimeoutHandleUsage.java:168)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.main(ZooKeeperTimeoutHandleUsage.java:101)
10:26:22:000 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Ready to perform action: Get node data
10:26:22:001 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=Disconnected, eventType=None, path=null
10:26:22:001 [main-EventThread] INFO  ZooKeeperTimeoutHandleUsage - Received[watched event], state=Disconnected, eventType=None, path=null

>>>>>>>>>>>>>>>>[Description) Automatic client reconnection
10:26:23:013 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Opening socket connection to server 192.168.199.130/192.168.199.130:2181. Will not attempt to authenticate using SASL (unknown error)
10:26:23:015 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Socket connection established to 192.168.199.130/192.168.199.130:2181, initiating session
10:26:23:018 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Session establishment request sent on 192.168.199.130/192.168.199.130:2181

>>>>>>>>>>>>>>>>[Description) ZooKeeper When the server processes a client's reconnect request, it finds that the session has timed out and notifies the client that the session has timed out
10:26:23:025 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=Expired, eventType=None, path=null
10:26:23:025 [main-EventThread] INFO  ZooKeeperTimeoutHandleUsage - Received[watched event], state=Expired, eventType=None, path=null

>>>>>>>>>>>>>>>>[Note) As you can see from the log below, ZooKeeper Clients reuse previous connections when reconnecting automatically sessionId(0x1000000ceb80035)
10:26:23:025 [main-SendThread(192.168.199.130:2181)] WARN  ClientCnxn - Unable to reconnect to ZooKeeper service, session 0x1000000ceb80035 has expired
10:26:23:026 [main-EventThread] INFO  ClientCnxn - EventThread shut down for session: 0x1000000ceb80035
10:26:23:026 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Unable to reconnect to ZooKeeper service, session 0x1000000ceb80035 has expired, closing socket connection

>>>>>>>>>>>>>>>>[Description) After a session timeout is detected, re-establish the connected session and retry the operation
10:26:23:127 [main] ERROR ZooKeeperTimeoutHandleUsage - [2]Failed to get node data!Session timed out, ready to recreate session and retry operation
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /usage/right-usage0000000032
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:130)
    at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1215)
    at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1244)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.lambda$rightUsage$1(ZooKeeperTimeoutHandleUsage.java:169)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.wrapperOperation(ZooKeeperTimeoutHandleUsage.java:113)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.rightUsage(ZooKeeperTimeoutHandleUsage.java:168)
    at org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperTimeoutHandleUsage.main(ZooKeeperTimeoutHandleUsage.java:101)
10:26:23:127 [main] INFO  ZooKeeper - Initiating client connection, connectString=192.168.199.130:2181 sessionTimeout=9000 watcher=org.setamv.jsetamv.thirdparty.zookeeper.official.ZooKeeperUtil$$Lambda$1/1661081225@45c7e403
10:26:23:130 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Opening socket connection to server 192.168.199.130/192.168.199.130:2181. Will not attempt to authenticate using SASL (unknown error)
10:26:23:131 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Socket connection established to 192.168.199.130/192.168.199.130:2181, initiating session
10:26:23:132 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Session establishment request sent on 192.168.199.130/192.168.199.130:2181
10:26:23:136 [main-SendThread(192.168.199.130:2181)] INFO  ClientCnxn - Session establishment complete on server 192.168.199.130/192.168.199.130:2181, sessionid = 0x1000000ceb80036, negotiated timeout = 9000
10:26:23:136 [main-EventThread] INFO  ZooKeeperUtil - Received[watched event], state=SyncConnected, eventType=None, path=null
10:26:23:137 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Ready to perform action: Get node data
10:26:23:141 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80036, packet:: clientPath:null serverPath:null finished:false header:: 1,4  replyHeader:: 1,549,0  request:: '/usage/right-usage0000000032,F  response:: #64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e74,s{547,547,1573957572125,1573957572125,0,0,0,0,43,0,547} 
10:26:23:149 [main] INFO  ZooKeeperTimeoutHandleUsage - [2]Getting node data succeeded
10:26:23:150 [main] INFO  ZooKeeperTimeoutHandleUsage - [3]Ready to perform action: Set node data
10:26:23:169 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80036, packet:: clientPath:null serverPath:null finished:false header:: 2,5  replyHeader:: 2,550,0  request:: '/usage/right-usage0000000032,#64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e742d61,-1  response:: s{547,550,1573957572125,1573957583538,1,0,0,0,45,0,547} 
10:26:23:169 [main] INFO  ZooKeeperTimeoutHandleUsage - [3]Setting node data succeeded
10:26:23:170 [main] INFO  ZooKeeperTimeoutHandleUsage - [4]Ready to perform action: Get node data
10:26:23:172 [main-SendThread(192.168.199.130:2181)] DEBUG ClientCnxn - Reading reply sessionid:0x1000000ceb80036, packet:: clientPath:null serverPath:null finished:false header:: 3,4  replyHeader:: 3,550,0  request:: '/usage/right-usage0000000032,F  response:: #64656d6f6e737472617465207269676874207573616765206f66207a6f6f6b656570657220636c69656e742d61,s{547,550,1573957572125,1573957583538,1,0,0,0,45,0,547} 
10:26:23:172 [main] INFO  ZooKeeperTimeoutHandleUsage - [4]Getting node data succeeded
Disconnected from the target VM, address: '127.0.0.1:53585', transport: 'socket'

Tags: Java Zookeeper Session Apache

Posted on Sun, 17 Nov 2019 04:08:54 -0500 by Biocide