Yahoo BigTent loops after authentication

[ozten]

Steps to Reproduce

1. Go to http://beta.123done.org/
2. Open HttpFox or another tool to see HTTP requests
3. Complete log in with a yahoo.com email address

Expected:
Dialog closes and your logged in

Actual
Dialog hangs on last screen

Note HTTP requests:
A loop is present. auth_with_assertion, list_emails, session_context, and then back to auth_with_assertion.

This does not reproduce in dev nor in my local dev instance.

[ozten]

Certificate issuer looks good, matching yahoo.login.anosrep.org.

BigTent portion of the flow appears to complete successfully.

After attempted login, localStorage has

({'eozten@yahoo.com':{created:"2013-02-04T17:01:02.856Z", updated:"2013-02-04T17:01:06.773Z"}})

It is missing several fields! With a successful auth, localStorage would also have cert, priv and pub.

[ozten]

The loop is after provisioning, we loop over have_email, auth_with_assertion, and list_email again and again.

https://login.anosrep.org/wsapi/session_context
authenticated: false
csrf_token: "4AjqL0nbvAoONr8T4hfjyQ=="
data_sample_rate: 0
domain_key_creation_time: 1322071714847
has_password: false
random_seed: "4X456JnwSX/jdJ4tNgi/fuJ6i4ZDw6BXNBgPvNqw04w="
server_time: 1359680197687
{"csrf_token":"4AjqL0nbvAoONr8T4hfjyQ==","server_time":1359680197687,"authenticated":false,"has_password":false,"domain_key_creation_time":1322071714847,"random_seed":"4X456JnwSX/jdJ4tNgi/fuJ6i4ZDw6BXNBgPvNqw04w=","data_sample_rate":0}

https://login.anosrep.org/wsapi/have_email?email=eozten%40yahoo.com
email_known: true

