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

Alex Ma added a comment - 24/Feb/12 3:38 PM 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.

Alex Ma added a comment - 24/Feb/12 3:38 PM 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

Alex Ma added a comment - 24/Feb/12 3:43 PM 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

Alex Ma added a comment - 24/Feb/12 3:44 PM 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

Alex Ma added a comment - 27/Feb/12 10:41 AM 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