Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Subscription assertion is not always in the profile claims. #2206

Closed
akatsoulas opened this issue Aug 15, 2019 · 37 comments

Comments

@akatsoulas
Copy link

commented Aug 15, 2019

During testing in SUMO we discovered that a few users, although they are subscribed to a service, they are missing the subscriptions attribute from the profile claims.
The requested scopes for all users are openid email profile. This is happening with the stage instance of FxA.

Please let me know what additional information you might need for this issue.

An example of such a user can be found here:
https://docs.google.com/document/d/1iCe3HXU2gQyUrkr84oWx6P417_Hiv9xjohcraLnlJ-k/edit?usp=sharing

@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 16, 2019

I don't have much visibility into stage, so I'm just kind of guessing at some things here:

  • What are you seeing in subscriptions when it does work?
  • Does the subscription assertion never appear in these users' profiles - or does it eventually appear? (i.e. might it be a caching issue?)
  • Is it always just the "fortress_monthly" product for which this happens? Are there other products for which the subscription assertion appears?
  • If one of these users attempts to change something like primary email or avatar image, does the subscription assertion show up then?
  • When you say "the support form is visible" - are there some users for whom the support form is not visible?

@jrgm - can we get a peek at what the config on stage looks like for the subscription stuff? In particular SUBSCRIPTIONS_PRODUCT_CAPABILITIES and SUBSCRIPTIONS_CLIENT_CAPABILITIES settings?

@akatsoulas

This comment has been minimized.

Copy link
Author

commented Aug 19, 2019

  • This is the response for my account u'subscriptions': [u'prod_FUUNYnlDso7FeB']
  • For all the users the attribute was visible after a while. For most users it took ~ 1 day. For the user referenced in the document it took almost a week.
  • So far all the testing has been performed with the fortress_monthly product.
  • IIRC this had no effect but I will retest this to verify.
  • The support form has always been visible for all the users that we tested it for.
@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 19, 2019

For all the users the attribute was visible after a while. For most users it took ~ 1 day. For the user referenced in the document it took almost a week.

Okay, but the subscription info did eventually appear? That smells like a caching issue to me, which can hopefully narrow it down.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 19, 2019

Re: caching issues, I'm fuzzy on how caching works in FxA. Wondering who might have insight here - @shane-tomlinson / @vbudhram / @philbooth?

It seems very unexpected this data would take almost a week to appear.

From what I can tell, this seems to be what other routes do when profile info is changed:

https://github.com/mozilla/fxa/blob/master/packages/fxa-auth-server/lib/routes/subscriptions.js#L163

        const devices = await request.app.devices;
        await push.notifyProfileUpdated(uid, devices);
        log.notifyAttachedServices('profileDataChanged', request, {
          uid,
          email,
        });

But... should this last call also include subscriptions?

@philbooth

This comment has been minimized.

Copy link
Member

commented Aug 19, 2019

From what I can tell, this seems to be what other routes do when profile info is changed:

...

But... should this last call also include subscriptions?

Nope, don't think it needs subscriptions. Looks like only uid is used, and even email isn't required:

var userId = getUserId(message);

@rfk

This comment has been minimized.

Copy link
Member

commented Aug 19, 2019

FYI the profile-caching logic lives in https://github.com/mozilla/fxa/blob/master/packages/fxa-profile-server/lib/profileCache.js and is called by https://github.com/mozilla/fxa/blob/master/packages/fxa-profile-server/lib/routes/profile.js.

I can't see anything obviously wrong with what you're doing though. The notifyAttachedServices should cause the cache to be flushed. You could also check whether new subscriptions are updating the profileChangedAt column on the accounts table, which we use as a kind of synchronous front-channel for communicating possible state changes to the profile-server.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 20, 2019

This is the response for my account u'subscriptions': [u'prod_FUUNYnlDso7FeB']

Oh but also, this doesn't sound right either. If we configured things as discussed, we shouldn't be exposing a product ID and this should be more like u'subscriptions': [u'Firefox Fortress']. We might still need to get a look at that config on staging (/cc @jrgm)

@vbudhram

This comment has been minimized.

