couchdb-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Nathan Vander Wilt <nate-li...@calftrail.com>
Subject Re: Sporadic _session/_users lookup failures
Date Sat, 17 Nov 2012 21:13:21 GMT
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


Mime
View raw message