Closed Bug 1856462 Opened 1 year ago Closed 4 months ago

MozillaUpdate causing Windows BITS service overflow (too many BITS operations queued)

Categories

(Toolkit :: Application Update, defect, P3)

Product:
Toolkit
Component:
Application Update
Version:
Firefox 120
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: alystair, Unassigned)

References

Details

(Whiteboard: [fidedi-ope])

Attachments

(8 files)

Event viewer list as requested
70.24 KB, image/png
Details
Results from BITSADMIN
199.18 KB, image/png
Details
BitsList Mozilla Bug
6.59 KB, text/plain
Details
Update since clearing the bitsadmin list
9.29 KB, text/plain
Details
AUS-logs opening Firefox console after several BITS errors
9.95 KB, text/plain
Details
AUS logs post BITS errors
9.95 KB, text/plain
Details
Attempt to copy/paste past few days of MOZ LOG
182.68 KB, text/plain
Details
backgroundupdate log showing DOWNLOADING issue
88.66 KB, text/plain
Details

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36

Steps to reproduce:

Installed Firefox, Firefox developer edition on my Windows 11 Pro machine.

Actual results:

Noted the following error has repeatedly showing up in Event Viewer for ages at this point:

Log Name: System
Source: Microsoft-Windows-Bits-Client
Date: 10/2/2023 10:12:35 AM
Event ID: 16398
Task Category: None
Level: Error
Keywords:
User: SYSTEM
Computer: Computer
Description:
A new BITS job could not be created. The current job count for the user Computer\user (60) is equal to or greater than the job limit (60) specified through group policy. To correct the problem, complete or cancel the BITS jobs that haven't made progress by looking at the error, and restart the BITS service. If this error recurs, contact your system administrator and increate the per-user and per-computer Group Policy job limits.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-Bits-Client" Guid="{ef1cc15b-46c1-414e-bb95-e76b077bd51e}" />
<EventID>16398</EventID>
<Version>0</Version>
<Level>2</Level>
<Task>0</Task>
<Opcode>0</Opcode>
<Keywords>0x8000000000000000</Keywords>
<TimeCreated SystemTime="2023-10-02T14:12:35.2039530Z" />
<EventRecordID>172944</EventRecordID>
<Correlation ActivityID="{92707003-f3c6-0008-571f-dc94c6f3d901}" />
<Execution ProcessID="42012" ThreadID="44368" />
<Channel>System</Channel>
<Computer>theVision</Computer>
<Security UserID="S-1-5-18" />
</System>
<EventData>
<Data Name="entityName">COMPUTER\user</Data>
<Data Name="currentSize">60</Data>
<Data Name="currentLimit">60</Data>
</EventData>
</Event>

Running bitsadmin /list as an admin will show that MozillaUpdate is to blame for all this.

Expected results:

Firefox should properly manage its BITS usage to prevent these errors, I believe this has been going on since Firefox started using the BITS service to self-update.

I accidentally set this as 120.0, it's actually 118.0.1 (64-bit), although likely even previous.

The Bugbug bot thinks this bug should belong to the 'Core::Widget: Win32' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: Untriaged → Widget: Win32
Product: Firefox → Core
Component: Widget: Win32 → Application Update
Product: Core → Toolkit

Looking at my own event viewer I'm not seeing anything, could you note where this is showing up?

Flags: needinfo?(alystair)

Here's the list showing repeated BITS errors due to stacking FF updaters, approximately 4115 recorded events since 2 months ago.

Flags: needinfo?(alystair)
Attached image Results from BITSADMIN —

Forgot to attach BITSAdmin listing screenshot. As you can see, BITS is totally clogged by Mozilla related items

Results of first/last listed:

C:\Windows\System32>bitsadmin /getcompletiontime {5A92B9BD-3FFE-4E06-BB7C-2E47CC6BE5D3}

BITSADMIN version 3.0
BITS administration utility.
(C) Copyright Microsoft Corp.

8/4/2023 9:45:39 AM

C:\Windows\System32>bitsadmin /getcompletiontime {7FF827BE-1E18-4CFC-8D5D-F823EFF201F3}

BITSADMIN version 3.0
BITS administration utility.
(C) Copyright Microsoft Corp.

10/31/2023 1:14:52 PM

My theory (without looking at your codebase) is that your BITS integration isn't checking for error responses, and your updater is deleting the downloaded files before declaring it 'complete' in BITS, which causes the BITSADMIN jobs to be stuck in 'TRANSFERRED' state limbo - getting stuck in the list forever until someone cancels the job... In this scenario the BITS job should be cancelled which will remove it from the queue.

C:\Windows\System32>bitsadmin /complete {5A92B9BD-3FFE-4E06-BB7C-2E47CC6BE5D3}

BITSADMIN version 3.0
BITS administration utility.
(C) Copyright Microsoft Corp.

Unable to complete job - 0x80070002
The system cannot find the file specified.

Hi! I see that this is something we should fix. Do I understand correctly, that it does not break the updater in any way and the only problem is, that this is list is getting longer? Based on that I have set the priority and severity to 3. If you can explain how that negatively affects functionality, we could increase the severity of this bug. Thanks for the report!

Severity: -- → S3
Priority: -- → P3

