1332552 - Go Sync server interprets "ttl": null as 0

Status: RESOLVED FIXED

(Cloud Services Graveyard :: Server: Sync, defect)

Description

[Benson Wong [:mostlygeek]]

While doing some stability analysis for gosync I noticed there is a really high number of 404's for crypto/keys. 

> [2017-01-20T03:26:01+00:00] "GET /1.5/user1/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/5.3 (Firefox)"
> [2017-01-20T03:26:01+00:00] "PUT /1.5/user1/storage/crypto/keys HTTP/1.1" 200 "Firefox-iOS-Sync/5.3 (Firefox)"
> [2017-01-20T03:26:02+00:00] "GET /1.5/user1/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/5.3 (Firefox)"
> [2017-01-20T03:35:07+00:00] "GET /1.5/user1/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/5.3 (Firefox)"
> [2017-01-20T03:35:09+00:00] "PUT /1.5/user1/storage/crypto/keys HTTP/1.1" 200 "Firefox-iOS-Sync/5.3 (Firefox)"
> ...
> 
> [2017-01-20T03:51:38+00:00] "GET /1.5/user2/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/6.0 (Firefox)"
> [2017-01-20T03:51:39+00:00] "PUT /1.5/user2/storage/crypto/keys HTTP/1.1" 200 "Firefox-iOS-Sync/6.0 (Firefox)"
> [2017-01-20T03:51:40+00:00] "GET /1.5/user2/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/6.0 (Firefox)"
> [2017-01-20T03:51:46+00:00] "GET /1.5/user2/storage/crypto/keys HTTP/1.1" 404 "Firefox-iOS-Sync/6.0 (Firefox)"
> [2017-01-20T03:51:46+00:00] "PUT /1.5/user2/storage/crypto/keys HTTP/1.1" 200 "Firefox-iOS-Sync/6.0 (Firefox)"
>

iOS clients successfully PUT 'storage/crypto/keys/' but cannot GET it back. Android or Desktop users don't exhibit this behaviour. 

The problem seems to be that the BSOs being PUT have a TTL of 0. I confirmed this in the sqlite data:

> sqlite> select id,payloadsize,Modified,TTL,TTL-Modified real_ttl from bso where collectionid=2;
> Id          PayloadSize  Modified       TTL            real_ttl
> ----------  -----------  -------------  -------------  ----------
> keys        362          1484884567210  1484884567210  0

Modified is the last time the BSO was updated. TTL is set to modified+(client ttl value). So the difference is what the client sent to gosync. 

When the client tries the GET the BSO is expired so it always 404's. If the TTL was omitted the default would have been used. So the client is explicitly sending a TTL of 0. 

This doesn't appear to affect pysync. I'm assuming it interprets a TTL of 0 as "use a default TTL". 

What should we do here? 

   1. Patch gosync so TTL's of 0 will use a default expiration, like pysync?
   2. Fix iOS clients to stop sending a DOA BSO?

FWIW the Sync 1.5 spec [1] only says a TTL must be a positive integer. If doesn't define how a 0 should be handled. 

[1] https://docs.services.mozilla.com/storage/apis-1.5.html

Comment 1

[Richard Newman [:rnewman]]

Patch the server, and we'll fix it as a nice-to-have on iOS.

Clients are in the wild, tested to work against pysync, and we can't break them just because of a more detailed reading of the spec.

This is one of those "don't build your first client in JS" spec things -- "If not specified or null, the record will not expire" (API spec) **to JS** means 0 is fine, because 0 == null == undefined.

You might consider never expiring crypto/keys: that's not behavior I can imagine anyone wanting!

Comment 2

[Richard Newman [:rnewman]]

This is puzzling, though: we did work in 2015 to allow records to exclude TTL.

Bug 1158216, 1cce59c8eac282e151568f1204ffbbcc27349eff.

Comment 3

[Richard Newman [:rnewman]]

I just created a fresh FxA in a build with extra logging:

2017-01-20 10:30:05.962 [Info] [StorageClient.swift:602] uploadCryptoKeys(_:withSyncKeyBundle:ifUnmodifiedSince:) > Record TTL: nil
2017-01-20 10:30:05.965 [Debug] [StorageClient.swift:693] put(_:ifUnmodifiedSince:) > PUT: {
  "payload" : "{\"IV\":\"fxovoz4Xrn1FkROf1kBX4g==\",\"ciphertext\":\"cs\\\/AyWec6oswVuPLyDNBLiOOmTZYvGW0uEvjU7exQ7MaT2e2+bvkEwA7gqI6y6bKLMPqeO1lCvJKclI0bf2jB1PpJ8KtDfr6lzFFGzEUhxFE3tbObeRuDmVCJaeyKXmy5nkbObe8QqT0FHJQjhFsJWH01dHM1sjWU0rfTiJpqHuqZM1O+8YwvIynh9zfbsBJtp0s7khrySPtrocvAmr\\\/XQPJSFl4HMGD5\\\/ALhKcp15A=\",\"hmac\":\"e2ae2d009fa557670d905e5622cc72b03139913f1bb0cf262eb603deaf78896b\"}",
  "sortindex" : 0,
  "id" : "keys",
  "ttl" : null
}
201


So… no, they don't upload a TTL of 0. Benson, is this a bug in your JSON parsing?

Comment 4

[Richard Newman [:rnewman]]

https://github.com/mozilla-services/go-syncstorage/blob/master/web/misc.go#L169-L177

"Because null is often used in JSON to mean “not present,” unmarshaling a JSON null into any other Go type has no effect on the value and produces no error. "

I bet that `var ttl int` in Go implicitly defaults it to 0, so that clause finishes with `ttl` equal to `0`.

Comment 5

[Benson Wong [:mostlygeek]]

> I bet that `var ttl int` in Go implicitly defaults it to 0, so that clause
> finishes with `ttl` equal to `0`.

That seems to be right. 

Here's some test code that confirms it: https://play.golang.org/p/4S80HaZET8

Thanks for the help. I think a patch to the gosync box is the right spot as "null" should mean never expire.

Comment 6

[Richard Newman [:rnewman]]

Is this code deployed in production for regular users?

If so, some thought needs to be given to data recovery for passwords. Users who made changes to passwords on iOS, or added new passwords, will have lost data.

Comment 7

[Benson Wong [:mostlygeek]]

I pushed two PR's: 

 - https://github.com/mozilla-services/go-syncstorage/pull/157 (the fix) 
 - https://github.com/mozilla-services/server-syncstorage/pull/56 (functional regression test)

> Is this code deployed in production for regular users?
> If so, some thought needs to be given to data recovery for passwords. Users who made changes to passwords on iOS, or added new passwords, will have lost data.

Yup. :|
I'll dig into the effect of it. This also fixed another bug where the default TTL was set to 1 year for items where ttl was undefined.

Comment 8

[Ryan Kelly [:rfkelly]]

I'm late to this party due to PTO, but FWIW the spec mentions handling of `null` specifically for the "ttl" field with:

  "If not specified or null, the record will not expire"

And more generally in the description of `PUT https://<endpoint-url>/storage/<collection>/<id>` with:

  "Fields that are not provided in the request body will not be overwritten, so it is possible to e.g.
   update the ttl field of a BSO without re-submitting its payload. Fields that are explicitly set to 
   null in the request body will be set to their default value by the server."

:mostlygeek thanks for adding an explicit testcase for the first; do you feel like the second description above is adequately covered by existing tests?

Comment 9

[Benson Wong [:mostlygeek]]

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

> :mostlygeek thanks for adding an explicit testcase for the first; do you
> feel like the second description above is adequately covered by existing
> tests?

Yes. I think it was only missing a test for ttl:null. There are tests for undefined TTLs and PUT with only TTL values.

