Addons-server: Basket integration causes user-profile edits to throw server errors.

Created on 3 Jun 2018  路  14Comments  路  Source: mozilla/addons-server

There are various exceptions visible in sentry that show that we get request timeouts and more from the Basket API, we should probably report them but fail in a more reasonable way for the user and throw an error message but avoid them landing on a 500-page.

https://sentry.prod.mozaws.net/operations/olympia-prod/issues/4365243/

Exception(most recent call first)

BasketException: 504 request returned from basket: 
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
  File "olympia/amo/decorators.py", line 127, in wrapper
    return f(*args, **kw)
  File "olympia/amo/decorators.py", line 114, in __call__
    return self.f(*args, **kw)
  File "olympia/amo/decorators.py", line 31, in wrapper
    return func(request, *args, **kw)
  File "olympia/users/views.py", line 156, in edit
    form = forms.UserEditForm(instance=amouser, request=request)
  File "olympia/users/forms.py", line 119, in __init__
    newsletters = fetch_subscribed_newsletters(self.instance)
  File "olympia/amo/utils.py", line 354, in fetch_subscribed_newsletters
    data = sync_user_with_basket(user_profile)
  File "olympia/amo/utils.py", line 339, in sync_user_with_basket
    data = basket.lookup_user(user.email)
  File "basket/base.py", line 223, in lookup_user
    headers={'x-api-key': api_key})
  File "basket/base.py", line 130, in request
    return parse_response(res)
  File "basket/base.py", line 98, in parse_response
    result=result)

https://sentry.prod.mozaws.net/operations/olympia-prod/issues/4370910/

Exception(most recent call first)

BasketNetworkException: Timeout connecting to basket
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
  File "olympia/amo/decorators.py", line 127, in wrapper
    return f(*args, **kw)
  File "olympia/amo/decorators.py", line 114, in __call__
    return self.f(*args, **kw)
  File "olympia/amo/decorators.py", line 31, in wrapper
    return func(request, *args, **kw)
  File "olympia/users/views.py", line 156, in edit
    form = forms.UserEditForm(instance=amouser, request=request)
  File "olympia/users/forms.py", line 119, in __init__
    newsletters = fetch_subscribed_newsletters(self.instance)
  File "olympia/amo/utils.py", line 354, in fetch_subscribed_newsletters
    data = sync_user_with_basket(user_profile)
  File "olympia/amo/utils.py", line 339, in sync_user_with_basket
    data = basket.lookup_user(user.email)
  File "basket/base.py", line 223, in lookup_user
    headers={'x-api-key': api_key})
  File "basket/base.py", line 129, in request
    raise BasketNetworkException("Timeout connecting to basket")

https://sentry.prod.mozaws.net/operations/olympia-prod/issues/4365191/

Exception(most recent call first)

BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head><body><p>Request Timeout.</p></body></html>
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
  File "olympia/amo/decorators.py", line 127, in wrapper
    return f(*args, **kw)
  File "olympia/amo/decorators.py", line 114, in __call__
    return self.f(*args, **kw)
  File "olympia/amo/decorators.py", line 31, in wrapper
    return func(request, *args, **kw)
  File "olympia/users/views.py", line 147, in edit
    form.save()
  File "olympia/users/forms.py", line 262, in save
    unsubscribe_newsletter(self.instance, basket_id)
  File "olympia/amo/utils.py", line 386, in unsubscribe_newsletter
    user_profile.basket_token, user_profile.email, basket_id)
  File "basket/base.py", line 194, in unsubscribe
    return request('post', 'unsubscribe', data=data, token=token)
  File "basket/base.py", line 130, in request
    return parse_response(res)
  File "basket/base.py", line 98, in parse_response
    result=result)

https://sentry.prod.mozaws.net/operations/olympia-prod/issues/4364824/

Exception(most recent call first)

