1627638 - 10MB error-sync-<bla>.txt files are being generated every few minutes

Status: RESOLVED FIXED

(WebExtensions :: Storage, defect, P2)

Description

[Patrice Peterson]

Attachment: error-sync-1586172566396.txt.gz

User Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:74.0) Gecko/20100101 Firefox/74.0

Steps to reproduce:

• Use Firefox 74.0.1 on up-to-date Fedora 31
• Turn on Sync
• Enable Multi-Account Containers

Not sure what else I did. I have FF Pioneer installed and I'm also sending Telemetry, in case that's useful.

Actual results:

There's an error-sync-<bla>.txt file generated every few minutes. I've attached one of those files, they gzip pretty well.

Last few lines of output from ls -l:

.rw-------@ 10M ajaam ajaam 2020-04-06 04:22 error-sync-1586139731434.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 05:22 error-sync-1586143359425.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 06:23 error-sync-1586146985782.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 07:23 error-sync-1586150611534.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 08:23 error-sync-1586154236909.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 09:24 error-sync-1586157861799.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 10:24 error-sync-1586161486343.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 11:25 error-sync-1586165111030.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 12:25 error-sync-1586168736269.txt
.rw-------@ 0 ajaam ajaam 2020-04-06 12:55 error-sync-1586170532906.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 13:06 error-sync-1586171204827.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 13:08 error-sync-1586171320240.txt
.rw-------@ 10M ajaam ajaam 2020-04-06 13:19 error-sync-1586171943157.txt

Expected results:

No such files should have been generated, I assume.

Comment 1

[Patrice Peterson]

Sorry, the files are generated in <ff-profile>/weave/logs. Forgot to mention that.