(In reply to Alystair from comment #6)

My theory (without looking at your codebase) is that your BITS integration isn't checking for error responses

We do attempt to handle error responses and tell BITS to cancel the transfer in that case, here.

and your updater is deleting the downloaded files before declaring it 'complete' in BITS

The documentation states:

Download files are not available until you call the Complete method. Call the Complete method after BITS successfully transfers the files. The method renames the temporary download files to their final destination names and removes the job from the queue.

As such, it isn't even possible for us to delete the downloaded files before calling Complete.

All I know is that I recently reset the BITS jobs using BITSADMIN and after about a week ago it's starting to amass them again in the list... if you have a suggestion as to how I can provide additional details I'm all ears.

BITS administration utility.
(C) Copyright Microsoft Corp.

{F851CDDA-B83A-4CCF-A8C7-25AC7C57E528} 'Edge Component Updater' TRANSFERRED 1 / 1 1673777 / 1673777
{01E3417E-C040-4C67-B64B-A7B2164A8EAE} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{B67954FC-EE85-4196-9D0C-5343818580ED} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{943572B1-7C7B-4D21-9E20-3E4207441336} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{C5A73C6E-97E5-42CC-B9A8-1CAA67CE6446} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{0E349208-39EF-430C-902E-9ED2A4E36BDD} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 8395165 / 8395165
{7F16B8E9-0C95-44D0-B31F-15C482348192} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{52B44442-5CC9-4EB0-92CE-016A7057FD5F} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 8395165 / 8395165
{678D2440-AB32-4175-A46A-E09CFFBA47F2} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{BB188BFF-18E8-4DAA-B177-B207A5DC95F5} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 8395165 / 8395165
{6C91955A-F06D-4845-A244-D90D2AE81417} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 11952252 / 11952252
{66BBC2EA-5EC1-4CA7-9223-501BF084E064} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 8395165 / 8395165
{2E82EEEC-728F-47F3-A667-94FF95DD4DC4} 'MozillaUpdate CA9422711AE1A81C' TRANSFERRED 1 / 1 12518828 / 12518828
Listed 13 job(s).```

What would be helpful is a browser console log of this issue happening. My usual instructions for collecting one are:

  1. Navigate to about:config.
  2. Set app.update.log to true.
  3. Open the Browser Console either with the hotkey Control+Shift+J (Command+Shift+J on macOS), or via Hamburger Menu->More Tools->Browser Console
  4. In the Filter textbox at the top, enter AUS: to filter out everything except the update messages.
  5. Navigate to the "Update" section of about:preferences. It should automatically check for an update.
  6. Once the update check has completed, copy the messages out of the Browser Console and attach them to this bug.

But I'm not entirely sure at what point the failure is happening, so I don't know if this will be sufficient to collect a log of the actual problem. But perhaps it will provide a place to start. Maybe wait a while before copying the log to see if any additional errors are logged that might be related?

Flags: needinfo?(alystair)

Just to confirm, I've set the flags on both FF and FF Dev Ed. - I don't need to keep the browsers open for the logs to be generated, correct? I have large swaths of time where I simply don't open the browser (it's not my day-to-day and mostly for site debugging and compat)

(In reply to Alystair from comment #11)

Just to confirm, I've set the flags on both FF and FF Dev Ed. - I don't need to keep the browsers open for the logs to be generated, correct? I have large swaths of time where I simply don't open the browser (it's not my day-to-day and mostly for site debugging and compat)

The short answer is that you do need the browser to be open for the logs to be generated. But even if you don't leave it open especially long, it could give us useful information. Oh, it would also be good if there is at least one free slot to create a BITS job so that we can see why it doesn't get removed rather than just seeing it not being able to create one in the first place.

Sorry but you'll need to come up with alternative tooling or some sort of passive logger as part of the updater system - I hardly ever have FF open outside of specific cross browser compatibility testing and debugging - I just checked in today and I had 21 jobs stuck in 'TRANSFERRED' state all from Mozilla update, it actually seems many are duplicates.

I discovered I can turn off background FF updates so that's what I'll do to keep BITS from jamming up again after a final reset. Sorry I can't spend additional time helping identity the root cause, if you can provide some sort of passive tooling I can reactivate the system and let it begin collecting data passively.

It does seem like there are multiple duplicate jobs for the same updates (as you can see per both bytes transferred and job names), perhaps something is terminating updates in the background (computer sleeping, reboot, aliens 👽), and then the updater creates a additional duplicate BITS jobs instead of utilizing prior ones ¯_(ツ)_/¯

Flags: needinfo?(alystair)
Attached file BitsList Mozilla Bug —
I've arrived here thanks to duckduckgo search engine terms "Mozilla fills BITS list 16398" Windows 10 Pro - Firefox installed - rarely use the machine or any browser on it as I use it as a file server and Plex media server - the machine is in a rack in a closet. Basically, only using Firefox when I remote to the machine to do updates and or verification of various family reported issues. In troubleshooting another random machine restart issue, I found hundreds of event log 16398. Another search led me to bitsadmin /list /allusers The common user of the machine that auto logs in on PC startup does not see this in list. Only /allusers. Other than uninstalling Firefox, which, for as little as I use it I'm willing to do, what do you need to fix this error?

I've arrived here thanks to duckduckgo search engine terms "Mozilla fills BITS list 16398"
Windows 10 Pro - Firefox installed - rarely use the machine or any browser on it as I use it as a file server and Plex media server - the machine is in a rack in a closet.
Basically, only using Firefox when I remote to the machine to do updates and or verification of various family reported issues.
In troubleshooting another random machine restart issue, I found hundreds of event log 16398. Another search led me to bitsadmin /list /allusers
The common user of the machine that auto logs in on PC startup does not see this in list. Only /allusers.
Other than uninstalling Firefox, which, for as little as I use it I'm willing to do, what do you need to fix this error?

C:\Windows\system32>bitsadmin /LIST /ALLUSERS

BITSADMIN version 3.0
BITS administration utility.
(C) Copyright Microsoft Corp.

{893F4020-6F86-4321-B30B-CAF0D1DA1247} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{0614D928-0283-4680-98FE-D617C56E588A} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{F7FC0988-523D-42D2-9FF2-6F74F954B048} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{C3BD1FEC-3FF0-4813-86F2-E6BCF9728A69} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{92CA26C2-4ACE-4DBD-81D3-560C954D37B9} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{9D017F72-5D1C-4B15-9070-28AB019D7D37} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{97152693-A3C7-4004-90E5-6DBB26793E67} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{2B3C87F4-F0E6-428A-9DF2-778614B682CB} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{A8E40242-D367-40CB-915F-E5174E9A8663} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{801D9F30-A364-456A-B882-22418721E500} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{A9FFB2CF-38D4-44AC-BC87-0D1CCE048CC6} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{C2763C02-0CC5-4EBB-99A3-C6BC38D90F5F} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{EC6C2A70-9E1D-41E0-9DA0-F65FB394ACF6} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{5703DC31-E437-45E7-925E-324D4BF6521F} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{5E4F907A-55F2-48B7-AA82-D4650BD20AE1} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{5E9CE1AD-7FD2-4931-90F9-9E26A2341663} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{974E4CE8-D3E6-4126-B1C5-12E1566735CD} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{5FEDFE2F-F771-4CCD-9927-D8769992E5FC} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{21D152C6-B1A2-40B5-855D-3DD1B0E0CF77} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{30E47573-4ACD-4DA3-B878-8998DDF5EED7} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{AE103604-2B83-418A-8DA7-EC9BC7817BFF} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{13EEF7EB-F558-473B-8950-9C23E82774CD} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{E61838DB-F22A-4B3E-944A-8DC39B8D5DBC} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{0EA2AA9E-1FA9-4C5B-B842-A3DC67FC1002} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{AB777115-1E43-49EF-8B66-3D85830E11B1} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{CD9AEC90-1050-4EC8-9506-7BD010399370} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{F262E784-A8E0-4252-847C-0ED2AA4820C6} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{904EA59A-D2D1-4E2C-9075-900012BE5499} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{7D99DB42-ED36-4D22-9F0C-9BE2DBB131C9} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{B1C93291-B0D0-48F5-9F64-22B93DE0EFE1} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{9ED1E52E-10D4-43EE-91F7-378724CD66FB} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{F58AE0B8-7B53-4BBB-806F-132C766B74AC} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{3A50FBF4-4EC8-4E43-B58C-11D7BA31A0DE} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{D6EAD624-5D77-402E-9094-AF72ECD2D498} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64714489 / 64714489
{37C7B136-8156-4655-A019-2A3C11130A14} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{BD43DE9F-C3E5-4BDE-A0F9-00F7EE09FA91} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{43EFEF97-EE20-4625-93AD-883F367C287D} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{45212430-B15C-496C-BA42-56BD17F5DE71} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{24767FA6-F1C4-4CDC-A09F-DC012033BB3E} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{97AB1C77-D0D0-459D-9D12-38BE49E6E29E} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{11A463BE-6883-4B75-8062-F5EA44A90AFD} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{37E9E4DA-B33E-4AC8-ADDF-AE7FC1E33A71} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{01B932B8-8066-4730-87E9-0E1B583BC142} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{339EBB3C-C828-4534-A28D-BA7FE98B8DA3} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{61907747-A0A8-450B-BC35-DBDFDE2DCBBF} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{0536FA49-5D96-4ACE-ABA5-B8615173B0EE} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{26429222-CD6E-4177-870F-1B4226ACBBE9} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{82772504-63C2-46D1-96F1-3FCE598E58E4} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{18FCA980-A362-4036-8722-E5F5C5981447} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{4FE7BAAA-4B7D-4929-B63D-65B87401180A} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{5B59A8D2-A57E-45DE-A0FE-C6214A1EF8CB} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{73F33426-C1A0-4C46-9CB5-8EE23E8BC2D7} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{D9CDE136-5AAA-4499-9A4A-3245D70D704E} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{3E59237C-EC99-4A2F-B704-4FD962723543} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{016A40B4-C3BA-497B-8010-F6DDB633D14E} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{D3D5E400-5AC5-44ED-B3C0-685526D43129} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{31968038-C21D-4215-BE4C-8040329B7F8C} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{BC599D58-232B-4A78-9A53-4312A7BD0A90} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{67CB0239-C52A-4DB9-A508-287B09359C32} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
{6BB8C489-24BF-4A0E-B188-99D8BD19FF52} 'MozillaUpdate 308046B0AF4A39CB' TRANSFERRED 1 / 1 64903789 / 64903789
Listed 60 job(s).

Would you be able to provide logs as requested in Comment 10?

Flags: needinfo?(jamminr)

While following instruction from comment 10, i forgot I'd found/followed a previous potential troubleshooting step of setting a false boolean for app.update.BITS.enabled. Ran the commands. I've not copied them as I believe they would not be helpful.
However, in Win event log, this error did occur, and is the first time it's occurred, and I can't find any other instance of it.

  • <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  • <System>
    <Provider Name="Firefox Default Browser Agent" />
    <EventID Qualifiers="32775">2</EventID>
    <Version>0</Version>
    <Level>2</Level>
    <Task>0</Task>
    <Opcode>0</Opcode>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2024-02-03T00:46:30.6608712Z" />
    <EventRecordID>66400</EventRecordID>
    <Correlation />
    <Execution ProcessID="0" ThreadID="0" />
    <Channel>Application</Channel>
    <Computer>xxxxx</Computer>
    <Security />
    </System>
  • <EventData>
    <Data>0x80070002 in RegistryDeleteValue:323</Data>
    </EventData>
    </Event>

After adjusting about:preferences to re-enable bits, restarted Firefox for good measure, opened the console and ran updates.
here is the latest....

AUS:STB UpdateServiceStub - Begin.
Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content. react-transition-group.js:9:10154
AUS:SVC Creating UpdateService
AUS:SVC Logging current UpdateService status:
AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC getCanApplyUpdates - testing write access C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\308046B0AF4A39CB\update.test
AUS:SVC isServiceInstalled - returning true
AUS:SVC shouldUseService - returning true
AUS:SVC getCanApplyUpdates - bypass the write checks because the Windows Maintenance Service can be used
AUS:SVC isServiceInstalled - returning true
AUS:SVC shouldUseService - returning true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC Elevation required: false
AUS:SVC Other instance of the application currently running: false
AUS:SVC Downloading: false
AUS:SVC End of UpdateService status
AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC CheckerService:checkForUpdates - checkType: 2
AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 1.
AUS:SVC waitForOtherInstances - beginning polling
AUS:SVC waitForOtherInstances - no other instances found, exiting
AUS:SVC CheckerService:getUpdateURL - checkType: 2
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - request got 'load' event
AUS:SVC CheckerService:#updateCheck - request completed downloading document
AUS:SVC CheckerService:#updateCheck - number of updates available: 0
AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC isServiceInstalled - returning true
AUS:SVC shouldUseService - returning true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC getCanUseBits - BITS can be used to download updates
AUS:AUM AppUpdater:check - currentState=STATE_IDLE
AUS:AUM AppUpdater:check - starting update check
AUS:SVC CheckerService:checkForUpdates - checkType: 2
AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 2.
AUS:SVC CheckerService:getUpdateURL - checkType: 2
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - request got 'load' event
AUS:SVC CheckerService:#updateCheck - request completed downloading document
AUS:SVC CheckerService:#updateCheck - number of updates available: 0
AUS:AUM AppUpdater:check - Update check succeeded
AUS:SVC UpdateManager:_loadXMLFileIntoArray - XML file does not exist. path: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\308046B0AF4A39CB\active-update.xml
AUS:SVC UpdateManager:UpdateManager - Initialized downloadingUpdate to null
AUS:SVC UpdateManager:UpdateManager - Initialized readyUpdate to null
AUS:AUM AppUpdater:check - result: NO_UPDATES_FOUND
AUS:AUM AppUpdater:check - currentState=STATE_IDLE
AUS:AUM AppUpdater:check - starting update check
AUS:SVC CheckerService:checkForUpdates - checkType: 2
AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 3.
AUS:SVC CheckerService:getUpdateURL - checkType: 2
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - request got 'load' event
AUS:SVC CheckerService:#updateCheck - request completed downloading document
AUS:SVC CheckerService:#updateCheck - number of updates available: 0
AUS:AUM AppUpdater:check - Update check succeeded
AUS:AUM AppUpdater:check - result: NO_UPDATES_FOUND
Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content. react-transition-group.js:9:10154
Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content. 2 aboutconfig.js:444:19

It takes 2-4 hours for the multiple BITS event logs to occur, i'll let both firefox and console sit open and will update once/if/when i notice them.

Flags: needinfo?(jamminr)

Apologies for the bold print - i do not know how to edit/correct it, and it was unintended.

No BITS Windows event log errors in the past 15 hours. I am not sure why. Previous to my post, counting past 2 days, there's been 25-30 per day. 3811 'bits task list full" entries since as far back as Jan 23, 2023
Perhaps they stopped due to any number of changes I'd made to the system in attempting to correct the random restarts the computer was doing averaging 2 in a 24 hour period. (That seems to have settled also).
The only two changes I directly made regarding Firefox were making it the default browser, and the disable/then re-enable, of the app.update.BITS.enabled feature.
The BITS task list is still full (and seems to be the same as I posted in comment 15)
I'll eventually teach myself how to clean that, but for now, leaving as is since attempting to help you help us.
The browser console did show one update cycle.
For now, i've closed the Firefox browser window (leaving the console open), and set Edge back as my default in hopes I can replicate.

Console log of the most recent auto update cycle.
I notice there's no timestamps in the console log. If there's a way to enable those, let me know.

AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC CheckerService:checkForUpdates - checkType: 2
AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 4.
AUS:SVC CheckerService:getUpdateURL - checkType: 2
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml?force=1
AUS:SVC CheckerService:#updateCheck - request got 'load' event
AUS:SVC CheckerService:#updateCheck - request completed downloading document
AUS:SVC CheckerService:#updateCheck - number of updates available: 0
AUS:SVC getCanApplyUpdates - testing write access C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\308046B0AF4A39CB\update.test
AUS:SVC isServiceInstalled - returning true
AUS:SVC shouldUseService - returning true
AUS:SVC getCanApplyUpdates - bypass the write checks because the Windows Maintenance Service can be used
AUS:SVC isServiceInstalled - returning true
AUS:SVC shouldUseService - returning true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC getCanUseBits - BITS can be used to download updates
AUS:SVC isServiceInstalled - returning true
AUS:SVC CheckerService:getUpdateURL - checkType: 1
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml
AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC CheckerService:checkForUpdates - checkType: 1
AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 5.
AUS:SVC CheckerService:getUpdateURL - checkType: 1
AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml
AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/122.0/20240118164516/WINNT_x86_64-msvc-x64/en-US/release/Windows_NT%252010.0.0.0.19045.3996%2520(x64)/ISET%3ASSE4_2%2CMEM%3A16295/default/default/update.xml
AUS:SVC CheckerService:#updateCheck - request got 'load' event
AUS:SVC CheckerService:#updateCheck - request completed downloading document
AUS:SVC CheckerService:#updateCheck - number of updates available: 0

Update - No further BITS event log errors since Feb2,2024 450pm(UTC-5), which is a short time before I posted my first comment here.
Until this morning, I'd kept Firefox console running during the previous posts as stated.
This morning, my PC did an automatic restart (I've got a scheduled task to do so once a week)
Post restart, The BITS task list is still full at 60 entries as in comment 15.
I do still have at least one Firefox event log error every 24 hours since Feb 1, occurring at ~745pm (UTC-5) every day.
"The system can not find the file specified"

  • <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  • <System>
    <Provider Name="Firefox Default Browser Agent" />
    <EventID Qualifiers="32775">2</EventID>
    <Version>0</Version>
    <Level>2</Level>
    <Task>0</Task>
    <Opcode>0</Opcode>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2024-02-04T00:46:30.6918387Z" />
    <EventRecordID>66425</EventRecordID>
    <Correlation />
    <Execution ProcessID="0" ThreadID="0" />
    <Channel>Application</Channel>
    <Computer>xxxmypcnamexxxx</Computer>
    <Security />
    </System>
  • <EventData>
    <Data>0x80070002 in RegistryDeleteValue:323</Data>
    </EventData>
    </Event>

After no event ID 16398 since 2/2/2024, i had 5 today 2/5/2024 from 530pm to 550pm (utc-5)
For now, i've cleared the list and will update to see if Mozilla fills it again.

Those event log errors are unrelated to this problem. I'm afraid that I'm not seeing any signs of what is going wrong in the log. I'll have to think about what further debugging steps might help here.

Lots of event log info in comment 22
I'd copied all the data to a notepad including conversation and it got attached as a file.

Unfortunately, I am not really learning anything new from the event log. What I really need is a browser console log, like the one you provided in comment 19, but one that logs this problem actually happening. The logs provided previously just show an update check that reports that there are no updates available. Really, I need one collected when this problem happens. Possibly this just means collecting one when there is an update actually available. But it seems like Firefox is updating successfully sometimes (since you are up-to-date). So it could be that that log shows nothing too, in which case it's possible that we need a background update agent log.

From the event logs it seems there _WAS_ an update available that wasn't being fully applied. I ran Firefox, opened console, and these were the AUS entries (now timestamped, still UTC-5) It seems to me running Firefox 'fixes' the issue until a new update is available and then keeps recurring until Firefox updates, without cleaning the BITS failures. I have several more Bits-Client errors as shown in comment 23 since posting that info, and 4 Mozilla entries in bitsadmin /list I'll try to keep Firefox console running, but I'm still troubleshooting PC restarts that prevent a continuous running FF in background (that do not coincide anywhere near the times this occurs, so far)
From the event logs it seems there _WAS_ an update available that wasn't being fully applied. I ran Firefox, opened console, and these were the AUS entries (now timestamped, still UTC-5) that seem to indicate it updated successfully(?) It seems to me running Firefox 'fixes' the issue until a new update is available and then keeps recurring until Firefox updates, without cleaning the BITS failures. I have several more Bits-Client errors as shown in comment 23 since posting that info, and 4 Mozilla entries in bitsadmin /list I'll try to keep Firefox console running, but I'm still troubleshooting PC restarts that prevent a continuous running FF in background (that do not coincide anywhere near the times this occurs, so far)

apologies for double post - Bugzilla kept reporting attachment failed. Feel free to delete above and this.

Hmm, okay. Well that log appears to be successfully calling Complete() on the job, which should remove it from the BITS job list. Can you double check for me that a job with the specified id (56FD981E-4B90-4551-9479-B753D4B2B5FF) is not still hanging around? I usually do this by opening Powershell and running Get-BitsTransfer or you could do Get-BitsTransfer -JobId 56FD981E-4B90-4551-9479-B753D4B2B5FF and see if you find anything or get an ObjectNotFound error.

Flags: needinfo?(jamminr)

Object not found - only the 4 previously mentioned having occurred after clearing the list, but before I started Firefox for first time in a while ~4 days ago.

Get-BitsTransfer -AllUsers

JobId DisplayName TransferType JobState

949580da-7e78-417c-bb40-8aacab9ea3c4 MozillaUpdate 308046B0AF4A39CB Download Transferred
daf8329d-b28f-404c-a34c-7b40bab3702b MozillaUpdate 308046B0AF4A39CB Download Transferred
c65e400b-5e8b-48e5-a86b-2d76590bf01d MozillaUpdate 308046B0AF4A39CB Download Transferred
0b0217c9-590a-49a8-b868-f37140d758c9 MozillaUpdate 308046B0AF4A39CB Download Transferred

Flags: needinfo?(jamminr)

Well it looks like that update did everything as-expected. I think the best thing to check next is the background update task. Could you follow these steps to collect a log from it?

  1. Make sure you are currently using the default profile. You can check by going to about:profiles. One profile will be labeled with "This is the profile in use and it cannot be deleted.", which is the profile you are currently using, of course. And one profile will not have the "Set as default profile" button. If those are the same profile, you are currently using the default profile.
  2. Navigate to about:support and find the "Update Folder" row and click "Open Folder". While you are here, make a note of the update directory name (this is also called your install hash). From your messages above, I believe you should find it is 308046B0AF4A39CB. But if you are testing a different installation it may be different.
  3. Navigate to about:config and set app.update.log to true and app.update.background.loglevel to debug.
  4. Close the browser. Make sure to wait for it to be fully closed, not just for the window to disappear. Consider checking the task manager to make sure all firefox processes have exited.
  5. From the Windows menu, search for Task Scheduler and open it.
  6. On the left side bar, click the little expansion arrow next to "Task Scheduler Library" and click on the "Mozilla" subdirectory.
  7. Find the task whose name looks like <product> Background Update <user_sid> <install hash>. Mine, for example, looks like Firefox Nightly Background Update S-1-5-21-1214616914-3149769447-2062550100-1001 6F193CCC56814779.
  8. Right-click on this task and press run. Allow it to run to completion (note that the the "running" status listed does not update automatically. You either need to refresh or check from the task manager that all Firefox processes have exited)
  9. Go to the Update Folder explorer window that you opened in step 2. There should be a file in it called backgroundupdate.moz_log. Attach that file to this bug.

File attached.
In other interesting perhaps purely co-incidental but i believe not info - From the 'open update folder' step, if i go further into the folder to <folder>/updates/downloading ..... there happens to be four BIT<4 character hash>.TMP files.
Which matches the exact number of entries I currently have 'stuck' in my BITS task list.
I'm really at a point now that I believe the update only fails when an update is available, and Firefox isn't being run.

*sigh* Bugzilla/Markup seem to hate me. It won't let me attach the file. I should just be able to drag/drop, correct?

Gah, I forgot one important detail in my instructions in Comment 31 - there ought to be an update to download. However, I was still able to get a fair amount out of the older entries in the logfile that I believe were made with app.update.log enabled but app.update.background.loglevel unchanged. And I'm fairly sure that I found the problem.

When we start a BITS job, we write its ID into active-update.xml. But there is a small period of time between when the job has been started and the BITS API returns that ID to us and it gets written to the file. And it looks to me like the Background Update Task is just exiting during that time. If the XML was written properly, we would see a Downloader:downloadUpdate - BITS download running. BITS ID: <ID> message. But instead the log contains 4 (same as the number of "stuck" BITS jobs!) Downloader:downloadUpdate - Starting BITS download messages with no corresponding BITS download running messages.

Launching BITS jobs but not properly recording their IDs explains this exact problem. We never complete or cancel those jobs because we don't even have a record of them being started in the first place.

I still need to investigate a bit further to figure out how and why this is happening, but I think I'm on the right track now.

Whiteboard: [fidedi-ope]

Okay, I believe I've tracked down the source of the problem, and I'm concerned enough that I'm increasing the severity to S2.

I don't think literally anything special needs to happen to cause this behavior. I believe it's just a race condition that anyone with a default configuration could hit. Potentially a large number of our users could be encountering this. Anecdotally, I have already found one person that I know personally that also seems to be experiencing this problem, though perhaps not as reliably.

I believe that this is what is going on:

  1. The Background Update Task starts (here) and instantiates an AppUpdater (here) and calls AppUpdater.check() (here).
  2. The AppUpdater determines that there is not currently an update check in-progress and starts one, which finds an available update and calls AppUpdater.#downloadUpdate.
  3. This immediately calls this.#setStatus(AppUpdater.STATUS.DOWNLOADING) (here) before it calls into the Application Update Service to download the update.
  4. Even before the Application Update Service can download the update, the #setStatus call notifies listeners of the status change.
  5. The Background Update Task's listener enters this block, which results in resolve() being called, _attemptBackgroundUpdate returning, and runBackgroundTask returning shortly after that. Naturally, after that, the background task exits.

aus.downloadUpdate() thus races against shutdown. I think that ostensibly this is supposed to address this race, but it seems pretty clear from the evidence that it isn't working reliably.

Glad the logs helped.
Still want a log from when an update is available?

(In reply to jamminr from comment #36)

Glad the logs helped.
Still want a log from when an update is available?

I don't think that will be necessary. Thank you for your help looking into this.

Firefox was blocking windows updates, store app updates and Chrome/Edge updates and some other programs on one of my machines because it created too many bits service tasks and never removed the tasks once the download completed and preventing other applications from creating their own bits update tasks.

The issue in my case was caused by Firefox Developer Edition creating autorun entries in the Windows Scheduled Tasks for the background updates... I installed the developer edition using a local administrator account then switched to a domain user account and sometime later uninstalled the developer edition from the domain user while continuing to use the 'normal' firefox releases - the uninstaller for the developer edition wasn't able to delete the scheduled tasks becasue they're unique for each user and each day the task was running, queuing an update to the bits service and just exiting without removing the download from bits.

Deleting the Mozilla folder from task scheduler was the only way to resolve the issue... The background update task doesn't appear to be configured correctly because Firefox is currently adding separate autorun entries for every user with their SID in the task title name but then they're all launching the same \program files\developer edition\firefox.exe ?

Instead of creating separate tasks running as different users, create 1 task that executes as system or the uninstaller won't be able to delete the binary or the autorun entries.

(In reply to Steven from comment #38)

Instead of creating separate tasks running as different users, create 1 task that executes as system or the uninstaller won't be able to delete the binary or the autorun entries.

First of all, we absolutely do not want the Background Update Task to run as SYSTEM. The task is a stripped down version of Firefox, and Firefox is far too big of an attack surface for us to regularly run it as such a highly privileged user.

My original design for the background update task called for the task to be run as LocalService, which would have had a similar effect but with reduced privileges. The design that was ultimately implemented, however, pulls certain data from the user's default Firefox profile. This means that (a) the Background Update Task won't be able to run without this data and shouldn't be registered, and (b) Firefox needs to run as a user account that has the necessary privileges to access that Firefox profile's files. These issues mean that it is necessary to register the Background Update Task as the user that runs Firefox.

I am experiencing the same problem. The amount of jobs stuck in 'TRANSFERRED' state is constantly growing and when reaching the max limi (I think the default is 60), it causes OS crash. I need to manually clear the queue every day using bitsadmin: bitsadmin /reset /allusers

Is there any way to disable this? I'd love my machine (Win11) not to crash every week (I am not switching it off, my home serves are running on it)

Note that I am currently seeting job files for 126 (current release) and 127 (current beta)
I am usin 127, but I don't have 126 running at all.

Honza

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #40)

Is there any way to disable this?

app.update.BITS.enabled = false

Note, however, that this will also disable the Background Update Agent altogether.

I have already set app.update.BITS.enabled to false in both my Nightly and Release versions of Firefox. However, 12 new jobs have been created since yesterday.

Is the Background Update Agent operating independently of Firefox? Could it be stuck somehow, continuing to run and generate these jobs? Is there anything I can check or disable in the system to address this?

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #42)

I have already set app.update.BITS.enabled to false in both my Nightly and Release versions of Firefox. However, 12 new jobs have been created since yesterday.

Do you use multiple profiles? Perhaps BITS is still enabled in another profile.

Is the Background Update Agent operating independently of Firefox?

That is it's purpose, yes.

Could it be stuck somehow, continuing to run and generate these jobs? Is there anything I can check or disable in the system to address this?

When it runs, it goes through the update cycle once and then exits. It should be impossible for a single invocation to initiate more than one download.

If you have further problems disabling the Background Update Agent that you would like to investigate, please file a different bug since this bug is for BITS specifically, not the Background Update Agent.

See Also: → 1903211
Duplicate of this bug: 1903211
I witnessed this locally and tracked down some potential issues with the help of :bytesized. We witnessed logs like: ``` 2024-10-03 17:52:20.050000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _attemptBackgroundUpdate: creating UpdateServiceStub() for "post-update-processing" 2024-10-03 17:52:20.050000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:STB UpdateServiceStub - Begin. 2024-10-03 17:52:20.051000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates 2024-10-03 17:52:20.051000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates 2024-10-03 17:52:20.061000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC readStatusFile - status: downloading, path: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\updates\0\update.status 2024-10-03 17:52:20.061000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService:_postUpdateProcessing - status = "downloading" 2024-10-03 17:52:20.061000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanApplyUpdates - testing write access C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\update.test 2024-10-03 17:52:20.062000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC isServiceInstalled - returning true 2024-10-03 17:52:20.062000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC shouldUseService - returning true 2024-10-03 17:52:20.062000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanApplyUpdates - bypass the write checks because the Windows Maintenance Service can be used 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC readStatusFile - status: downloading, path: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\updates\0\update.status 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateManager:UpdateManager - status = "downloading" 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateManager:UpdateManager - Initialized downloadingUpdate to [object Object] 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateManager:UpdateManager - Initialized downloadingUpdate state to downloading 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateManager:UpdateManager - Initialized readyUpdate to null 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC readStringFromFile - file doesn't exist: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\updates\0\bt.result 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC readBinaryTransparencyResult - result: null, path: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\updates\0\bt.result 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService:_postUpdateProcessing - resuming patch found in downloading state 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Creating Downloader 2024-10-03 17:52:20.084000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService:downloadUpdate 2024-10-03 17:52:20.114000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:_selectPatch - found existing patch with state: downloading 2024-10-03 17:52:20.114000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:_selectPatch - resuming download 2024-10-03 17:52:20.114000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanUseBits - BITS can be used to download updates 2024-10-03 17:52:20.114000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:_canUseBits - Patch is able to use BITS download 2024-10-03 17:52:20.114000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:downloadUpdate - Connecting to in-progress download. BITS ID: {610FBD7A-5794-478F-BFD0-7ABFE0C50356} 2024-10-03 17:52:20.115000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.115000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _attemptBackgroundUpdate: checking for preconditions necessary to update this installation 2024-10-03 17:52:20.115000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.115000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking app.update.auto 2024-10-03 17:52:20.116000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.116000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking app.update.background.enabled 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking for MOZ_BACKGROUNDTASKS 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that updates are not disabled by policy, testing configuration, or abnormal runtime environment 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that we can make progress: updates can stage and/or apply 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC isServiceInstalled - returning true 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC shouldUseService - returning true 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanStageUpdates - able to stage updates using the service 2024-10-03 17:52:20.117000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that we are on a supported OS (currently only Windows) 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that we can usually use Windows BITS 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanUseBits - BITS can be used to download updates 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.118000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that the Mozilla Maintenance Service Registry key exists, or that the unelevated installs are permitted 2024-10-03 17:52:20.121000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.121000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _reasonsToNotUpdateInstallation: checking that this installation has an omnijar 2024-10-03 17:52:20.122000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:AUM AppUpdater:check - currentState=STATE_IDLE 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _attemptBackgroundUpdate: This session will be limited to downloading updates only. 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:AUM AppUpdater:check - starting update check 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:checkForUpdates - checkType: 2 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 1. 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC waitForOtherInstances - beginning polling 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC waitForOtherInstances - no other instances found, exiting 2024-10-03 17:52:20.123000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:getUpdateURL - checkType: 2 2024-10-03 17:52:20.127000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/127.0/20240606181944/WINNT_x86_64-msvc-x64/en-CA/beta/Windows_NT%252010.0.0.0.22631.4169%2520(x64)/ISET%3ASSE4_2%2CMEM%3A65234/default/default/update.xml?force=1 2024-10-03 17:52:20.172000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/127.0/20240606181944/WINNT_x86_64-msvc-x64/en-CA/beta/Windows_NT%252010.0.0.0.22631.4169%2520(x64)/ISET%3ASSE4_2%2CMEM%3A65234/default/default/update.xml?force=1 2024-10-03 17:52:20.507000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:#updateCheck - request got 'load' event 2024-10-03 17:52:20.507000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:#updateCheck - request completed downloading document 2024-10-03 17:52:20.509000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC CheckerService:#updateCheck - number of updates available: 1 2024-10-03 17:52:20.509000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:AUM AppUpdater:check - Update check succeeded 2024-10-03 17:52:20.509000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanApplyUpdates - testing write access C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\update.test 2024-10-03 17:52:20.510000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC isServiceInstalled - returning true 2024-10-03 17:52:20.510000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC shouldUseService - returning true 2024-10-03 17:52:20.510000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanApplyUpdates - bypass the write checks because the Windows Maintenance Service can be used 2024-10-03 17:52:20.510000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:AUM AppUpdater:check - updateAuto is active and manualUpdateOnlydateOnly is inactive. Start the download. 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.debug: BackgroundUpdate: 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] _attemptBackgroundUpdate: Download in progress. Exiting task while download transfers 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:AUM AppUpdater:stop called 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader: cancel 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Creating Downloader 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC UpdateService:downloadUpdate 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:_selectPatch - Patch selected. Assigning update to downloadingUpdate. 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC getCanUseBits - BITS can be used to download updates 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:_canUseBits - Patch is able to use BITS download 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] *** AUS:SVC Downloader:downloadUpdate - Starting BITS download with url: https://download.mozilla.org/?product=firefox-132.0b2-complete&os=win64&lang=en-CA, updateDir: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\B4A8F2AF719D4BF\updates\downloading, filename: update.mar 2024-10-03 17:52:20.511000 UTC - [Parent 10484: Main Thread]: D/Dump [Backstage.Dump] console.info: BackgroundUpdate: runBackgroundTask: attempted background update ``` Observe that we read `update.status`, discover that we are `downloading`, and then start the update check in `STATE_IDLE`! This is because, before Bug 1875502 (landed in Firefox 128), we didn't transition the update state to downloading correctly at https://searchfox.org/mozilla-central/rev/5c7a3b3caac7ce4576f9a3f8c888640043da47a2/toolkit/mozapps/update/UpdateService.sys.mjs#4330-4345. The new code does transition the state correctly at https://searchfox.org/mozilla-central/rev/488d81581a9142d532bf814efa60564ff11599ca/toolkit/mozapps/update/UpdateService.sys.mjs#4363-4367 (and is more careful to reload the state with a single unified code path). It seems likely that Bug 1875502 therefore has addressed one of the causes of this ticket. There may, of course, be more causes.

I'm going to tentatively marked this as WORKSFORME, fully aware that we may still have issues that produce the same results. And of course, we have no way to fix background update loops that are currently wedged.

Status: UNCONFIRMED → RESOLVED
Closed: 4 months ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: