Couchbase 5.0.0: ERROR net.spy.memcached.protocol.binary.GetOperationImpl: Error: Auth failure
Opened this issue · 1 comments
pietervogelaar commented
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
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.