1683896 - Firefox Sync sends lots of chatter to my system logs every minute

Status: RESOLVED INVALID

(Firefox :: Sync, defect)

Description

[Jeff Fortin]

Attachment: firefox-sync-spamming-my-logs-anonymized.txt

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

Steps to reproduce:

journalctl -f

Actual results:

I see the attached result in my logs, with Firefox generating about 124 lines every minute (somehow categorized under the "gnome-shell" process according to systemd's journalctl, I'm not sure why)

Expected results:

Is it really necessary to send this to the system logs everytime Firefox Sync runs?

Comment 1

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

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

Comment 2

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

The sync logs use the standard logging facilities built in to Firefox and as far as I know, they make no attempt to send messages to systemd or integrate with the gnome-shell. The best I can suggest is that you disable sync logging - using about:config to set the preference services.sync.log.appender.file.logOnSuccess to false is probably the easiest way, so you'll only see logs when sync fails (setting services.sync.log.appender.file.logOnError to false will also avoid that, but will mean you have no visibility even inside Firefox when sync fails)

Comment 3

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

I don't think there's anything actionable here for us, so I'm closing this, but feel free to add more comments etc if you think there is.

Comment 4

[Jeff Fortin]

Hi Mark, just want to check something here, as today on Firefox 107 I observed that it prints all of this stuff to the terminal too, when running Firefox in a terminal without any arguments (i.e. not asking explicitly for debug level output)

1669575374166	Sync.Engine.Clients	TRACE	Event: weave:engine:sync:finish
1669575374166	Sync.RemoteTabs	TRACE	observed topic=weave:engine:sync:finish, data=clients, subject=null
1669575374167	Sync.SyncScheduler	TRACE	Handling weave:engine:sync:finish
1669575374167	Sync.Telemetry	TRACE	observed weave:engine:sync:finish clients
1669575374168	Sync.Synchronizer	INFO	Updating enabled engines: 4 clients.
1669575374169	Sync.EngineManager	TRACE	No change for engine extension-storage (webextensions.storage.sync.kinto is still false)
1669575374169	Sync.Synchronizer	INFO	Syncing all enabled engines.
1669575374170	Sync.Engine.Bookmarks	TRACE	Event: weave:engine:sync:start
1669575374170	Sync.Telemetry	TRACE	observed weave:engine:sync:start bookmarks
1669575374171	Sync.Engine.Bookmarks	DEBUG	Checking if server sync ID some_hash matches existing
1669575374171	Sync.Engine.Bookmarks.BookmarkSyncUtils	TRACE	Bookmarks sync ID up-to-date: {"existingSyncId":"some_hash"}
1669575374173	Sync.Engine.Bookmarks.Mirror	TRACE	Sync ID up-to-date in mirror: {"existingSyncId":"some_hash"}
1669575374176	Sync.Engine.Bookmarks	TRACE	Downloading & applying server changes
1669575374181	Sync.Engine.Bookmarks	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1669575374181	Sync.ErrorHandler	TRACE	Handling weave:engine:sync:applied
1669575374181	Sync.SyncScheduler	TRACE	Handling weave:engine:sync:applied
1669575374181	Sync.SyncScheduler	TRACE	Engine bookmarks successfully applied 0 items.
1669575374181	Sync.Telemetry	TRACE	observed weave:engine:sync:applied bookmarks
1669575374182	Sync.Engine.Bookmarks.Mirror	DEBUG	Merging bookmarks in Rust
1669575374263	Sync.Engine.Bookmarks.Mirror	DEBUG	Building local tree
1669575374447	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1669575374447	Sync.Engine.Bookmarks.Mirror	DEBUG	Building remote tree
1669575374655	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1669575374655	Sync.Telemetry	TRACE	observed weave:engine:validate:finish bookmarks
1669575374655	Sync.Engine.Bookmarks.Mirror	DEBUG	Building merged tree
1669575374666	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1669575374666	Sync.Engine.Bookmarks.Mirror	DEBUG	Applying merged tree
1669575374668	Sync.Telemetry	TRACE	observed weave:engine:sync:step bookmarks
1669575374669	Sync.Engine.Bookmarks.Mirror	DEBUG	Merging bookmarks in Rust took 486.881ms
1669575374669	Sync.Engine.Bookmarks.Mirror	DEBUG	No changes detected in both mirror and Places
1669575374669	Sync.Engine.Bookmarks.Mirror	TRACE	Recalculating frecencies for new URLs
1669575374671	Sync.Engine.Bookmarks	TRACE	Uploading local changes to server.
1669575374671	Sync.Engine.Bookmarks	INFO	Uploading 0 outgoing records
1669575374671	Sync.Engine.Bookmarks	TRACE	Finishing up sync

[etc., repeat this dozens of times]

Doesn't it seem odd that it prints "DEBUG" and "TRACE" outputs without being requested to do so? Because pretty much nothing else is printing to the terminal except ERROR-level statements and "JavaScript warning:" statements. I don't see why sync's statements would be more important than everything else going on in the browser, and I'm sure if I were to tell the app to print DEBUG, TRACE, INFO, etc. it would open the flood gates much wider than what I'm seeing now, hence why it looks a bit like a bug; it's as if the Firefox sync logging was pretending to be a certain log level, but proceeded to print everything by default regardless of severity...

Comment 5

[Jeff Fortin]

Oh, I see now that the logOnSuccess setting's default is "false" (I have no idea how mine could possibly have been turned on to "true", but oh well, I have reset it to false now) so I see now what you meant by "no action needed on our part", if it is expected that turning on that setting would cause printing and logging to occur regardless of the debug print level (presuming there is no bug as per the above)...

Comment 6

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

logOnSuccess is badly named - that generally just controls whether a log file (ie, the files shown in about:sync-log) is created on success. The terminal window seeing output generally means that browser.dom.window.dump.enabled is true (default=true on Nightly, false otherwise iirc) and services.sync.log.appender.dump is set to "Trace" (default = "Error") - so unless those prefs are set I can't explain what you are seeing.