search

magro / memcached-session-manager

A tomcat session manager that backups sessions in memcached and pulls them from there if asked for unknown sessions
Apache License 2.0
760 stars 346 forks source link

Negative memcachedExpirationTime #387

Closed worpet closed 5 years ago

worpet commented 5 years ago

When running with Redis, Tomcat is logging exceptions like this at random times:

java.util.concurrent.ExecutionException: redis.clients.jedis.exceptions.JedisDataException: ERR invalid expire time in setex

After increasing the log level to FINE I am able to see it is trying to store to Redis with a negative value for memcachedExpirationTime. In the example below it is attempting to set -3.

28-Sep-2018 14:19:58.328 FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.MemcachedSessionService.updateExpirationInMemcached Checking session 9AE3A546ECB8A38BB316FAC901F4B23B:
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: true
- memcachedExpirationTime: -3
28-Sep-2018 14:19:58.328 FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.BackupSessionService.updateExpiration Updating expiration time for session 9AE3A546ECB8A38BB316FAC901F4B23B
28-Sep-2018 14:19:58.328 FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.BackupSessionTask.doBackupSession Trying to store session in memcached: 9AE3A546ECB8A38BB316FAC901F4B23B
28-Sep-2018 14:19:58.329 FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.storage.RedisStorageClient.set Setting key in Redis (key=a1.formsite.com_9AE3A546ECB8A38BB316FAC901F4B23B, exp=-3, o=[B)
28-Sep-2018 14:19:58.339 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.BackupSessionTask.handleException Could not store session 9AE3A546ECB8A38BB316FAC901F4B23B in memcached.
Note that this session was relocated to this node because the original node was not available.
 java.util.concurrent.ExecutionException: redis.clients.jedis.exceptions.JedisDataException: ERR invalid expire time in setex
        at java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.util.concurrent.FutureTask.get(FutureTask.java:206)
        at de.javakaffee.web.msm.BackupSessionTask.storeSessionInMemcached(BackupSessionTask.java:235)
        at de.javakaffee.web.msm.BackupSessionTask.doBackupSession(BackupSessionTask.java:198)
        at de.javakaffee.web.msm.BackupSessionService.updateExpiration(BackupSessionService.java:132)
        at de.javakaffee.web.msm.MemcachedSessionService.updateExpirationInMemcached(MemcachedSessionService.java:1615)
        at de.javakaffee.web.msm.MemcachedBackupSessionManager.backgroundProcess(MemcachedBackupSessionManager.java:578)
        at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5406)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1396)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1400)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1400)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1368)
        at java.lang.Thread.run(Thread.java:748)
Caused by: redis.clients.jedis.exceptions.JedisDataException: ERR invalid expire time in setex
        at redis.clients.jedis.Protocol.processError(Protocol.java:127)
        at redis.clients.jedis.Protocol.process(Protocol.java:161)
        at redis.clients.jedis.Protocol.read(Protocol.java:215)
        at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:340)
        at redis.clients.jedis.Connection.getStatusCodeReply(Connection.java:239)
        at redis.clients.jedis.BinaryJedis.setex(BinaryJedis.java:616)
        at de.javakaffee.web.msm.storage.RedisStorageClient$2.execute(RedisStorageClient.java:112)
        at de.javakaffee.web.msm.storage.RedisStorageClient$2.execute(RedisStorageClient.java:107)
        at de.javakaffee.web.msm.storage.RedisStorageClient$RedisCommandCallable.call(RedisStorageClient.java:180)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        ... 1 more

I am using Redis, but this may affect memcached too. memcached seems to accept negative values, but it is not clear how they should be interpreted, as discussed here: https://github.com/memcached/memcached/issues/142.

magro commented 5 years ago

Thanks for reporting, the fix is released with 2.3.1

magro commented 5 years ago

D'oh, I just checked maven central and 2.3.1 doesn't show up there - it seems something went wrong with the release. I'll publish again soon.

magro commented 5 years ago

It's now released with 2.3.2, currently on its way to maven central...