1635487 - Wire up sync logging to the bridged extension storage engine

Status: RESOLVED FIXED

(Firefox :: Sync, task)

Description

[Lina Butler [:lina]]

Once we have our new extension storage engine, we'll want to wire it up to the Desktop Sync logging machinery. For Reasons, this is a bit more complicated than it has to be, and I wanted to capture some of those sticking points in this ticket. This will involve changes to both a-s and m-c.

The standard for Rust logging is the log crate, which we use extensively in a-s. Unfortunately, log only lets you set a global logger, and only once. That means calling set_boxed_logger will set it for all of Firefox—I think one is already set, anyway, so that will fail with an error. But, even if it did work, we wouldn't want that, because other in-tree crates also use log. We don't want, say, WebRender and Necko trace logs getting written into about:sync-log!

This is why Dogear basically reimplements the log macros, but with a "driver" as the first argument. The driver has a logger, which, by default, uses the log crate's global logger. But Desktop overrides this to return its own logger, which calls into the Sync logger. There's some complicated machinery around dispatching log messages to the main thread, which we need to do because the logger is in JS. All of that is factored out into golden_gate::LogSink. On the JS side, we have another tiny helper class that adapts a Log.jsm logger to a mozIServicesLogger that golden_gate::LogSink expects.

If we want to copy what Dogear does, on the a-s side, we can add a new support crate (log-support?) with our reimplemented macros, and have them take a &dyn Log. We can store the logger in a field on webext_storage::Store, and pass it to any method that needs it, and thread that through to the callback.

It's kind of unfortunate that this means passing an extra log: &dyn Log as an argument to any function that wants to do logging, but it's one approach. Let's brainstorm others in this ticket, too!

Whatever approach we decide on here, we'll probably want to copy for our other Desktop integrations.

Comment 1

[Lina Butler [:lina]]

Lougenia, Thom, and I met last week to talk about this! I think the 😈 will be in the details, but here's a half-baked plan to wire up a-s logging to Gecko. Since we agreed to use a global logger, and use the target string to filter log messages, I think we only change a few things in Gecko! 🎉 We'll need to annotate all log macro calls with targets in a-s, but it seems like we can keep using the log crate without reimplementing our own.

On the m-c side:

• We already call log::set_boxed_logger to set the global logger in GeckoLogger, which currently just forwards WebRender messages to the graphics logger. We can extend it to specially handle a-s log messages too.
• For JS code to receive log messages from Rust, we can expose a new Rust XPCOM service. The service would own a map with strong references to one or more loggers, keyed by their targets (IOW, a HashMap<String, ThreadPtrHolder<mozIServicesLogger>>).
• The service would also have a method, like register(UTF8String target, mozIServicesLogger logger), to register a logger for a target by adding it to the map. This is what gets called from JavaScript, so FxA can do something like loggerService.register("app-services:fxa_client", new LogAdapter(FxAccountsCommon.log)), and extension storage can do the same thing, but replace fxa_client with webext_storage.
• Finally, we have our log method implementation check if the service has a logger registered for the target of the log record. If so, it gets a handle to the ThreadPtrHolder, and dispatches a runnable to the main thread, where it can unwrap the holder and call into the mozIServicesLogger. This is how LogSink works under the hood. Once we have the new logger wired up, we can get rid of LogSink.

Why would we want to support registering multiple loggers on the JS side? I think supporting multiple loggers is valuable because not everything from a-s can go into Sync logs. For example, if there's an error in an extension storage API method, like passing invalid JSON to set, we'd want to log that somewhere, so that debugging prints a more useful error than NS_ERROR_INVALID_ARG...but it can't go in about:sync-log, because that's not called as part of a sync, and Sync might not even be configured yet. But we could log those API errors in our Rust component using a separate "app-services:webext-storage:api" tag, and register a mozIServicesLogger that logs those to the browser console instead. And, when a sync runs, we can write sync-related errors, which would have their own tag, into about:sync-log.

What's ThreadPtrHolder and why do we need it? ThreadPtrHolder is a RefPtr (like Arc for XPCOM objects) that can only be unwrapped on the thread where it was created. It's handy because Rust might send log messages on any thread, but we can only call into a JS implementation of mozIServicesLogger on the main thread.

Why use a global logger? At first, I was thinking we'd have to rewrite our own log macros to take a &dyn Logger as their first argument. But, Thom pointed out that means we'd have to pass around the logger, either as an argument or struct field (what if we wanted to log inside a From<Error> conversion method, for example?), wherever we wanted to log, and that gets old quickly.

What about multiple loggers for a target? We could have the map store a Vec<ThreadPtrHolder<mozIServicesLogger>>, if we wanted to have loggers write to multiple places. But Log.jsm can do that already with its "appenders". For now, we can pass an adapter instead, and handle the logging in multiple places—like the console and Sync logs—on the JS side.

Comment 2

[Lougenia Bailey]

Attachment: Bug 1635487 - Added app services crate for sync logging

Comment 3

[Lina Butler [:lina]]

