You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@couchdb.apache.org by Nathan Vander Wilt <na...@calftrail.com> on 2012/11/17 20:41:22 UTC
Sporadic _session/_users lookup failures
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
Re: Sporadic _session/_users lookup failures
Posted by Robert Newson <rn...@apache.org>.
Nice find!
On 18 November 2012 00:55, Nathan Vander Wilt <na...@gmail.com> wrote:
> 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
> >
>
>
Re: Sporadic _session/_users lookup failures
Posted by Nathan Vander Wilt <na...@gmail.com>.
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
>
Re: Sporadic _session/_users lookup failures
Posted by Nathan Vander Wilt <na...@calftrail.com>.
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