Closed Bug 1458917 Opened 6 years ago Closed 6 years ago

Register dedicated timer for remote settings polling

Categories

(Firefox :: Remote Settings Client, enhancement)

enhancement
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 63
Tracking Status
firefox63 --- fixed

People

(Reporter: leplatrem, Assigned: leplatrem)

References

Details

Attachments

(1 file)

Currently, the RemoteSettings polling is done from nsBlocklistService::notify (for no good reason).

It would be better to decorelate the two, and let the RemoteSettings polling have its own "schedule" (from code with `timerManager.registerTimer()` or from manifest)
Assignee: nobody → mathieu
Target Milestone: --- → Future
Version: 57 Branch → Trunk
I'm stuck with the registration of the component. The timer does not seem to run, and when I try to get handle on the interface service in the tests with `getService()` I have this error:

```
 0:00.87 ERROR Unexpected exception NS_ERROR_XPC_GS_RETURNED_FAILURE: Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]
test_update_timer_interface@/home/mathieu/Code/Mozilla/firefox/obj-x86_64-pc-linux-gnu/_tests/xpcshell/services/settings/test/unit/test_remote_settings_poll.js:64:26
async*run_next_test/_run_next_test/<@/home/mathieu/Code/M
```

Florian, do have an idea what could be missing in my patch?

Thanks for your insights!
Flags: needinfo?(florian)
Your remote-settings.js file is registered with the build system as a JS module, not as an xpcom component.

If you want to register it as an xpcom component, you need to add it to the EXTRA_COMPONENTS list at https://searchfox.org/mozilla-central/rev/d0a41d2e7770fc00df7844d5f840067cc35ba26f/services/settings/moz.build#12 and to package it at https://searchfox.org/mozilla-central/rev/d0a41d2e7770fc00df7844d5f840067cc35ba26f/browser/installer/package-manifest.in#300

Once that is done, after rebuilding with 'mach build faster', I get this failure message instead:
PID 54842 | JavaScript error: file:///<objdir>/dist/Nightly.app/Contents/Resources/components/remote-settings.js, line 712: Error: Polling for changes failed: payload is undefined.

Note that the change I suggested above is for your testing/debugging only, as it would result in the remote-settings.js file being shipped twice. If you need your component to be accessible through Components.classes[...].getService, you should move it to a separate file.
Flags: needinfo?(florian)
Excellent! Thanks Florian!

There is one last thing: if I set the interval preference to 1 second, I can see that one notify() is called very close to startup (<1min). But then it looks like there is no other call. How can I trust that my timer will be triggered every X seconds as expected?

Is there another black belt trick to adjust?

Thanks again! :)
Flags: needinfo?(florian)
(In reply to Mathieu Leplatre (:leplatrem) from comment #6)

> There is one last thing: if I set the interval preference to 1 second, I can
> see that one notify() is called very close to startup (<1min). But then it
> looks like there is no other call.

There's a strict minimum interval of 30s enforced at https://searchfox.org/mozilla-central/rev/d0a41d2e7770fc00df7844d5f840067cc35ba26f/toolkit/components/timermanager/nsUpdateTimerManager.js#61-62
And the minimum actually used is longer, set by the pref at https://searchfox.org/mozilla-central/rev/d0a41d2e7770fc00df7844d5f840067cc35ba26f/browser/app/profile/firefox.js#100-103 to 120s.

For testing purposes, you can force this minimum interval to be reduced to 500ms, see https://searchfox.org/mozilla-central/search?q=utm-test-init
Flags: needinfo?(florian)
Alright, now that you showed it to me I feel guilty not having read the original source code...

Thanks a lot for your help on this :) It works \o/
Comment on attachment 8985603 [details]
Bug 1458917 - Register dedicated timer for Remote Settings

https://reviewboard.mozilla.org/r/251146/#review259154

Apologies for the delay! My Friday was a bit of a mess. Generally this looks nice - I just wonder if we could move the initialize() call into the new component as well, so it initializes at the same time as when the timer fires, which will be more or less the same as now? :-)

::: services/common/docs/RemoteSettings.rst
(Diff revision 5)
>          // await InternalAPI.reload(entry.id, entry.label, entry.weight);
>        }
>      });
>  
> -.. note::
> -    Currently, the update of remote settings is triggered by the `nsBlocklistService <https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/extensions/nsBlocklistService.js>`_ (~ every 24H).

Might be worth replacing this with some information on how we update this now (and how often) ?

::: toolkit/mozapps/extensions/Blocklist.jsm:248
(Diff revision 5)
> +    // Instantiate blocklist clients.
> +    BlocklistClients.initialize();

