1928636 - perma toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasNotFirefox.js | test_task_noBITS - [test_task_noBITS : 5209] Headers should be as expected - [{"mode":null,"name":null}] deepEqual [{"mode":null,"name":null},{"mode":null,"name":null}]

Status: RESOLVED WORKSFORME

(Thunderbird :: Upstream Synchronization, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: mkmelin [at] iki.fi
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=480738888&repo=comm-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WR2EEyDjR-uJgRv9yDyLOg/runs/0/artifacts/public/logs/live_backing.log

---

Comment 1

[Nick Alexander :nalexander [he/him]]

Hello Thunderbird friends! I tried to anticipate Thunderbird's configuration, but evidently missed. (I didn't run against your CI, not having done that before.)

You have 2 options:

1. Easiest -- disable this test.
2. More interesting -- figure out why only 1 request is being made, i.e., why only a Balrog query or only a MAR query. That's unexpected.

Comment 2

[Intermittent Failures Robot]

15 failures in 4361 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 15

Platform and build breakdown:

• windows11-32-2009-qr: 3
  • opt: 2
  • debug: 1
• linux1804-64-qr: 2
  • opt: 1
  • debug: 1
• windows11-64-2009-qr: 2
  • debug: 1
  • opt: 1
• windows11-64-2009-shippable-qr: 1
  • opt: 1
• macosx1015-64-qr: 2
  • debug: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1
• linux1804-64-asan-qr: 1
  • opt: 1
• linux1804-64-ccov-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1
• windows11-32-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1928636&startday=2024-10-28&endday=2024-11-03&tree=all

Comment 3

[John Bieling]

Hi Nick, thanks for your message.

If I have understood this test correct, then the failing test test_task_noBITS is the only one where a background task is used. In all other tests we either use BITS, or a plain download, correct?

What I can see is that the MAR download actually suceeds, but then the update gets lost somehow:

0:12.11 pid:22264 *** AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: http://127.0.0.1:8888/simple.mar, path: C:\\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates\\downloading\\update.mar, interval: 0
 0:12.11 pid:22264 *** AUS:SVC Downloader:downloadUpdate - Setting status to downloading
 0:12.11 pid:22264 *** AUS:SVC Downloader:downloadUpdate - Setting state to downloading
 0:12.11 pid:22264 *** AUS:SVC Downloader:downloadUpdate - setting currentState to STATE_DOWNLOADING
 0:12.11 pid:22264 *** AUS:SVC transitionState - "STATE_IDLE" -> "STATE_DOWNLOADING".
 0:12.11 pid:22264 *** AUS:SVC Downloader:onStartRequest - original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar
 0:12.12 pid:22264 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:12.12 pid:22264 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:12.12 pid:22264 *** AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar, status: 0
 0:12.12 pid:22264 *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
 0:12.12 pid:22264 *** AUS:SVC Downloader:_verifyDownload called
 0:12.12 pid:22264 *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
 0:12.12 pid:22264 *** AUS:SVC Downloader:onStopRequest - Clearing readyUpdate in preparation of moving downloadingUpdate into readyUpdate.
 0:12.12 pid:22264 *** AUS:SVC isServiceInstalled - returning true
 0:12.12 pid:22264 *** AUS:SVC shouldUseService - returning false
 0:12.12 pid:22264 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:12.12 pid:22264 *** AUS:SVC Downloader:onStopRequest - Ready to apply. Setting state to "pending".
 0:12.13 pid:22264 *** AUS:SVC Downloader:onStopRequest - Setting internalResult to 0
 0:12.13 pid:22264 *** AUS:SVC Downloader:onStopRequest - setting state to: pending
 0:12.13 pid:22264 *** AUS:SVC Downloader:onStopRequest - Moving downloadingUpdate into readyUpdate
 0:12.13 pid:22264 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:12.13 pid:22264 *** AUS:SVC Downloader:onStopRequest - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
 0:12.13 pid:22264 *** AUS:SVC transitionState - "STATE_DOWNLOADING" -> "STATE_PENDING".
 0:12.34 pid:22264 *** AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates.xml
 0:13.14 FAIL test_task_noBITS - [test_task_noBITS : 5213] Headers should be as expected - [{"mode":null,"name":null}] deepEqual [{"mode":null,"name":null},{"mode":null,"name":null}]
