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
