[SPY-81] spike in requests causes large amount of java exceptions and tomcat crash Created: 24/Feb/12  Updated: 03/Oct/13

Status: Open
Project: Spymemcached Java Client
Component/s: docs
Affects Version/s: None
Fix Version/s: .next
Security Level: Public

Type: Bug Priority: Major
Reporter: Alex Ma Assignee: Alex Ma
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
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.





 Comments   
Comment by Alex Ma [ 24/Feb/12 ]
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.

Comment by Alex Ma [ 24/Feb/12 ]
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
Comment by Alex Ma [ 24/Feb/12 ]
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
Comment by Alex Ma [ 24/Feb/12 ]
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
Comment by Alex Ma [ 27/Feb/12 ]
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
Comment by Michael Nitschinger [ 29/May/13 ]
Is this good to close?
Comment by Amy Kurtzman [ 03/Oct/13 ]
Does this really affect the documentation? If not, please take if off the component list. Thanks.
Generated at Wed Jul 30 08:14:33 CDT 2014 using JIRA 5.2.4#845-sha1:c9f4cc41abe72fb236945343a1f485c2c844dac9.