https://login.anosrep.org/wsapi/address_info?email=eozten%40yahoo.com
{"auth":"https://yahoo.login.anosrep.org/authentication","prov":"https://yahoo.login.anosrep.org/provision","type":"primary","issuer":"yahoo.login.anosrep.org","state":"known"

https://yahoo.login.anosrep.org/provision
{"cert":"eyJhbGciOiJEUzI1NiJ9.eyJwdWJsaWMta2V5Ijp7ImFsZ29yaXRobSI6IkRTIiwieSI6IjU0ZDZlY2ZkNGYyMzBiN2U3ZGU0ZjU3ZjhhNWYzMTRkNGRlYTc1MWJhMmYyNTk4MmQ1NTBlYTQ0N2ZkMWUyYzk0M2I4YmEwZGJmYzYwN2I0NTU5Zjk5NDhhZTJlYWM4ZDZkZWYwNTBkOWY1Zjg2NzhkMWZiYzllNzc5MTI4MzA2ZDdlMjExZTk4NDE5ZmM1YmY4NTZiYTlkNmQ5M2Y5Njc0ZDQzMWM3ZDUyZWM2ZDA1YjkzNjljMzhlYTQ5ZmM1YjYwM2NiN2VkNGNjMjkxNjU3ZmQxODQ1MzIxZTQ1MDJjZjFjYzhiZDI1MWRmZWI0ZjMwOWY1MWU4MDk2M2RiMTAiLCJwIjoiZmY2MDA0ODNkYjZhYmZjNWI0NWVhYjc4NTk0YjM1MzNkNTUwZDlmMWJmMmE5OTJhN2E4ZGFhNmRjMzRmODA0NWFkNGU2ZTBjNDI5ZDMzNGVlZWFhZWZkN2UyM2Q0ODEwYmUwMGU0Y2MxNDkyY2JhMzI1YmE4MWZmMmQ1YTViMzA1YThkMTdlYjNiZjRhMDZhMzQ5ZDM5MmUwMGQzMjk3NDRhNTE3OTM4MDM0NGU4MmExOGM0NzkzMzQzOGY4OTFlMjJhZWVmODEyZDY5YzhmNzVlMzI2Y2I3MGVhMDAwYzNmNzc2ZGZkYmQ2MDQ2MzhjMmVmNzE3ZmMyNmQwMmUxNyIsInEiOiJlMjFlMDRmOTExZDFlZDc5OTEwMDhlY2FhYjNiZjc3NTk4NDMwOWMzIiwiZyI6ImM1MmE0YTBmZjNiN2U2MWZkZjE4NjdjZTg0MTM4MzY5YTYxNTRmNGFmYTkyOTY2ZTNjODI3ZTI1Y2ZhNmNmNTA4YjkwZTVkZTQxOWUxMzM3ZTA3YTJlOWUyYTNjZDVkZWE3MDRkMTc1ZjhlYmY2YWYzOTdkNjllMTEwYjk2YWZiMTdjN2EwMzI1OTMyOWU0ODI5YjBkMDNiYmM3ODk2YjE1YjRhZGU1M2UxMzA4NThjYzM0ZDk2MjY5YWE4OTA0MWY0MDkxMzZjNzI0MmEzODg5NWM5ZDViY2NhZDRmMzg5YWYxZDdhNGJkMTM5OGJkMDcyZGZmYTg5NjIzMzM5N2EifSwicHJpbmNpcGFsIjp7ImVtYWlsIjoiZW96dGVuQHlhaG9vLmNvbSJ9LCJleHAiOjEzNTk2ODA0MzkyODQsImlzcyI6InlhaG9vLmxvZ2luLmFub3NyZXAub3JnIn0.qSJrBq2IH4yoUyZOk1lQTRpfcV0NNr0iO7esX9HO2fqtGstbO5laWcdY4TYt5bLGIbB5PUNebIVj3giVpR3j5w"}

https://yahoo.login.anosrep.org/provision.js
provision({"eozten@yahoo.com":true}, 1);

https://yahoo.login.anosrep.org/provision
{"cert":"eyJhbGciOiJEUzI1NiJ9.eyJwdWJsaWMta2V5Ijp7ImFsZ29yaXRobSI6IkRTIiwieSI6Ijk0ZGYxOTBkZDQ2ZjAwYmE5OTA0ZDk2ODQ3ODk4MDc5ZGIxMDk1YTkzYTYzZmU3OTljNjFmYzEyY2M3YzAwMDk0ZTBhMDFlOGUwNTY2ZmJkMzcxNmJiNmRlY2E3Y2QyZWQ5OWU3MjRmNzllZGM3MWM4NmY5NjUwNzdjZWRkYmNlZTllNjZmZTM0NzFjZWM2YWViY2M3ZWQyZjQ2N2I2NjU3M2MyZGVlZTg3NDE4M2NmMDUxOGRhMzA3NWMzNzg0NzQ3NmNmODFjMjkzMDRkZTI4MDY4YmVhZDQ4OGRhZTFmOTUyY2QyZjcwZmJlMjhjZGMzNzIyMWE5ZGYyMzg0Y2QiLCJwIjoiZmY2MDA0ODNkYjZhYmZjNWI0NWVhYjc4NTk0YjM1MzNkNTUwZDlmMWJmMmE5OTJhN2E4ZGFhNmRjMzRmODA0NWFkNGU2ZTBjNDI5ZDMzNGVlZWFhZWZkN2UyM2Q0ODEwYmUwMGU0Y2MxNDkyY2JhMzI1YmE4MWZmMmQ1YTViMzA1YThkMTdlYjNiZjRhMDZhMzQ5ZDM5MmUwMGQzMjk3NDRhNTE3OTM4MDM0NGU4MmExOGM0NzkzMzQzOGY4OTFlMjJhZWVmODEyZDY5YzhmNzVlMzI2Y2I3MGVhMDAwYzNmNzc2ZGZkYmQ2MDQ2MzhjMmVmNzE3ZmMyNmQwMmUxNyIsInEiOiJlMjFlMDRmOTExZDFlZDc5OTEwMDhlY2FhYjNiZjc3NTk4NDMwOWMzIiwiZyI6ImM1MmE0YTBmZjNiN2U2MWZkZjE4NjdjZTg0MTM4MzY5YTYxNTRmNGFmYTkyOTY2ZTNjODI3ZTI1Y2ZhNmNmNTA4YjkwZTVkZTQxOWUxMzM3ZTA3YTJlOWUyYTNjZDVkZWE3MDRkMTc1ZjhlYmY2YWYzOTdkNjllMTEwYjk2YWZiMTdjN2EwMzI1OTMyOWU0ODI5YjBkMDNiYmM3ODk2YjE1YjRhZGU1M2UxMzA4NThjYzM0ZDk2MjY5YWE4OTA0MWY0MDkxMzZjNzI0MmEzODg5NWM5ZDViY2NhZDRmMzg5YWYxZDdhNGJkMTM5OGJkMDcyZGZmYTg5NjIzMzM5N2EifSwicHJpbmNpcGFsIjp7ImVtYWlsIjoiZW96dGVuQHlhaG9vLmNvbSJ9LCJleHAiOjEzNTk2ODA0OTg2NzIsImlzcyI6InlhaG9vLmxvZ2luLmFub3NyZXAub3JnIn0.pIs9ppYF92cDZ-XcvllOMvqq_qbCdzIpoIhoVoO9sEdPeOb6vkRmAKX0qT_uDmXdY_1NTXKzPTnJA81o6EU-lA"}

https://login.anosrep.org/wsapi/auth_with_assertion
{"success":true,"userid":10533058}

https://login.anosrep.org/wsapi/list_emails
{"success":true,"emails":["eozten@yahoo.com"]}

have_email

auth_with_assertion

list_email
...

[ozten]

The second time the dialog is launched, the user is logged in with an active session.

I wasn't seeing this earlier, when I discovered this issue.

If one clicks 'Sign in', then the infinite loop happens.

[ozten]

I think this is failing somewhere in syncEmails... still digging.

[ozten]

Hmm, a bug is that we note identities to add or delete, but not to update.

[ozten]

syncEmails doesn't look like the root cause.

What I tried to reproduce this was to create the broken state in localStorage manually, but this didn't reproduce the problem in dev or my local dev instance.

Another weird thing is that I can log in via the browserid homepage:
https://login.anosrep.org/
but not via the dialog via
http://beta.123done.org/

[jrgm]

Just by the way, stage was updated to train-2013.02.01 at 11:52, and was broken somewhat from 11:00 to then.

[jrgm]

Actually, the broken webheads would have been taken out of load-balance, so this wouldn't have been user visible during that time.

But the version has changed to train-2013.02.01.

[ozten]

Hmmm, "signing in" from the homepage isn't really a proper sign in. LocalStorage still is missing cert, priv, and pub keys. It does however let you edit your account into.

If you switch back to 123done and click sign in, then the site goes through provisioning again and gets stuck in the infinite loop.

[ozten]

I minified scripts and put my local machine into production mode, no dice.

I connected to stage with Chrome's debugger. This seems promising, but minified, most funciton names are changed.

Filed https://bugzilla.mozilla.org/show_bug.cgi?id=837925 to get stage put on to original JS sources.

[ozten]

We switched use_minified_resources to false in stage, but this won't work without having run scripts/create_templates.js. Boo.

[ozten]

Using Chrome's debugger against the minified sources, it looks like we:

• Properly write a cert and public key to local storage
• Make it to primary.verified case in provision primary user
• Catch an exception (syntax error) and later localStorage is reset to just create and updated dates (losing cert, pub, priv)

This exception could just be normal usage of jquery, Chrome debugger chokes on our current codebase a lot.

[ozten]

One of the possible exceptions being thrown is

cannot serialize an assertion in a different format than is prescribed by overlaying data structure, e.g. cert

I don't know that this is the case, it's just a possibility.

Looking at the assertion which is sent up in auth with assertion...

dev env:

{"alg":"RS256"}
"principal":
{"email":"eozten@yahoo.com"},"iat":1360004617042,"exp":1360004917042,"iss":"yahoo.personatest.org"

In stage:

{"alg":"DS256"}
"principal":{"email":"eozten@yahoo.com"},"exp":1360004545274,"iss":"yahoo.login.anosrep.org"}