x

Do you have any idea where we should start looking?

Comment 4

[Intermittent Failures Robot]

39 failures in 927 pushes (0.042 failures/push) were associated with this bug yesterday.

Repository breakdown:

• comm-central: 39

Platform and build breakdown:

• linux1804-64-ccov-qr: 2
  • opt: 2
• windows11-64-2009-qr: 6
  • debug: 3
  • opt: 3
• linux1804-64-qr: 6
  • opt: 3
  • debug: 3
• linux1804-64-shippable-qr: 3
  • opt: 3
• macosx1015-64-qr: 6
  • opt: 3
  • debug: 3
• windows11-32-2009-qr: 6
  • opt: 3
  • debug: 3
• windows11-64-2009-shippable-qr: 3
  • opt: 3
• macosx1015-64-shippable-qr: 3
  • opt: 3
• windows11-32-2009-shippable-qr: 3
  • opt: 3
• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1928636&startday=2024-11-05&endday=2024-11-05&tree=all

Comment 5

[Magnus Melin [:mkmelin]]

Not sure if this is relevant or not, but I was looking at why the sister test downloadExtrasFirefox.js doesn't fail, and noticed this:

FAILS: ./mach xpcshell-test toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasFirefox.js
SUCCEEDS (but 0 passing): ./mach test toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasFirefox.js

I then notice https://searchfox.org/mozilla-central/rev/aecb006bbb135d707ca4b8cea7572dd8abab6817/toolkit/mozapps/update/tests/unit_aus_update/xpcshell.toml#39 - I guess this is then a twist off good old bug 1168178, and downloadExtrasNotFirefox.js does not really work for Firefox either - it's just that Thunderbird always uses firefox-appdir = "browser" for xpschell-tests while Firefox doesn't so it doesn't notice? (Can someone with a firefox build verify adding that entry to xpcshell.toml for this test fails on Firefox?)

Comment 6

[Magnus Melin [:mkmelin]]

Or maybe that's not it, or only partly the reasons. The failing test (downloadExtrasNotFirefox.js) is actually disabled for Firefox...
https://searchfox.org/mozilla-central/rev/aecb006bbb135d707ca4b8cea7572dd8abab6817/toolkit/mozapps/update/tests/unit_aus_update/xpcshell.toml#48. When is it supposed to run?

Comment 7

[John Bieling]

(In reply to Magnus Melin [:mkmelin] from comment #5)

Not sure if this is relevant or not, but I was looking at why the sister test downloadExtrasFirefox.js doesn't fail, and noticed this:

FAILS: ./mach xpcshell-test toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasFirefox.js
SUCCEEDS (but 0 passing): ./mach test toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasFirefox.js

I think it does not fail because it is disabled for Thunderbird.

Regarding preferences:

• the Firefox test is using `firefox-appdir = "browser"´, so it is using its standard environment, but it is only run by Firefox
• the non-Firefox test is run by everything but Firefox, and Thunderbird is using its standard environment, because it does not depend on the appdir thingy
• it looks like the relevant preferences are set by the test, but I will check if there is anything else relevant in firefox.js, which we might need.

Comment 8

[John Bieling]

I did some more digging. My first observation is that the test passes if I force-skip one of these two, it does not matter which one is skipped:

• test_task_noBITS()
• test_noTask_noBITS()

As soon as both run, the second (!) one fails with the missing request entry for the MAR download. Which means handleResponse() is not called. I can flip the tests around, it is always the MAR download of the second test which fails. The file is downloaded, but handleResponse() is not called. If I see it correctly, then not even onInputStreamReady() is called.

My second observation is that I do get a response in both cases, if I request the additional info to be added, forcing shouldAddExtras = true here. In that case the other test downloadExtrasFirefox.js PASSES for us (after I enabled it for Thunderbird).

I then of course had to try the oposite: always forcing shouldAddExtras = false even for Firefox. In that case, Firefox FAILS downloadExtrasNotFirefox.js with the exact same sympthoms (after I enabled it for Firefox).

I think observation #3 is critical, as it shows that toolkit code is not doing what is expected.

Log with additional entries for observation #1/#3:

test #1:

 0:11.60 INFO toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasNotFirefox.js | Starting test_task_noBITS
 0:11.60 INFO (xpcshell/head.js) | test test_task_noBITS pending (3)
 0:11.61 pid:20044 Full command: ['F:\\mozilla\\mozilla-central\\obj-x86_64-pc-windows-msvc-tb-artifacts\\dist\\bin\\xpcshell.exe', '-g', 'F:\\mozilla\\mozilla-central\\obj-x86_64-pc-windows-msvc-tb-artifacts\\dist\\bin', '-a', 'F:\\mozilla\\mozilla-central\\obj-x86_64-pc-windows-msvc-tb-artifacts\\dist\\bin', '-m', '-e', 'const _HEAD_JS_PATH = "f:/mozilla/mozilla-central/testing/xpcshell/head.js";', '-e', 'const _MOZINFO_JS_PATH = "C:\\\\Users\\\\John\\\\AppData\\\\Local\\\\Temp\\\\firefox\\\\xpcshellprofile\\\\mozinfo.json";', '-e', 'const _PREFS_FILE = "F:\\\\mozilla\\\\mozilla-central\\\\obj-x86_64-pc-windows-msvc-tb-artifacts\\\\temp\\\\xpc-other-gc_ujlms\\\\user.js";', '-e', 'const _TESTING_MODULES_DIR = "F:\\\\mozilla\\\\mozilla-central\\\\obj-x86_64-pc-windows-msvc-tb-artifacts\\\\_tests\\\\modules\\\\";', '-f', 'f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js', '-e', 'const _HEAD_FILES = ["F:/mozilla/mozilla-central/obj-x86_64-pc-windows-msvc-tb-artifacts/_tests/xpcshell/toolkit/mozapps/update/tests/unit_aus_update/head_update.js"];', '-e', 'const _JSDEBUGGER_PORT = 0;', '-e', 'const _TEST_FILE = ["F:/mozilla/mozilla-central/obj-x86_64-pc-windows-msvc-tb-artifacts/_tests/xpcshell/toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasNotFirefox.js"];', '-e', 'const _TEST_NAME = "toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasNotFirefox.js";', '-e', '_execute_test(); quit(0);']
pid:20044 *** AUS:SVC UpdateManager:#reload - Reloading update data.
 0:11.61 pid:20044 *** AUS:SVC transitionState - Not transitioning state because it isn't changing.
 0:11.61 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded downloadingUpdate as null
 0:11.61 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded readyUpdate as null
 0:11.61 pid:20044 *** AUS:SVC UpdateManager:UpdateManager - Reloaded updateInstalledAtStartup as  null
 0:11.62 INFO (xpcshell/head.js) | test run_next_test 1 finished (3)
 0:11.62 INFO "12:43:20:783 | TEST-INFO | shared.js | [setUpdateURL : 258] setting update URL to http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0"
 0:11.62 pid:20044 *** AUS:SVC Creating UpdateService
 0:11.62 pid:20044 *** AUS:SVC Logging current UpdateService status:
 0:11.63 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:11.63 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:11.63 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:11.63 pid:20044 *** AUS:SVC Elevation required: false
 0:11.63 pid:20044 *** AUS:SVC Other instance of the application currently running: false
 0:11.63 pid:20044 *** AUS:SVC Downloading: false
 0:11.63 pid:20044 *** AUS:SVC End of UpdateService status
 0:11.63 pid:20044 *** AUS:STB UpdateServiceStub - Begin (force_update_init=true)
 0:11.63 pid:20044 *** AUS:STB UpdateServiceStub:migrateUpdateDirectory Performing migration
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloading update data.
 0:11.63 pid:20044 *** AUS:SVC transitionState - Not transitioning state because it isn't changing.
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:_loadXMLFileIntoArray - XML file does not exist. path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\active-update.xml
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:_loadXMLFileIntoArray - XML file does not exist. path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates.xml
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded downloadingUpdate as null
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded readyUpdate as null
 0:11.63 pid:20044 *** AUS:SVC UpdateManager:UpdateManager - Reloaded updateInstalledAtStartup as  null
 0:11.63 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:11.63 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:11.63 pid:20044 *** AUS:SVC readStringFromFile - file doesn't exist: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates\\0\\update.status
 0:11.63 pid:20044 *** AUS:SVC readStatusFile - status: null, path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates\\0\\update.status
 0:11.63 pid:20044 *** AUS:SVC UpdateService:#asyncInit - status = "null"
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:11.63 pid:20044 *** AUS:SVC UpdateService:#asyncInit - Initial cleanup
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:11.63 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:11.63 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:11.63 pid:20044 *** AUS:SVC getCanUseBits - Not using BITS. Disabled by pref.
 0:11.63 pid:20044 *** AUS:SVC isServiceInstalled - returning true
 0:11.63 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - checkType: 1
 0:11.63 PASS test_task_noBITS - [test_task_noBITS : 5112] Update check should have started - true == true
 0:11.63 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - update URL: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:11.64 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:11.64 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:11.64 pid:20044 *** AUS:SVC CheckerService:checkForUpdates - checkType: 1
 0:11.64 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:11.64 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:11.64 pid:20044 *** AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 1.
 0:11.64 pid:20044 *** AUS:SVC waitForOtherInstances - beginning polling
 0:11.64 pid:20044 *** AUS:SVC waitForOtherInstances - no other instances found, exiting
 0:11.64 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - checkType: 1
 0:11.64 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - update URL: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:11.64 pid:20044 *** AUS:SVC CheckerService:#updateCheck - sending request to: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:11.64 pid:20044 console.log: "  ~~~~~~ A"
 0:11.64 pid:20044 console.log: "  ~~~~~~ B"
 0:11.64 pid:20044 console.log: "  ~~~~~~ C"
 0:11.64 pid:20044 console.log: "  ~~~~~~ D" 0
 0:11.64 pid:20044 console.log: "*** _processBody" true
 0:11.64 pid:20044 console.log: "*** remaining body data len=0"
 0:11.64 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~" ({_method:"GET", _path:"/app_update.sjs", _queryString:"appVersion=999000.0", _scheme:"http", _host:"127.0.0.1", _port:8888, _bodyInputStream:({}), _bodyOutputStream:({}), _headers:{_headers:{host:["127.0.0.1:8888"], 'user-agent':["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0 /134.0a1"], accept:["*/*"], 'accept-language':["en-US,en;q=0.5"], 'accept-encoding':["gzip, deflate, br, zstd"], 'cache-control':["no-cache"], pragma:["no-cache"], connection:["keep-alive"]}}, _bag:null, _httpVersion:{major:1, minor:1}})
 0:11.64 pid:20044 console.trace:
 0:11.64 pid:20044 xpcshellUtilsAUS.js 5138 handleResponse
 0:11.64 pid:20044 resource://testing-common/httpd.sys.mjs 1344 process
 0:11.64 pid:20044 resource://testing-common/httpd.sys.mjs 1796 _handleResponse
 0:11.64 pid:20044 resource://testing-common/httpd.sys.mjs 1644 _processBody
 0:11.64 pid:20044 resource://testing-common/httpd.sys.mjs 1520 onInputStreamReady
 0:11.64 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 245 _do_main
 0:11.64 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 596 _execute_test
 0:11.64 pid:20044 -e 1
 0:11.64 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~"
 0:11.65 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.65 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.65 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.65 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.65 pid:20044 *** AUS:SVC CheckerService:#updateCheck - request got 'load' event
 0:11.65 pid:20044 *** AUS:SVC CheckerService:#updateCheck - request completed downloading document
 0:11.65 pid:20044 *** AUS:SVC CheckerService:#updateCheck - number of updates available: 1
 0:11.65 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:11.65 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:11.66 pid:20044 *** AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
 0:11.66 pid:20044 *** AUS:SVC Creating Downloader
 0:11.66 pid:20044 *** AUS:SVC Downloader:downloadUpdate
 0:11.66 pid:20044 *** AUS:SVC Downloader:_selectPatch - Patch selected. Assigning update to downloadingUpdate.
 0:11.66 pid:20044 *** AUS:SVC getCanUseBits - Not using BITS. Disabled by pref.
 0:11.66 pid:20044 *** AUS:SVC Downloader:_maybeWithExtras - Not adding extras
 0:11.66 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: http://127.0.0.1:8888/simple.mar, path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates\\downloading\\update.mar, interval: 0
 0:11.66 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Setting status to downloading
 0:11.66 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Setting state to downloading
 0:11.66 pid:20044 *** AUS:SVC Downloader:downloadUpdate - setting currentState to STATE_DOWNLOADING
 0:11.66 pid:20044 *** AUS:SVC transitionState - "STATE_IDLE" -> "STATE_DOWNLOADING".
 0:11.67 pid:20044 console.log: "  ~~~~~~ A"
 0:11.67 pid:20044 console.log: "  ~~~~~~ B"
 0:11.67 pid:20044 console.log: "  ~~~~~~ C"
 0:11.67 pid:20044 console.log: "  ~~~~~~ D" 0
 0:11.67 pid:20044 console.log: "*** _processBody" true
 0:11.67 pid:20044 console.log: "*** remaining body data len=0"
 0:11.67 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~" ({_method:"GET", _path:"/simple.mar", _queryString:"", _scheme:"http", _host:"127.0.0.1", _port:8888, _bodyInputStream:({}), _bodyOutputStream:({}), _headers:{_headers:{host:["127.0.0.1:8888"], 'user-agent':["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0 /134.0a1"], accept:["*/*"], 'accept-language':["en-US,en;q=0.5"], connection:["keep-alive"], 'sec-fetch-dest':["empty"], 'sec-fetch-mode':["no-cors"], 'sec-fetch-site':["none"], priority:["u=4"]}}, _bag:null, _httpVersion:{major:1, minor:1}})
 0:11.67 pid:20044 console.trace:
 0:11.67 pid:20044 xpcshellUtilsAUS.js 5138 handleResponse
 0:11.67 pid:20044 resource://testing-common/httpd.sys.mjs 1344 process
 0:11.67 pid:20044 resource://testing-common/httpd.sys.mjs 1796 _handleResponse
 0:11.67 pid:20044 resource://testing-common/httpd.sys.mjs 1644 _processBody
 0:11.67 pid:20044 resource://testing-common/httpd.sys.mjs 1520 onInputStreamReady
 0:11.67 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 245 _do_main
 0:11.67 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 596 _execute_test
 0:11.67 pid:20044 -e 1
 0:11.67 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~"
 0:11.67 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.67 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.67 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.67 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:11.67 pid:20044 *** AUS:SVC Downloader:onStartRequest - original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar
 0:11.67 pid:20044 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:11.67 pid:20044 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:11.67 pid:20044 *** AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar, status: 0
 0:11.67 pid:20044 *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
 0:11.67 pid:20044 *** AUS:SVC Downloader:_verifyDownload called
 0:11.67 pid:20044 *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
 0:11.67 pid:20044 *** AUS:SVC Downloader:onStopRequest - Clearing readyUpdate in preparation of moving downloadingUpdate into readyUpdate.
 0:11.67 pid:20044 *** AUS:SVC isServiceInstalled - returning true
 0:11.67 pid:20044 *** AUS:SVC shouldUseService - returning false
 0:11.68 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:11.68 pid:20044 *** AUS:SVC Downloader:onStopRequest - Ready to apply. Setting state to "pending".
 0:11.69 pid:20044 *** AUS:SVC Downloader:onStopRequest - Setting internalResult to 0
 0:11.69 pid:20044 *** AUS:SVC Downloader:onStopRequest - setting state to: pending
 0:11.69 pid:20044 *** AUS:SVC Downloader:onStopRequest - Moving downloadingUpdate into readyUpdate
 0:11.69 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:11.69 pid:20044 *** AUS:SVC Downloader:onStopRequest - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
 0:11.69 pid:20044 *** AUS:SVC transitionState - "STATE_DOWNLOADING" -> "STATE_PENDING".
 0:13.21 PASS test_task_noBITS - [test_task_noBITS : 5215] Headers should be as expected - [{"mode":null,"name":null},{"mode":null,"name":null}] deepEqual [{"mode":null,"name":null},{"mode":null,"name":null}]
 0:13.21 PASS test_task_noBITS - [test_task_noBITS : 5229] Query parameters should be as expected - [{"mode":null,"name":null},{"mode":null,"name":null}] deepEqual [{"mode":null,"name":null},{"mode":null,"name":null}]
 0:13.21 INFO (xpcshell/head.js) | test run_next_test 2 pending (3)
 0:13.21 INFO (xpcshell/head.js) | test test_task_noBITS finished (3)

and test #2:

0:13.21 INFO toolkit/mozapps/update/tests/unit_aus_update/downloadExtrasNotFirefox.js | Starting test_noTask_noBITS
 0:13.21 INFO (xpcshell/head.js) | test test_noTask_noBITS pending (3)
 0:13.21 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloading update data.
 0:13.21 pid:20044 *** AUS:SVC transitionState - "STATE_PENDING" -> "STATE_IDLE".
 0:13.21 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded downloadingUpdate as null
 0:13.21 pid:20044 *** AUS:SVC UpdateManager:#reload - Reloaded readyUpdate as null
 0:13.21 pid:20044 *** AUS:SVC UpdateManager:UpdateManager - Reloaded updateInstalledAtStartup as  null
 0:13.21 INFO (xpcshell/head.js) | test run_next_test 2 finished (3)
 0:13.21 INFO "12:43:22:377 | TEST-INFO | shared.js | [setUpdateURL : 258] setting update URL to http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0"
 0:13.21 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:13.21 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:13.21 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:13.21 pid:20044 *** AUS:SVC getCanUseBits - Not using BITS. Disabled by pref.
 0:13.21 pid:20044 *** AUS:SVC isServiceInstalled - returning true
 0:13.21 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - checkType: 1
 0:13.21 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - update URL: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:13.21 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:13.21 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:13.21 pid:20044 *** AUS:SVC CheckerService:checkForUpdates - checkType: 1
 0:13.21 pid:20044 *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
 0:13.21 pid:20044 *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
 0:13.21 pid:20044 *** AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 2.
 0:13.21 PASS test_noTask_noBITS - [test_noTask_noBITS : 5112] Update check should have started - true == true
 0:13.21 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - checkType: 1
 0:13.21 pid:20044 *** AUS:SVC CheckerService:getUpdateURL - update URL: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:13.21 pid:20044 *** AUS:SVC CheckerService:#updateCheck - sending request to: http://127.0.0.1:8888/app_update.sjs?appVersion=999000.0
 0:13.21 pid:20044 console.log: "  ~~~~~~ A"
 0:13.21 pid:20044 console.log: "  ~~~~~~ B"
 0:13.22 pid:20044 console.log: "  ~~~~~~ C"
 0:13.22 pid:20044 console.log: "  ~~~~~~ D" 0
 0:13.22 pid:20044 console.log: "*** _processBody" true
 0:13.22 pid:20044 console.log: "*** remaining body data len=0"
 0:13.22 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~" ({_method:"GET", _path:"/app_update.sjs", _queryString:"appVersion=999000.0", _scheme:"http", _host:"127.0.0.1", _port:8888, _bodyInputStream:({}), _bodyOutputStream:({}), _headers:{_headers:{host:["127.0.0.1:8888"], 'user-agent':["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:134.0) Gecko/20100101 Firefox/134.0 /134.0a1"], accept:["*/*"], 'accept-language':["en-US,en;q=0.5"], 'accept-encoding':["gzip, deflate, br, zstd"], 'cache-control':["no-cache"], pragma:["no-cache"], connection:["keep-alive"]}}, _bag:null, _httpVersion:{major:1, minor:1}})
 0:13.22 pid:20044 console.trace:
 0:13.22 pid:20044 xpcshellUtilsAUS.js 5138 handleResponse
 0:13.22 pid:20044 resource://testing-common/httpd.sys.mjs 1344 process
 0:13.22 pid:20044 resource://testing-common/httpd.sys.mjs 1796 _handleResponse
 0:13.22 pid:20044 resource://testing-common/httpd.sys.mjs 1644 _processBody
 0:13.22 pid:20044 resource://testing-common/httpd.sys.mjs 1520 onInputStreamReady
 0:13.22 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 245 _do_main
 0:13.22 pid:20044 f:\\mozilla\\mozilla-central\\testing\\xpcshell\\head.js 596 _execute_test
 0:13.22 pid:20044 -e 1
 0:13.22 pid:20044 console.log: "~~~~~~~~~~~~~~~~~~~~~~~"
 0:13.22 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:13.22 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:13.23 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:13.23 pid:20044 console.log: "  ~~~~~~ AAAAA"
 0:13.23 pid:20044 *** AUS:SVC CheckerService:#updateCheck - request got 'load' event
 0:13.23 pid:20044 *** AUS:SVC CheckerService:#updateCheck - request completed downloading document
 0:13.23 pid:20044 *** AUS:SVC CheckerService:#updateCheck - number of updates available: 1
 0:13.23 pid:20044 *** AUS:SVC getCanApplyUpdates - testing write access C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\update.test
 0:13.23 pid:20044 *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on macOS and Windows
 0:13.23 pid:20044 *** AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
 0:13.23 pid:20044 *** AUS:SVC Creating Downloader
 0:13.23 pid:20044 *** AUS:SVC Downloader:downloadUpdate
 0:13.23 pid:20044 *** AUS:SVC Downloader:_selectPatch - Patch selected. Assigning update to downloadingUpdate.
 0:13.23 pid:20044 *** AUS:SVC getCanUseBits - Not using BITS. Disabled by pref.
 0:13.23 pid:20044 *** AUS:SVC Downloader:_maybeWithExtras - Not adding extras
 0:13.23 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: http://127.0.0.1:8888/simple.mar, path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates\\downloading\\update.mar, interval: 0
 0:13.23 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Setting status to downloading
 0:13.23 pid:20044 *** AUS:SVC Downloader:downloadUpdate - Setting state to downloading
 0:13.23 pid:20044 *** AUS:SVC Downloader:downloadUpdate - setting currentState to STATE_DOWNLOADING
 0:13.23 pid:20044 *** AUS:SVC transitionState - "STATE_IDLE" -> "STATE_DOWNLOADING".
 0:13.23 pid:20044 *** AUS:SVC Downloader:onStartRequest - original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar
 0:13.23 pid:20044 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:13.23 pid:20044 *** AUS:SVC Downloader:onProgress - progress: 1419/1419
 0:13.23 pid:20044 *** AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: http://127.0.0.1:8888/simple.mar, final URI spec: http://127.0.0.1:8888/simple.mar, status: 0
 0:13.23 pid:20044 *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
 0:13.23 pid:20044 *** AUS:SVC Downloader:_verifyDownload called
 0:13.23 pid:20044 *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
 0:13.23 pid:20044 *** AUS:SVC Downloader:onStopRequest - Clearing readyUpdate in preparation of moving downloadingUpdate into readyUpdate.
 0:13.23 pid:20044 *** AUS:SVC isServiceInstalled - returning true
 0:13.23 pid:20044 *** AUS:SVC shouldUseService - returning false
 0:13.23 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:13.23 pid:20044 *** AUS:SVC Downloader:onStopRequest - Ready to apply. Setting state to "pending".
 0:13.25 pid:20044 *** AUS:SVC Downloader:onStopRequest - Setting internalResult to 0
 0:13.25 pid:20044 *** AUS:SVC Downloader:onStopRequest - setting state to: pending
 0:13.25 pid:20044 *** AUS:SVC Downloader:onStopRequest - Moving downloadingUpdate into readyUpdate
 0:13.25 pid:20044 *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
 0:13.25 pid:20044 *** AUS:SVC Downloader:onStopRequest - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
 0:13.25 pid:20044 *** AUS:SVC transitionState - "STATE_DOWNLOADING" -> "STATE_PENDING".
 0:13.46 pid:20044 *** AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\downloadExtrasNotFirefox\\updates.xml

Comment 9

[Nick Alexander :nalexander [he/him]]

John, Magnus -- please accept my apologies for taking your time running this issue down. I was trying to accommodate Firefox and !Firefox (i.e., Thunderbird) with the Firefox and NotFirefox variations, because I don't want your update process to change with Firefox-specific extras (headers and query parameters). So you have interpreted the conditions for the tests to run correctly.

I saw issues like this when testing locally and evidently worked around them for Firefox, while forgetting that they may arise for Thunderbird. I think what is happening is that the incremental downloader doesn't do expected things the second time -- either the browser cache kicks in, or the file being on disk and the right size already makes it take no action. I think the query parameters "break the cache" sufficiently that it doesn't happen in the Firefox tests.

I see a patch up, which I will look at shortly. My apologies again.

Comment 10

[Alastor Wu [:alwu]]

Attachment: Bug 1928636 - part2 : revert workaround from bug 1928484.

Depends on D228387

Comment 11

[John Bieling]

@:alwu: wrong bug.

Comment 12

[Phabricator Automation]

Comment on attachment 9436266 [details]
Bug 1928636 - part2 : revert workaround from bug 1928484.

Revision D228388 was moved to bug 1928536. Setting attachment 9436266 [details] to obsolete.

Comment 13

[Intermittent Failures Robot]

70 failures in 4515 pushes (0.016 failures/push) were associated with this bug in the last 7 days.

This is the #25 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• comm-central: 70

Platform and build breakdown:

• linux1804-64-ccov-qr: 6
  • opt: 6
• windows11-64-2009-qr: 10
  • debug: 5
  • opt: 5
• linux1804-64-qr: 11
  • opt: 6
  • debug: 5
• linux1804-64-shippable-qr: 6
  • opt: 6
• macosx1015-64-qr: 10
  • opt: 5
  • debug: 5
• windows11-32-2009-qr: 10
  • opt: 5
  • debug: 5
• windows11-64-2009-shippable-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 5
  • opt: 5
• windows11-32-2009-shippable-qr: 5
  • opt: 5
• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1928636&startday=2024-11-04&endday=2024-11-10&tree=all

Comment 14

[Magnus Melin [:mkmelin]]

(No longer perma failing since disabled in bug 1929581)

Comment 15

[John Bieling]

Can this be closed then?

Comment 16

[Magnus Melin [:mkmelin]]

I'll refer to Nick.
If kept, probably re-titled and moved?

Comment 17

[Nick Alexander :nalexander [he/him]]

We believe it's addressed, so let's close it and it'll be re-opened if it's really intermittent. Thanks, Thunderbird friends!

Comment 18

[Magnus Melin [:mkmelin]]

Thanks for the help!