OK, this is sort of unfortunate because it now happens relatively early on startup, instead of just when we end up polling for changes.

Can the service you wrote that does the updates not handle the initialization as well? Then we can decouple these bits of code completely... :-)
Attachment #8985603 - Flags: review?(gijskruitbosch+bugs)
> Can the service you wrote that does the updates not handle the initialization as well? Then we can decouple these bits of code completely... :-)

That was the point I was trying to make in Bug 1454970, I don't want the remote settings module to depend on other components and be in charge of initializing its «consumers».

Regarding the timing of initialization for the blocklist stuff at startup, I can move it from the constructor to the `Blocklist::notify()` method if you prefer. What do you think?
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Mathieu Leplatre (:leplatrem) from comment #12)
> > Can the service you wrote that does the updates not handle the initialization as well? Then we can decouple these bits of code completely... :-)
> 
> That was the point I was trying to make in Bug 1454970, I don't want the
> remote settings module to depend on other components and be in charge of
> initializing its «consumers».
> 
> Regarding the timing of initialization for the blocklist stuff at startup, I
> can move it from the constructor to the `Blocklist::notify()` method if you
> prefer. What do you think?

Shouldn't it be in its own notify method, ie in RemoteSettingsTimer::notify ? :-)
Flags: needinfo?(gijskruitbosch+bugs)
Comment on attachment 8985603 [details]
Bug 1458917 - Register dedicated timer for Remote Settings

https://reviewboard.mozilla.org/r/251146/#review259186

Marking this as r+ per discussion on IRC. We'll go ahead with this and can re-evaluate if the impact of calling the remotesettingclient constructors and so on turns out to have a significant impact here. We'll merge blocklist-clients.js into Blocklist.jsm in a separate bug.
Attachment #8985603 - Flags: review+
Status: NEW → ASSIGNED
Keywords: checkin-needed
Target Milestone: Future → Firefox 63
Blocks: 1471522
We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s 5d382d9f9f20c5f1471f1b686fb9044e47052f72 -d a37e6ed0f4e7: rebasing 470043:5d382d9f9f20 "Bug 1458917 - Register dedicated timer for Remote Settings r=Gijs" (tip)
merging browser/installer/package-manifest.in
merging mobile/android/installer/package-manifest.in
merging modules/libpref/init/all.js
merging toolkit/mozapps/extensions/Blocklist.jsm
warning: conflicts while merging toolkit/mozapps/extensions/Blocklist.jsm! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)
Couldn't land your patch. Can you have a look at the previous comment?
Flags: needinfo?(mathieu)
Oh, indeed, lots of things had moved in Blocklist.jsm!

I rebased and pushed.
Flags: needinfo?(mathieu)
Keywords: checkin-needed
Pushed by ebalazs@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/23948209664a
Register dedicated timer for Remote Settings r=Gijs
Keywords: checkin-needed
Backed out changeset 23948209664a (bug 1458917) for Eslint failure and reftest crashes. CLOSED TREE

Logs:

Eslint:
https://treeherder.mozilla.org/logviewer.html#?job_id=185175634&repo=autoland&lineNumber=267

Error processing command. Ignoring because optional. (optional:packages.txt:comm/build/virtualenv_packages.txt)
[task 2018-06-27T14:34:29.622Z] TEST-UNEXPECTED-ERROR | /builds/worker/checkouts/gecko/toolkit/mozapps/extensions/Blocklist.jsm:695:36 | 'PREF_BLOCKLIST_UPDATE_ENABLED' is not defined. (no-undef)
[task 2018-06-27T14:34:29.622Z] TEST-UNEXPECTED-ERROR | /builds/worker/checkouts/gecko/toolkit/mozapps/extensions/Blocklist.jsm:696:7 | 'RemoteSettings' is not defined. (no-undef)
[taskcluster 2018-06-27 14:34:29.979Z] === Task Finished ===
[taskcluster 2018-06-27 14:34:29.979Z] Unsuccessful task run with exit code: 1 completed in 557.71 seconds

Reftests:
https://treeherder.mozilla.org/logviewer.html#?job_id=185180200&repo=autoland&lineNumber=1267 