Not sure why iat is missing. I'm also not sure how the alg is chosen, for the backing certificate.

[lloyd]

why is dev RSA and stage DSA? Relevant?

[ozten]

It probably isn't, I'm noting things that are different between dev and stage, which I don't know why they are different.

[ozten]

Lloyd had a good idea, spin up http://looping.123done.org/ and point stage bigtent at that. See if we can get a repro. If so, we can debug it easily.

[ozten]

Seems like the problem is in User.syncEmails - this is done async... maybe a timing issue?

Digging, looking at server times.

[ozten]

AOK cert payload= 1360094458818 serverTime= 1360094168459

cert set to expires at Tue Feb 05 2013 12:00:58 GMT-0800 (PST)

server's time is Tue Feb 05 2013 11:56:08 GMT-0800 (PST)

diff = 292,764
tolerance is up to 120,000

Boom.

[ozten]

Okay, I misdiagnosed.

Bigtent in stage doesn't provision certs with an iat field. user.js line 48 checks that and calls them expired.

I'll look at why I've got a good browserid-certifier deployment, bug stage doesn't.

[ozten]

Local dev I'm running d3bec1ea178076b107fdbd35e8630f16fd2f9b80 of browserid-certifier.
jwcrypto@0.3.1

AWS dev we're running 98a1b7fb0be14765236435025c0b7abb066abd9b
jwcrypto@0.3.1

I've asked in bug 837925 what stage's versions are.

[ozten]

To repro locally

1. Install d81cd1de83e630a03ac0cb48662374b9d0fe25f1
2. npm install (maybe blow away node_modules if npm is being flaky)
3. restart bigtent

d81cd1de83e630a03ac0cb48662374b9d0fe25f1 is from June of 2012 and uses jwcrypto@0.2.2.

We'll cut a train of browserid-certifier to fix the root cause.

I've created PR 2991 for improving logging of expired certs.

[ozten]

browserid-certifier bumped to jwcrypto@0.4.2.
Deployment requested

bigtent bumped to jwcrypto in PR 119 also, still testing locally.
We'll deploy certifier first and make sure this fixes looping without any other tweaks. bigtent jwcrypto update isn't needed to fix this bug, just a good idea.

[ozten]

With the new certifier deployed, http://looping.123done.org/ is fixed.

Hooray.

[ozten]

BigTent re-pointed at Stage.

http://beta.123done.org/ looping bug fixed.