1655531 - Verify clients act sanely on quota related error from server

Status: RESOLVED FIXED

(Firefox :: Sync, task, P1)

Description

[Rachel Tublitz [:rachel]]

We are in the process of implementing a new storage quota that will affect user collections.

On the client, we'd like to prevent users who have exceeded this quota from syncing. We should also log something that we can easily track for debugging purposes in the future.

See plan here related to this work.

Comment 1

[Mark Hammond [:markh] [:mhammond]]

Thanks Rachel,
Can you please clarify what you mean by preventing them from syncing? Is it necessary for the client to take action here, or can it just try and POST and handle the non-200 response appropriately?

Re logging, I suspect that it will already log in this case, including the response body - so there's a reasonable chance that already does the right thing.

What's the intention re testing this? ie, how could we force the server to enter the state where it thinks we are over quota without needing us to upload 2GB of records?

Comment 2

[Ryan Kelly [:rfkelly]]

FWIW the server protocol docs already reserve 400 Bad Request with error code 14 for "user has exeeded their quota", and there is even a special failure status for this in the desktop client code. I don't think this special failure status provides an satisfying UX or anything like that, but if nothing else it should help the failure show up in an intelligible way in the sync logs.

Comment 3

[Rachel Tublitz [:rachel]]

(In reply to Mark Hammond [:markh] [:mhammond] from comment #1)

Thanks Rachel,
Can you please clarify what you mean by preventing them from syncing? Is it necessary for the client to take action here, or can it just try and POST and handle the non-200 response appropriately?

Sorry yes, I should have been more clear. Attempted post and handling the error is completely fine here.

Re logging, I suspect that it will already log in this case, including the response body - so there's a reasonable chance that already does the right thing.

Excellent. In that case, maybe there's actually nothing to do here :)

What's the intention re testing this? ie, how could we force the server to enter the state where it thinks we are over quota without needing us to upload 2GB of records?

One option would be to set the quota really low in staging to test/confirm behaviour.

Comment 4

[Rachel Tublitz [:rachel]]

(In reply to Ryan Kelly [:rfkelly] from comment #2)

FWIW the server protocol docs already reserve 400 Bad Request with error code 14 for "user has exeeded their quota", and there is even a special failure status for this in the desktop client code. I don't think this special failure status provides an satisfying UX or anything like that, but if nothing else it should help the failure show up in an intelligible way in the sync logs.

Oh, that's perfect actually. It's the sign of a well designed system when it already has things built in way ahead of time that we now are finding we need :)

If we can confirm that this works, I think a 400 with error code 14 sounds like plenty here; ie - maybe there is no client work to be done here. Let me ni JR here to confirm, and then maybe we can just resolve this one.

JR - I think it sounds like we may already have what we need here on the client side. Anything else that you can think of that we'd need client side, or can we close this one out?

Comment 5

[JR Conlin [:jrconlin,:jconlin]]

Hmm. I think these might do well. I see that there are several other, similar error codes available:

• 16: client is known to be incompatible with the server.
• 17: server limit exceeded, likely due to too many items or too large a payload in a POST request.

From what I've been able to tell from a quick search, we have some of these defined, but they do not appear to be in use.

These should work well for clients that monitor status code returns correctly. We may need to work with ops to do the same sort of blocking we do with Autopush should there some clients that do not. I may need to work with Ops to determine if this might be needed and what additional headers they may require. That should be done as a separate issue.

Comment 6

[JR Conlin [:jrconlin,:jconlin]]

As a bit of follow up: While this return code will be useful for us, determining user quota usage on the server could potentially be very expensive. It would be nice(?) if the client would check or be mindful of how much data is currently in use and offer warnings or suggestions that the user might be reaching a quota limit.

We'll be working at managing quota better on the server (for less well behaved clients), but it might be a nice user experience to see something other than DENIED on a save.

Comment 7

[Rachel Tublitz [:rachel]]

(In reply to JR Conlin [:jrconlin,:jconlin] from comment #6)

We'll be working at managing quota better on the server (for less well behaved clients), but it might be a nice user experience to see something other than DENIED on a save.

I think that's something we can pursue at a later date. It may be worth doing at some point, but we need to weigh that against our existing projects.

I'm going to close this out as invalid, and we'll plan on testing to confirm client behaviour next week again the existing status codes.

Comment 8

[Mark Hammond [:markh] [:mhammond]]

(In reply to JR Conlin [:jrconlin,:jconlin] from comment #6)

if the client would check or be mindful of how much data is currently in use and offer warnings or suggestions that the user might be reaching a quota limit.

Sadly that's literally impossible for the client to know in our recent adventures with tombstones - these are only on the server and not on the client.

We'll be working at managing quota better on the server (for less well behaved clients), but it might be a nice user experience to see something other than DENIED on a save.

By all accounts, sync did enforce quotas years ago and before my time. The primary problem with the UI was that it didn't offer any reasonable way to solve the problem. If we tell them they have too much "form history" there's literally no way to trim that down to a sane amount. In our recent bookmarks example, the user had around 200 "live" bookmarks - telling them their bookmarks were over quota would have been a terrible outcome (they would have deleted them and still not have solved the issue - at least by just not syncing them they exist somewhere)

All that said though, I think it's worth having this open to verify the client acts as we expect it to - and in particular, we need to think about non-desktop clients - eg, none of the mobile products have a sane way of grabbing sync logs. So while I expect them to roughly "do the right thing", it's going to be almost impossible for the average user to determine sync is failing due to a quota issue.

Comment 9

[Rachel Tublitz [:rachel]]

I'll take this one for next week. Once we have a way to force staging to return this response, I'll plan on testing to verify against latest versions of Desktop, Fenix, and iOS.

Comment 10

[Rachel Tublitz [:rachel]]

Attachment: success-sync-1596639851005.txt

-

Comment 11

[Rachel Tublitz [:rachel]]

Attachment: successful sync

Just tested against staging, and am not seeing expected results:

1. Followed instructions here to create a new staging sync account. (sync id 6384991)
2. Added a new bookmark after deploy was finished.
3. Attempted a sync. Instead of a specific error, I got a successful sync response (atttached)

JR: can you confirm the exact steps you took to verify this PR locally so we can rule out staging env issues here?

Comment 12

[JR Conlin [:jrconlin,:jconlin]]

When testing locally, I use a script that runs:

SENTRY_DSN="https://..." \
    RUST_LOG=debug \
    GOOGLE_APPLICATION_CREDENTIALS=keys/sync-spanner-dev.json \
    cargo run -- --config spanner_sync_jr.ini $*

My local .ini file does not have discrete sections, instead it has:

host=0.0.0.0
database_url=spanner://...
master_secret=Ted_Koppel_is_a_robot
human_logs=true
limits.debug_client=123,1

I'll note that I did discover a bug in how syncstorage reads configuration environment variables, so a config file would probably be best for now. Environment variables will take precedence.

Comment 13

[Rachel Tublitz [:rachel]]

Erik, would it be possible to apply a config file as suggested by JR against stage?

if not, JR, to confirm, it looks like if we make a change to not use a . in that config value we should be able to get this working? Ie, just use a top level value like debug_client instead of limits.debug_client.... Could you confirm? That could be plan B here.

Comment 14

[Erik Olson]

Yeah sure, not clear what changes I need to make here.

Comment 15

[JR Conlin [:jrconlin,:jconlin]]

if you want to test the current version, you'd do best to use a config file that contains:

limits.debug_client=...

and then use either
syncserver --config /path/to/config
or
SYNC_CONFIG=/path/to/config syncserver

If we decide to use a different config value, we might as well promote the current dev version which uses double underscore as a separator, in which case SYNC_LIMITS__DEBUG_CLIENT=... syncserver would work fine.

Comment 16

[Rachel Tublitz [:rachel]]

Testing against 0.5.5 in staging now and still seeing exactly the same thing as with 0.5.4 as noted here. Next step is to test locally to try and isolate where the problem lies here.

Comment 17

[Philip Jenvey [:pjenvey]]

Looks like SYNC_LIMITS__DEBUG_CLIENT didn't quite make it to stage: https://console.cloud.google.com/kubernetes/configmap/us-west1/sync-nonprod-v1/stage-sync/sync-stage-sync-app-1/details?project=moz-fx-sync-nonprod-904c

Comment 18

[Rachel Tublitz [:rachel]]

Attachment: Failed desktop sync - sync error logs.

Testing Notes:

Using syncid 6384991 against staging, syncstorage-rs 0.5.5:

Desktop:

1. Followed steps here to point Desktop to staging.
2. Attempted a sync.
3. Saw it appear to succeed, until I checked the logs to see failure. This confirms what we expect to happen in the UI. (full logs attached)
4. Verified that I saw an associated error in Sentry here with the appropriate size-limit-exceeded type.

The notable part of the client logs is the error code 17 below, which maps to "Size limit exceeded". So, safe to say we're good here!

1596746994393	Sync.ErrorHandler	DEBUG	clients failed: {"data":"17","url":"https://stage.sync.nonprod.cloudops.mozgcp.net/1.5/6384991/storage/clients?batch=true&commit=true","status":400,"success":false,"headers":{"access-control-allow-origin":"null","alt-svc":"clear","content-length":"2","content-type":"application/json","date":"Thu, 06 Aug 2020 20:49:54 GMT","server":"openresty/1.15.8.2","vary":"Origin","via":"1.1 google","x-firefox-spdy":"h2","x-weave-timestamp":"1596746994.35"},"obj":17,"failureCode":"error.engine.reason.record_upload_fail"}

iOS:

Tried to follow the steps here to point iOS to staging. It looks like the iOS menu options have changed since that doc was written :(

I filed a bug for this here - In the meantime, I'll get a request in to ops to route one of my production sync accounts through the debug_client to test mobile.

Comment 19

[Mark Hammond [:markh] [:mhammond]]

(In reply to Rachel Tublitz [:rachel] from comment #18)

The notable part of the client logs is the error code 17 below, which maps to "Size limit exceeded". So, safe to say we're good here!

It's not a huge deal, but IIUC, 17 could also imply a bug in the client (eg, exceeding the max advertised request or batch size, for example). 14 is explicitly "over quota" so would probably be better here. Any chance of an issue on the server to change that?

Comment 20

[Rachel Tublitz [:rachel]]

(In reply to Mark Hammond [:markh] [:mhammond] from comment #19)

It's not a huge deal, but IIUC, 17 could also imply a bug in the client (eg, exceeding the max advertised request or batch size, for example). 14 is explicitly "over quota" so would probably be better here. Any chance of an issue on the server to change that?

Absolutely, we can change it. JR - would you mind addressing this (next week is fine too, doesn't need to be ASAP) so we can do one more round of testing to confirm behaviour next week?

Comment 21

[JR Conlin [:jrconlin,:jconlin]]

https://github.com/mozilla-services/syncstorage-rs/issues/769

Comment 22

[Erik Olson]

In regards to the env var SYNC_LIMITS__DEBUG_CLIENT mentioned by :pjenvey, the helm change was not pushed to the repo at the time the code was deployed. All should be fixed now.

Comment 23

[Rachel Tublitz [:rachel]]

Attachment: Failed desktop sync - sync error logs - Aug 17 2020

Testing Notes:

Desktop (Nightly 81.0a1 (2020-08-17) )

1. Added a bookmark
2. Tried to sync, saw no issues in the UI (ie, failed silently).
3. Confirmed failure in logs (attached) and noted the relevant bit here:

1597692258637	Sync.Status	DEBUG	Status for engine bookmarks: error.engine.reason.record_upload_fail
1597692258637	Sync.Status	DEBUG	Status.service: error.sync.failed_partial => error.sync.failed_partial
1597692258637	Sync.ErrorHandler	DEBUG	bookmarks failed: {"data":"14","url":"https://sync-1-us-west1-g.sync.services.mozilla.com/1.5/157673256/storage/bookmarks?batch=true&commit=true","status":400,"success":false,"headers":{"access-control-allow-origin":"null","alt-svc":"clear","content-length":"2","content-type":"application/json","date":"Mon, 17 Aug 2020 19:24:18 GMT","server":"openresty/1.15.8.2","vary":"Origin","via":"1.1 google","x-firefox-spdy":"h2","x-last-modified":"1596558861.49","x-weave-timestamp":"1597692258.57"},"obj":14,"failureCode":"error.engine.reason.record_upload_fail"}

4. Confirmed associated error in Sentry here

iOS (v28.0 18809)

1. Added a bookmark
2. Tried to sync, saw no issues in the UI (ie, failed silently).
3. Confirmed associated error in Sentry here - Note the missing UI info - filing separate issue for that.

Android (Nightly 200817 06:01)

1. Added a bookmark
2. Tried to sync, saw no issues in the UI (ie, failed silently).
3. Confirmed associated error in Sentry here - Note the missing UI info - filing separate issue for that.

I will also note for the record that for mobile clients, errors don't always seem to make it into sentry. The sync does indeed fail silently, but it looks like a smaller percentage of the errors actually appeared.

This does however confirm client behaviour is as expected, so I'm going to close this out for now.

Comment 24

[Rachel Tublitz [:rachel]]

For reference, the followup issue to get mobile client UA data into sentry lives here.