UnsupportedOperationException: SASL is not supported for ASCII protocol

[ecmendenhall]

Cheers to everyone at Clojurewerkz! Developing a web app with Monger and Spyglass was an absolute joy, and I'm glad you're out there abstracting ConnectionFactoryBuilders for people like me.

I'm still running into an SASL error connecting a Heroku app to a remote Memcached server. The client still seems to be using the ASCII protocol, even when I use clojurewerkz.spyglass.client/bin-connection. I saw that there was an authentication fix in the latest beta, so I grabbed the new code and replaced bin-connection and all its dependencies in my project, but it throws the same exception: java.lang.UnsupportedOperationException: SASL is not supported for ASCII protocol.

I solved this issue by using the example in this blog post to set up my client and pass it to spyglass, but I'm not a Java dev and have no idea what I'm doing when I have to deal with interop stuff.

Here's my code:

(ns partial-applications.memcachehacks
  (:import [net.spy.memcached.auth AuthDescriptor PlainCallbackHandler]
            net.spy.memcached.transcoders.Transcoder
            net.spy.memcached.transcoders.SerializingTranscoder
           [net.spy.memcached MemcachedClient 
                              ConnectionFactory 
                              BinaryConnectionFactory
                              ConnectionFactoryBuilder
                              ConnectionFactoryBuilder$Protocol
                              FailureMode
                              AddrUtil]
           [java.io ByteArrayOutputStream ByteArrayInputStream File]
           [java.net InetSocketAddress]))

(defn- servers
  [^String server-list]
  (AddrUtil/getAddresses server-list))

(defprotocol AsFailureMode
  (^FailureMode to-failure-mode [input]))

(extend-protocol AsFailureMode
  FailureMode
  (to-failure-mode [input]
    input)

  String
  (to-failure-mode [input]
    (case input
      "redistribute" FailureMode/Redistribute
      "retry"        FailureMode/Retry
      "cancel"       FailureMode/Cancel))

  clojure.lang.Named
  (to-failure-mode [input]
    (to-failure-mode (name input))))

(defn- ^ConnectionFactory customize-factory
  [^ConnectionFactory cf {:keys [failure-mode transcoder auth-descriptor]}]
  (let [;; Houston, we have a *FactoryFactory here!
        cfb (ConnectionFactoryBuilder. cf)]
    (when failure-mode
      (.setFailureMode cfb (to-failure-mode failure-mode)))
    (when transcoder
      (.setTranscoder cfb transcoder))
    (when auth-descriptor
      (.setAuthDescriptor cfb auth-descriptor))
    (.build cfb)))

(defn ^ConnectionFactory bin-connection-factory
  [& {:as opts}]
  (customize-factory (BinaryConnectionFactory.) opts))

(defn bin-connection
  "Returns a new binary protocol client that will use the provided list of servers."
  ([^String server-list]
     (MemcachedClient. (BinaryConnectionFactory.) (servers server-list)))
  ([^String server-list ^BinaryConnectionFactory cf]
     (MemcachedClient. cf (servers server-list)))
  ([^String server-list ^String username ^String password]
     (let [ad (AuthDescriptor/typical username password)]
       (MemcachedClient. (bin-connection-factory :auth-descriptor ad) (servers server-list)))))

(defn connect [server user pw]
  (let [auth (AuthDescriptor/typical user pw)
        tmc-client (bin-connection server
                                   (bin-connection-factory
                                     :failure-mode :redistribute 
                                     :auth-descriptor auth))]
    tmc-client))

And here's the whole error (server address redacted):

2013-02-15 21:35:13.297 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=MEMCACHE_SERVER:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2013-02-15 21:35:13.373 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@5777b4d3
Exception in thread "Thread-5" java.lang.UnsupportedOperationException: SASL is not supported for ASCII protocol
    at net.spy.memcached.protocol.ascii.AsciiOperationFactory.saslAuth(AsciiOperationFactory.java:172)
    at net.spy.memcached.auth.AuthThread.buildOperation(AuthThread.java:117)
    at net.spy.memcached.auth.AuthThread.run(AuthThread.java:86)