REFTEST TEST-START | http://10.0.2.2:8888/tests/dom/svg/crashtests/380101-1.svg
[task 2018-06-27T14:50:27.972Z] 14:50:27     INFO -  REFTEST TEST-LOAD | http://10.0.2.2:8888/tests/dom/svg/crashtests/380101-1.svg | 0 / 361 (0%)
[task 2018-06-27T14:50:28.176Z] 14:50:28     INFO -  INFO | automation.py | Application ran for: 0:03:02.042993
[task 2018-06-27T14:50:28.176Z] 14:50:28     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpAtHatgpidlog
[task 2018-06-27T14:50:28.794Z] 14:50:28     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2018-06-27T14:50:29.613Z] 14:50:29     INFO -  REFTEST INFO | Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmp_YGSXZ/4484d5b0-a0cd-091d-0c2d-615e39121c12.dmp /builds/worker/workspace/build/symbols
[task 2018-06-27T14:50:40.120Z] 14:50:40     INFO -  REFTEST INFO | Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/4484d5b0-a0cd-091d-0c2d-615e39121c12.dmp
[task 2018-06-27T14:50:40.120Z] 14:50:40     INFO -  REFTEST INFO | Saved app info as /builds/worker/workspace/build/blobber_upload_dir/4484d5b0-a0cd-091d-0c2d-615e39121c12.extra
[task 2018-06-27T14:50:40.123Z] 14:50:40     INFO -  REFTEST PROCESS-CRASH | http://10.0.2.2:8888/tests/dom/svg/crashtests/380101-1.svg | application crashed [@ mozilla::net::nsSocketTransport::InitiateSocket()]
[task 2018-06-27T14:50:40.124Z] 14:50:40     INFO -  Crash dump filename: /tmp/tmp_YGSXZ/4484d5b0-a0cd-091d-0c2d-615e39121c12.dmp
[task 2018-06-27T14:50:40.124Z] 14:50:40     INFO -  Operating system: Android
[task 2018-06-27T14:50:40.125Z] 14:50:40     INFO -                    0.0.0 Linux 2.6.29-gea477bb #1 Wed Sep 26 11:04:45 PDT 2012 armv7l
[task 2018-06-27T14:50:40.125Z] 14:50:40     INFO -  CPU: arm
[task 2018-06-27T14:50:40.125Z] 14:50:40     INFO -       ARMv7 ARM Cortex-A8 features: swp,half,thumb,fastmult,vfpv2,edsp,neon,vfpv3
[task 2018-06-27T14:50:40.126Z] 14:50:40     INFO -       1 CPU
[task 2018-06-27T14:50:40.126Z] 14:50:40     INFO -  GPU: UNKNOWN
[task 2018-06-27T14:50:40.126Z] 14:50:40     INFO -  Crash reason:  SIGSEGV
[task 2018-06-27T14:50:40.127Z] 14:50:40     INFO -  Crash address: 0x0
[task 2018-06-27T14:50:40.127Z] 14:50:40     INFO -  Process uptime: not available
[task 2018-06-27T14:50:40.127Z] 14:50:40     INFO -  Thread 30 (crashed)
[task 2018-06-27T14:50:40.128Z] 14:50:40     INFO -   0  libxul.so!mozilla::net::nsSocketTransport::InitiateSocket() [nsSocketTransport2.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 0 + 0x2]
[task 2018-06-27T14:50:40.128Z] 14:50:40     INFO -       r0 = 0x00000000    r1 = 0xc94bddbf    r2 = 0x60317061    r3 = 0x00000529
[task 2018-06-27T14:50:40.128Z] 14:50:40     INFO -       r4 = 0x00000529    r5 = 0x5725aca8    r6 = 0x59a2f600    r7 = 0x534c7300
[task 2018-06-27T14:50:40.129Z] 14:50:40     INFO -       r8 = 0x534c71f0    r9 = 0x5725ac9c   r10 = 0x804b000b   r12 = 0x00000003
[task 2018-06-27T14:50:40.129Z] 14:50:40     INFO -       fp = 0x52d8fc00    sp = 0x534c7000    lr = 0x5cba6ae1    pc = 0x5ccb9c76
[task 2018-06-27T14:50:40.129Z] 14:50:40     INFO -      Found by: given as instruction pointer in context
[task 2018-06-27T14:50:40.130Z] 14:50:40     INFO -   1  libxul.so!mozilla::net::nsSocketTransport::OnSocketEvent(unsigned int, nsresult, nsISupports*) [nsSocketTransport2.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 0 + 0x5]
[task 2018-06-27T14:50:40.130Z] 14:50:40     INFO -       r4 = 0x5725ac00    r5 = 0x5725aca0    r6 = 0x549a6840    r7 = 0x534c7330
[task 2018-06-27T14:50:40.131Z] 14:50:40     INFO -       r8 = 0x00000000    r9 = 0x5725ac9c   r10 = 0x804b000b    fp = 0x52d8fc00
[task 2018-06-27T14:50:40.131Z] 14:50:40     INFO -       sp = 0x534c7308    lr = 0x5ccbadb7    pc = 0x5ccbadb7
[task 2018-06-27T14:50:40.131Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.132Z] 14:50:40     INFO -   2  libxul.so!mozilla::net::nsSocketEvent::Run() [nsSocketTransport2.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 90 + 0x3]
[task 2018-06-27T14:50:40.132Z] 14:50:40     INFO -       r4 = 0x5855c280    r5 = 0x5cc2c8dd    r6 = 0x00000000    r7 = 0x534c7340
[task 2018-06-27T14:50:40.132Z] 14:50:40     INFO -       r8 = 0x534c73bd    r9 = 0x534c73c0   r10 = 0x534c7837    fp = 0x52d8fc00
[task 2018-06-27T14:50:40.133Z] 14:50:40     INFO -       sp = 0x534c7338    lr = 0x5cccab61    pc = 0x5cccab61
[task 2018-06-27T14:50:40.133Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.133Z] 14:50:40     INFO -   3  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 1051 + 0x5]
[task 2018-06-27T14:50:40.134Z] 14:50:40     INFO -       r4 = 0x00000000    r5 = 0x5cc2c8dd    r6 = 0x00000000    r7 = 0x534c7828
[task 2018-06-27T14:50:40.134Z] 14:50:40     INFO -       r8 = 0x534c73bd    r9 = 0x534c73c0   r10 = 0x534c7837    fp = 0x52d8fc00
[task 2018-06-27T14:50:40.134Z] 14:50:40     INFO -       sp = 0x534c7348    lr = 0x5cc3306f    pc = 0x5cc3306f
[task 2018-06-27T14:50:40.135Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.136Z] 14:50:40     INFO -   4  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 519 + 0xd]
[task 2018-06-27T14:50:40.136Z] 14:50:40     INFO -       r4 = 0x00000001    r5 = 0x52d8fc00    r6 = 0x00000000    r7 = 0x534c7848
[task 2018-06-27T14:50:40.136Z] 14:50:40     INFO -       r8 = 0x534c78a0    r9 = 0x00000001   r10 = 0x534c78d7    fp = 0x534c78c8
[task 2018-06-27T14:50:40.136Z] 14:50:40     INFO -       sp = 0x534c7830    lr = 0x5cc34d71    pc = 0x5cc34d71
[task 2018-06-27T14:50:40.137Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.137Z] 14:50:40     INFO -   5  libxul.so!mozilla::net::nsSocketTransportService::Run() [nsSocketTransportService2.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 1026 + 0x5]
[task 2018-06-27T14:50:40.138Z] 14:50:40     INFO -       r4 = 0x52d6c120    r5 = 0x534c78a8    r6 = 0x00000000    r7 = 0x534c7918
[task 2018-06-27T14:50:40.138Z] 14:50:40     INFO -       r8 = 0x534c78a0    r9 = 0x00000001   r10 = 0x534c78d7    fp = 0x534c78c8
[task 2018-06-27T14:50:40.138Z] 14:50:40     INFO -       sp = 0x534c7850    lr = 0x5ccbf17d    pc = 0x5ccbf17d
[task 2018-06-27T14:50:40.139Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.139Z] 14:50:40     INFO -   6  libxul.so!non-virtual thunk to mozilla::net::nsSocketTransportService::Run() [nsSocketTransportService2.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 0 + 0x3]
[task 2018-06-27T14:50:40.139Z] 14:50:40     INFO -       r4 = 0x00000000    r5 = 0x5cc2c8dd    r6 = 0x00000000    r7 = 0x534c7920
[task 2018-06-27T14:50:40.140Z] 14:50:40     INFO -       r8 = 0x534c799d    r9 = 0x534c79a0   r10 = 0x534c7e17    fp = 0x52d8fc00
[task 2018-06-27T14:50:40.140Z] 14:50:40     INFO -       sp = 0x534c7920    lr = 0x5ccbf8f9    pc = 0x5ccbf8f9
[task 2018-06-27T14:50:40.140Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.141Z] 14:50:40     INFO -   7  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 1051 + 0x5]
[task 2018-06-27T14:50:40.147Z] 14:50:40     INFO -       r4 = 0x00000000    r5 = 0x5cc2c8dd    r6 = 0x00000000    r7 = 0x534c7e08
[task 2018-06-27T14:50:40.147Z] 14:50:40     INFO -       r8 = 0x534c799d    r9 = 0x534c79a0   r10 = 0x534c7e17    fp = 0x52d8fc00
[task 2018-06-27T14:50:40.147Z] 14:50:40     INFO -       sp = 0x534c7928    lr = 0x5cc3306f    pc = 0x5cc3306f
[task 2018-06-27T14:50:40.147Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.147Z] 14:50:40     INFO -   8  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 519 + 0xd]
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r4 = 0x00000000    r5 = 0x52d8fc00    r6 = 0x534c7e34    r7 = 0x534c7e28
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r8 = 0x52da0e3c    r9 = 0x52d8fc00   r10 = 0x52da0e30    fp = 0x2a322920
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       sp = 0x534c7e10    lr = 0x5cc34d71    pc = 0x5cc34d71
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -   9  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:23948209664a31c153463815fb4e93f62a2b3e0b : 334 + 0x7]
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r4 = 0x52da0e20    r5 = 0x52d2e3a0    r6 = 0x534c7e34    r7 = 0x534c7e50
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r8 = 0x52da0e3c    r9 = 0x52d8fc00   r10 = 0x52da0e30    fp = 0x2a322920
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       sp = 0x534c7e30    lr = 0x5cfb9605    pc = 0x5cfb9605
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -  10  libxul.so!MessageLoop::RunInternal() [message_loop.cc:23948209664a31c153463815fb4e93f62a2b3e0b : 325 + 0x7]
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r4 = 0x52d2e3a0    r5 = 0x52d8fc14    r6 = 0x534c7ea4    r7 = 0x534c7e70
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r8 = 0x00000000    r9 = 0x534c7e9c   r10 = 0x534c7f00    fp = 0x2a322920
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       sp = 0x534c7e58    lr = 0x5cf70ea1    pc = 0x5cf70ea1
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -  11  libxul.so!MessageLoop::Run() [message_loop.cc:23948209664a31c153463815fb4e93f62a2b3e0b : 318 + 0x5]
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r0 = 0x52d2e3a0    r1 = 0x00000000    r2 = 0x00000001    r3 = 0x00000001
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r4 = 0x52d2e3a0    r5 = 0x52d8fc14    r6 = 0x534c7ea4    r7 = 0x534c7e90
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       r8 = 0x00000000    r9 = 0x534c7e9c   r10 = 0x534c7f00    fp = 0x2a322920
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -       sp = 0x534c7e78    lr = 0x5cf70e4f    pc = 0x5cf70e4f
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -      Found by: call frame info
[task 2018-06-27T14:50:40.148Z] 14:50:40     INFO -  12  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:23948209664a31c15346381

