Multiple open id responses

Showing 1-1 of 1 messages
Multiple open id responses Chinh Tran 11/22/11 5:07 PM
Hi,

I'm running into a strange behavior with openid (+oauth ext) that I'm
wondering if anyone here has seen. We have setup the standard OpenID/
Oauth ext flow and it's working fine, except once in a while we would
see multiple open id response for the same oauth.request_token about
30 seconds to a minute apart. The parameters in the open id responses
that we get are almost identical, with the exception of openid.sig,
openid.assoc_handle and openid.response_nonce. Here's a sample
sequence (in apache access log)

[our own uri to initiate open id]
xxx.xxx.189.18 - - [21/Nov/2011:21:05:03 +0000] "GET /openid/login/
google/ HTTP/1.1" 302 20

[first openid response...with an oauth request token - internally we
are making a direct server-2-server call to exchange for access token]
xxx.xxx.189.18 - - [21/Nov/2011:21:05:06 +0000] "GET /openid/response/?
janrain_nonce=2011-11-21T21%3A05%3A03ZT8PhOw&openid.ns=http%3A%2F
%2Fspecs.openid.net%2Fauth
%2F2.0&openid.mode=id_res&openid.op_endpoint=https%3A%2F
%2Fwww.google.com%2Faccounts
%2Fo8%2Fud&openid.response_nonce=2011-11-21T21%3A05%3A06ZITzl4wDnDq2U9Q&openid.return_to=.......&openid.ext2.request_token=4%2FXXupI7jTN9jiOUueoS1WzmBWSnk5
HTTP/1.1" 302 20

[got an access token....user is now browsing our site....etc]
xxx.xxx.189.18 - - [21/Nov/2011:21:05:08 +0000] "GET / HTTP/1.1" 200
13773
xxx.xxx.189.18 - - [21/Nov/2011:21:05:10 +0000] "GET /favicon.ico HTTP/
1.1" 200 1150
xxx.xxx.189.18 - - [21/Nov/2011:21:05:28 +0000] "GET / HTTP/1.1" 200
12996
xxx.xxx.189.18 - - [21/Nov/2011:21:05:35 +0000] "GET /purchases/ HTTP/
1.1" 200 7662
xxx.xxx.189.18 - - [21/Nov/2011:21:05:38 +0000] "GET / HTTP/1.1" 200
12996
xxx.xxx.189.18 - - [21/Nov/2011:21:06:05 +0000] "GET /
fb_oauth_response/?............ HTTP/1.1" 200 86
xxx.xxx.189.18 - - [21/Nov/2011:21:06:08 +0000] "GET /social_offer/?
t=1&c=FB_SHARE_MAST_purc&c=FB_CONN_MAST_purc&c=TW_FOLLOW_MAST_purc&_=1321909568719
HTTP/1.1" 200 20
xxx.xxx.189.18 - - [21/Nov/2011:21:06:08 +0000] "GET /purchases_ajax/?
period=91&_=1321909568722 HTTP/1.1" 200 67
xxx.xxx.189.18 - - [21/Nov/2011:21:06:09 +0000] "GET /social_offer/?
t=1&c=FB_SHARE_MAST_home&c=FB_CONN_MAST_home&c=TW_FOLLOW_MAST_home&_=1321909569004
HTTP/1.1" 200 20
xxx.xxx.189.18 - - [21/Nov/2011:21:06:09 +0000] "GET /dashboard_ajax/?
want_recs=1&test=1&_=1321909569059 HTTP/1.1" 200 155

[HERE COMES THE WEIRD PART! This second openid response came with the
same request token (same value) - when we use this token to exchange
with an access token we got an error (invalid request token). It's the
same account (I removed it here but it's for the same email_address
and came from the same ip)]

xxx.xxx.189.18 - - [21/Nov/2011:21:06:13 +0000] "GET /openid/response/?
janrain_nonce=2011-11-21T21%3A05%3A03ZT8PhOw&openid.ns=http%3A%2F
%2Fspecs.openid.net%2Fauth
%2F2.0&openid.mode=id_res&openid.op_endpoint=https%3A%2F
%2Fwww.google.com%2Faccounts
%2Fo8%2Fud&openid.response_nonce=2011-11-21T21%3A06%3A12ZCdSR7D0j12bdGQ&openid.return_to=........&openid.ext2.request_token=4%2FXXupI7jTN9jiOUueoS1WzmBWSnk5
HTTP/1.1" 500 172

I'm not sure what exactly is happening here. It can't be a replay, can
it? If the user had gone back to re-authenticate, I should have seen
"GET /openid/login/google/ HTTP/1.1" 302 20. If the user somehow got
back to browsing history, the entire parameter set should have been
identical, but it's not the case, the second response has different
openid.sig, openid.assoc_handle and openid.response_nonce value (I'm
not showing in my sample data).

Thanks in advanced for any insights you may have.

Chinh