ZooKeeper
  1. ZooKeeper
  2. ZOOKEEPER-706

large numbers of watches can cause session re-establishment to fail

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Critical Critical
    • Resolution: Unresolved
    • Affects Version/s: 3.1.2, 3.2.2, 3.3.0
    • Fix Version/s: 3.5.0
    • Component/s: c client, java client
    • Labels:
      None

      Description

      If a client sets a large number of watches the "set watches" operation during session re-establishment can fail.

      for example:
      WARN [NIOServerCxn.Factory:22801:NIOServerCnxn@417] - Exception causing close of session 0xe727001201a4ee7c due to java.io.IOException: Len error 4348380

      in this case the client was a web monitoring app and had set both data and child watches on > 32k znodes.

      there are two issues I see here we need to fix:

      1) handle this case properly (split up the set watches into multiple calls I guess...)
      2) the session should have expired after the "timeout". however we seem to consider any message from the client as re-setting the expiration on the server side. Probably we should only consider messages from the client that are sent during an established session, otherwise we can see this situation where the session is not established however the session is not expired either. Perhaps we should create another JIRA for this particular issue.

        Issue Links

          Activity

          Hide
          Patrick Hunt added a comment -

          This is a pretty easy one for someone to fix, and as more users use more watches it would be good to get this addressed.

          Show
          Patrick Hunt added a comment - This is a pretty easy one for someone to fix, and as more users use more watches it would be good to get this addressed.
          Hide
          Mahadev konar added a comment -

          not a blocker. Moving it out of 3.4 release.

          Show
          Mahadev konar added a comment - not a blocker. Moving it out of 3.4 release.
          Hide
          Eric Hwang added a comment -

          I am seeing this issue coming up quite a bit right now. Some clients are getting continually disconnected/reconnected with that error message from what I assume is the large number of watches. For example:

          2011-08-29 13:26:43,750 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32866
          2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32866
          2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32866
          2011-08-29 13:26:43,775 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32866 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:26:47,276 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32871
          2011-08-29 13:26:47,298 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32871
          2011-08-29 13:26:47,298 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32871
          2011-08-29 13:26:47,298 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:47,300 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32871 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:26:51,124 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32879
          2011-08-29 13:26:51,142 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32879
          2011-08-29 13:26:51,143 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32879
          2011-08-29 13:26:51,143 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:51,143 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32879 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:26:53,985 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32885
          2011-08-29 13:26:54,006 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32885
          2011-08-29 13:26:54,007 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32885
          2011-08-29 13:26:54,007 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:54,007 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32885 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:26:57,495 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32892
          2011-08-29 13:26:57,513 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32892
          2011-08-29 13:26:57,513 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32892
          2011-08-29 13:26:57,514 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:57,514 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32892 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:26:59,937 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32897
          2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32897
          2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32897
          2011-08-29 13:26:59,958 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247
          2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32897 which had sessionid 0x1319819fcd1000b
          2011-08-29 13:27:03,711 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32904

          It would be great to get this fixed in an upcoming release since it is impacting us quite a bit.

          Show
          Eric Hwang added a comment - I am seeing this issue coming up quite a bit right now. Some clients are getting continually disconnected/reconnected with that error message from what I assume is the large number of watches. For example: 2011-08-29 13:26:43,750 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32866 2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32866 2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32866 2011-08-29 13:26:43,775 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:43,775 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32866 which had sessionid 0x1319819fcd1000b 2011-08-29 13:26:47,276 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32871 2011-08-29 13:26:47,298 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32871 2011-08-29 13:26:47,298 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32871 2011-08-29 13:26:47,298 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:47,300 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32871 which had sessionid 0x1319819fcd1000b 2011-08-29 13:26:51,124 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32879 2011-08-29 13:26:51,142 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32879 2011-08-29 13:26:51,143 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32879 2011-08-29 13:26:51,143 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:51,143 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32879 which had sessionid 0x1319819fcd1000b 2011-08-29 13:26:53,985 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32885 2011-08-29 13:26:54,006 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32885 2011-08-29 13:26:54,007 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32885 2011-08-29 13:26:54,007 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:54,007 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32885 which had sessionid 0x1319819fcd1000b 2011-08-29 13:26:57,495 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32892 2011-08-29 13:26:57,513 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32892 2011-08-29 13:26:57,513 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32892 2011-08-29 13:26:57,514 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:57,514 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32892 which had sessionid 0x1319819fcd1000b 2011-08-29 13:26:59,937 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32897 2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@770] - Client attempting to renew session 0x1319819fcd1000b at /10.141.241.188:32897 2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1580] - Established session 0x1319819fcd1000b with negotiated timeout 10000 for client /10.141.241.188:32897 2011-08-29 13:26:59,958 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@639] - Exception causing close of session 0x1319819fcd1000b due to java.io.IOException: Len error 1150247 2011-08-29 13:26:59,958 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1435] - Closed socket connection for client /10.141.241.188:32897 which had sessionid 0x1319819fcd1000b 2011-08-29 13:27:03,711 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn$Factory@251] - Accepted socket connection from /10.141.241.188:32904 It would be great to get this fixed in an upcoming release since it is impacting us quite a bit.
          Hide
          Patrick Hunt added a comment -

          You might be seeing ZOOKEEPER-1162 – see if the workaround there fixes your problem.

          Show
          Patrick Hunt added a comment - You might be seeing ZOOKEEPER-1162 – see if the workaround there fixes your problem.
          Hide
          Eric Hwang added a comment -

          Any idea if the jute.maxbuffer setting needs to be applied to both server and client? or just client?

          Show
          Eric Hwang added a comment - Any idea if the jute.maxbuffer setting needs to be applied to both server and client? or just client?
          Hide
          Eric Hwang added a comment -

          Thanks Patrick, setting jute.maxbuffer size to a larger value in the server and client seems to have fixed the problem.

          Show
          Eric Hwang added a comment - Thanks Patrick, setting jute.maxbuffer size to a larger value in the server and client seems to have fixed the problem.
          Hide
          Patrick Hunt added a comment -

          Good to know, thanks Eric. Even more reason to address ZOOKEEPER-1162

          Show
          Patrick Hunt added a comment - Good to know, thanks Eric. Even more reason to address ZOOKEEPER-1162

            People

            • Assignee:
              Unassigned
              Reporter:
              Patrick Hunt
            • Votes:
              7 Vote for this issue
              Watchers:
              15 Start watching this issue

              Dates

              • Created:
                Updated:

                Development