BasketException: 504 request returned from basket: 
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
  File "olympia/amo/decorators.py", line 127, in wrapper
    return f(*args, **kw)
  File "olympia/amo/decorators.py", line 114, in __call__
    return self.f(*args, **kw)
  File "olympia/amo/decorators.py", line 31, in wrapper
    return func(request, *args, **kw)
  File "olympia/users/views.py", line 144, in edit
    instance=amouser)
  File "olympia/users/forms.py", line 119, in __init__
    newsletters = fetch_subscribed_newsletters(self.instance)
  File "olympia/amo/utils.py", line 354, in fetch_subscribed_newsletters
    data = sync_user_with_basket(user_profile)
  File "olympia/amo/utils.py", line 339, in sync_user_with_basket
    data = basket.lookup_user(user.email)
  File "basket/base.py", line 223, in lookup_user
    headers={'x-api-key': api_key})
  File "basket/base.py", line 130, in request
    return parse_response(res)
  File "basket/base.py", line 98, in parse_response
    result=result)

https://sentry.prod.mozaws.net/operations/olympia-prod/issues/4364716/

Exception(most recent call first)

BasketException: 504 request returned from basket: 
  File "django/core/handlers/base.py", line 132, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "django/utils/decorators.py", line 145, in inner
    return func(*args, **kwargs)
  File "olympia/amo/decorators.py", line 127, in wrapper
    return f(*args, **kw)
  File "olympia/amo/decorators.py", line 114, in __call__
    return self.f(*args, **kw)
  File "olympia/amo/decorators.py", line 31, in wrapper
    return func(request, *args, **kw)
  File "olympia/users/views.py", line 147, in edit
    form.save()
  File "olympia/users/forms.py", line 262, in save
    unsubscribe_newsletter(self.instance, basket_id)
  File "olympia/amo/utils.py", line 378, in unsubscribe_newsletter
    sync_user_with_basket(user_profile)
  File "olympia/amo/utils.py", line 339, in sync_user_with_basket
    data = basket.lookup_user(user.email)
  File "basket/base.py", line 223, in lookup_user
    headers={'x-api-key': api_key})
  File "basket/base.py", line 130, in request
    return parse_response(res)
  File "basket/base.py", line 98, in parse_response
    result=result)
p4 stale triaged
Source
picture EnTeQuAk

Most helpful comment

basket-dev should be working again. Please ping me if not.

picture pmac on 13 Nov 2018
👍2

All 14 comments

cc @pmac on this to maybe investigate the timeouts and 504-errors we see. These should obviously not happen that often and we see at least 20-30 exceptions that happened since we flipped the switch last week.

EnTeQuAk picture EnTeQuAk on 3 Jun 2018

I can't see that project in Sentry. Do you have more info you can give me on when these are happening and for what exact URL? I'll try to trace them down on my side. FWIW I don't see errors in Sentry for basket that seem to correlate.

pmac picture pmac on 4 Jun 2018