Copy link
Contributor

commented Aug 20, 2019

You could also check whether new subscriptions are updating the profileChangedAt column on the accounts table

A quick look at subscription stored procedures, it doesn't seem that this happens? Something that that should invalid the cache is adding a secondary email. If you did this and you might be able to check for new subscription claims.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 20, 2019

You could also check whether new subscriptions are updating the profileChangedAt column on the accounts table
A quick look at subscription stored procedures, it doesn't seem that this happens?

Yup, I'm going to try throwing together a PR that does this. The data in the profile isn't directly changed by subscription changes, but a kind of derived property does change.

lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 20, 2019
@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 20, 2019

Not sure if #2278 is actually a fix, but we can try it!

lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 20, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 20, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 21, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 21, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 21, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 21, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Aug 22, 2019
@lmorchard

This comment has been minimized.

Copy link
Member

commented Aug 26, 2019

Circling back to this after the work-week: We merged #2278, but it probably won't be deployed to staging for a week or so (?). I haven't been able to reproduce this exact issue on my local stack or in dev. But, I talked to just about everyone who's touched these parts of fxa last week, and the consensus is that updating profileChangedAt is what seems most promising as a fix.

@clouserw

This comment has been minimized.

Copy link
Member

commented Aug 28, 2019

We should see this on stage next week around Sep 3rd/4th I'd expect (/cc @jrgm )

@clouserw

This comment has been minimized.

Copy link
Member

commented Sep 3, 2019

Bump on this -- hoping to get it on stage today/tomorrow for testing

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

I am seeing this issue on stage with the guardian_vpn product. I can help verify the fix after it's deployed.

@clouserw

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

@rlr I think it's out (according to https://bugzilla.mozilla.org/show_bug.cgi?id=1578488#c1 ). Would you try to reproduce?

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

Looks fixed to me! \o/

I subscribed, then logged in and got the subscriptions back:

{"email":..."subscriptions":["guardian_vpn"],...}
@rlr

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

I think I found a bug with the Activate now link in the Verify Your Account email though. I'll try to repro again and file an issue if so.

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

I think I found a bug with the Activate now link in the Verify Your Account email though. I'll try to repro again and file an issue if so.

NVM. I was signed into multiple accounts in different browsers. I hit the activate link from a browser signed into a different account that already had the subscription. So it just redirected me to the product download page. I guess that's kind of expected and a super edge case.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

Looks fixed to me! \o/

Okay, going to close this issue for now. Let's keep an eye on things and reopen if it proves not to have been fixed.

@akatsoulas - let us know if you see this again after this fix!

@lmorchard lmorchard closed this Sep 4, 2019

@akatsoulas

This comment has been minimized.

Copy link
Author

commented Sep 5, 2019

  • Subscription status changes are working perfectly for sumo-dev. Every time there is a change, the assertions are updated when a user logs in.
  • When a user subscribes though for the first time, the assertion is not always there. This happens randomly as it works for a few new subscribers but not all of them. The accounts that are missing the assertion, if the subscription status is updated (eg cancel and reactivate) then the assertion is updated successfully.
@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 5, 2019

This happens randomly as it works for a few new subscribers but not all of them.

Is there anything we can do to narrow down the "randomly" to what might be different about the subscribers? Also, does the assertion never show up until the status is updated via cancel / reactivate, or is it still also a thing that eventually shows up?

@bbangert

This comment has been minimized.

Copy link
Contributor

commented Sep 5, 2019

If you can make this occur for a user that you subscribed to a product, can you tell us the users email address that you know is subscribed but is not returning it? Ideally we could look into the system to see what data has propagated internally, and where it might be out of sync.

@bbangert bbangert reopened this Sep 5, 2019

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 5, 2019

Trying to troubleshoot this in staging, but hitting some roadblocks:

  • I can subscribe to both "123done Pro" and "Firefox Fortress" - these both show up fine in my subscriptions management page on payments-server
  • However, auth-server doesn't seem configured in staging to expose any subscription capabilities to 123Done. So, I can't check whether 123done in staging successfully sees a subscription. I submitted a PR for cloudops-deployment to try to fix this.
  • I can't find a deployment of Firefox Fortress in staging, so I can't verify that subscription.
  • It looks like "Firefox Fortress" is the product with the most subscribers (118?) so I assume that's what folks are testing with?
