New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
pietervogelaar opened this Issue Dec 5, 2017 · 1 comment

Comments

Projects
None yet
2 participants
@pietervogelaar

pietervogelaar commented Dec 5, 2017

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

This comment has been minimized.

Show comment
Hide comment
@magro

magro Mar 14, 2018

Owner

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.

Owner

magro commented Mar 14, 2018

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment