1641939 - Signature failed when updating whilst application is running

Status: VERIFIED FIXED

(Firefox :: Remote Settings Client, defect)

Description

[Cristian Comorasu, QA [:ccomorasu], Releae Desktop QA - Please contact [e-mail]]

Attachment: reduced_configuration2.json

[Steps to reproduce]:

1. Upload on main-preview/search-config staging reduced_configuration1.json attachment 9152799 [details].
2. Start Firefox with the attached user.js attachment 9152801 [details] (vary test with dump==true and dump=false).
3. Check that search engines are listed accordingly to the main-preview from staging with reduced_configuration1.json attachment 9152799 [details] applied.
4. Upload on main-preview/search-config staging reduced_configuration2.json attachment 9152798 [details].
5. Wait 2-3 minutes while checking the browser console.

[Expected result]:
Browser console lists SearchEngineSelector: Search configuration updated remotely after which you can restart browser or wait 5' as idle
The browser search engine list is updated with the required search engines that are listed in the updated config (step 3)

[Actual result]:
services.settings: main-preview/search-config Signature failed InvalidSignatureError: Invalid content signature (main-preview/search-config) RemoteSettingsClient.jsm:882
services.settings: Signature verified failed for main-preview/search-config. Retry from scratch RemoteSettingsClient.jsm:591
Full log: https://pastebin.com/RNYRmBEy

[Regression range]:
This is a remote settings issue, the regression range is not applicable.

[Note]:

• It is possible that this bug is a dupe after bug 1640023;
• Seems that the problem is not reproducible if we are using a different configuration than the reduced_configuration2.json, which adds a non existing search engine.

Comment 1

[Cristian Comorasu, QA [:ccomorasu], Releae Desktop QA - Please contact [e-mail]]

Attachment: reduced_configuration1.json

Comment 2

[Cristian Comorasu, QA [:ccomorasu], Releae Desktop QA - Please contact [e-mail]]

Attachment: user.js

Comment 3

[Mark Banner (:standard8)]

I've just seen this on the current nightly (78.0a1, 20200529095426) with the search-config on production main. We deployed an update earlier this evening:

22:00:24.595 services.settings: main/search-config Signature failed  InvalidSignatureError: Invalid content signature (main/search-config) RemoteSettingsClient.jsm:880
22:00:24.632 services.settings: Signature verified failed for main/search-config. Retry from scratch RemoteSettingsClient.jsm:589
22:00:24.709 services.settings: main/search-config Signature failed again InvalidSignatureError: Invalid content signature (main/search-config) RemoteSettingsClient.jsm:880
22:00:24.739 services.settings: InvalidSignatureError: Invalid content signature (main/search-config)
    InvalidSignatureError resource://services-settings/RemoteSettingsClient.jsm:131
    _validateCollectionSignature resource://services-settings/RemoteSettingsClient.jsm:780
    _importChanges resource://services-settings/RemoteSettingsClient.jsm:874
    maybeSync resource://services-settings/RemoteSettingsClient.jsm:592
    pollChanges resource://services-settings/remote-settings.js:310
    receivedBroadcastMessage resource://services-settings/remote-settings.js:464
    receivedBroadcastMessage resource://gre/modules/PushBroadcastService.jsm:263
    receivedBroadcastMessage resource://gre/modules/PushService.jsm:843
    finishHandshake resource://gre/modules/PushServiceWebSocket.jsm:618
    _handleHelloReply resource://gre/modules/PushServiceWebSocket.jsm:661
    _wsOnMessageAvailable resource://gre/modules/PushServiceWebSocket.jsm:1202
    onMessageAvailable resource://gre/modules/PushServiceWebSocket.jsm:111
remote-settings.js:318
22:00:24.740 BroadcastService: receivedBroadcastMessage: handler for remote-settings/monitor_changes threw error: InvalidSignatureError: Invalid content signature (main/search-config)
    InvalidSignatureError resource://services-settings/RemoteSettingsClient.jsm:131
    _validateCollectionSignature resource://services-settings/RemoteSettingsClient.jsm:780
    _importChanges resource://services-settings/RemoteSettingsClient.jsm:874
    maybeSync resource://services-settings/RemoteSettingsClient.jsm:592
    pollChanges resource://services-settings/remote-settings.js:310
    receivedBroadcastMessage resource://services-settings/remote-settings.js:464
    receivedBroadcastMessage resource://gre/modules/PushBroadcastService.jsm:263
    receivedBroadcastMessage resource://gre/modules/PushService.jsm:843
    finishHandshake resource://gre/modules/PushServiceWebSocket.jsm:618
    _handleHelloReply resource://gre/modules/PushServiceWebSocket.jsm:661
    _wsOnMessageAvailable resource://gre/modules/PushServiceWebSocket.jsm:1202
    onMessageAvailable resource://gre/modules/PushServiceWebSocket.jsm:111
PushBroadcastService.jsm:265

Comment 4

[Mark Banner (:standard8)]

[Tracking Requested - why for this release]: Remote settings might not be pushing out updates correctly.

Comment 5

[Mathieu Leplatre [:leplatrem]]

Attachment: sign_error spike after update

The last update was this one: (source)

  "main-workspace/search-config": [
    {
      "timestamp": 1590779207953,
      "datetime": "2020-05-29T19:06:47.945066+00:00",
      "by": "ldap:[e-mail]",
      "changes": {
        "delete": 2,
        "update": 562,
        "create": 83
      }
    }
  ],

And we can clearly see a spike of sign_error on Telemetry. Since we don't see much of sign_retry_error it means that clients flushed the local DB and retried successfully.

It seems like a lot to update 562 records, but I have a gut feeling that deletes are causing us issues. I will try to assemble a profile with old data to try to reproduce the pulling of this update locally.

Comment 6

[Mark Banner (:standard8)]

(In reply to Mathieu Leplatre [:leplatrem] from comment #5)

And we can clearly see a spike of sign_error on Telemetry. Since we don't see much of sign_retry_error it means that clients flushed the local DB and retried successfully.

That's strange. My Firefox Nightly was repeatedly complaining over a couple of days (unfortunately I've restarted it now), and it didn't actually pick up the changes.

Comment 7

[Mathieu Leplatre [:leplatrem]]

Attachment: distribution of sign_retry_errors

Indeed, there's something going on Nightly, we see a lot of retry errors.

While trying to reproduce locally, I found a critical bug on the server that causes updates with deletes to fail. https://github.com/Kinto/kinto-changes/issues/175 It will be fixed ASAP.
Nevertheless this bug does not affect retries, so I should investigate more what is going on here exactly.

Comment 8

[Tim Spurway [:tspurway]]

S1 or S2 bugs need an assignee - could you find someone for this bug?

Comment 9

[Mathieu Leplatre [:leplatrem]]

Attachment: Bug 1641939 - Flush local DB after retrying r?standard8

Comment 10

[Mathieu Leplatre [:leplatrem]]

Comment on attachment 9154017 [details]
Bug 1641939 - Flush local DB after retrying r?standard8

Beta/Release Uplift Approval Request

• User impact if declined: The code that is in charge of recovering from signature errors is flawed in certain situation. Declining this patch would make Remote Settings sync less robust.
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): The change only impact the part that is in charge of recovering from errors.
• String changes made/needed:

Comment 11

[Mathieu Leplatre [:leplatrem]]

Attachment: reproduce-search-config-error.js

This is the snippet that I used to reproduce the issue.

Note 1: the fix was induced by an issue with the way we handle deletions of records. So I would suggest that you delete records on the server to verify the fix.

Note 2: you may not be able to reproduce the issue anymore, even on old versions of the client, since a part of the fix was already deployed on the server.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a93b27ba6429
Flush local DB after retrying r=Standard8

Comment 13

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/a93b27ba6429

Comment 14

[Julien Cristau [:jcristau]]

Comment on attachment 9154017 [details]
Bug 1641939 - Flush local DB after retrying r?standard8

approved for 78.0b5

Comment 15

[Julien Cristau [:jcristau]]

Comment on attachment 9154017 [details]
Bug 1641939 - Flush local DB after retrying r?standard8

This patch conflicts with bug 1640136 which isn't on beta. Can you provide a rebased version?

Comment 16

[Cristian Comorasu, QA [:ccomorasu], Releae Desktop QA - Please contact [e-mail]]

I can confirm this issue is no longer reproducible, I verified using Fx 79.0a1, on macOS 10.13.6.

Comment 17

[Mathieu Leplatre [:leplatrem]]

Attachment: Bug 1641939 - Flush local DB after retrying r=standard8

Comment 18

[Mathieu Leplatre [:leplatrem]]

I opened this revision in phabricator, rebased on beta, tell me if it's convenient enough:
https://phabricator.services.mozilla.com/D79074

Alternatively we could also uplift Bug 1640136 and Bug 1644153 in the next iteration.

Comment 19

[Julien Cristau [:jcristau]]

Comment on attachment 9155571 [details]
Bug 1641939 - Flush local DB after retrying r=standard8

thanks.

Comment 20

[Julien Cristau [:jcristau]]

https://hg.mozilla.org/releases/mozilla-beta/rev/abd313068892

Comment 21

[Emil Ghitta, QA [:emilghitta]]

I can confirm that this issue is verified fixed using Firefox 78.0b6 (BuildId:20200611192304).