1874215 - Sync sets the log max_level for Rust code to Debug in all builds

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P2)

Description

[Randell Jesup [:jesup] (needinfo me)]

In all builds, if you're logged into Sync, Rust's log level (max_level) get set to Debug. This setting comes from JS via mozIAppServicesLogger in https://searchfox.org/mozilla-central/source/services/common/app_services_logger/src/lib.rs#36-49

Note that this changes logging for ALL rust modules, though most rust code compiles out Debug and Info level logging. Neqo (Http3/WebTransport) does not get compiled out, however, and so this makes neqo format every packet for logging in h3.

This is caused by one of services.sync.logger and services.sync.logger.engine, which are set to Debug.
Setting them to Error makes h3 downloads use 10% less CPU time in socket thread.

Sync shouldn't be changing the global logging level for the entire application by default

Comment 1

[Ben Dean-Kawamura [:bdk]]

I think we should be able to fix this one, but I have a few questions:

Note that this changes logging for ALL rust modules, though most rust code compiles out Debug and Info level logging

How does this work? I thought that the code would only be compiled out when certain feature flags were set on the log crate. However, if those feature flags are set I believe that all crates would have those log statements compiled out and the sync code wouldn't be able to change the log level to include debug records.

Setting them to Error makes h3 downloads use 10% less CPU time in socket thread.

Do you know what causes this difference? Is it formatting the records themselves or is it caused by writing to the console or some other file?

Sync shouldn't be changing the global logging level for the entire application by default

This makes sense, but if we removed that code and put the log level to INFO, is there a way to configure FF to include the debug statements if we wanted to?

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

The necko code checks max_level, and if it's DEBUG it formats data for logging and then calls qdebug!(), which eventually will call the method that's compiled out in opt builds. (we check max_level in a few other places as well). The compile-out feature only apply to the macro calls themselves (debug!/info!/etc)

The 10% cpu is entirely just formatting in the case I was looking at, but there are other internal logs in neqo that directly look at max_level and

To get the debugs, just set the about:config value to Debug/Info/etc, and run a debug build (so the calls aren't compiled out). If you make them info!()'s, then they'll be compiled in even in opt/release builds, and output if you change the pref.

They're compiled out in https://searchfox.org/mozilla-central/rev/961a9e56a0b5fa96ceef22c61c5e75fb6ba53395/toolkit/library/rust/shared/Cargo.toml#36 - that disables debug and trace levels in opt builds.

This causes significant CPU use in all http3 use (~25% of web traffic and growing), and the CPU use is impacting large uploads/downloads on high-bandwidth connections, where we end up maxed out on the core.

Comment 3

[Ben Dean-Kawamura [:bdk]]

I did some testing of the sync Rust logs and I think we should be able to just remove that LOC. I can get a PR up monday.

My setup was to build gecko from source, then use the RUST_LOG env variable to enable the debugging logs. I compared that to my more-or-less vanilla nightly install.

• With the debug build + RUST_LOG=debug, I saw logs from tabs in my console. I think dogear was there as well, but I just missed them.
• No matter what, I didn't see any Rust logs in the about:sync-logs.

So, I think removing that line shouldn't affect us short-term. Long-term, we should probably make it so that:

• Our Rust log records get forwarded to the sync log
• We use the INFO level for records that should be stored in normal user's sync logs (or whatever the default level is)
• You can use a debug build plus the RUST_LOG env var to see more detailed logs.

Comment 4

[Ben Dean-Kawamura [:bdk]]

Attachment: Bug 1874215 - Don't set the Rust max log level r=markh

Increasing the level to DEBUG is causing slowdowns for the necko code
and it doesn't seem like we're actually getting the Rust records into
the sync logs anyways.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3d7050fc3010
Don't set the Rust max log level r=markh

Comment 6

[Atila Butkovits]

Backed out for causing build bustages.

Backout link: https://hg.mozilla.org/integration/autoland/rev/b1c04f4cc46836ca84052c2d0e4c6f556a77a864

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=3d7050fc30108a4d43e72de826be1f291a5212ce&selectedTaskRun=ZFgSldFGTeeNM53ZpOUE1g.0

Failure log: https://treeherder.mozilla.org/logviewer?job_id=444219286&repo=autoland&lineNumber=53512

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bba5c678e394
Don't set the Rust max log level r=markh

Comment 8

[Iulian Moraru]

Backed out for causing xpchsell failures on test_register_app_services_logger.js.

• Push with failures

• Failure log

• Backout link

[task 2024-01-23T20:10:02.995Z] 20:10:02     INFO -  TEST-START | toolkit/profile/xpcshell/test_register_app_services_logger.js
[task 2024-01-23T20:15:03.008Z] 20:15:03  WARNING -  TEST-UNEXPECTED-TIMEOUT | toolkit/profile/xpcshell/test_register_app_services_logger.js | Test timed out
[task 2024-01-23T20:15:03.008Z] 20:15:03     INFO -  TEST-INFO took 300006ms
[task 2024-01-23T20:15:03.008Z] 20:15:03     INFO -  >>>>>>>
[task 2024-01-23T20:15:03.008Z] 20:15:03     INFO -  PID 6413 | [Parent 6413, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2886
[task 2024-01-23T20:15:03.008Z] 20:15:03     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-01-23T20:15:03.008Z] 20:15:03     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2024-01-23T20:15:03.009Z] 20:15:03     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-01-23T20:15:03.009Z] 20:15:03     INFO -  running event loop
[task 2024-01-23T20:15:03.010Z] 20:15:03     INFO -  PID 6413 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2024-01-23T20:15:03.010Z] 20:15:03     INFO -  PID 6413 | [Parent 6413, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:402
[task 2024-01-23T20:15:03.011Z] 20:15:03     INFO -  toolkit/profile/xpcshell/test_register_app_services_logger.js | Starting
[task 2024-01-23T20:15:03.012Z] 20:15:03     INFO -  (xpcshell/head.js) | test pending (2)
[task 2024-01-23T20:15:03.012Z] 20:15:03     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2024-01-23T20:15:03.014Z] 20:15:03     INFO -  "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
[task 2024-01-23T20:15:03.014Z] 20:15:03     INFO -  <<<<<<<
[task 2024-01-23T20:15:03.015Z] 20:15:03     INFO -  xpcshell return code: None
[task 2024-01-23T20:15:03.015Z] 20:15:03     INFO -  toolkit/profile/xpcshell/test_register_app_services_logger.js | Process still running after test!
[task 2024-01-23T20:15:03.018Z] 20:15:03     INFO -  TEST-START | xpcshell.toml:toolkit/components/extensions/test/xpcshell/test_ext_captivePortal.js

Comment 9

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/0ed9f0aba88d
Backed out changeset bba5c678e394 for causing xpchsell failures on test_register_app_services_logger.js. CLOSED TREE

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fc30ebd83cd5
Don't set the Rust max log level r=markh

Comment 11

[Cristian Tuns]

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