For the gateway timeouts (there's 17 more):

Jun 7, 2018 10:13:14 PM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 10  ip-172-31-19-226.us-west-2.compute.internal     https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 6, 2018 1:53:41 AM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 10  ip-172-31-2-66.us-west-2.compute.internal   /es/firefox/users/edit  https://addons.mozilla.org/es/firefox/users/edit    

Jun 5, 2018 10:56:21 PM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 10  ip-172-31-7-65.us-west-2.compute.internal   /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 5, 2018 1:02:59 PM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 10  ip-172-31-31-160.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 4, 2018 8:32:36 PM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 7   ip-172-31-22-233.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 2, 2018 9:12:57 AM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 7   ip-172-31-39-252.us-west-2.compute.internal /zh-CN/firefox/users/edit   https://addons.mozilla.org/zh-CN/firefox/users/edit 

May 31, 2018 9:17:08 AM UTC
BasketException: 504 request returned from basket:
    Samsung Internet 6.4    Samsung SM-J700M    error   Android 6.0.1   ip-172-31-19-201.us-west-2.compute.internal /es/firefox/users/edit  https://addons.mozilla.org/es/firefox/users/edit    

May 30, 2018 6:56:20 PM UTC
BasketException: 504 request returned from basket:
    Firefox 60.0    Other   error   Windows 10  ip-172-31-27-60.us-west-2.compute.internal  /de/firefox/users/edit  https://addons.mozilla.org/de/firefox/users/edit

For request timeouts:

Jun 7, 2018 4:55:33 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 47.0    Other   error   Ubuntu  ip-172-31-0-146.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 5, 2018 2:22:24 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Chrome 67.0 Other   error   Windows 10  ip-172-31-15-41.us-west-2.compute.internal  /pt-BR/firefox/users/edit   https://addons.mozilla.org/pt-BR/firefox/users/edit 

Jun 4, 2018 1:06:01 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox Mobile 60.0 Generic Smartphone  error   Android 8.0.0   ip-172-31-43-4.us-west-2.compute.internal   /en-US/android/users/edit   https://addons.mozilla.org/en-US/android/users/edit 

Jun 4, 2018 11:41:31 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Chrome 66.0 Other   error   Windows 10  ip-172-31-33-249.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 4, 2018 11:34:53 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox Mobile 60.0 Generic Smartphone  error   Android 5.1.1   ip-172-31-33-249.us-west-2.compute.internal /en-US/android/users/edit   https://addons.mozilla.org/en-US/android/users/edit 

Jun 4, 2018 10:03:10 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Chrome 67.0 Other   error   Windows 10  ip-172-31-31-160.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 4, 2018 9:43:27 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Mac OS X 10.13  ip-172-31-43-4.us-west-2.compute.internal   /pl/firefox/users/edit  https://addons.mozilla.org/pl/firefox/users/edit    

Jun 4, 2018 9:36:08 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Chrome 66.0 Other   error   Windows 8.1 ip-172-31-0-146.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 4, 2018 3:51:28 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox Mobile 61.0 Generic Smartphone  error   Android 7.0 ip-172-31-22-233.us-west-2.compute.internal /en-US/android/users/edit   https://addons.mozilla.org/en-US/android/users/edit 

Jun 3, 2018 1:26:08 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Windows 10  ip-172-31-7-65.us-west-2.compute.internal   /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 2, 2018 3:34:08 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 52.0    Other   error   Windows 8   ip-172-31-31-160.us-west-2.compute.internal /es/firefox/users/edit  https://addons.mozilla.org/es/firefox/users/edit    

Jun 1, 2018 3:03:05 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Windows 10  ip-172-31-33-227.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 1, 2018 7:28:56 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Mac OS X 10.13  ip-172-31-5-13.us-west-2.compute.internal   /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

May 31, 2018 1:07:07 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Windows 10  ip-172-31-7-187.us-west-2.compute.internal  /en-US/android/users/edit   https://addons.mozilla.org/en-US/android/users/edit 

May 31, 2018 12:45:51 AM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Firefox 60.0    Other   error   Windows 10  ip-172-31-27-60.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit

Rate limit reached:

Jun 7, 2018 3:13:55 AM UTC
BasketException: rate limit reached
    Firefox 60.0    Other   error   Windows 10  ip-172-31-15-41.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 7, 2018 3:13:25 AM UTC
BasketException: rate limit reached
    Firefox 60.0    Other   error   Windows 10  ip-172-31-31-160.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 6, 2018 7:54:12 PM UTC
BasketException: 408 request returned from basket: <html><head><title>Request Timeout</title></head>
    Chrome 66.0 Other   error   Mac OS X 10.13.3    ip-172-31-15-41.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 5, 2018 10:46:31 AM UTC
BasketException: rate limit reached
    Firefox 47.0    Other   error   Windows 10  ip-172-31-2-66.us-west-2.compute.internal   /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 5, 2018 10:46:18 AM UTC
BasketException: rate limit reached
    Firefox 47.0    Other   error   Windows 10  ip-172-31-15-41.us-west-2.compute.internal  /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit

And general request-timeout:

Jun 4, 2018 5:14:16 AM UTC
BasketNetworkException: Timeout connecting to basket
    Firefox 61.0    Other   error   Mac OS X 10.13  ip-172-31-22-244.us-west-2.compute.internal /en-US/firefox/users/edit   https://addons.mozilla.org/en-US/firefox/users/edit 

Jun 2, 2018 6:35:37 PM UTC
BasketNetworkException: Timeout connecting to basket
    Firefox 60.0    Other   error   Windows 10  ip-172-31-22-233.us-west-2.compute.internal /ja/firefox/users/edit  https://addons.mozilla.org/ja/firefox/users/edit

I wonder if the gateway and request timeouts happen during a deployment? The rate-limit reached is very unfortunate but can happen if a user simply, subscribes, unsubscribes and subscribes again (because they changed their mind or clicked the wrong check-box).

EnTeQuAk picture EnTeQuAk on 8 Jun 2018

Very strange. Can you tell me what kinds of requests these are? Are they mostly looking up user info (/news/lookup-user/) or subscribing to newsletters (/news/subscribe/)? I'll increase the subscription rate-limit.

pmac picture pmac on 8 Jun 2018

/cc @jgmize @metadave

pmac picture pmac on 8 Jun 2018

I don't think it's deployments. We've not deployed prod basket for a while. Can you also verify the full basket URLs this is hitting and from where? i.e. is this happening on your servers from a particular AWS region only?

pmac picture pmac on 8 Jun 2018

I've just deployed an update to the rate-limits on basket. They are now limited to 4 requests every 5 min. This should hopefully alleviate some of the rate-limit errors for simple mistakes with the checkboxes.

pmac picture pmac on 8 Jun 2018

I've just deployed an update to the rate-limits on basket. They are now limited to 4 requests every 5 min. This should hopefully alleviate some of the rate-limit errors for simple mistakes with the checkboxes.

Perfect, thanks! That seems to me much more reasonable.

Very strange. Can you tell me what kinds of requests these are? Are they mostly looking up user info (/news/lookup-user/) or subscribing to newsletters (/news/subscribe/)? I'll increase the subscription rate-limit.

Both, seems to happen on all the endpoints eventually. It happens more often on lookup-user but we simply call that endpoint more often so take that with a bit of salt.

I don't think it's deployments. We've not deployed prod basket for a while. Can you also verify the full basket URLs this is hitting and from where? i.e. is this happening on your servers from a particular AWS region only?

prod is us-west-2, dev and stage are us-east-1.

Does that help?

EnTeQuAk picture EnTeQuAk on 8 Jun 2018

Here's some 4xx/5xx data over 2 weeks from our Oregon-B basket ELB:

ec2_management_console

ec2_management_console

I see a lot of these types of messages in our oregon-b K8s cluster:
https://gist.github.com/metadave/0d9988ef60ada6374bd6ed7b65a5ca76
https://gist.github.com/metadave/04d667f24c58c72251def0dee6bdb4aa

edit: I believe the requests to www.exacttargetapis.com are for Salesforce.

metadave picture metadave on 20 Jun 2018

edit: I believe the requests to www.exacttargetapis.com are for Salesforce.

They are indeed. ExactTarget is the company that Salesforce bought that became "Salesforce Marketing Cloud".

pmac picture pmac on 2 Jul 2018

The -dev environment is down for the last 5 hours. The Basket API returns 500 all the time, which makes our own API returns 500 errors too (for the notifications API endpoint only).

willdurand picture willdurand on 13 Nov 2018

I'm looking into this now. The sandbox Salesforce account on which basket-dev relies is refreshed from time to time by IT to bring it up-to-date with the production instance. This always resets authentication and causes 500s due to authentication failure with their API. This is expected and unless we're actively testing something on basket-dev we don't often notice. basket-dev is our testing instance and is really not intended for public use. If you do want to continue using it then I'd suggest changing things to continue working even if it's down. Otherwise you can switch to using our staging instance (basket.allizom.org) that is much more reliable but still non-production.

pmac picture pmac on 13 Nov 2018
👍1

basket-dev should be working again. Please ping me if not.

pmac picture pmac on 13 Nov 2018
👍2

This issue has been automatically marked as stale because it has not had recent activity. If you think this bug should stay open, please comment on the issue with further details. Thank you for your contributions.

stale[bot] picture stale[bot] on 6 Sep 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

spoji picture spoji  路  6Comments
jvillalobos picture jvillalobos  路  3Comments
erosman picture erosman  路  6Comments
Juraj-Masiar picture Juraj-Masiar  路  6Comments
ioanarusiczki picture ioanarusiczki  路  8Comments