@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 6, 2019

tl;dr for my efforts today, so far: We fixed 123done in staging, but I still can't reproduce this issue. Running through a fresh signup, email verify, and subscription payment flow for 123done worked three times in a row. We'll need some more info on how to reproduce in order to have any next steps.

@bbangert

This comment has been minimized.

Copy link
Contributor

commented Sep 6, 2019

@akatsoulas We're blocked at this point without a more detailed reproduction. What pages are involved, in what order, and under what conditions?

For example, is this the flow?

  1. Go to SUMO with user not logged in.
  2. Go to a payments page to sign-up for a subscription and create new user as well
  3. Go back to SUMO and login with FxA
  4. Redirect after logging in back to SUMO
  5. SUMO does profile server query and doesn't see subscriptions in response

Or is it something different?

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 6, 2019

One more idea from Slack: Looks like the general OIDC userinfo endpoint at https://profile.accounts.firefox.com/v1/profile is heavily cached.

I thought I had a fix for that, but there still might be latency in the cache invalidation. (Not sure about this, though, still kind of guessing.)

However, there are also endpoints specifically for individual profile properties (e.g. /email, /uid, /subscriptions) - you might try hitting https://profile.accounts.firefox.com/v1/subscriptions to get a fresh query of user subscriptions. If that resolves the issue, then I think we know for sure it's a cache invalidation race condition kind of thing

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

Looks like I'm running into this issue again on stage.

Here is what shows on my subscriptions page:

rrosario+new1@mozilla.com
Subscriptions
guardian_monthly
Billing Information

You'll be billed $9.99 per month for guardian_monthly. Your next payment occurs on 10/04/2019.
Card ending 4242
Expires November 2019

This is what comes back in my profile:

{"email":"rrosario+new1@mozilla.com","locale":"en-US,en;q=0.7,de;q=0.3","amrValues":["pwd","email"],"twoFactorAuthentication":false,"uid":"77b21ee30e7742ebbe841c38f5d2ec05","avatar":"https://mozillausercontent.com/00000000000000000000000000000000","avatarDefault":true,"sub":"77b21ee30e7742ebbe841c38f5d2ec05"}

This is using client with ID = 64ef9b544a31bca8

I'll try to go through the whole flow with a new account next and see what happens.

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

It's not working for me using brand new users anymore either.

rrosario+new2@mozilla.com
Subscriptions
guardian_monthly
Billing Information

You'll be billed $9.99 per month for guardian_monthly. Your next payment occurs on 10/09/2019.
Card ending 4242
Expires November 2019
{"email":"rrosario+new2@mozilla.com","locale":"en-US,en;q=0.7,de;q=0.3","amrValues":["pwd","email"],"twoFactorAuthentication":false,"uid":"ca4fe831aaab4bc8b5814dc741211ab4","avatar":"https://mozillausercontent.com/00000000000000000000000000000000","avatarDefault":true,"sub":"ca4fe831aaab4bc8b5814dc741211ab4"}
@akatsoulas

This comment has been minimized.

Copy link
Author

commented Sep 9, 2019

Detailed steps that we took in order to reproduce this can be found here
https://docs.google.com/document/d/1J1B5-evtbY8zHkMQXQxCMdOTI_pkfUqTeOjwuGa8B4A/edit

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

FWIW, I just spent the last hour or two really trying to hammer this stuff with a bunch of new accounts https://gist.github.com/lmorchard/d31b93bc6ff99e4197b09f4c30931a53

tl;dr: I was able to reproduce the issue, but only once out of 20 tries. And when I reproduced it, neither SUMO nor 123done could see the subscription - so it's not a SUMO-specific issue.

One thing I was able to reproduce consistently is that even when 123done sees the subscription, SUMO never sees it on new user creation - only after logging out and back in

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

Further tl;dr: when I could reproduce the issue, the only thing that seemed to cause the subscription status to be seen correctly by SUMO & 123done was to cancel the subscription.

