1907476 - CloseTab commands are not bulk sending urls together

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Sammy Khamis [:skhamis]]

I realized recently that some refactors to our flushQueue() logic for queuing CloseTab commands ended up having it so it's nearly impossible to bulk send urls together.

While it's not a "bug" in the code as the log shows:

1720731431279	Sync.RemoteTabs	INFO	Final tab list has 7 clients with 29 tabs.
1720731434380	Sync.RemoteTabs	INFO	Queued remote tab close command.
1720731434380	FirefoxAccounts	TRACE	CommandQueue observed topic=services.sync.tabs.command-queued, data=null, subject=null
1720731434385	FirefoxAccounts	TRACE	flushQueue total queued items: 1
1720731434385	FirefoxAccounts	TRACE	command for url https://www.sciencealert.com/physicists-have-created-the-worlds-most-fiendishly-difficult-maze was queued for sending 0.005s ago, so ensuring the next timer is set for it.
1720731434385	FirefoxAccounts	INFO	Setting a new close-tab timer with delay=4995 with existing timer=false
1720731434769	Sync.RemoteTabs	INFO	Queued remote tab close command.
1720731434769	FirefoxAccounts	TRACE	CommandQueue observed topic=services.sync.tabs.command-queued, data=null, subject=null
1720731434771	FirefoxAccounts	TRACE	flushQueue total queued items: 2
1720731434771	FirefoxAccounts	TRACE	command for url https://www.sciencealert.com/physicists-have-created-the-worlds-most-fiendishly-difficult-maze was queued for sending 0.391s ago, so ensuring the next timer is set for it.
1720731434771	FirefoxAccounts	TRACE	command for url https://news.ycombinator.com/item?id=40938325 was queued for sending 0.002s ago, so ensuring the next timer is set for it.
1720731434771	FirefoxAccounts	INFO	Setting a new close-tab timer with delay=4609 with existing timer=true
1720731435511	Sync.RemoteTabs	INFO	Queued remote tab close command.
1720731435511	FirefoxAccounts	TRACE	CommandQueue observed topic=services.sync.tabs.command-queued, data=null, subject=null
1720731435520	FirefoxAccounts	TRACE	flushQueue total queued items: 3
1720731435520	FirefoxAccounts	TRACE	command for url https://www.sciencealert.com/physicists-have-created-the-worlds-most-fiendishly-difficult-maze was queued for sending 1.14s ago, so ensuring the next timer is set for it.
1720731435520	FirefoxAccounts	TRACE	command for url https://news.ycombinator.com/item?id=40938325 was queued for sending 0.751s ago, so ensuring the next timer is set for it.
1720731435520	FirefoxAccounts	TRACE	command for url https://github.com/postgresml/korvus was queued for sending 0.01s ago, so ensuring the next timer is set for it.
1720731435520	FirefoxAccounts	INFO	Setting a new close-tab timer with delay=3860 with existing timer=true
1720731439385	FirefoxAccounts	TRACE	flushQueue total queued items: 3
1720731439386	FirefoxAccounts	TRACE	command for url https://www.sciencealert.com/physicists-have-created-the-worlds-most-fiendishly-difficult-maze was queued for sending 5.005s ago, so sending it now
1720731439386	FirefoxAccounts	TRACE	command for url https://news.ycombinator.com/item?id=40938325 was queued for sending 4.616s ago, so ensuring the next timer is set for it.
1720731439386	FirefoxAccounts	TRACE	command for url https://github.com/postgresml/korvus was queued for sending 3.875s ago, so ensuring the next timer is set for it.
1720731439386	FirefoxAccounts	INFO	Sending tab closures to 1333f78a7a86a7a62bbdfdf63bf87ccc device.
1720731439388	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for undefined
1720731439393	Services.Common.RESTRequest	DEBUG	POST request to https://api.accounts.firefox.com/v1/account/devices/invoke_command
1720731439393	Services.Common.RESTRequest	DEBUG	POST Length: 541
1720731439635	Services.Common.RESTRequest	DEBUG	POST https://api.accounts.firefox.com/v1/account/devices/invoke_command 200
1720731439635	Hawk	DEBUG	(Response) /account/devices/invoke_command: code: 200 - Status text: 
1720731439635	Hawk	DEBUG	Clock offset vs https://api.accounts.firefox.com/v1: -635
1720731439635	FirefoxAccounts	INFO	Successfully sent: {"enqueued":true,"notified":true}
1720731439635	FirefoxAccounts	INFO	Payload sent to device 1333f78a7a86a7a62bbdfdf63bf87ccc.
1720731439636	Sync.Telemetry	DEBUG	recording event: {"object":"command-sent","method":"close-uri/v1","value":"82730e658b90737a0b3522db2bb246b441728e71089538cf650a87d196638536","extra":{"flowID":"7d9574f4-dbdd-49c1-8ad6-79e740dbed18","streamID":"779c5f36-28d7-43c1-9fee-ed9ff8826f95"}}
1720731439636	FirefoxAccounts	TRACE	Setting pending command for device 1333f78a7a86a7a62bbdfdf63bf87ccc as sent: {"deviceId":"1333f78a7a86a7a62bbdfdf63bf87ccc","command":{"url":"https://www.sciencealert.com/physicists-have-created-the-worlds-most-fiendishly-difficult-maze"},"timeRequested":1720731434380,"timeSent":null}
1720731439637	FirefoxAccounts	INFO	Setting a new close-tab timer with delay=384 with existing timer=true

it seems to be more of a mismatch in expectation of logic. We ideally want to wait for as many to be due before we actually send a push. Thus allowing multiple commands close in timing to be bulked together. We should update the logic accordingly.

Comment 1

[Sammy Khamis [:skhamis]]

Attachment: Bug 1907476: Fix CloseTab commands not bulk sending URLs r?markh,lina

Comment 2

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/534a287e5c3f
Fix CloseTab commands not bulk sending URLs r=lina

Comment 3

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/534a287e5c3f