Push with failures:
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=23948209664a31c153463815fb4e93f62a2b3e0b&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified

Backout:
https://hg.mozilla.org/integration/autoland/rev/e7c4e41b0d236e741d694a057eac22bca3a9a5af
Flags: needinfo?(mathieu)
This bug also causes XPCShell failures:

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=185196199&repo=autoland

TEST-START | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js
16:22:14  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js | xpcshell return code: 0
16:22:14     INFO -  TEST-INFO took 505ms
16:22:14     INFO -  >>>>>>>
16:22:14     INFO -  PID 3640 | JavaScript strict warning: resource://testing-common/AddonTestUtils.jsm, line 310: ReferenceError: reference to undefined property "testScope"
16:22:14     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "testScope"" {file: "resource://testing-common/AddonTestUtils.jsm" line: 310}]"
16:22:14     INFO -  PID 3640 | JavaScript strict warning: Z:/task_1530114860/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js, line 34: ReferenceError: reference to undefined property "enabledState"
16:22:14     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
16:22:14     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
16:22:14     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
16:22:14     INFO -  running event loop
16:22:14     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "enabledState"" {file: "Z:/task_1530114860/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js" line: 34}]"
16:22:14     INFO -  xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js | Starting setup
16:22:14     INFO -  (xpcshell/head.js) | test setup pending (2)
16:22:14     INFO -  PID 3640 | 1530116534066	addons.manager	DEBUG	Application has been upgraded
16:22:14     INFO -  PID 3640 | 1530116534075	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]
16:22:14     INFO -  PID 3640 | 1530116534077	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
16:22:14     INFO -  PID 3640 | 1530116534081	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm
16:22:14     INFO -  PID 3640 | 1530116534082	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm
16:22:14     INFO -  PID 3640 | 1530116534083	addons.manager	DEBUG	Starting provider: XPIProvider
16:22:14     INFO -  PID 3640 | 1530116534083	addons.xpi	DEBUG	startup
16:22:14     INFO -  PID 3640 | 1530116534083	addons.xpi	WARN	List of valid built-in add-ons could not be parsed.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2093"  data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2093
16:22:14     INFO -  PID 3640 | callProvider()@resource://gre/modules/AddonManager.jsm:206
16:22:14     INFO -  PID 3640 | _startProvider()@resource://gre/modules/AddonManager.jsm:654
16:22:14     INFO -  PID 3640 | startup()@resource://gre/modules/AddonManager.jsm:813
16:22:14     INFO -  PID 3640 | startup()@resource://gre/modules/AddonManager.jsm:2808
16:22:14     INFO -  PID 3640 | observe()@jar:file:///Z:/task_1530114860/build/application/firefox/omni.ja!/components/addonManager.js:66
16:22:14     INFO -  PID 3640 | promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:773
16:22:14     INFO -  PID 3640 | 1530116534085	addons.xpi	INFO	SystemAddonLocation directory is missing
16:22:14     INFO -  PID 3640 | 1530116534093	addons.xpi	INFO	Removing all system add-on upgrades.
16:22:14     INFO -  PID 3640 | 1530116534094	addons.xpi	DEBUG	checkForChanges
16:22:14     INFO -  PID 3640 | 1530116534094	addons.xpi	DEBUG	Loaded add-on state: ${}
16:22:14     INFO -  PID 3640 | 1530116534094	addons.xpi	DEBUG	scanForChanges changed: false, state: {}
16:22:14     INFO -  PID 3640 | 1530116534095	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 27
16:22:14     INFO -  PID 3640 | 1530116534095	addons.xpi	DEBUG	No changes found
16:22:14     INFO -  PID 3640 | 1530116534102	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider
16:22:14     INFO -  PID 3640 | 1530116534102	addons.manager	DEBUG	Provider finished startup: XPIProvider
16:22:14     INFO -  PID 3640 | 1530116534102	addons.manager	DEBUG	Starting provider: LightweightThemeManager
16:22:14     INFO -  PID 3640 | 1530116534102	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager
16:22:14     INFO -  PID 3640 | 1530116534102	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager
16:22:14     INFO -  PID 3640 | 1530116534103	addons.manager	DEBUG	Starting provider: GMPProvider
16:22:14     INFO -  PID 3640 | 1530116534105	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider
16:22:14     INFO -  PID 3640 | 1530116534105	addons.manager	DEBUG	Provider finished startup: GMPProvider
16:22:14     INFO -  PID 3640 | 1530116534105	addons.manager	DEBUG	Starting provider: PluginProvider
16:22:14     INFO -  PID 3640 | 1530116534105	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider
16:22:14     INFO -  PID 3640 | 1530116534106	addons.manager	DEBUG	Provider finished startup: PluginProvider
16:22:14     INFO -  PID 3640 | JavaScript strict warning: resource://gre/modules/LightweightThemeManager.jsm, line 694: ReferenceError: reference to undefined property "version"
16:22:14     INFO -  PID 3640 | 1530116534109	addons.manager	DEBUG	Completed startup sequence
16:22:14     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534066	addons.manager	DEBUG	Application has been upgraded"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534075	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534077	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534081	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534082	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534083	addons.manager	DEBUG	Starting provider: XPIProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534083	addons.xpi	DEBUG	startup"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534083	addons.xpi	WARN	List of valid built-in add-ons could not be parsed.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2093"  data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2093
16:22:14     INFO -  callProvider()@resource://gre/modules/AddonManager.jsm:206
16:22:14     INFO -  _startProvider()@resource://gre/modules/AddonManager.jsm:654
16:22:14     INFO -  startup()@resource://gre/modules/AddonManager.jsm:813
16:22:14     INFO -  startup()@resource://gre/modules/AddonManager.jsm:2808
16:22:14     INFO -  observe()@jar:file:///Z:/task_1530114860/build/application/firefox/omni.ja!/components/addonManager.js:66
16:22:14     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:773"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534085	addons.xpi	INFO	SystemAddonLocation directory is missing"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534093	addons.xpi	INFO	Removing all system add-on upgrades."
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534094	addons.xpi	DEBUG	checkForChanges"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534094	addons.xpi	DEBUG	Loaded add-on state: ${}"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534094	addons.xpi	DEBUG	scanForChanges changed: false, state: {}"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534095	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 27"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534095	addons.xpi	DEBUG	No changes found"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534102	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534102	addons.manager	DEBUG	Provider finished startup: XPIProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534102	addons.manager	DEBUG	Starting provider: LightweightThemeManager"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534102	addons.manager	DEBUG	Registering shutdown blocker for LightweightThemeManager"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534102	addons.manager	DEBUG	Provider finished startup: LightweightThemeManager"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534103	addons.manager	DEBUG	Starting provider: GMPProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534105	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534105	addons.manager	DEBUG	Provider finished startup: GMPProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534105	addons.manager	DEBUG	Starting provider: PluginProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534105	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534106	addons.manager	DEBUG	Provider finished startup: PluginProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "version"" {file: "resource://gre/modules/LightweightThemeManager.jsm" line: 694}]"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534109	addons.manager	DEBUG	Completed startup sequence"
16:22:14     INFO -  (xpcshell/head.js) | test pending (2)
16:22:14     INFO -  PID 3640 | JavaScript strict warning: resource://gre/modules/PushService.jsm, line 18: ReferenceError: reference to undefined property "getCryptoParams"
16:22:14     INFO -  (xpcshell/head.js) | test finished (2)
16:22:14     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "getCryptoParams"" {file: "resource://gre/modules/PushService.jsm" line: 18}]"
16:22:14     INFO -  TEST-PASS | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js | setup - [setup : 86] 0 == 0
16:22:14     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
16:22:14     INFO -  (xpcshell/head.js) | test setup finished (2)
16:22:14     INFO -  xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js | Starting test_part_1
16:22:14     INFO -  (xpcshell/head.js) | test test_part_1 pending (2)
16:22:14     INFO -  PID 3640 | *** Blocklist::notify: Requesting http://example.com/data/test_bug514327_3_outdated_1.xml
16:22:14     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
16:22:14     INFO -  Unexpected exception ReferenceError: PREF_BLOCKLIST_UPDATE_ENABLED is not defined at resource://gre/modules/Blocklist.jsm:695
16:22:14     INFO -  notify@resource://gre/modules/Blocklist.jsm:695:1
16:22:14     INFO -  loadBlocklist@Z:/task_1530114860/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js:59:3
16:22:14     INFO -  async*test_part_1@Z:/task_1530114860/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/test_blocklist_plugin_outdated.js:91:9
16:22:14     INFO -  async*run_next_test/_run_next_test/<@Z:\task_1530114860\build\tests\xpcshell\head.js:1430:22
16:22:14     INFO -  async*_run_next_test@Z:\task_1530114860\build\tests\xpcshell\head.js:1430:10
16:22:14     INFO -  run@Z:\task_1530114860\build\tests\xpcshell\head.js:681:9
16:22:14     INFO -  _do_main@Z:\task_1530114860\build\tests\xpcshell\head.js:219:3
16:22:14     INFO -  _execute_test@Z:\task_1530114860\build\tests\xpcshell\head.js:526:5
16:22:14     INFO -  @-e:1:1
16:22:14     INFO -  exiting test
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) Blocklist::notify: Requesting http://example.com/data/test_bug514327_3_outdated_1.xml"
16:22:14     INFO -  PID 3640 | 1530116534228	addons.manager	DEBUG	shutdown
16:22:14     INFO -  PID 3640 | 1530116534228	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider
16:22:14     INFO -  PID 3640 | 1530116534228	addons.xpi	DEBUG	shutdown
16:22:14     INFO -  PID 3640 | 1530116534234	addons.xpi-utils	DEBUG	Starting async load of XPI database c:\\users\\task_1530114860\\appdata\\local\\temp\\xpc-profile-dp8ook\\extensions.json
16:22:14     INFO -  PID 3640 | 1530116534234	addons.manager	DEBUG	Calling shutdown blocker for LightweightThemeManager
16:22:14     INFO -  PID 3640 | 1530116534234	addons.manager	DEBUG	Calling shutdown blocker for GMPProvider
16:22:14     INFO -  PID 3640 | 1530116534235	addons.manager	DEBUG	Calling shutdown blocker for PluginProvider
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534228	addons.manager	DEBUG	shutdown"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534228	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534228	addons.xpi	DEBUG	shutdown"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534234	addons.xpi-utils	DEBUG	Starting async load of XPI database c:\\users\\task_1530114860\\appdata\\local\\temp\\xpc-profile-dp8ook\\extensions.json"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534234	addons.manager	DEBUG	Calling shutdown blocker for LightweightThemeManager"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534234	addons.manager	DEBUG	Calling shutdown blocker for GMPProvider"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534235	addons.manager	DEBUG	Calling shutdown blocker for PluginProvider"
16:22:14     INFO -  PID 3640 | 1530116534237	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions
16:22:14     INFO -  PID 3640 | 1530116534237	addons.xpi-utils	DEBUG	shutdown
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534237	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions"
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534237	addons.xpi-utils	DEBUG	shutdown"
16:22:14     INFO -  PID 3640 | 1530116534240	addons.manager	DEBUG	Async provider shutdown done
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1530116534240	addons.manager	DEBUG	Async provider shutdown done"
16:22:14     INFO -  PID 3640 | *** Blocklist:onError: There was an error loading the blocklist file
16:22:14     INFO -  PID 3640 | XMLHttpRequest channel unavailable
16:22:14     INFO -  "CONSOLE_MESSAGE: (info) Blocklist:onError: There was an error loading the blocklist file
16:22:14     INFO -  XMLHttpRequest channel unavailable"
16:22:14     INFO -  <<<<<<<
16:22:14     INFO -  TEST-START | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_prefs.js
16:22:15  WARNING -  TEST-UNEXPECTED-FAIL | xpcshell.ini:toolkit/mozapps/extensions/test/xpcshell/test_blocklist_prefs.js | xpcshell return code: 0
16:22:15     INFO -  TEST-INFO took 622ms
Pushed by aiakab@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9aa9b21d0108
Register dedicated timer for Remote Settings r=Gijs
Keywords: checkin-needed
Ok, so this patch introduces a new timer which trigger RemoteSettings.pollChanges(), which initiates connections to http://firefox.settings.services.mozilla.com when the browser is running. This is prohibited while running test suites.