(In reply to Patrice Peterson from comment #0)

There's an error-sync-<bla>.txt file generated every few minutes. I've attached one of those files, they gzip pretty well.

Last few lines of output from ls -l:

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 3

[janet [:janet]]

multi-container syncing bug, moving to core:security.

Comment 4

[Lina Butler (ex-Mozilla)]

Thanks for uploading an example log, Patrice, that's super helpful! There are a couple of things happening here:

1586172566365 Sync.Engine.Extension-Storage ERROR Syncing @testpilot-containers: request failed: Error: HTTP 507 Insufficient Storage: Resource access is forbidden for this user (Maximum bytes per object exceeded " "(31483 > 16384 Bytes.)(resource://services-common/kinto-http-client.js:2771:5) JS Stack trace: [e-mail]:2771:5

That means an add-on (Containers, in this case) is exceeding the storage.sync quota. Unfortunately, there's not much we can do about it here—bug 1311516 tracks bubbling these up to the extension, and letting it handle the error instead of failing at sync time (Luca elaborates in bug 1575322, comment 4).

I saw you filed https://github.com/mozilla/multi-account-containers/issues/1661, and we can use that issue to track the Containers side of things.

Then there's the log bloat, where it looks like we're noisily recreating a key bundle for the same set of extensions:

1586172545829 Sync.CollectionKeyManager INFO Setting collection keys contents. Our last modified: 0, input modified: 1583839699482.
[...]
1586172546323 Sync.Engine.Extension-Storage INFO Successfully synced '[e-mail]'
1586172546346 Sync.CollectionKeyManager INFO Setting collection keys contents. Our last modified: 0, input modified: 1583839699482.
[...]
1586172546358 Sync.Engine.Extension-Storage INFO Successfully synced '[e-mail]'
1586172546361 Sync.Engine.Extension-Storage INFO Successfully synced 'jid1-BoFifL9Vbdl2zQ@jetpack'
[...]
1586172546372 Sync.CollectionKeyManager INFO Setting collection keys contents. Our last modified: 0, input modified: 1583839699482.
1586172546373 Sync.Engine.Extension-Storage INFO Successfully synced '{7a7a4a92-a2a0-41d1-9fd7-1e92480d612d}'
[...]

That logging comes from CollectionKeyManager#setContents, which is called by extension storage here, inside getKeyRing. That, in turn, is called by getKeys.

But this comment inside getKeys suggests we fetch the key ring record for every extension? The log seems to confirm that, where we have a Successfully synced <add-on> line followed by Setting collection keys contents, for each extension.

Is that correct, :glasserc? If so, I wonder if we want to cache the keyring, both to reduce calls to the server (it doesn't look like this does any caching?), and avoid recreating key bundles for all extensions every time we sync (and download and upload?) a record?

Comment 5

[Lina Butler (ex-Mozilla)]

(IIUC, I think the fix will be to cache the keyring in ExtensionStorageSync.jsm, so moving this over to that component).

Comment 6

[Ethan Glasser-Camp (:glasserc)]

Hmm, I wouldn't say "fetched", but yes we do reload it probably for every record, and yes we probably should cache it. When I wrote the original implementation, I was worried about how we would invalidate the cache once the sync was over, but now that I think about it again I think we should do the following:

• Don't provide the transformer when opening the collection outside of sync. We only use it during sync and we only call sync from within syncAll so dropping it in other places should be safe.
• Instead of passing the transformer a link to the crypto collection, get the keyring/salts or whatever from the crypto collection and pass those instead.

We drop the handle to the collection as soon as sync is over so we shouldn't have to invalidate this "cache" in any way.

Comment 7

[Ryan Kelly [:rfkelly]]

Thanks for providing these logs!

I'm marking this bug employee-confidential because the logs may reveal some of your browsing history. I'll follow up separately about whether we should actually be logging as much detail as we do at this log level.

Comment 8

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

(In reply to :Lina Cambridge from comment #4)

But this comment inside getKeys suggests we fetch the key ring record for every extension? The log seems to confirm that, where we have a Successfully synced <add-on> line followed by Setting collection keys contents, for each extension.

Best I can tell there are 21 extensions. If we were only fetching the keyring etc per extension, then we'd be in a much better position - Setting collection keys contents appears 3915 times in that log file, which is very bad

Ethan, any ideas?

Comment 9

[Ryan Kelly [:rfkelly]]

I'm marking this bug employee-confidential because the logs may reveal some of your browsing history.
I'll follow up separately about whether we should actually be logging as much detail as we do at this log level.

I filed Bug 1627856 to ensure we don't log lines that this in future. We really don't want to have any potentially-private information in your sync logs by default, because we don't want users to have to decide between their privacy and our ability to debug whatever problem they're facing.

Patrice, if you didn't realize that the sync logs contained some of the URLs you were currently visiting in the browser, then (a) I apologize for this oversight and want to assure you that it's a bug that will be fixed, and (b) please let us know if you'd like us to remove the attachment from bugzilla in order to protect your privacy.

Comment 10

[Ethan Glasser-Camp (:glasserc)]

:markh, I think the number of log lines regarding the keyring is due to what :lina said in Slack: "but i think the kinto extension storage engine is fetching keys for all records twice for each record—once to decrypt, once to encrypt".

Comment 11

[Patrice Peterson]

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

Patrice, if you didn't realize that the sync logs contained some of the URLs you were currently visiting in the browser, then (a) I apologize for this oversight and want to assure you that it's a bug that will be fixed, and (b) please let us know if you'd like us to remove the attachment from bugzilla in order to protect your privacy.

Indeed I didn't realize that, and I would like to request a deletion of the attachment.

Is there an easy way for me to provide you guys with a sanitized version of the log file?

Comment 12

[Lina Butler (ex-Mozilla)]

Hi Emma! Can you please scrub attachment 9138499 [details]? It contains PII.

Comment 13

[Lina Butler (ex-Mozilla)]

(In reply to Patrice Peterson from comment #11)

Indeed I didn't realize that, and I would like to request a deletion of the attachment.

Thanks for getting back to us, and apologies once again! Ryan's audited all our logs in bug 1627856, and we'll have a patch up shortly to avoid leaking URLs and other sensitive data in non-Trace logs.

Is there an easy way for me to provide you guys with a sanitized version of the log file?

Unfortunately, I think the only way now is to manually delete lines with Failed to fetch favicon for <URL> from the log. But, since (I think?) we have some idea of what's causing the issue—though not why it's logging so frequently—we can do without the log for now.

Comment 14

[Emma Humphries ☕️🎸🧞‍♀️✨ (she/they) [:emceeaich] (Pacific Time) use needinfo]

The content of attachment 9138499 [details] has been deleted for the following reason:

Removed by request.

Comment 15

[Lina Butler (ex-Mozilla)]

Thanks Emma! Opening this up again since the log is gone.

Comment 17

[Ethan Glasser-Camp (:glasserc)]

Attachment: Bug 1627638: Remove unused `context` argument

Comment 18

[Ethan Glasser-Camp (:glasserc)]

Attachment: Bug 1627638: Pass remote transformer only when syncing

Comment 19

[Ethan Glasser-Camp (:glasserc)]

Attachment: Bug 1627638: Get keyring once rather than on each record

This saves work because the keyring shouldn't change over the course
of a sync. One important kind of work is the logging work that is done
when add keys to a BulkKeyBundle.

It unfortunately has the consequence that we have to ensure the
keyring is "complete" before we create the transformer -- there's a
sequencing dependency here. This means changing the tests to behave
correctly.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/04243dce0349
Remove unused `context` argument r=rpl
https://hg.mozilla.org/integration/autoland/rev/453048c84b3f
Pass remote transformer only when syncing r=rpl
https://hg.mozilla.org/integration/autoland/rev/20f96c756cea
Get keyring once rather than on each record r=rpl

Comment 21

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/04243dce0349
https://hg.mozilla.org/mozilla-central/rev/453048c84b3f
https://hg.mozilla.org/mozilla-central/rev/20f96c756cea