Thanks for uploading the work-in-progress patch Lougenia, it's looking solid! Would you like any feedback now, or should I hold off until you've pushed more changes?

Comment 4

[Lougenia Bailey]

Attachment: Bug 1635487 - Moved app services logger interface file, added test files

Depends on D79631

Comment 5

[Lougenia Bailey]

Attachment: Bug 1635487 - Moved app services logger interface file, added test files, fixed lint errors

Depends on D79631

Comment 6

[Lougenia Bailey]

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

Thanks for uploading the work-in-progress patch Lougenia, it's looking solid! Would you like any feedback now, or should I hold off until you've pushed more changes?

My apologies, Lina. I was trying to fix this revision and thought I had already hit Save Changes. Yes, please feel free to leave feedback.

Comment 7

[Lougenia Bailey]

Attachment: (Bug 1635487) Wired up sync logging for extension pref storage

Comment 8

[Lougenia Bailey]

Attachment: Bug 1635487 - Added app services crate for sync logging

Comment 9

[Lougenia Bailey]

Attachment: (Bug 1635487) Wired up sync logging for extension pref storage

Comment 10

[Lougenia Bailey]

Sorry for all the phabricator noise. I was bringing my github sensibilities to a phabricator party. If it's not clear this is the revision to review: https://phabricator.services.mozilla.com/D80975.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fec02fef5e73
 Wired up sync logging for extension pref storage r=lina,markh

Comment 12

[Razvan Maries]

Backed out for build bustages and xpcshell failure.

Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedTaskRun=aIsHfvseQ6yez5hDE31r8g.0&resultStatus=testfailed%2Cbusted%2Cexception&revision=fec02fef5e73cf4e56373bb830e8591647f192ca

Logs:
Bustage: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307711490&repo=autoland&lineNumber=32462
Xpcshell: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307713197&repo=autoland&lineNumber=7229

Backout: https://hg.mozilla.org/integration/autoland/rev/2f4d9a22b5da4665a1052ceb929e5db4a68ab49c

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8cd7fabbe270
 Wired up sync logging for extension pref storage r=lina,markh

Comment 14

[Lina Butler [:lina]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b5132a18f5dbf6d88976e53544bb369b1d57a501

Comment 15

[Natalia Csoregi [:nataliaCs]]

Backed out for multiple leaks.

backout: https://hg.mozilla.org/integration/autoland/rev/da08f29b4fbc09c1408c37d4a1354d26faccf8fe

push: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&revision=8cd7fabbe2703b2c2a70b3139f0cc2a4cb6621b6&selectedTaskRun=VXAlixIaSRiYEyd-n03FeQ.0

failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307731613&repo=autoland&lineNumber=5098

[task 2020-06-27T07:17:22.397Z] 07:17:22 INFO - nsTraceRefcnt::DumpStatistics: 2147 entries
[task 2020-06-27T07:17:22.397Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 BackstagePass
[task 2020-06-27T07:17:22.397Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 CondVar
[task 2020-06-27T07:17:22.397Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 IdlePeriod
[task 2020-06-27T07:17:22.397Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 Mutex
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 2 TaskManager
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 ThreadEventTarget
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 ThreadTargetSink
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 4 XPCNativeInterface
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 4 XPCNativeMember
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 3 XPCNativeSet
[task 2020-06-27T07:17:22.398Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 3 XPCWrappedNative
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 XPCWrappedNativeProto
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 4 XPCWrappedNativeTearOff
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 nsConverterOutputStream
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 nsJSPrincipals
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 nsStorageStream
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 7 nsTArray_base
[task 2020-06-27T07:17:22.399Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 1 nsThread
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO - TEST-INFO | leakcheck | default leaked 21 nsXPCWrappedJS
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO - TEST-UNEXPECTED-FAIL | leakcheck | default 4208 bytes leaked (BackstagePass, CondVar, IdlePeriod, Mutex, TaskManager, ...)
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO -
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO - leakcheck | Processing leak log file /var/folders/04/c5tnmbzj2v3d2hd11kp882kh000017/T/tmpm1u23I.mozrunner/runtests_leaks_tab_pid1550.log
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO -
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1550
[task 2020-06-27T07:17:22.400Z] 07:17:22 INFO -
[task 2020-06-27T07:17:22.401Z] 07:17:22 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-27T07:17:22.401Z] 07:17:22 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-27T07:17:22.401Z] 07:17:22 INFO - 0 |TOTAL | 38 0| 16932 0|
[task 2020-06-27T07:17:22.402Z] 07:17:22 INFO -
[task 2020-06-27T07:17:22.402Z] 07:17:22 INFO - nsTraceRefcnt::DumpStatistics: 400 entries

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/df0a1af35e23
 Wired up sync logging for extension pref storage r=lina,markh

Comment 17

[Lougenia Bailey]

The failures that caused the bustages have been resolved and the test failures look like they're already know. https://treeherder.mozilla.org/#/jobs?repo=try&revision=deeaa4ed53b861bc27a1cdd82821739d3f1cb993

Comment 18

[Cristina Coroiu [:ccoroiu]]

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