WARNING: An exception occurred when trying to ping session

[Billy Bacon]

Hi Martin!

Since upgrading to msm 1.5.1, I continue to see the exception logged
to both Tomcat catalina.out files on each request. It doesn't seem
fatal, especially because the logging level is WARNING but it really
muddy's up the log files and it does happen consistently so I feel
there's something wrong. Keep in mind, I remain logged in to the
webapp and the user experience is unaffected (session is preserved
between tomcat 1 and tomcat 2).

We are in an Beanstalk EC2 environment running JDK 1.6 and Tomcat 7.
Here is our msm configuration in the war files META-INF/context.xml
file.

Please let me know what you think I may have configured incorrectly!
The only thing that has changed is now we are deploying to Tomcat 7
rather than Tomcat 6. And I have the proper jar files in each
$CATALINA_HOME/lib for Tomcat 7.

<Manager
className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
sticky="false"

memcachedNodes="n1:domU-12-31-39-05-25-19.compute-1.internal:11211
n2:domU-12-31-39-16-F4-A3.compute-1.internal:11211"
requestUriIgnorePattern=".*\.(png|gif|jpg|css|js|ico)
$"
sessionBackupAsync="false" sessionBackupTimeout="100"

transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory"/
>


The exception we see in our logs on every request:

Oct 15, 2011 2:51:36 PM de.javakaffee.web.msm.LockingStrategy
$OnAfterBackupSessionTask pingSessionBackup
WARNING: An exception occurred when trying to ping session
CEF0E061154D9B2E53C9302FEE874652-n1
java.util.concurrent.ExecutionException: java.lang.RuntimeException:
Cancelled
at
net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:
75)
at de.javakaffee.web.msm.LockingStrategy
$OnAfterBackupSessionTask.pingSessionBackup(LockingStrategy.java:533)
at de.javakaffee.web.msm.LockingStrategy
$OnAfterBackupSessionTask.call(LockingStrategy.java:489)
at de.javakaffee.web.msm.LockingStrategy
$OnAfterBackupSessionTask.call(LockingStrategy.java:443)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
1110)
at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
Caused by: java.lang.RuntimeException: Cancelled
... 9 more

[Martin Grotzke]

Hi Billy,

the configuration looks ok. Perhaps it's just coincidence that you're now seeing those exceptions, not being caused by the msm 1.5.1 or tomcat7 upgrade.

Searching for the exception took me to http://code.google.com/p/spymemcached/issues/detail?id=136 and http://code.google.com/p/spymemcached/issues/detail?id=108, perhaps this is a good start for an analysis.

Questions I'd try to answer:
- does it happen always or does it start at some time, does it stop sometimes?
- does it only happen under load?
- (how) can it be reproduced in a test environment
- how is CPU load when this is happening
- is there gc activity at the same time?
- when it happens, how long does it take when you perform an equivalent "add" operation manually?

Cheers,
Martin

[Billy Bacon]

Hi Martin,

The good news is that I'm no longer seeing the exception I reported earlier. The bad news is that I don't know why :-) It disappeared on its own. I've had to rebuild the EC2 instances several times over the weekend for testing purposes so this might have had something to do with the issue resolving itself.

One item I should note is that I did discover that 1 of the memcache servers was not running. The host was up but the memcached process had been killed for some time. I'm not sure how this happened but this may have had something to do with the issue. I discovered that the memcache server was down due to this exception I was seeing in my Tomcat logs:

2011-10-17 08:54:34.193 INFO net.spy.memcached.MemcachedConnection:  Reconnecting due to failure to connect to {QA sa=domU-12-31-39-16-F4-A3.compute-1.internal/10.96.247.81:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}

java.net.ConnectException: Connection refused

at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)

at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:592)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:322)

at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:219)

at net.spy.memcached.MemcachedClient.run(MemcachedClient.java:1591)

2011-10-17 08:54:34.193 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=domU-12-31-39-16-F4-A3.compute-1.internal/10.96.247.

After logging in to that machine and starting the memcached process back up, this exception (Connection refused) has been resolved.

To answer some of your questions below (by the way, thank you for researching the issue). The exception was happening all the time, on each request. No load whatsoever on the machines, I was the only one testing/hitting the application. Not sure about the garbage collection activity.

So for now I think all is well and we don't have to look into this further. I'll let you know if it crops back up for some reason.

Thanks Martin!

- Billy -

[Martin Grotzke]

Hi Billy,

when the memcached server was down and there were also those
ConnectExceptions ("Connection refused") the WARNING makes sense,
there's a good reason for it.

Cheers,
Martin

>>> <mailto:billy...@gmail.com>>:

>>> Hi Martin!
>>>
>>> Since upgrading to msm 1.5.1, I continue to see the exception logged
>>> to both Tomcat catalina.out files on each request. It doesn't seem
>>> fatal, especially because the logging level is WARNING but it really
>>> muddy's up the log files and it does happen consistently so I feel
>>> there's something wrong. Keep in mind, I remain logged in to the
>>> webapp and the user experience is unaffected (session is preserved
>>> between tomcat 1 and tomcat 2).
>>>
>>> We are in an Beanstalk EC2 environment running JDK 1.6 and Tomcat 7.
>>> Here is our msm configuration in the war files META-INF/context.xml
>>> file.
>>>
>>> Please let me know what you think I may have configured incorrectly!
>>> The only thing that has changed is now we are deploying to Tomcat 7
>>> rather than Tomcat 6. And I have the proper jar files in each
>>> $CATALINA_HOME/lib for Tomcat 7.
>>>
>>> <Manager
>>> className="de.javakaffee.web.msm.MemcachedBackupSessionManager

>>> <http://web.msm.MemcachedBackupSessionManager>"

>>> sticky="false"
>>>
>>> memcachedNodes="n1:domU-12-31-39-05-25-19.compute-1.internal:11211
>>> n2:domU-12-31-39-16-F4-A3.compute-1.internal:11211"
>>> requestUriIgnorePattern=".*\.(png|gif|jpg|css|js|ico)
>>> $"
>>> sessionBackupAsync="false" sessionBackupTimeout="100"
>>>
>>> transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory

>>> <http://web.msm.serializer.kryo.KryoTranscoderFactory>"/

>>> >
>>>
>>>
>>> The exception we see in our logs on every request:
>>>
>>> Oct 15, 2011 2:51:36 PM de.javakaffee.web.msm.LockingStrategy

>>> <http://web.msm.LockingStrategy>

>>> $OnAfterBackupSessionTask pingSessionBackup
>>> WARNING: An exception occurred when trying to ping session
>>> CEF0E061154D9B2E53C9302FEE874652-n1
>>> java.util.concurrent.ExecutionException: java.lang.RuntimeException:
>>> Cancelled
>>> at
>>> net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:
>>> 75)
>>> at de.javakaffee.web.msm.LockingStrategy

>>> <http://web.msm.LockingStrategy>
>>> $OnAfterBackupSessionTask.pingSessionBackup(LockingStrategy.java:533)
>>> at de.javakaffee.web.msm.LockingStrategy
>>> <http://web.msm.LockingStrategy>
>>> $OnAfterBackupSessionTask.call(LockingStrategy.java:489)
>>> at de.javakaffee.web.msm.LockingStrategy
>>> <http://web.msm.LockingStrategy>

[Billy Bacon]

Excellent, thanks Martin, I like when things make sense!