Comment 10

[Benson Wong [:mostlygeek]]

Picking up the conversation from the PR [1] about what to do to fix the gosync server's TTLs. I think the safest thing to do is to migrate everybody to new servers. This is the standard procedure when a node is no good and we're very comfortable with it.

Two bugs were fixed in the PR[1]: 

 1. null TTLs     : 0 => 100 years TTL 
 2. undefined TTL : 1 year => 100 years TTL

The second bug affected everybody. While we don't need to worry about corrupt data for another 9 months, it's better to do it sooner than later.

[1] https://github.com/mozilla-services/go-syncstorage/pull/157

Comment 11

[Richard Newman [:rnewman]]

Migration does cause full uploads and downloads of history and bookmarks, which isn't great.

An alternative would be to silently bump the TTLs for all bookmarks whose TTL is in the affected range (iOS doesn't upload bookmarks) and alter the syncIDs for other affected collections to cause them to be re-synced. Needs more careful thought, but we can have a smaller impact on users if we choose to do the work.

Comment 12

[Bob Micheletto [:bobm]]

(In reply to Benson Wong [:mostlygeek] from comment #10)
> Picking up the conversation from the PR [1] about what to do to fix the
> gosync server's TTLs. I think the safest thing to do is to migrate everybody
> to new servers. This is the standard procedure when a node is no good and
> we're very comfortable with it.

If we decide to go this route, I'd suggest that we:
* Build a new go-sync node with capacity and available set to zero.
* Manually migrate the node's users over in waves (say 1/3 at a time.)

However, I'm interested in discussion along how we'd implement the alternative suggested by :rnewman from Comment 11. Even if we don't do it, I think it'd be worth figuring out how we would lock and repair user data in a go-sync environment.

Comment 13

[Benson Wong [:mostlygeek]]

To patch all the user's data we would: 

1. shut down the go-syncstorage server and 503 w/ Retry-After users
2. go through each DB and add 99 years to the TTLs where they are 1 year: 

   UPDATE bsos SET ttl=ttl+(99*365*86400*1000) WHERE ttl-modified=(365*86400*1000)

This would probably take a very long time since it's a full table scan and the number of databases we have.

Comment 14

[Ryan Kelly [:rfkelly]]

I also have a meta-level question while this is fresh in our minds - is there a way we could have detected this issue sooner, e.g. from client or server-side metrics data?

Comment 15

[Benson Wong [:mostlygeek]]

I rolled out the fix to both gosync servers.

It looks like it works. A few notes below:

> [2017-01-23 20:57:22] "GET /1.5/xxx/info/collections HTTP/1.1"                        200
> [2017-01-23 20:57:23] "GET /1.5/xxx/storage/crypto/keys HTTP/1.1"                     404   [1] 
> [2017-01-23 20:57:23] "DELETE /1.5/xxx HTTP/1.1"                                      200   [2]
> [2017-01-23 20:57:23] "PUT /1.5/xxx/storage/meta/global HTTP/1.1"                     200 
> [2017-01-23 20:57:24] "PUT /1.5/xxx/storage/crypto/keys HTTP/1.1"                     200 
> [2017-01-23 20:57:24] "GET /1.5/xxx/info/collections HTTP/1.1"                        200 
> [2017-01-23 20:57:25] "GET /1.5/xxx/storage/meta/global HTTP/1.1"                     200 
> [2017-01-23 20:57:25] "GET /1.5/xxx/storage/crypto/keys HTTP/1.1"                     200   [3]
> [2017-01-23 20:57:26] "PUT /1.5/xxx/storage/clients/AOSW2nlifeoJ HTTP/1.1"            200 
> [2017-01-23 20:57:26] "PUT /1.5/xxx/storage/tabs/AOSW2nlifeoJ HTTP/1.1"               200 
> [2017-01-23 20:57:26] "GET /1.5/xxx/storage/passwords?full=1&newer=0.00 HTTP/1.1"     200 
> [2017-01-23 20:57:28] "POST /1.5/xxx/storage/history?batch=true HTTP/1.1"             202
> [2017-01-23 20:57:29] "POST /1.5/xxx/storage/history?batch=b1 HTTP/1.1"               202
> [2017-01-23 20:57:30] "POST /1.5/xxx/storage/history?batch=b1 HTTP/1.1"               202
> [2017-01-23 20:57:30] "POST /1.5/xxx/storage/history?batch=b1&commit=true HTTP/1.1"   200 


1. 404 is expected as the previous record had a TTL of 0

2. iOS deletes everything if storage/crypto/keys 404s. 
All clients will have to upload all their data after this. Since all data must be uploaded it means the data will eventually be in sync. No data patching required to get everything right.

3. No 404. Confirms that the bug no longer exists.

Comment 16

[Benson Wong [:mostlygeek]]

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

> I also have a meta-level question while this is fresh in our minds - is
> there a way we could have detected this issue sooner, e.g. from client or
> server-side metrics data?

For Bug 1324600 (android not committing batches) I noticed the large number of batch purges in elasticsearch. This bug was found because I was comparing HTTP response code counts between pysync and gosync. Finding them coincidentally doesn't seem like the right approach. :)

Maybe we can: 

 - look for holes/edge cases the python functional tests don't cover
 - real, automated client testing using iOS, fennec and desktop

Comment 17

[Benson Wong [:mostlygeek]]

Resolving this issue as it appears to be fixed now.

Comment 18

[Richard Newman [:rnewman]]

(In reply to Ryan Kelly [:rfkelly] from comment #14)
> I also have a meta-level question while this is fresh in our minds - is
> there a way we could have detected this issue sooner, e.g. from client or
> server-side metrics data?

Yes:

- The 404 rate on crypto/keys should be zero. A zero TTL on keys would cause a 100% PUT-then-GET 201-then-404 rate.

On this note, this version of the Go server code should never have been rolled out, because trivial hand testing of an iOS client would have shown an obvious 404 failure during first setup, and a consequent inability to sync. This means we rolled out a service into prod and started putting real users on it without _any_ manual testing -- not even smoketesting -- which is pretty terrible.

- We could measure both TTLed-out records and speculative TTL load -- that is, how many records will we be TTLing next year? For bookmarks, passwords, crypto, etc. there should be _zero_ records that we ever plan to TTL. Obviously this is adding a metric for a bug, but the idea might be generalizable.

Comment 19

[Richard Newman [:rnewman]]

(In reply to Benson Wong [:mostlygeek] from comment #15)

> All clients will have to upload all their data after this. Since all data
> must be uploaded it means the data will eventually be in sync. No data
> patching required to get everything right.

You missed a case.

- iOS comes to a server that desktop has already synced with. The server already has keys (with TTL=1 year, prior to your fix).
- crypto/keys downloads successfully.
- Later, iOS adds or changes a password or form history record. This record is POSTed with ttl=null. The server immediately and silently throws the record away.

That's the data loss I'm worried about.

Comment 20

[Ryan Kelly [:rfkelly]]

> - The 404 rate on /crypto/keys should be zero. 

:heart: metrics like these, sounds like something we should put a monitor in for more generally.  Is this true even for users doing a first sync?  (i.e. do they discover that there's no data on the server by getting a 404 on something other than /crypto/keys?)

Comment 21

[Richard Newman [:rnewman]]

(In reply to Ryan Kelly [:rfkelly] from comment #20)
> > - The 404 rate on /crypto/keys should be zero. 
> 
> :heart: metrics like these, sounds like something we should put a monitor in
> for more generally.  Is this true even for users doing a first sync?  (i.e.
> do they discover that there's no data on the server by getting a 404 on
> something other than /crypto/keys?)

They shouldn't: they'll check info/collections, and shouldn't attempt a download unless 'crypto' is present. 

The only time they do a blind download is if there's an HMAC mismatch, in which case there's data on the server, which implies that there's a keys object, so a 404 in that case is also a huge red flag.

A 404 on crypto/keys means one of two things:

- Someone deleted crypto/keys, which is a client bug.
- The server threw away crypto/keys, which is a server or client bug. (info/collections will still report the last modified time of an empty collection.)

Comment 22

[Benson Wong [:mostlygeek]]

> On this note, this version of the Go server code should never have been rolled out, because trivial hand testing of an iOS client would have shown an obvious 404 failure during first setup, and a consequent inability to sync. 

It appears to be a bit more complex than that. It seems only people exclusively using iOS are affected. If you sync desktop or fennec with iOS the problem doesn't happen. Desktop / fennec omits the ttl field so they defaulted to the 1 year TTL. If desktop or fennec syncs first then iOS will be fine. If iOS syncs first it'll be broken until desktop or fennec rolled around. If somebody is only syncing with iOS clients it would have been be broken until today.

When I was testing the sync I kept a tail on the nginx logs. I synced my desktop and then my iPhone. If I did it the other way around order I would have noticed this bug immediately. Though the problem would have repaired itself when desktop wrote a crypto/keys record. 

There may be other edge cases. However, I took a small sample of the people who were stuck in an iOS 404 loop and they appeared to be exclusively iOS.

Comment 23

[Benson Wong [:mostlygeek]]

> They shouldn't: they'll check info/collections, and shouldn't attempt a
> download unless 'crypto' is present. 

Desktop doesn't behave this way. Logs from my very first sync on the gosync box:

> UA = Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> 
> [2016-11-07T21:54:06] "GET /1.5/xxx/info/collections HTTP/1.1"          200
> [2016-11-07T21:54:06] "GET /1.5/xxx/storage/meta/global HTTP/1.1"       404 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "GET /1.5/xxx/storage/meta/global HTTP/1.1"       404 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "PUT /1.5/xxx/storage/meta/global HTTP/1.1"       200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "DELETE /1.5/xxx/storage HTTP/1.1"                200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "PUT /1.5/xxx/storage/meta/global HTTP/1.1"       200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "PUT /1.5/xxx/storage/crypto/keys HTTP/1.1"       200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "GET /1.5/xxx/info/collections HTTP/1.1"          200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "GET /1.5/xxx/storage/crypto/keys HTTP/1.1"       200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop
> [2016-11-07T21:54:06] "GET /1.5/xxx/info/collections?v=1.51.0 HTTP/1.1" 200 Firefox/49.0.2 (Intel Mac OS X 10.11) FxSync/1.51.0.20161019084923.desktop

There must be a reason for this weird request pattern: 

 - info/collections, all collection timestamps will be 0.00 when DB is empty
 - it'll attempt to get meta/global ... twice?!
 - since meta/global 404's it'll PUT a new one
 - but DELETE everything immediately after 
 - then PUT meta/global and crypto/keys
 - ... then normal syncing 

While unlikely, there could be a race condition here if iOS and desktop try to first sync at the same time. Since they use different keys to determine if they should nuke the whole database. Though an X-If-Unmodified-Since should protect against that.

Comment 24

[Richard Newman [:rnewman]]

(In reply to Benson Wong [:mostlygeek] from comment #22)

> It appears to be a bit more complex than that. It seems only people
> exclusively using iOS are affected.

Yes: smoke-testing should include the account creation flow on all platforms.

And this doesn't only affect exclusive iOS users. As noted earlier, it also affects password and form history uploads from iOS to any Sync account. That is: if you're on a Go server, and you add a password on your iOS device, it never arrives on your desktop. (That's why I reopened this bug, because those users have still lost data.)

> When I was testing the sync I kept a tail on the nginx logs. I synced my
> desktop and then my iPhone. If I did it the other way around order I would
> have noticed this bug immediately.

Or if the testing had exercised syncing new data from each platform, which would exercise the TTL bug on non-TTLed collections.

Comment 25

[Richard Newman [:rnewman]]

(In reply to Benson Wong [:mostlygeek] from comment #22)

> When I was testing the sync I kept a tail on the nginx logs. I synced my
> desktop and then my iPhone.

More broadly: it's not enough to watch server logs to determine if Sync is working correctly; one needs to make sure that clients do the right thing (e.g., action in one place => new data in another), and ideally be watching the log output of each client.

I'm generally risk averse, so I'd only feel confident cutting a new Sync server release -- Go or Python -- with testing on an Android emulator and a copy of Xcode. Better that than have some protocol edge case come to light in production and lose user data.

Comment 26

[Richard Newman [:rnewman]]

(In reply to Benson Wong [:mostlygeek] from comment #23)

> > They shouldn't: they'll check info/collections, and shouldn't attempt a
> > download unless 'crypto' is present. 
> 
> Desktop doesn't behave this way.

You'll note that it fetches info/collections, and subsequently does not GET crypto/keys until it has PUT crypto/keys.



>  - info/collections, all collection timestamps will be 0.00 when DB is empty

This is incorrect; if that's the behavior of the Go server it's another urgent bug.

Entries should *not be present* in info/collections until the collection has been created. There is a difference between an empty collection (one that's been POSTed to with an empty body, or one that's had its contents deleted) and a non-existent collection.

A brand new server should return {} for info/collections.

The odd sequence you're seeing is probably because the server is lying to the client -- if it's returning

  {"meta": 0, "crypto": 0, …}

then you're telling the client that there's a meta/global and a crypto/keys. The client tries to fetch meta/global and gets a 404, which is a surprise, forcing it into a corrupt server recovery flow. That flow is generic, and involves…

>  - it'll attempt to get meta/global ... twice?!

… fetching m/g a second time to try to recover the user's datatype elections, then wiping storage and trying to rebuild the server.



> While unlikely, there could be a race condition here if iOS and desktop try
> to first sync at the same time. Since they use different keys to determine
> if they should nuke the whole database. Though an X-If-Unmodified-Since
> should protect against that.

The recovery flow uses XIUS and re-fetches data in order to avoid corruption during a recovery race. It's one of the parts of the system I have more faith in.

Comment 27

[Benson Wong [:mostlygeek]]

> This is incorrect; if that's the behavior of the Go server it's another urgent bug.

Sorry. My bad. It omits them if they're empty. So the first info/collections should respond with a {} (empty json object).

Comment 28

[Benson Wong [:mostlygeek]]

I'd like to to bring the conversation back a bit.

The secondary thread going on are questions around server quality assurance. The python server's functional tests seem like the best answer. Since some bugs slipped through it is seems prudent to see if there are obvious/edge cases we can should add tests for. 

The main question we should focus on is what should we do about the data loss and 1yr TTL?
I consider this box dead/dying and we should just migrate all the users. ASAP.

Comment 29

[Richard Newman [:rnewman]]

(In reply to Benson Wong [:mostlygeek] from comment #28)

> The main question we should focus on is what should we do about the data
> loss and 1yr TTL?
> I consider this box dead/dying and we should just migrate all the users.
> ASAP.

The cheapest thing to attempt from the user's perspective:

* For all users with an iOS device (or all users, if you wish)
* If their meta/global includes 'passwords':
  * Alter the syncID in meta/global for 'passwords'. For example, you could prepend 'X'.
  * If any alteration occurred, bump the timestamp of meta/global.

This will cause devices to re-sync passwords from scratch, but leave the rest of their data intact.

Comment 30

[Benson Wong [:mostlygeek]]

Affected iOS users were migrated in Bug 1333585. 

On everybody being affected by the 1year TTL bug:

We won't be migrating or patching anybody's data on the gosync server. We'll have the experiment data we need by August, 2017. At that point we'll migrate all the users well before we're affected by the 1 year TTL bug.