Figured this out, it is indeed a bug in CouchDB's cookie processing: https://issues.apache.org/jira/browse/COUCHDB-1607 Basically, if the cookie handler happens to generate a cookie signature that starts with any colon(s) it will be rejected when the client sends it back. This explains the random/sporadic nature of the bug.
hth, -nvw On Nov 17, 2012, at 1:13 PM, Nathan Vander Wilt wrote: > Got curious, so I retested with two changes: > - using a local build of CouchDB 1.2.0 (as I remembered Iris Couch has some > additional auth handlers active) > - check if the cookie is accepted later on, after the initial failed request > — to see if the issue is temporary > > Result? > Still experiencing the same problem. > > So I'm leaning more to suspect an occasional problem with cookie > *generation*, than to intermittent failures of _users look up or timestamp > checking — otherwise I would expect proffering the cookie a second time, > while it still had half a minute left, might have worked. > > My test script here, requires node, `npm install fermata` and appropriate > user/password setup: https://gist.github.com/4100307 > I recommend letting it run simultaneously in a whole bunch of terminal tabs > to get a result quicker — sometimes it continues happily for even an hour or > so but it seems eventually the problem strikes every tab's session. Log below > from the first failure I got with the revised test. > > hth, > -natevw > > > ``` > /my/shell$ DB_SERVER=http://localhost:5984 node backend/session_test.js > Logged in. AuthSession=YWxpY2U6NTBBN0Y4Njg6Amsau3CBhrOxcl8NPRW1LsUdBqs > > Sending cookie: AuthSession=YWxpY2U6NTBBN0Y4Njg6Amsau3CBhrOxcl8NPRW1LsUdBqs > at 2012-11-17T20:50:14.194Z > Recv'd cookie: AuthSession=YWxpY2U6NTBBN0Y4ODY629p85Iq4vUndBunYBQGyszCgAXI > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"cookie"}} > > > Sending cookie: AuthSession=YWxpY2U6NTBBN0Y4ODY629p85Iq4vUndBunYBQGyszCgAXI > at 2012-11-17T20:50:44.193Z > Recv'd cookie: AuthSession=YWxpY2U6NTBBN0Y4QTQ6HBAugsm_iCPtwKXgwZFDaw1Lz6g > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"cookie"}} > > # …snip… > > Sending cookie: AuthSession=YWxpY2U6NTBBN0Y5QjI6WYCCehzuxW7gGFFFGxAv4QsLiZ4 > at 2012-11-17T20:55:44.192Z > Recv'd cookie: AuthSession=YWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"cookie"}} > > > Sending cookie: AuthSession=YWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU > at 2012-11-17T20:56:14.192Z > {"ok":true,"userCtx":{"name":null,"roles":["_admin"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"default"}} > > > Sending cookie: AuthSession=YWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU > at 2012-11-17T20:56:44.192Z > {"ok":true,"userCtx":{"name":null,"roles":["_admin"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"default"}} > > > > /Users/natevw/Desktop/Clients/Inquirium/readi-sensemaker-prototype/backend/session_test.js:34 > if (brokt) throw "Previous request logged out!"; > ^ > Previous request logged out! > ``` > > > > > > > On Nov 17, 2012, at 11:41 AM, Nathan Vander Wilt wrote: > >> I'm trying to diagnose an issue we're having with users getting unexpectedly >> logged out of an app. This is affecting real-world use, interrupting work >> when our heartbeat check unexpectedly detects the API is unusable. >> >> I've reduced this to a test script I can run. The setup is as follows: >> - set _config/couch_httpd_auth/timeout to 90 >> - run a script that logs in, then refreshes the AuthSession cookie every 30 >> seconds via /_session >> >> What happens is shown below. After just a few or perhaps a whole lot of >> correct responses to the _session request, all of a sudden the user appears >> to be logged out! >> >> ``` >> Logged in. AuthSession=YWxpY2U6NTBBN0RBMjE6zpoSjz9lYJJ1tse3bpTvuS7H84Q >> >> Sending cookie: AuthSession=YWxpY2U6NTBBN0RBMjE6zpoSjz9lYJJ1tse3bpTvuS7H84Q >> at 2012-11-17T18:41:09.250Z >> Recv'd cookie: AuthSession=YWxpY2U6NTBBN0RBM0Y6SqE-uad8GVVtE5nwLk5Woh6pW0U >> {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"cookie"}} >> >> // seemingly random duration passes, script often continues logging every 30 >> seconds for a while… >> >> Sending cookie: AuthSession=YWxpY2U6NTBBN0RDQjU66jE52YKejdDLVZZ_N5oPL74Gsl0 >> at 2012-11-17T18:52:09.250Z >> Recv'd cookie: AuthSession=YWxpY2U6NTBBN0RDRDM6Ogig0a9RpBMdZ4hHjHuet2KKurI >> {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"],"authenticated":"cookie"}} >> >> >> Sending cookie: AuthSession=YWxpY2U6NTBBN0RDRDM6Ogig0a9RpBMdZ4hHjHuet2KKurI >> at 2012-11-17T18:52:39.250Z >> {"ok":true,"userCtx":{"name":null,"roles":[]},"info":{"authentication_db":"_users","authentication_handlers":["oauth","cookie","default"]}} >> >> >> >> /Users/natevw/Desktop/Clients/Inquirium/readi-sensemaker-prototype/backend/session_test.js:33 >> if (!~d.data.indexOf('alice')) throw "Logged out!"; >> ^ >> Logged out! >> ``` >> >> The last cookie sent still has signed session data "alice:50A7DCD3" >> (2012-11-17T18:52:03Z timestamp on server) which should still be valid for >> about another minute at the time of request. But there is no "authenticated" >> field and "userCtx.name" turns up `null`! Why would this be? >> >> >> To add to the intrigue, I just received a report of some (at first glance >> unrelated) initial login trouble. Inspecting the logs, I found this: >> >> GET /_users/org.couchdb.user%3Abob 404 >> GET /_users/org.couchdb.user%3Abob 404 >> // … time passes, with no intervening PUT/POST requests to the _users DB >> GET /_users/org.couchdb.user%3Abob 200 >> >> This document would have been accessed using cookie credentials for user >> `bob`...again we see an intermittent issue with either looking up a user or >> retaining a logged in state. (In this case the cookie would have been only a >> few millseconds old.) >> >> >> I strongly suspect this is a bug somewhere within CouchDB's the cookie >> handling path, or user lookup path — but what and where in the code could be >> going wrong? Testing so far has been against 1.2.0 as deployed on Iris Couch. >> >> thanks, >> -natevw >
