From dev-return-24166-apmail-couchdb-dev-archive=couchdb.apache.org@couchdb.apache.org Sun Nov 18 11:13:34 2012 Return-Path: X-Original-To: apmail-couchdb-dev-archive@www.apache.org Delivered-To: apmail-couchdb-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 13362D7AC for ; Sun, 18 Nov 2012 11:13:34 +0000 (UTC) Received: (qmail 5051 invoked by uid 500); 18 Nov 2012 11:13:33 -0000 Delivered-To: apmail-couchdb-dev-archive@couchdb.apache.org Received: (qmail 5021 invoked by uid 500); 18 Nov 2012 11:13:32 -0000 Mailing-List: contact dev-help@couchdb.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@couchdb.apache.org Delivered-To: mailing list dev@couchdb.apache.org Received: (qmail 4977 invoked by uid 99); 18 Nov 2012 11:13:31 -0000 Received: from minotaur.apache.org (HELO minotaur.apache.org) (140.211.11.9) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 18 Nov 2012 11:13:31 +0000 Received: from localhost (HELO mail-vc0-f180.google.com) (127.0.0.1) (smtp-auth username rnewson, mechanism plain) by minotaur.apache.org (qpsmtpd/0.29) with ESMTP; Sun, 18 Nov 2012 11:13:30 +0000 Received: by mail-vc0-f180.google.com with SMTP id fk26so64968vcb.11 for ; Sun, 18 Nov 2012 03:13:29 -0800 (PST) MIME-Version: 1.0 Received: by 10.220.157.68 with SMTP id a4mr14580047vcx.60.1353237209380; Sun, 18 Nov 2012 03:13:29 -0800 (PST) Received: by 10.52.69.79 with HTTP; Sun, 18 Nov 2012 03:13:29 -0800 (PST) In-Reply-To: References: <3C7358CB-B7BB-40D6-B808-1A792F80E7E9@calftrail.com> <31EA871D-38FC-4CCD-8E48-A9F423DFE403@calftrail.com> Date: Sun, 18 Nov 2012 11:13:29 +0000 Message-ID: Subject: Re: Sporadic _session/_users lookup failures From: Robert Newson To: "dev@couchdb.apache.org" Content-Type: multipart/alternative; boundary=f46d043c7ea829762f04cec31756 --f46d043c7ea829762f04cec31756 Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: quoted-printable Nice find! On 18 November 2012 00:55, Nathan Vander Wilt 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 i= t > 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 =97 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 timestam= p > checking =97 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 =97 sometimes it continues happily for even = an > hour or so but it seems eventually the problem strikes every tab's sessio= n. > Log below from the first failure I got with the revised test. > > > > hth, > > -natevw > > > > > > ``` > > /my/shell$ DB_SERVER=3Dhttp://localhost:5984 node backend/session_test.= js > > Logged in. > AuthSession=3DYWxpY2U6NTBBN0Y4Njg6Amsau3CBhrOxcl8NPRW1LsUdBqs > > > > Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0Y4Njg6Amsau3CBhrOxcl8NPRW1LsUdBqs at > 2012-11-17T20:50:14.194Z > > Recv'd cookie: > AuthSession=3DYWxpY2U6NTBBN0Y4ODY629p85Iq4vUndBunYBQGyszCgAXI > > > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info= ":{"authentication_db":"_users","authentication_handlers":["oauth","cookie"= ,"default"],"authenticated":"cookie"}} > > > > > > Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0Y4ODY629p85Iq4vUndBunYBQGyszCgAXI at > 2012-11-17T20:50:44.193Z > > Recv'd cookie: > AuthSession=3DYWxpY2U6NTBBN0Y4QTQ6HBAugsm_iCPtwKXgwZFDaw1Lz6g > > > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info= ":{"authentication_db":"_users","authentication_handlers":["oauth","cookie"= ,"default"],"authenticated":"cookie"}} > > > > # =85snip=85 > > > > Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0Y5QjI6WYCCehzuxW7gGFFFGxAv4QsLiZ4 at > 2012-11-17T20:55:44.192Z > > Recv'd cookie: > AuthSession=3DYWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU > > > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info= ":{"authentication_db":"_users","authentication_handlers":["oauth","cookie"= ,"default"],"authenticated":"cookie"}} > > > > > > Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU at > 2012-11-17T20:56:14.192Z > > > {"ok":true,"userCtx":{"name":null,"roles":["_admin"]},"info":{"authentica= tion_db":"_users","authentication_handlers":["oauth","cookie","default"],"a= uthenticated":"default"}} > > > > > > Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0Y5RDA6Ot-kqL0ATZPL8fnWZRTMyegLxjU at > 2012-11-17T20:56:44.192Z > > > {"ok":true,"userCtx":{"name":null,"roles":["_admin"]},"info":{"authentica= tion_db":"_users","authentication_handlers":["oauth","cookie","default"],"a= uthenticated":"default"}} > > > > > > > > > /Users/natevw/Desktop/Clients/Inquirium/readi-sensemaker-prototype/backen= d/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 i= s > 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 o= f > correct responses to the _session request, all of a sudden the user appea= rs > to be logged out! > >> > >> ``` > >> Logged in. > AuthSession=3DYWxpY2U6NTBBN0RBMjE6zpoSjz9lYJJ1tse3bpTvuS7H84Q > >> > >> Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0RBMjE6zpoSjz9lYJJ1tse3bpTvuS7H84Q at > 2012-11-17T18:41:09.250Z > >> Recv'd cookie: > AuthSession=3DYWxpY2U6NTBBN0RBM0Y6SqE-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=85 > >> > >> Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0RDQjU66jE52YKejdDLVZZ_N5oPL74Gsl0 at > 2012-11-17T18:52:09.250Z > >> Recv'd cookie: > AuthSession=3DYWxpY2U6NTBBN0RDRDM6Ogig0a9RpBMdZ4hHjHuet2KKurI > >> > {"ok":true,"userCtx":{"name":"alice","roles":["student","teacher"]},"info= ":{"authentication_db":"_users","authentication_handlers":["oauth","cookie"= ,"default"],"authenticated":"cookie"}} > >> > >> > >> Sending cookie: > AuthSession=3DYWxpY2U6NTBBN0RDRDM6Ogig0a9RpBMdZ4hHjHuet2KKurI 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/backen= d/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 fo= r > 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 thi= s: > >> > >> GET /_users/org.couchdb.user%3Abob 404 > >> GET /_users/org.couchdb.user%3Abob 404 > >> // =85 time passes, with no intervening PUT/POST requests to the _user= s 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 =97 but what and where in the code cou= ld > be going wrong? Testing so far has been against 1.2.0 as deployed on Iris > Couch. > >> > >> thanks, > >> -natevw > > > > --f46d043c7ea829762f04cec31756--