Changing display name or primary email address appeared to have no effect on subscription status - even though RPs seemed to pick up the email address change. So that makes me wonder if it's as simple as profile caching, since those changes should have invalidated the cache (and appeared to do so)

Unfortunately, cancelling the subscription basically destroyed the account state that demonstrated the reproduction of the issue. So, I'm trying a bit more to see if I can reproduce again.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

One thing I was able to reproduce consistently is that even when 123done sees the subscription, SUMO never sees it on new user creation - only after logging out and back in

Just gave it one more go and yeah - this is one thing that seems to happen consistently: It always takes a login, logout, login on the initial visit to SUMO dev in order to get the subscription to be detected.

@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

Looking at users/auth.py in kitsune. I can see the update_user method sets profile.has_subscriptions, but create_user does not.

I don't think that explains this whole issue, but I think it does explain the need to log out and back in after the initial log in to SUMO.

Also noticed that update_user doesn't seem to pick up FxA display name changes after the initial user creation, but maybe that's intentional?

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

Further tl;dr: when I could reproduce the issue, the only thing that seemed to cause the subscription status to be seen correctly by SUMO & 123done was to cancel the subscription.

FWIW, I just tested and I get this same behavior....

Before cancelling my subscription (no subscriptions in my profile):

{"email":"rrosario+new2@mozilla.com","locale":"en-US,en;q=0.7,de;q=0.3","amrValues":["pwd","email"],"twoFactorAuthentication":false,"uid":"ca4fe831aaab4bc8b5814dc741211ab4","avatar":"https://mozillausercontent.com/00000000000000000000000000000000","avatarDefault":true,"sub":"ca4fe831aaab4bc8b5814dc741211ab4"}

After cancelling the subscription (subscriptions shows up):

{"email":"rrosario+new2@mozilla.com","locale":"en-US,en;q=0.7,de;q=0.3","amrValues":["pwd","email"],"twoFactorAuthentication":false,"subscriptions":["guardian_vpn"],"uid":"ca4fe831aaab4bc8b5814dc741211ab4","avatar":"https://mozillausercontent.com/00000000000000000000000000000000","avatarDefault":true,"sub":"ca4fe831aaab4bc8b5814dc741211ab4"}
@lmorchard

This comment has been minimized.

Copy link
Member

commented Sep 10, 2019

Spent most of the day trying different combinations of things, but still can't reproduce this issue more than once.

Tried two different products - 123done Pro Monthly (prod_FfiuDs9u11ESbD) and fortress_monthly (prod_FUUNYnlDso7FeB). Tried signing into 123done before SUMO and vice versa. Tried never signing into 123done and just SUMO. Tried changing email addresses, display name, etc.

The only reliably reproducible thing I found is that SUMO won't get subscription status on the first sign-in. You have to sign-in, then sign-out, then sign-in again.

Can anyone else reproduce this issue reliably and repeatedly with different accounts? If we can get an account into a state where the subscription management page shows a subscription but SUMO does not after repeated logins, we might be able to grab some data and diagnose further. (Oh, and if you get an account into this state, do not cancel the subscription. We want to preserve the problem.)

@rlr

This comment has been minimized.

Copy link
Member

commented Sep 10, 2019

Can anyone else reproduce this issue reliably and repeatedly with different accounts?

@lmorchard I have at least one account on stage that is currently in this state. I am not using SUMO to get the profile though. Ping me on slack if you want to look into my case together. Thanks

@bbangert

This comment has been minimized.

Copy link
Contributor

commented Sep 11, 2019

@akatsoulas and @rlr are using the /subscription endpoint for now as a work-around for this cache timing issue. Given the time spent already, and the fact that the clearing code is complex and obtuse, this issue is being closed in favor of changing the system to ensure cache clearing (#2463).

@bbangert bbangert closed this Sep 11, 2019

lmorchard added a commit to lmorchard/fxa that referenced this issue Sep 12, 2019
lmorchard added a commit to lmorchard/fxa that referenced this issue Sep 12, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
8 participants
You can’t perform that action at this time.