Multiple open id responses

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

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] - - [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] - - [21/Nov/2011:21:05:06 +0000] "GET /openid/response/?
HTTP/1.1" 302 20

[got an access token....user is now browsing our site....etc] - - [21/Nov/2011:21:05:08 +0000] "GET / HTTP/1.1" 200
13773 - - [21/Nov/2011:21:05:10 +0000] "GET /favicon.ico HTTP/
1.1" 200 1150 - - [21/Nov/2011:21:05:28 +0000] "GET / HTTP/1.1" 200
12996 - - [21/Nov/2011:21:05:35 +0000] "GET /purchases/ HTTP/
1.1" 200 7662 - - [21/Nov/2011:21:05:38 +0000] "GET / HTTP/1.1" 200
12996 - - [21/Nov/2011:21:06:05 +0000] "GET /
fb_oauth_response/?............ HTTP/1.1" 200 86 - - [21/Nov/2011:21:06:08 +0000] "GET /social_offer/?
HTTP/1.1" 200 20 - - [21/Nov/2011:21:06:08 +0000] "GET /purchases_ajax/?
period=91&_=1321909568722 HTTP/1.1" 200 67 - - [21/Nov/2011:21:06:09 +0000] "GET /social_offer/?
HTTP/1.1" 200 20 - - [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)] - - [21/Nov/2011:21:06:13 +0000] "GET /openid/response/?
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.