```
 FATAL ERROR: Non-local network connections are disabled and a connection attempt to firefox.settings.services.mozilla.com (13.32.205.187) was made.
```

For blocklist.xml there seems to be a lot of places where the extensions.blocklist.url preference is set to a dummy/local value:
https://searchfox.org/mozilla-central/search?q=extensions.blocklist.url&path=

I can try to mimic that, but before encouraging cargo cult, and grope for green tests I wish I could get some help to find the right way to do it. Gijs, is there any magic place to «mock» the call to the server, or clean way to simply disable the timer during tests?

Thanks in advance for your insights (and patience on this) :]
Flags: needinfo?(mathieu) → needinfo?(gijskruitbosch+bugs)
This used to be really terrible and you needed to modify like 5 different files. Now it's easier ( https://groups.google.com/forum/?fromgroups=&hl=en#!searchin/firefox-dev/user.js%7Csort:date/firefox-dev/jtavxJEAuDs/juOv9Wc8AgAJ ) - you can just add a dummy value in https://dxr.mozilla.org/mozilla-central/source/testing/profiles/perf/user.js . I think that should be enough, but you probably want to push to try to make sure...
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to :Gijs (he/him) from comment #29)
> This used to be really terrible and you needed to modify like 5 different
> files. Now it's easier (
> https://groups.google.com/forum/?fromgroups=&hl=en#!searchin/firefox-dev/
> user.js%7Csort:date/firefox-dev/jtavxJEAuDs/juOv9Wc8AgAJ ) - you can just
> add a dummy value in
> https://dxr.mozilla.org/mozilla-central/source/testing/profiles/perf/user.js
> . I think that should be enough, but you probably want to push to try to
> make sure...