2013-02-15 21:35:13.457:INFO:oejs.Server:jetty-7.6.1.v20120215
Started server on port 3000
2013-02-15 21:35:13.497:INFO:oejs.AbstractConnector:Started SelectChannelConnector@0.0.0.0:3000
Exception: net.spy.memcached.OperationTimeoutException: Timeout waiting for value
                     MemcachedClient.java:1009 net.spy.memcached.MemcachedClient.get
                     MemcachedClient.java:1024 net.spy.memcached.MemcachedClient.get
                                client.clj:105 clojurewerkz.spyglass.client/get
                               database.clj:20 partial-applications.database/cached-get
                                handler.clj:22 partial-applications.handler/get-strategy
                                handler.clj:37 partial-applications.handler/main-handler
                               response.clj:27 compojure.response/eval1073[fn]
                               response.clj:10 compojure.response/eval1034[fn]
                                   core.clj:93 compojure.core/make-route[fn]
                                   core.clj:39 compojure.core/if-route[fn]
                                   core.clj:24 compojure.core/if-method[fn]
                                  core.clj:106 compojure.core/routing[fn]
                                 core.clj:2390 clojure.core/some
                                  core.clj:106 compojure.core/routing
                               RestFn.java:139 clojure.lang.RestFn.applyTo
                                  core.clj:603 clojure.core/apply
                                  core.clj:111 compojure.core/routes[fn]
                         keyword_params.clj:27 ring.middleware.keyword-params/wrap-keyword-params[fn]
                          nested_params.clj:65 ring.middleware.nested-params/wrap-nested-params[fn]
                                 params.clj:55 ring.middleware.params/wrap-params[fn]
                      multipart_params.clj:103 ring.middleware.multipart-params/wrap-multipart-params[fn]
                                  flash.clj:14 ring.middleware.flash/wrap-flash[fn]
                                session.clj:43 ring.middleware.session/wrap-session[fn]
                               cookies.clj:160 ring.middleware.cookies/wrap-cookies[fn]
                                  Var.java:415 clojure.lang.Var.invoke
                                 reload.clj:18 ring.middleware.reload/wrap-reload[fn]
                             stacktrace.clj:15 ring.middleware.stacktrace/wrap-stacktrace-log[fn]
                             stacktrace.clj:79 ring.middleware.stacktrace/wrap-stacktrace-web[fn]
                                  jetty.clj:18 ring.adapter.jetty/proxy-handler[fn]
                              (Unknown Source) ring.adapter.jetty.proxy$org.eclipse.jetty.server.handler.AbstractHandler$0.handle
                       HandlerWrapper.java:111 org.eclipse.jetty.server.handler.HandlerWrapper.handle
                               Server.java:349 org.eclipse.jetty.server.Server.handle
               AbstractHttpConnection.java:452 org.eclipse.jetty.server.AbstractHttpConnection.handleRequest
               AbstractHttpConnection.java:884 org.eclipse.jetty.server.AbstractHttpConnection.headerComplete
               AbstractHttpConnection.java:938 org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete
                           HttpParser.java:634 org.eclipse.jetty.http.HttpParser.parseNext
                           HttpParser.java:230 org.eclipse.jetty.http.HttpParser.parseAvailable
                   AsyncHttpConnection.java:76 org.eclipse.jetty.server.AsyncHttpConnection.handle
                SelectChannelEndPoint.java:609 org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle
                 SelectChannelEndPoint.java:45 org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run
                     QueuedThreadPool.java:599 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob
                     QueuedThreadPool.java:534 org.eclipse.jetty.util.thread.QueuedThreadPool$3.run
                               Thread.java:680 java.lang.Thread.run
Caused by: net.spy.memcached.internal.CheckedOperationTimeoutException: Timed out waiting for operation - failing node: MEMCACHE_SERVER:11211
                      OperationFuture.java:159 net.spy.memcached.internal.OperationFuture.get
                             GetFuture.java:62 net.spy.memcached.internal.GetFuture.get
                     MemcachedClient.java:1003 net.spy.memcached.MemcachedClient.get

