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
758 stars 348 forks source link

Couchbase 5.0.0: ERROR net.spy.memcached.protocol.binary.GetOperationImpl: Error: Auth failure #372

Open pietervogelaar opened 6 years ago

pietervogelaar commented 6 years ago

I have a setup with two client side moxi processes. One on port 11411 and as failover on port 11511.

As MSM configuration:

<Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager" memcachedNodes="n1:localhost:11411,n2:localhost:11511" failoverNodes="n2" username="sessions" password="secret" memcachedProtocol="binary" sticky="true" sessionBackupAsync="false" storageKeyPrefix="static:couchbase,static:tomcat,static:lab,static:example" requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"></Manager>

Artifacts:

memcached-session-manager 2.1.1
memcached-session-manager-tc8 2.1.1
spymemcached 2.12.3

Moxi-server: 4.6.0

This setup worked great with Couchbase version 4.5.1. After the upgrade to Couchbase version 5.0.0 the Moxi-server process seems to authenticate successfully.

Spymemcached seems to also authenticate sucessfully: INFO net.spy.memcached.auth.AuthThread: Authenticated to localhost/127.0.0.1:11411

However, when I login to the Tomcat manager a session is created and the catalina.out says: ERROR net.spy.memcached.protocol.binary.GetOperationImpl: Error: Auth failure

05-Dec-2017 15:47:46.059 WARNING [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [34,885] milliseconds.
05-Dec-2017 15:47:46.060 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.startInternal  starts initialization... (configured nodes definition n1:localhost:11411,n2:localhost:11511, failover nodes n2)
2017-12-05 15:47:46.153 INFO net.spy.memcached.MemcachedConnection:  Setting retryQueueSize to -1
2017-12-05 15:47:46.173 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=localhost/127.0.0.1:11411, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2017-12-05 15:47:46.175 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=localhost/127.0.0.1:11511, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
05-Dec-2017 15:47:46.200 INFO [localhost-startStop-1] de.javakaffee.web.msm.RequestTrackingHostValve.<init> Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
05-Dec-2017 15:47:46.218 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.setLockingMode Setting lockingMode to null
05-Dec-2017 15:47:46.245 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.createTranscoderFactory Creating transcoder factory de.javakaffee.web.msm.JavaSerializationTranscoderFactory
05-Dec-2017 15:47:46.249 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.startInternal --------
-  finished initialization:
- sticky: true
- operation timeout: 1000
- node ids: [n1]
- failover node ids: [n2]
- storage key prefix: couchbase:tomcat:lab:example_
--------
2017-12-05 15:47:46.300 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11411
2017-12-05 15:47:46.301 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11511
05-Dec-2017 15:47:46.433 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcats/example/webapps/host-manager] has finished in [37,478] ms
05-Dec-2017 15:47:46.433 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/var/lib/tomcats/example/webapps/manager]
05-Dec-2017 15:47:47.560 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
05-Dec-2017 15:47:47.562 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.startInternal  starts initialization... (configured nodes definition n1:localhost:11411,n2:localhost:11511, failover nodes n2)
2017-12-05 15:47:47.562 INFO net.spy.memcached.MemcachedConnection:  Setting retryQueueSize to -1
2017-12-05 15:47:47.563 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=localhost/127.0.0.1:11411, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2017-12-05 15:47:47.563 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=localhost/127.0.0.1:11511, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
05-Dec-2017 15:47:47.575 INFO [localhost-startStop-1] de.javakaffee.web.msm.RequestTrackingHostValve.<init> Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
05-Dec-2017 15:47:47.576 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.setLockingMode Setting lockingMode to null
05-Dec-2017 15:47:47.576 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.createTranscoderFactory Creating transcoder factory de.javakaffee.web.msm.JavaSerializationTranscoderFactory
05-Dec-2017 15:47:47.576 INFO [localhost-startStop-1] de.javakaffee.web.msm.MemcachedSessionService.startInternal --------
-  finished initialization:
- sticky: true
- operation timeout: 1000
- node ids: [n1]
- failover node ids: [n2]
- storage key prefix: couchbase:tomcat:lab:example_
--------
05-Dec-2017 15:47:47.578 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcats/example/webapps/manager] has finished in [1,145] ms
05-Dec-2017 15:47:47.584 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8016"]
05-Dec-2017 15:47:47.669 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-9016"]
05-Dec-2017 15:47:47.670 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 38836 ms
2017-12-05 15:47:47.704 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11411
2017-12-05 15:47:47.705 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11511
2017-12-05 15:47:47.975 ERROR net.spy.memcached.protocol.binary.GetOperationImpl:  Error:  Auth failure
2017-12-05 15:47:47.976 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl:  Discarding partially completed op: Cmd: 0 Opaque: 5 Key: couchbase:tomcat:lab:example_ping-n1
2017-12-05 15:47:47.976 INFO net.spy.memcached.MemcachedConnection:  Reconnection due to exception handling a memcached operation on {QA sa=localhost/127.0.0.1:11411, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=1}. This may be due to an authentication failure.
OperationException: SERVER: Auth failure
    at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:192)
    at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:204)
    at net.spy.memcached.protocol.binary.OperationImpl.readPayloadFromBuffer(OperationImpl.java:196)
    at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:139)
    at net.spy.memcached.MemcachedConnection.readBufferAndLogMetrics(MemcachedConnection.java:872)
    at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:851)
    at net.spy.memcached.MemcachedConnection.handleReadsAndWrites(MemcachedConnection.java:732)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:697)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:450)
    at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1457)
2017-12-05 15:47:47.977 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=localhost/127.0.0.1:11411, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=1}, attempt 0.
2017-12-05 15:47:47.995 ERROR net.spy.memcached.protocol.binary.GetOperationImpl:  Error:  Auth failure
2017-12-05 15:47:47.996 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl:  Discarding partially completed op: Cmd: 0 Opaque: 6 Key: couchbase:tomcat:lab:example_ping-n2
2017-12-05 15:47:47.996 INFO net.spy.memcached.MemcachedConnection:  Reconnection due to exception handling a memcached operation on {QA sa=localhost/127.0.0.1:11511, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=1}. This may be due to an authentication failure.
OperationException: SERVER: Auth failure
    at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:192)
    at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:204)
    at net.spy.memcached.protocol.binary.OperationImpl.readPayloadFromBuffer(OperationImpl.java:196)
    at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:139)
    at net.spy.memcached.MemcachedConnection.readBufferAndLogMetrics(MemcachedConnection.java:872)
    at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:851)
    at net.spy.memcached.MemcachedConnection.handleReadsAndWrites(MemcachedConnection.java:732)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:697)
    at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:450)
    at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:1457)
2017-12-05 15:47:47.996 WARN net.spy.memcached.MemcachedConnection:  Closing, and reopening {QA sa=localhost/127.0.0.1:11511, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=1}, attempt 0.
2017-12-05 15:47:49.979 INFO net.spy.memcached.MemcachedConnection:  Reconnecting {QA sa=localhost/127.0.0.1:11411, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
2017-12-05 15:47:49.982 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11411
2017-12-05 15:47:49.998 INFO net.spy.memcached.MemcachedConnection:  Reconnecting {QA sa=localhost/127.0.0.1:11511, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}
2017-12-05 15:47:50.001 INFO net.spy.memcached.auth.AuthThread:  Authenticated to localhost/127.0.0.1:11511

How can I solve this issue?

magro commented 6 years ago

Sorry for the late response. In case this is still relevant I'd suggest to debug this issue with a simple main class just verifying the spymemcached operation.