ZooKeeper
  1. ZooKeeper
  2. ZOOKEEPER-564

Give more feedback on that current flow of events in java client logs

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.2.1
    • Fix Version/s: 3.3.0
    • Component/s: None
    • Labels:
    • Hadoop Flags:
      Reviewed

      Description

      As discussed during the 10/23 meeting, one issue we have in debugging ZK client logs with HBase is that we have a hard time following the flow of events. It may be obvious for a ZK dev, but in our POV that kind of trace isn't very intuitive:

      2009-09-27 15:41:10,776 INFO org.apache.zookeeper.ClientCnxn: Attempting connection to server ...
      2009-09-27 15:41:10,776 INFO org.apache.zookeeper.ClientCnxn: Priming connection to java.nio.channels.SocketChannel[connected local=/ ... remote=...
      2009-09-27 15:41:10,776 INFO org.apache.zookeeper.ClientCnxn: Server connection successful 
      2009-09-27 15:41:10,784 WARN org.apache.zookeeper.ClientCnxn: Exception closing session 0x0 to sun.nio.ch.SelectionKeyImpl@2c9b42e6
      

      This excerpt is just an example. We would like to see something like a numbering of the events and possibly, in the case of an exception, at which point did it went wrong and what's the next step.

        Issue Links

          Activity

          Hide
          Patrick Hunt added a comment -

          I've worked out the following for session establishment, teardown and expiration handling. I'm not convinced about the numbering (and getting the numbers "right" (no gaps for example) in all cases might be tough).

          We'd also include some documentation describing the client session establishment, teardown, and expiration handling which would refer to the messages (a bit of handwaving here cuz nothing yet, but think that it would be some docs describing what's below). These logs make it more clear re documenting the steps - first a socket connection is created, then a session is established.

          following is logging at info level

          client side log create session

          2009-10-29 21:37:05,393 - INFO - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@1608e05
          2009-10-29 21:37:05,449 - INFO - Opening socket connection to server localhost/127.0.0.1:2181
          2009-10-29 21:37:05,493 - INFO - Socket connection established to localhost/127.0.0.1:2181, initiating session
          Welcome to ZooKeeper!
          2009-10-29 21:37:05,547 - INFO - Session establishment complete, sessionid = 0x124a3f255ce0000

          client side log close session

          2009-10-29 21:37:08,677 - INFO - Session: 0x124a3f255ce0000 closed

          server watching client session creation

          2009-10-29 20:57:19,748 - INFO - Accepted socket connection from /127.0.0.1:49641
          2009-10-29 20:57:19,784 - INFO - Client attempting to establish new session at /127.0.0.1:49641
          2009-10-29 20:57:19,801 - INFO - Established session 0x124a3cdf52d0000 for client /127.0.0.1:49641

          server watching client close session

          2009-10-29 20:57:49,772 - INFO - Processed session termination for sessionid: 0x124a3cdf52d0000
          2009-10-29 20:57:49,775 - INFO - Closed socket connection for client /127.0.0.1:49641 which had sessionid 0x124a3cdf52d0000

          server expiring client session

          2009-10-29 21:00:18,001 - INFO - Expiring session 0x124a3cdf52d0001, timeout of 30000ms exceeded
          2009-10-29 21:00:18,002 - INFO - Processed session termination for sessionid: 0x124a3cdf52d0001
          2009-10-29 21:00:18,004 - INFO - Closed socket connection for client /127.0.0.1:49644 which had sessionid 0x124a3cdf52d0001

          server watching client attempt to re-establish expired session

          2009-10-29 21:00:28,222 - INFO - Accepted socket connection from /127.0.0.1:51000
          2009-10-29 21:00:28,223 - INFO - Client attempting to renew session 0x124a3cdf52d0001 at /127.0.0.1:51000
          2009-10-29 21:00:28,225 - INFO - Invalid session 0x124a3cdf52d0001 for client /127.0.0.1:51000, probably expired
          2009-10-29 21:00:28,227 - INFO - Closed socket connection for client /127.0.0.1:51000 which had sessionid 0

          Show
          Patrick Hunt added a comment - I've worked out the following for session establishment, teardown and expiration handling. I'm not convinced about the numbering (and getting the numbers "right" (no gaps for example) in all cases might be tough). We'd also include some documentation describing the client session establishment, teardown, and expiration handling which would refer to the messages (a bit of handwaving here cuz nothing yet, but think that it would be some docs describing what's below). These logs make it more clear re documenting the steps - first a socket connection is created, then a session is established. following is logging at info level client side log create session 2009-10-29 21:37:05,393 - INFO - Initiating client connection, connectString=localhost:2181 sessionTimeout=30000 watcher=org.apache.zookeeper.ZooKeeperMain$MyWatcher@1608e05 2009-10-29 21:37:05,449 - INFO - Opening socket connection to server localhost/127.0.0.1:2181 2009-10-29 21:37:05,493 - INFO - Socket connection established to localhost/127.0.0.1:2181, initiating session Welcome to ZooKeeper! 2009-10-29 21:37:05,547 - INFO - Session establishment complete, sessionid = 0x124a3f255ce0000 client side log close session 2009-10-29 21:37:08,677 - INFO - Session: 0x124a3f255ce0000 closed server watching client session creation 2009-10-29 20:57:19,748 - INFO - Accepted socket connection from /127.0.0.1:49641 2009-10-29 20:57:19,784 - INFO - Client attempting to establish new session at /127.0.0.1:49641 2009-10-29 20:57:19,801 - INFO - Established session 0x124a3cdf52d0000 for client /127.0.0.1:49641 server watching client close session 2009-10-29 20:57:49,772 - INFO - Processed session termination for sessionid: 0x124a3cdf52d0000 2009-10-29 20:57:49,775 - INFO - Closed socket connection for client /127.0.0.1:49641 which had sessionid 0x124a3cdf52d0000 server expiring client session 2009-10-29 21:00:18,001 - INFO - Expiring session 0x124a3cdf52d0001, timeout of 30000ms exceeded 2009-10-29 21:00:18,002 - INFO - Processed session termination for sessionid: 0x124a3cdf52d0001 2009-10-29 21:00:18,004 - INFO - Closed socket connection for client /127.0.0.1:49644 which had sessionid 0x124a3cdf52d0001 server watching client attempt to re-establish expired session 2009-10-29 21:00:28,222 - INFO - Accepted socket connection from /127.0.0.1:51000 2009-10-29 21:00:28,223 - INFO - Client attempting to renew session 0x124a3cdf52d0001 at /127.0.0.1:51000 2009-10-29 21:00:28,225 - INFO - Invalid session 0x124a3cdf52d0001 for client /127.0.0.1:51000, probably expired 2009-10-29 21:00:28,227 - INFO - Closed socket connection for client /127.0.0.1:51000 which had sessionid 0
          Hide
          Patrick Hunt added a comment -

          ZOOKEEPER-558 patch includes this issue (same general area)

          Please review the patch for 558 ASAP and provide any feedback there if you notice issues.

          Show
          Patrick Hunt added a comment - ZOOKEEPER-558 patch includes this issue (same general area) Please review the patch for 558 ASAP and provide any feedback there if you notice issues.
          Hide
          Patrick Hunt added a comment -

          Fixed as part of ZOOKEEPER-558

          Show
          Patrick Hunt added a comment - Fixed as part of ZOOKEEPER-558

            People

            • Assignee:
              Patrick Hunt
              Reporter:
              Jean-Daniel Cryans
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development