1102652 - "invalid language" error when calling the Basket API

Status: RESOLVED FIXED

(Websites :: Basket, defect)

Description

[Chris Karlof [:ckarlof]]

We're getting a fair number of these errors when notifying Basket of an FxA creation.

Comment 1

[Chris Karlof [:ckarlof]]

:ckolos, in the error logs you provided me earlier today, I don't see any request or response details. Is there any way to get that information?

Comment 2

[Chris Karlof [:ckarlof]]

We're seeing some other errors too. In the collection of 4907 errors I'm looking at, here's the breakdown:

400 "invalid language": 3953
500 "internal server error": 236
500 "service unavailable": 457
504 "bad gateway": 114
ECONNRESET: 118
ETIMEDOUT: 28
401 "fxa-register requires accept_lang": 1

We need to track down the cause of the "invalid language" errors and resolve those. We may be providing an locale string that either Basket or ET doesn't like.

:dcoates are we doing anything to retry the 5xx, ECONNRESET, or ETIMEDOUT errors?

Comment 3

[Paul [:pmac] McLanahan]

"invalid language" is returned from basket when no language codes can be extracted from the data sent in the accept_lang parameter. We did this because without language data we can't reliably email the person anyway. I've NI'd Jess to see  if she has an opinion on what we should do, but the decision was made earlier to reject submissions that contain no language info, and from what I can tell this is what is being rejected.

The other possibility is that our accept-language header parsing code[0] is wrong. If you have examples of the data submitted that was rejected we can debug our function and accept more users. 

[0] https://github.com/mozilla/basket/blob/master/news/utils.py#L417-417

Comment 4

[Chris Kolosiwsky [:ckolos] (ckolos has left the building)]

:ckarlof, bumping the logging level up might capture what you're looking for, but what I sent you is exactly what's being captured right now.

Comment 5

[Jessilyn Davis]

Yo! I'm happy that we made language required so that we could find this bug and fix it before we have a bunch of people with blank language settings in ET (that we then cannot communicate with).

Questions:

1) Has this always errored or is this a new error?
2) Are all calls erroring, or only for certain headers that contain certain languages?
3) Has something changed in the accept-language header parsing code?
4) Has something changed in the language headers that are being sent from FxA?


I'd rather not turn off the language requirement until we figure out this bug. That way we have the examples to debug, and once we find the bug and fix it, know that it works (ie we stop getting these errors after the fix is in place).

The accounts that have errored/will error until the bug is tracked down and fixed, can be imported later with the historical accounts, right? So we're not "losing" anyone at the moment - they're just not being seamlessly added at this point in time.

Comment 6

[Chris Karlof [:ckarlof]]

We have insufficient logging on our side to see what language code caused the error, and it sounds like Basket might not be logging the language code that caused the error either. 

:ckolos, turning up the logging level to trace might be a good short to fix (https://github.com/mozilla/fxa-auth-server/blob/master/bin/basket.js#L21), but since there is a request in there, we're going to have to match the trace logs with the error logs. 

It's better than nothing until we can land better logging.

Comment 7

[Chris Karlof [:ckarlof]]

Jessilyn, no account data was lost, and we'll be able to resolve this later.

Comment 8

[Paul [:pmac] McLanahan]

Attachment: Link to Github pull-request: https://github.com/mozilla/basket/pull/127

Patch to capture data when accept_lang is rejected for fxa registrations.

Comment 9

[[github robot]]

Commits pushed to master at https://github.com/mozilla/basket

https://github.com/mozilla/basket/commit/bcc07d8338a167d901eae5c03da5df20d29f376b
Bug 1102652: Capture fxa accept_lang failures.

https://github.com/mozilla/basket/commit/8dbbe38c82fd01adfe06899e704230a63e423d34
Merge pull request #127 from pmclanahan/fxa-accept-lang-error-logging-1102652

Bug 1102652: Capture fxa accept_lang failures.

Comment 10

[Ryan Kelly [:rfkelly]]

Hi Paul, I'm going to see about adding more diagnostics on the FxA side of this.  Did the change in Comment 9 produce any useful hints on the basket side?

Comment 11

[Paul [:pmac] McLanahan]

Unfortunately not. It on our dev server, but I can't get it to send any info to sentry (which we're thinking of ditching anyway). I'll get back on this and collect the data another way.

Comment 12

[Ryan Kelly [:rfkelly]]

See Bug 1120804 for a sample of the reasons behind the invalid accept_lang values.

Some are due to missing/empty Accept-Language header, which I don't think we can do much about except avoid sending these records over to basket in the first place.

A small handful are due to Accept-Language using underscores rather than hyphens, e.g. "en_US" rather than "en-US".  These are technically invalid per the RFC but the meaning is pretty clear, so we could probably do something useful with them.  Perhaps we can normalize them inside FxA, or change basket API to accept this form  Paul, thoughts?

Comment 13

[Paul [:pmac] McLanahan]

I'm happy to patch basket to deal with the underscore versions. I think that's the right thing. Storing what the user sent you seems appropriate on your side. I'll file a bug for basket to fix this. Thanks Ryan!

Comment 14

[Paul [:pmac] McLanahan]

Actually I'll just fix it using this bug. Thanks again :rfkelly. Hope to have a patch this week.

Comment 15

[Chris Karlof [:ckarlof]]

We decided in our monthly FxA-Engagement meeting that FxA will send en-US when it is missing locale information for the user.

We also decided not to address notifying Basket of updates to the user's locale at this time, but we may want to in the future.

Comment 16

[Paul [:pmac] McLanahan]

Ryan, is it possible for you to provide me a few samples of the errant headers (with the underscores). I'd like to write some tests with the real issue.

Comment 17

[Ryan Kelly [:rfkelly]]

The "locale" values in Bug 1121799 Comment 2 should the raw headers; in both cases its just the string "en_US" without any of the other complicated Accept-Language header stuff that might make for an interesting test-case.

Comment 18

[Paul [:pmac] McLanahan]

Thanks Ryan. I can't see that bug (not authorized), but if it's literally "en_US" that's all I need.

Comment 19

[Paul [:pmac] McLanahan]

Funny story: we've got a test that specifically ensures that "en_us" is invalid :(

https://github.com/mozilla/basket/blob/3e902d80db6fa48b13d02213d1a36e40f1aa99b9/news/tests/test__utils.py#L196

It is invalid, but I still think we want to err on the side of acceptance. I'm quite suspicious of a client that would sent an invalid accept-language header. It's probably a bot. But as long as it otherwise makes sense, converting an _ to an - seems innocuous enough.

Comment 20

[Ryan Kelly [:rfkelly]]

We added more logging on our end, and by next week we should be able to get the uid and user-agent for these accounts to investigate whether there's anything fishy about them.  ni? myself to check back with more details about that.

Comment 21

[Paul [:pmac] McLanahan]

Attachment: PR to allow accept-language headers with underscores.

Comment 22

[Ryan Kelly [:rfkelly]]

> We added more logging on our end, and by next week we should be able to get
> the uid and user-agent for these accounts to

Huh, turns out we didn't add user-agent logging after all.  I don't think it's really worth another round of updates to add it just to see who these handful of folks are, but I'd be happy to add if you think it would be valuable :pmac.

Comment 23

[Paul [:pmac] McLanahan]

I think you're right. We'll go with the changes I've got and see where that gets us. If we need to do more later we can.

Comment 24

[Paul [:pmac] McLanahan]

I think we're good here. We can always reopen if we think otherwise.