Err, and https://dxr.mozilla.org/mozilla-central/source/testing/profiles/unittest/user.js . Oops.
(In reply to Mathieu Leplatre (:leplatrem) from comment #31)
> It looks like it was no enough :/
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=b85d150ea07c04f52f70bdbbb74b3179faea9cd2&selectedJob=1
> 85533980

I don't see any changes to either https://dxr.mozilla.org/mozilla-central/source/testing/profiles/unittest/user.js or https://dxr.mozilla.org/mozilla-central/source/testing/profiles/perf/user.js in the commits you pushed. Am I missing them? Wrong try link? Something else?
Flags: needinfo?(mathieu)
It's getting better now, but since the remote settings code tries to fetch the dummy URL it still fails here and there.

Apart from having dedicated preferences for tests to disable polling or silence errors, I don't have a clear plan for this right now...
Flags: needinfo?(mathieu)
Depends on: 1474252
Comment on attachment 8985603 [details]
Bug 1458917 - Register dedicated timer for Remote Settings

https://reviewboard.mozilla.org/r/251146/#review262798

::: browser/components/nsBrowserGlue.js:1070
(Diff revision 12)
> +
> +    RemoteSettings.init();

Hmm, can we add this to the startup idle tasks instead (ie at the bottom of `_scheduleStartupIdleTasks` ) ?
Keywords: checkin-needed
Pushed by csabou@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/101f97abc1d4
Register dedicated timer for Remote Settings r=Gijs
Keywords: checkin-needed
Pushed by cbrindusan@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d7f07181ca93
Register dedicated timer for Remote Settings r=Gijs
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/d7f07181ca93
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Pushed by mozilla@jorgk.com:
https://hg.mozilla.org/comm-central/rev/8fc3d2e640f5
Port bug 1458917 to TB/SM: add RemoteSettingsComponents.js to package manifests. rs=bustage-fix
You need to log in before you can comment on or make changes to this bug.