[michaelklishin]

SASL is only supported by Memcached's binary protocol:

In order to enable SASL support in the server you must use the -S flag.

The -S flag does a few things things:

Enable all of the SASL commands.
Require binary protocol only.
Require authentication to have been successful before commands may be issued on a connection.

There is no way to add SASL into text protocol in a backwards-compatible way.

[ecmendenhall]

I don't have access to the server. I'm just connecting to it with a username and password, using client/bin-connection. Is that not the binary protocol?

[michaelklishin]

It should use binary protocol. I can't immediately say what may cause text protocol to be used, Spyglass uses Spymemcached's binary connection factory which should set everything up for us.

[michaelklishin]

I have a theory about what may be going but don't have a SASL-enabled memcached instance to test against. Can you email me credentials I can use? It will only be necessary for a couple of days.

[michaelklishin]

Please try 1.1.0-SNAPSHOT, if my hypothesis is correct, bin-connection should be using the binary protocol now.

[ecmendenhall]

I'll check it out. Just sent you an email if you want to test it yourself.

[michaelklishin]

Looks like this particular exception is gone but I cannot yet get the test suite to pass using binary protocol with SASL.

[michaelklishin]

Debugging a local copy of Memcached built with SASL and plain text password DB support suggests binary connections now work fine, however, authentication still fails.

[janus]

Got the below, is I call select all after delete a id

2013-08-14 23:54:05.257 WARN net.spy.memcached.transcoders.SerializingTranscoder: Caught CNFE decoding 2768 bytes of data
java.lang.ClassNotFoundException: app.controllers.continent$delete$fn__5568
at java.net.URLClassLoader$1.run(URLClassLoader.java:202)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:190)
at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:247)
at java.io.ObjectInputStream.resolveClass(ObjectInputStream.java:603)
at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1574)
at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1495)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1731)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.readArray(ObjectInputStream.java:1666)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1322)
at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1946)
at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1870)
at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350)
at net.spy.memcached.transcoders.BaseSerializingTranscoder.deserialize(BaseSerializingTranscoder.java:129)
at net.spy.memcached.transcoders.SerializingTranscoder.decode(SerializingTranscoder.java:88)
at net.spy.memcached.transcoders.TranscodeService$1.call(TranscodeService.java:63)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at net.spy.memcached.transcoders.TranscodeService$Task.run(TranscodeService.java:110)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)

[michaelklishin]

@janus

java.lang.ClassNotFoundException: app.controllers.continent$delete$fn__5568

has nothing to do with Spyglass or Memcached. Also, if you have an issue, file a new one or ask on the mailing list instead of leaving comments to existing ones.

[kendagriff]

Was this ever resolved? I'm getting:

       2015-04-10 22:20:34.664 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@9ee1b7
       2015-04-10 22:20:34.666 ERROR net.spy.memcached.protocol.binary.NoopOperationImpl:  Error:  Auth failure.
       2015-04-10 22:20:34.666 WARN net.spy.memcached.protocol.binary.BinaryMemcachedNodeImpl:  Discarding partially completed op: Cmd: 10 Opaque: 31
       2015-04-10 22:20:34.666 INFO net.spy.memcached.MemcachedConnection:  Reconnection due to exception handling a memcached operation on {QA sa=pub-memcache-18892.us-east-1-3.4.ec2.garantiadata.com/54.87.212.91:18892, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=8}. This may be due to an authentication failure.
       OperationException: SERVER: Auth failure.
        at net.spy.memcached.protocol.BaseOperationImpl.handleError(BaseOperationImpl.java:164)
        at net.spy.memcached.protocol.binary.OperationImpl.finishedPayload(OperationImpl.java:176)
        at net.spy.memcached.protocol.binary.OperationImpl.readFromBuffer(OperationImpl.java:162)
        at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:521)
        at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:414)
        at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:247)
        at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:894)

... on Heroku using Memcached Cloud.

[michaelklishin]

@kendagriff not to my knowledge. In addition we found out that older SpyMemcached versions don't have this issue. Testing Memcached with authentication locally has been a major pain for us. Feel free to investigate it.