Uploaded image for project: 'Spymemcached Java Client'
  1. Spymemcached Java Client
  2. SPY-81

spike in requests causes large amount of java exceptions and tomcat crash

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Fix Version/s: .next
    • Component/s: docs
    • Security Level: Public
    • Labels:
      None
    • Environment:
      MB 1.7.1-community
      Spy 2.7.0

      Description

      user is trying to understand why they are seeing these messages in the logs, application servers and membase are on the same local subnet and value sizes are under 1k

      spy is connected to membase through a server side moxi.

      2012-02-23 13:55:02.462 ERROR net.spy.memcached.protocol.binary.StoreOperationImpl: Error: Too large
      2012-02-23 13:55:02.462 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

      {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@43452e96, topWop=null, toWrite=0, interested=1}

      . This may be due to an authentication failure.
      OperationException: SERVER: Too large
      at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:136)
      at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:154)
      at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:140)
      at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:493)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:425)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:278)
      at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1981)
      2012-02-23 13:55:02.463 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening

      {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@43452e96, topWop=null, toWrite=0, interested=1}

      , attempt 0.
      2012-02-23 13:55:02.463 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.StoreOperationImpl@43452e96
      Feb 23, 2012 1:55:02 PM org.apache.tomcat.util.http.Parameters processParameters
      INFO: Parameters: Invalid chunk '' ignored.
      Feb 23, 2012 1:55:02 PM org.apache.tomcat.util.http.Parameters processParameters
      INFO: Parameters: Invalid chunk '' ignored.
      2012-02-23 13:55:03.132 ERROR net.spy.memcached.protocol.binary.StoreOperationImpl: Error: Too large
      2012-02-23 13:55:03.132 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

      {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@f4c9792, topWop=null, toWrite=0, interested=1}

      . This may be due to an authentication failure.
      OperationException: SERVER: Too large
      at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:136)
      at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:154)
      at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:140)
      at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:493)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:425)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:278)
      at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1981)
      2012-02-23 13:55:03.133 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening

      {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@f4c9792, topWop=null, toWrite=0, interested=1}

      , attempt 0.
      2012-02-23 13:55:03.133 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.StoreOperationImpl@f4c9792
      Feb 23, 2012 1:55:03 PM org.apache.tomcat.util.http.Parameters processParameters
      INFO: Parameters: Invalid chunk '' ignored.
      2012-02-23 13:55:03.348 ERROR net.spy.memcached.protocol.binary.StoreOperationImpl: Error: Too large
      2012-02-23 13:55:03.348 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

      {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@2307e11c, topWop=null, toWrite=0, interested=1}

      . This may be due to an authentication failure.
      OperationException: SERVER: Too large
      at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:136)
      at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:154)
      at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:140)
      at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:493)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:425)
      at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:278)
      at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1981)
      2012-02-23 13:55:03.349 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening

      {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperationImpl@2307e11c, topWop=null, toWrite=0, interested=1}

      , attempt 0.
      2012-02-23 13:55:03.349 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.StoreOperationImpl@2307e11c
      2012-02-23 13:55:03.350 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.OptimizedGetImpl@7a8100c5
      2012-02-23 13:55:03.350 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl: Discarding partially completed op: net.spy.memcached.protocol.binary.StoreOperationImpl@44423a6b

      2012-02-23 13:55:03.788 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/7yV9qppJ38flpgQqm0Dw31bNYdlyruj_bbj7mHGzQyo.
      2012-02-23 13:55:03.789 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/7yV9qppJ38flpgQqm0Dw31bNYdlyruj_bbj7mHGzQyo[Ljava.lang.String;@9dbde1b.
      2012-02-23 13:55:03.790 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatclient_config_iPhone_4.0.0.
      2012-02-23 13:55:03.824 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/cTGxajvGtJg_sO0cQfTqMr3dwOJDbAwv0ecbJJGzgcM.

      No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

        Hide
        alex Alex Ma added a comment -

        255 characters? For the key? That's seems small. I'll check though.

        Spike happened at 1:55PM EST

        The below illustrates the phenomenon I was mentioning, where we would periodically get these exceptions on node 208, but at 13:55, we got them almost every second on all nodes.

        2012-02-23 13:45:02.096 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6bd7804f, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:45:10.526 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@1495ff2a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:46:12.062 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@77aa45c4, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:47:31.371 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@307a06ac, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:47:32.632 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@28880048, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:47:56.512 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@4eeea211, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:49:07.056 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@51331ef7, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:50:42.727 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2614ee30, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:51:19.931 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@617b407, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:51:24.891 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2e4cdcdc, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:52:07.895 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6732298, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:52:32.891 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@59957070, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:53:45.257 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@1b2ad24d, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:53:48.354 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@ca5a4f4, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:00.252 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@7c115e09, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:01.322 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@268c45a6, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:05.110 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@28c8f84f, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:05.277 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@29d4788a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:06.323 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6ca7da19, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:07.147 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@36e9f3fb, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:07.714 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@5daa976a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:08.319 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=1, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2ca7381b, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:08.429 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6ebcca2a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:09.812 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=4, #Wops=8, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6896c3f6, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@2f5328e3, toWrite=2084, interested=5}

        . This may be due to an authentication failure.
        2012-02-23 13:55:10.514 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@27ecc9f1, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:10.625 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2d54eb63, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:10.772 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@501e1cda, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:11.838 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=6, #Wops=9, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2673663f, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@623dc5d1, toWrite=12448, interested=5}

        . This may be due to an authentication failure.
        2012-02-23 13:55:12.580 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@47220d57, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:12.783 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@21a4291c, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:13.387 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@5f8df69a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:14.655 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6015cf4f, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:15.223 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=7, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@a452f7a, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:15.537 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=5, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@64f2f745, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:16.728 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=6, #Wops=1, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@18143b2d, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@583913b4, toWrite=935, interested=5}

        . This may be due to an authentication failure.
        2012-02-23 13:55:18.125 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@644a454c, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:18.427 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6898c0f3, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:18.767 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=6, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@583913b4, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:21.555 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6695fdb1, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.
        2012-02-23 13:55:21.713 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=3, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@722d9c9b, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@1084bead, toWrite=9864, interested=5}

        . This may be due to an authentication failure.
        2012-02-23 13:55:22.091 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=4, #Wops=17, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperati nImpl@7dc74a72, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@c18dcd9, toWrite=9688, interested=5}

        . This may be due to an authentication failure.
        2012-02-23 13:55:23.015 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on

        {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@a7605cb, topWop=null, toWrite=0, interested=1}

        . This may be due to an authentication failure.

        Show
        alex Alex Ma added a comment - 255 characters? For the key? That's seems small. I'll check though. Spike happened at 1:55PM EST The below illustrates the phenomenon I was mentioning, where we would periodically get these exceptions on node 208, but at 13:55, we got them almost every second on all nodes. 2012-02-23 13:45:02.096 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6bd7804f, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:45:10.526 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@1495ff2a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:46:12.062 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@77aa45c4, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:47:31.371 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@307a06ac, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:47:32.632 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@28880048, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:47:56.512 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@4eeea211, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:49:07.056 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@51331ef7, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:50:42.727 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2614ee30, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:51:19.931 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@617b407, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:51:24.891 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2e4cdcdc, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:52:07.895 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6732298, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:52:32.891 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@59957070, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:53:45.257 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@1b2ad24d, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:53:48.354 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@ca5a4f4, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:00.252 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@7c115e09, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:01.322 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@268c45a6, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:05.110 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@28c8f84f, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:05.277 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@29d4788a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:06.323 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=1, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6ca7da19, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:07.147 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@36e9f3fb, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:07.714 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@5daa976a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:08.319 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=1, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2ca7381b, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:08.429 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6ebcca2a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:09.812 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=4, #Wops=8, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6896c3f6, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@2f5328e3, toWrite=2084, interested=5} . This may be due to an authentication failure. 2012-02-23 13:55:10.514 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@27ecc9f1, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:10.625 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2d54eb63, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:10.772 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@501e1cda, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:11.838 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=6, #Wops=9, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@2673663f, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@623dc5d1, toWrite=12448, interested=5} . This may be due to an authentication failure. 2012-02-23 13:55:12.580 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@47220d57, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:12.783 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@21a4291c, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:13.387 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=2, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@5f8df69a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:14.655 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6015cf4f, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:15.223 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=7, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@a452f7a, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:15.537 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=5, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@64f2f745, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:16.728 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=6, #Wops=1, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@18143b2d, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@583913b4, toWrite=935, interested=5} . This may be due to an authentication failure. 2012-02-23 13:55:18.125 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@644a454c, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:18.427 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6898c0f3, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:18.767 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=6, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@583913b4, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:21.555 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a02/10.90.46.209:11211, #Rops=3, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@6695fdb1, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure. 2012-02-23 13:55:21.713 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a03/10.90.46.210:11211, #Rops=3, #Wops=3, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@722d9c9b, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@1084bead, toWrite=9864, interested=5} . This may be due to an authentication failure. 2012-02-23 13:55:22.091 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a01/10.90.46.208:11211, #Rops=4, #Wops=17, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperati nImpl@7dc74a72, topWop=net.spy.memcached.protocol.binary.StoreOperationImpl@c18dcd9, toWrite=9688, interested=5} . This may be due to an authentication failure. 2012-02-23 13:55:23.015 INFO net.spy.memcached.MemcachedConnection: Reconnection due to exception handling a memcached operation on {QA sa=apimemcache1a04/10.90.46.211:11211, #Rops=4, #Wops=0, #iq=0, topRop=net.spy.memcached.protocol.binary.StoreOperatio Impl@a7605cb, topWop=null, toWrite=0, interested=1} . This may be due to an authentication failure.
        Show
        alex Alex Ma added a comment - Logs: https://s3.amazonaws.com/customers.couchbase.com/clearchannel/apimemcache1a01-logs.gz https://s3.amazonaws.com/customers.couchbase.com/clearchannel/apimemcache1a02-logs.gz https://s3.amazonaws.com/customers.couchbase.com/clearchannel/apimemcache1a03-logs.gz https://s3.amazonaws.com/customers.couchbase.com/clearchannel/apimemcache1a03-logs.gz https://s3.amazonaws.com/customers.couchbase.com/clearchannel/mbcollect_info1 https://s3.amazonaws.com/customers.couchbase.com/clearchannel/mbcollect_info2 https://s3.amazonaws.com/customers.couchbase.com/clearchannel/mbcollect_info3 https://s3.amazonaws.com/customers.couchbase.com/clearchannel/mbcollect_info4.out.gz
        Hide
        alex Alex Ma added a comment -

        Most of our keys are similar to the ones below. All seem to be less than 255 bytes. But since the error doesn't output the offending key, its hard to tell.

        Is this error definitely because there is a key with length > 255? Does it really reconnect when this happens? If there is high traffic, could all these reconnects cause other traffic over those connections to back up?

        2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I.
        2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.551 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I[Ljava.lang.String;@545acbad.
        2012-02-23 13:55:20.559 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ZyAcC9APYXbwMfyKDot-QF_z4PILJwA7Gfz3U0d7gtY.
        2012-02-23 13:55:20.563 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/a3DEa75_f6hvrMEvTTvvxY8fNP8uJkzPZiv8pgxIiNs.
        2012-02-23 13:55:20.575 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_mobile.app.thumbplay.com.
        2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/lcwBQO0SdTLe7QnFqFKbVm741GBn41Kvf4Uh2Y5y43Y.
        2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfeatured_mood_st.
        2012-02-23 13:55:20.686 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_224185.
        2012-02-23 13:55:20.689 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.693 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ihkQHiENsFisbc8oRssNsRdSurGOKulqHAzkaAgK6Mg.
        2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_2948934.
        2012-02-23 13:55:20.702 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat2312526_4f3c704f84ae41ff550b3d42

        Show
        alex Alex Ma added a comment - Most of our keys are similar to the ones below. All seem to be less than 255 bytes. But since the error doesn't output the offending key, its hard to tell. Is this error definitely because there is a key with length > 255? Does it really reconnect when this happens? If there is high traffic, could all these reconnects cause other traffic over those connections to back up? 2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I. 2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.551 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I[Ljava.lang.String;@545acbad. 2012-02-23 13:55:20.559 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ZyAcC9APYXbwMfyKDot-QF_z4PILJwA7Gfz3U0d7gtY. 2012-02-23 13:55:20.563 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/a3DEa75_f6hvrMEvTTvvxY8fNP8uJkzPZiv8pgxIiNs. 2012-02-23 13:55:20.575 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_mobile.app.thumbplay.com. 2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/lcwBQO0SdTLe7QnFqFKbVm741GBn41Kvf4Uh2Y5y43Y. 2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfeatured_mood_st. 2012-02-23 13:55:20.686 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_224185. 2012-02-23 13:55:20.689 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.693 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ihkQHiENsFisbc8oRssNsRdSurGOKulqHAzkaAgK6Mg. 2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_2948934. 2012-02-23 13:55:20.702 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat2312526_4f3c704f84ae41ff550b3d42
        Hide
        alex Alex Ma added a comment -

        Most of our keys are similar to the ones below. All seem to be less than 255 bytes. But since the error doesn't output the offending key, its hard to tell.

        Is this error definitely because there is a key with length > 255? Does it really reconnect when this happens? If there is high traffic, could all these reconnects cause other traffic over those connections to back up?

        2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I.
        2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.551 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I[Ljava.lang.String;@545acbad.
        2012-02-23 13:55:20.559 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ZyAcC9APYXbwMfyKDot-QF_z4PILJwA7Gfz3U0d7gtY.
        2012-02-23 13:55:20.563 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/a3DEa75_f6hvrMEvTTvvxY8fNP8uJkzPZiv8pgxIiNs.
        2012-02-23 13:55:20.575 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_mobile.app.thumbplay.com.
        2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/lcwBQO0SdTLe7QnFqFKbVm741GBn41Kvf4Uh2Y5y43Y.
        2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfeatured_mood_st.
        2012-02-23 13:55:20.686 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_224185.
        2012-02-23 13:55:20.689 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.693 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ihkQHiENsFisbc8oRssNsRdSurGOKulqHAzkaAgK6Mg.
        2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp.
        2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_2948934.
        2012-02-23 13:55:20.702 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat2312526_4f3c704f84ae41ff550b3d42

        Show
        alex Alex Ma added a comment - Most of our keys are similar to the ones below. All seem to be less than 255 bytes. But since the error doesn't output the offending key, its hard to tell. Is this error definitely because there is a key with length > 255? Does it really reconnect when this happens? If there is high traffic, could all these reconnects cause other traffic over those connections to back up? 2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I. 2012-02-23 13:55:20.550 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.551 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/HvhlxKUA55PJ14PKFmHavPSWkkSfVkYIko1ZEmj3n5I[Ljava.lang.String;@545acbad. 2012-02-23 13:55:20.559 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ZyAcC9APYXbwMfyKDot-QF_z4PILJwA7Gfz3U0d7gtY. 2012-02-23 13:55:20.563 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/a3DEa75_f6hvrMEvTTvvxY8fNP8uJkzPZiv8pgxIiNs. 2012-02-23 13:55:20.575 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_mobile.app.thumbplay.com. 2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/lcwBQO0SdTLe7QnFqFKbVm741GBn41Kvf4Uh2Y5y43Y. 2012-02-23 13:55:20.684 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfeatured_mood_st. 2012-02-23 13:55:20.686 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_224185. 2012-02-23 13:55:20.689 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.693 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat/authkeys/ihkQHiENsFisbc8oRssNsRdSurGOKulqHAzkaAgK6Mg. 2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatHostConfig_webapp. 2012-02-23 13:55:20.694 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcatfriend_hist_2948934. 2012-02-23 13:55:20.702 WARN net.spy.memcached.MemcachedConnection: Could not redistribute to another node, retrying primary node for ihr_tomcat2312526_4f3c704f84ae41ff550b3d42
        Hide
        alex Alex Ma added a comment -

        Update from Monday:

        Need steps to confirm that this is a network issue or steps to move forward with troubleshooting.

        Thanks, Alex. Here's some info below. I think this problem will be tough to reproduce because it was related to the particular load that was suddenly on the driver/membase server. Could you tell us if you believe our settings are correct? As you'll see below, we are using the spymemcached spring config and for the port that failed us, 11211, we are using the default values. What settings (aside from lowering the timeout) do you think we should tune, if any? Do we know for sure whether or not there was any failure on the server? Last time we got this same spike, 1/4 moxies failed and restarted. Its very hard at the moment to ascertain if the problem is on the server or in the driver. There needs to be better logging.

        <dependency>
        <groupId>spy</groupId>
        <artifactId>spymemcached</artifactId>
        <version>2.7</version>
        </dependency>

        #port 11211 (memcache bucket, this is the one that appears to have been failing per the logs)
        <bean id="memcachedClient" class="net.spy.memcached.spring.MemcachedClientFactoryBean">
        <property name="servers" value="$

        {memcache.servers}

        " />
        <property name="protocol" value="BINARY" />
        </bean>
        #port 11212 (this is a persistent, membase bucket, but appears to have been working)
        <bean id="userSessionMemcachedClient" class="net.spy.memcached.spring.MemcachedClientFactoryBean">
        <property name="servers" value="$

        {membase.usersessions.servers}

        " />
        <property name="protocol" value="BINARY" />
        <property name="transcoder">
        <bean class="net.spy.memcached.transcoders.SerializingTranscoder">
        <property name="compressionThreshold" value="4096" />
        </bean>
        </property>
        <property name="opTimeout" value="-1" />
        <property name="timeoutExceptionThreshold" value="998" />
        <property name="hashAlg" value="NATIVE_HASH" />
        <property name="locatorType" value="ARRAY_MOD" />
        <property name="failureMode" value="Redistribute" />
        <property name="useNagleAlgorithm" value="false" />
        </bean>

        #Stack Trace – Most of our issues during the outage had almost identical stacks, just trying to get different keys.
        2012-02-23 13:55:13,542 ERROR: com.ccrd.utils.cache.FrontendCache.getNoSanitize(166): Could not get value from cache! [featured_mood_st]
        net.spy.memcached.OperationTimeoutException: Timeout waiting for value
        at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1142)
        at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1157)
        at com.ccrd.utils.cache.FrontendCache.getNoSanitize(FrontendCache.java:160)
        at com.ccrd.facade.catalog.CatalogFacade.getFeaturedMoodStations(CatalogFacade.java:404)
        at sun.reflect.GeneratedMethodAccessor585.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
        at com.ccrd.rest.web.interceptor.PerformanceMonitorInterceptor.invoke(PerformanceMonitorInterceptor.java:41)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy120.getFeaturedMoodStations(Unknown Source)
        at com.ccrd.rest.service.catalog.CatalogService.getFeaturedMoodStations(CatalogService.java:1337)
        at sun.reflect.GeneratedMethodAccessor584.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
        at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:255)
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:220)
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:209)
        at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:519)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119)
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:304)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:164)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929)

        Caused by: net.spy.memcached.internal.CheckedOperationTimeoutException: Timed out waiting for operation - failing node: apimemcache1a01/10.90.46.208:11211
        at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:65)
        at net.spy.memcached.internal.GetFuture.get(GetFuture.java:37)
        at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1135)
        ... 45 more

        Show
        alex Alex Ma added a comment - Update from Monday: Need steps to confirm that this is a network issue or steps to move forward with troubleshooting. Thanks, Alex. Here's some info below. I think this problem will be tough to reproduce because it was related to the particular load that was suddenly on the driver/membase server. Could you tell us if you believe our settings are correct? As you'll see below, we are using the spymemcached spring config and for the port that failed us, 11211, we are using the default values. What settings (aside from lowering the timeout) do you think we should tune, if any? Do we know for sure whether or not there was any failure on the server? Last time we got this same spike, 1/4 moxies failed and restarted. Its very hard at the moment to ascertain if the problem is on the server or in the driver. There needs to be better logging. <dependency> <groupId>spy</groupId> <artifactId>spymemcached</artifactId> <version>2.7</version> </dependency> #port 11211 (memcache bucket, this is the one that appears to have been failing per the logs) <bean id="memcachedClient" class="net.spy.memcached.spring.MemcachedClientFactoryBean"> <property name="servers" value="$ {memcache.servers} " /> <property name="protocol" value="BINARY" /> </bean> #port 11212 (this is a persistent, membase bucket, but appears to have been working) <bean id="userSessionMemcachedClient" class="net.spy.memcached.spring.MemcachedClientFactoryBean"> <property name="servers" value="$ {membase.usersessions.servers} " /> <property name="protocol" value="BINARY" /> <property name="transcoder"> <bean class="net.spy.memcached.transcoders.SerializingTranscoder"> <property name="compressionThreshold" value="4096" /> </bean> </property> <property name="opTimeout" value="-1" /> <property name="timeoutExceptionThreshold" value="998" /> <property name="hashAlg" value="NATIVE_HASH" /> <property name="locatorType" value="ARRAY_MOD" /> <property name="failureMode" value="Redistribute" /> <property name="useNagleAlgorithm" value="false" /> </bean> #Stack Trace – Most of our issues during the outage had almost identical stacks, just trying to get different keys. 2012-02-23 13:55:13,542 ERROR: com.ccrd.utils.cache.FrontendCache.getNoSanitize(166): Could not get value from cache! [featured_mood_st] net.spy.memcached.OperationTimeoutException: Timeout waiting for value at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1142) at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1157) at com.ccrd.utils.cache.FrontendCache.getNoSanitize(FrontendCache.java:160) at com.ccrd.facade.catalog.CatalogFacade.getFeaturedMoodStations(CatalogFacade.java:404) at sun.reflect.GeneratedMethodAccessor585.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at com.ccrd.rest.web.interceptor.PerformanceMonitorInterceptor.invoke(PerformanceMonitorInterceptor.java:41) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) at $Proxy120.getFeaturedMoodStations(Unknown Source) at com.ccrd.rest.service.catalog.CatalogService.getFeaturedMoodStations(CatalogService.java:1337) at sun.reflect.GeneratedMethodAccessor584.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140) at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:255) at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:220) at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:209) at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:519) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) at javax.servlet.http.HttpServlet.service(HttpServlet.java:722) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:304) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:164) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:100) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929) Caused by: net.spy.memcached.internal.CheckedOperationTimeoutException: Timed out waiting for operation - failing node: apimemcache1a01/10.90.46.208:11211 at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:65) at net.spy.memcached.internal.GetFuture.get(GetFuture.java:37) at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1135) ... 45 more
        Hide
        daschl Michael Nitschinger added a comment -

        Is this good to close?

        Show
        daschl Michael Nitschinger added a comment - Is this good to close?
        Hide
        akurtzman Amy Kurtzman added a comment -

        Does this really affect the documentation? If not, please take if off the component list. Thanks.

        Show
        akurtzman Amy Kurtzman added a comment - Does this really affect the documentation? If not, please take if off the component list. Thanks.

          People

          • Assignee:
            alex Alex Ma
            Reporter:
            alex Alex Ma
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:

              Gerrit Reviews

              There are no open Gerrit changes