Closed Bug 1888279 Opened 3 months ago Closed 2 months ago

Intermittent TVw TEST-UNEXPECTED-TIMEOUT | /css/motion/offset-path-shape-shape-001.html | expected PASS

Categories

(Testing :: web-platform-tests, defect, P5)

Product:
Testing
Component:
web-platform-tests
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, test-verify-fail)

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=452569382&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VD9qboV0RNuGz76mmdmf-g/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VD9qboV0RNuGz76mmdmf-g/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2024-03-27T21:08:12.216Z] 21:08:12     INFO - TEST-START | /css/motion/offset-path-shape-shape-001.html
[task 2024-03-27T21:08:12.216Z] 21:08:12     INFO - Run 1/10
[task 2024-03-27T21:08:12.231Z] 21:08:12     INFO - Setting pref dom.animations-api.compositing.enabled to true
[task 2024-03-27T21:08:12.244Z] 21:08:12     INFO - Setting pref layout.css.transition-behavior.enabled to true
[task 2024-03-27T21:08:12.251Z] 21:08:12     INFO - Setting pref layout.css.individual-transform.enabled to true
[task 2024-03-27T21:08:12.259Z] 21:08:12     INFO - Setting pref layout.css.basic-shape-rect.enabled to true
[task 2024-03-27T21:08:12.266Z] 21:08:12     INFO - Setting pref layout.css.basic-shape-shape.enabled to true
[task 2024-03-27T21:08:12.273Z] 21:08:12     INFO - Setting pref layout.css.basic-shape-xywh.enabled to true
[task 2024-03-27T21:08:12.279Z] 21:08:12     INFO - Setting pref layout.css.motion-path-url.enabled to true
[task 2024-03-27T21:08:12.299Z] 21:08:12     INFO - PID 1680 | 2024-03-27 21:08:12.298 firefox[1680:22837] Mozilla has caught an Obj-C exception [NSGenericException: *** Collection <__NSArrayM: 0x1504e5550> was mutated while being enumerated.]
[task 2024-03-27T21:08:12.338Z] 21:08:12     INFO - PID 1680 | 1711573692337	Marionette	INFO	Testing http://web-platform.test:8000/css/motion/offset-path-shape-shape-001.html == http://web-platform.test:8000/css/motion/offset-path-shape-shape-001-ref.html
[task 2024-03-27T21:08:32.342Z] 21:08:32     INFO - TEST-UNEXPECTED-TIMEOUT | /css/motion/offset-path-shape-shape-001.html | expected PASS
[task 2024-03-27T21:08:32.342Z] 21:08:32     INFO - TEST-INFO took 20126ms
[task 2024-03-27T21:08:32.352Z] 21:08:32     INFO - PID 1680 | 1711573712351	Marionette	INFO	Stopped listening on port 49310
[task 2024-03-27T21:08:32.918Z] 21:08:32     INFO - Browser exited with return code 0
[task 2024-03-27T21:08:32.919Z] 21:08:32     INFO - Closing logging queue
[task 2024-03-27T21:08:32.919Z] 21:08:32     INFO - queue closed
[task 2024-03-27T21:08:32.939Z] 21:08:32     INFO - Application command: /opt/worker/tasks/task_171157197409172/build/application/Firefox Nightly.app/Contents/MacOS/firefox --marionette about:blank -foreground -profile /var/folders/54/8r5nfdcs0q7415rh7wc7wd_4000014/T/tmpnlrr8rwc
[task 2024-03-27T21:08:32.945Z] 21:08:32     INFO - Starting runner
[task 2024-03-27T21:08:33.285Z] 21:08:33     INFO - PID 1709 | 1711573713284	Marionette	INFO	Marionette enabled
[task 2024-03-27T21:08:33.517Z] 21:08:33     INFO - PID 1709 | 1711573713516	Marionette	INFO	Listening on port 49317
[task 2024-03-27T21:08:35.631Z] 21:08:35     INFO - PID 1709 | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-03-27T21:08:35.633Z] 21:08:35     INFO - PID 1709 | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-03-27T21:08:35.715Z] 21:08:35     INFO - TEST-START | /css/motion/offset-path-shape-shape-001.html

:boris, since you are the author of the regressor, bug 1884424, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(boris.chiou)
Assignee: nobody → boris.chiou
Flags: needinfo?(boris.chiou)
Blocks: motion-1

Set release status flags based on info from the regressing bug 1884424

status-firefox124: --- → unaffected
status-firefox125: --- → unaffected
status-firefox126: --- → affected
status-firefox-esr115: --- → unaffected

Set release status flags based on info from the regressing bug 1884424

status-firefox127: --- → affected

A few things:
(1) bug 1884424 didn't regress the behavior of this test; it's where we added this test. (And adding the test triggered a test-verify run, which apparently experienced some unexpected timeouts on mac, which resulted in this bug.)

(2) It's pretty surprising that this test would timeout, since it's just a static html+css testcase with no scripting or animation or anything; it should just load instantly.

(3) Looking at the log, I think the timeout is something happening in the harness or the environment, possibly before we even attempt to load the test (though it ends up [mistakenly?] getting attributed to the test). Before each test that times out in the log, I see this:

Mozilla has caught an Obj-C exception [NSGenericException: *** Collection <__NSArrayM: 0x16304dd60> was mutated while being enumerated.]

There are 45 instances of this message in the log here (one for each timeout that happened, I think).

So this seems to be an issue with the harness or environment, not with this test.

--> Unmarking this as a regression from bug 1884424, and reclassifying in the Testing component, tentatively under web-platform-tests if this is that harness (or perhaps the associated test-verify machinery).

jmaher, do you know what might be going on here? Maybe something about test-verify and the harness is using a __NSArrayM under the hood and mutating it as we go? (Or maybe this was just a one-off, not sure.)

No longer blocks: motion-1
status-firefox124: unaffected → ---
status-firefox125: unaffected → ---
status-firefox126: affected → ---
status-firefox127: affected → ---
status-firefox-esr115: unaffected → ---
Component: CSS Parsing and Computation → web-platform-tests
Flags: needinfo?(jmaher)
Keywords: regression
Product: Core → Testing
No longer regressed by: 1884424

(resetting the assignee, given the above; boris, hope that's all right with you :) )

Assignee: boris.chiou → nobody

Whatever the issue was here may also have gone away... TVw is now green when I trigger it for this test on try, on Mac:
https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=ZC9hB0AgR2uw3Iryr6Ozbw.0&revision=23f47be190fee4c9ca73a7ea670c051097c061ca

I don't see anything out of the ordinary in a few logs, so I am going to say that either the machine(s) had an odd state, or this was build or something external dependent.

Flags: needinfo?(jmaher)

FWIW this seems to have been a perma-fail for the original push where we ran into this. I retriggered the test-verify run a bunch there, and every one was orange with this issue:
https://treeherder.mozilla.org/jobs?repo=autoland&revision=232a3ceaa4069c7a3dc9faf06cec8047d7b03131&searchStr=mac%2Cverify&selectedTaskRun=atB_8uXHTpmPduf2rpiDNQ.0

I kicked off some more Try runs to see if I can get it to reproduce on Try, so we can perhaps learn a bit more & see if this is still a latent issue that just requires the right set of conditions...

The debug instances of this failure have a backtrace, which seems to indicate that this is/was indeed a gecko bug rather than a harness bug (though still looking unrelated to the features used by this test):

[task 2024-05-02T16:08:58.007Z] 16:08:58     INFO - PID 869 | [Parent 869, Main Thread] WARNING: NS_ENSURE_TRUE(uri) failed: file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1494
[task 2024-05-02T16:08:58.041Z] 16:08:58     INFO - PID 869 | 2024-05-02 16:08:58.040 firefox[869:11728] Mozilla has caught an Obj-C exception [NSGenericException: *** Collection <__NSArrayM: 0x129790370> was mutated while being enumerated.]
[task 2024-05-02T16:08:58.066Z] 16:08:58     INFO - PID 869 | 2024-05-02 16:08:58.065 firefox[869:11728] Stack trace:
[task 2024-05-02T16:08:58.066Z] 16:08:58     INFO - PID 869 | (
[task 2024-05-02T16:08:58.067Z] 16:08:58     INFO - PID 869 | 	0   CoreFoundation                      0x00007fff2e8d1b57 __exceptionPreprocess + 250
[task 2024-05-02T16:08:58.067Z] 16:08:58     INFO - PID 869 | 	1   libobjc.A.dylib                     0x00007fff675b55bf objc_exception_throw + 48
[task 2024-05-02T16:08:58.068Z] 16:08:58     INFO - PID 869 | 	2   CoreFoundation                      0x00007fff2e94a30b __NSFastEnumerationMutationHandler + 159
[task 2024-05-02T16:08:58.068Z] 16:08:58     INFO - PID 869 | 	3   XUL                                 0x0000000109f6a3a5 _ZN13nsCocoaWindow16HideWindowChromeEb + 373
[task 2024-05-02T16:08:58.069Z] 16:08:58     INFO - PID 869 | 	4   XUL                                 0x000000010b344830 _ZN7mozilla9AppWindow22SyncAttributesToWidgetEv + 464
[task 2024-05-02T16:08:58.070Z] 16:08:58     INFO - PID 869 | 	5   XUL                                 0x000000010b34caae _ZThn16_N7mozilla9AppWindow17BeforeStartLayoutEv + 30
[task 2024-05-02T16:08:58.070Z] 16:08:58     INFO - PID 869 | 	6   XUL                                 0x00000001069a1589 _ZN7mozilla3dom8Document17SetMayStartLayoutEb + 169
[task 2024-05-02T16:08:58.071Z] 16:08:58     INFO - PID 869 | 	7   XUL                                 0x00000001094d37db _ZN7mozilla3dom28PrototypeDocumentContentSink11StartLayoutEv + 315
[task 2024-05-02T16:08:58.071Z] 16:08:58     INFO - PID 869 | 	8   XUL                                 0x00000001094d3222 _ZN7mozilla3dom28PrototypeDocumentContentSink11DoneWalkingEv + 242
[task 2024-05-02T16:08:58.072Z] 16:08:58     INFO - PID 869 | 	9   XUL                                 0x00000001094d308f _ZN7mozilla3dom28PrototypeDocumentContentSink16MaybeDoneWalkingEv + 63
[task 2024-05-02T16:08:58.072Z] 16:08:58     INFO - PID 869 | 	10  XUL                                 0x00000001094d239b _ZN7mozilla3dom28PrototypeDocumentContentSink18ResumeWalkInternalEv + 2251
[task 2024-05-02T16:08:58.073Z] 16:08:58     INFO - PID 869 | 	11  XUL                                 0x00000001094d4014 _ZN7mozilla3dom28PrototypeDocumentContentSink23OnScriptCompileCompleteEPN2js8frontend18CompilationStencilE8nsresult + 196
[task 2024-05-02T16:08:58.074Z] 16:08:58     INFO - PID 869 | 	12  XUL                                 0x00000001094d3d4e _ZN7mozilla3dom28PrototypeDocumentContentSink16OnStreamCompleteEP15nsIStreamLoaderP11nsISupports8nsresultjPKh + 718
[task 2024-05-02T16:08:58.074Z] 16:08:58     INFO - PID 869 | 	13  XUL                                 0x00000001055c7f94 _ZN7mozilla3net14nsStreamLoader13OnStopRequestEP10nsIRequest8nsresult + 164
[task 2024-05-02T16:08:58.076Z] 16:08:58     INFO - PID 869 | 	14  XUL                                 0x0000000105f75786 _ZN12nsJARChannel13OnStopRequestEP10nsIRequest8nsresult + 150
[task 2024-05-02T16:08:58.076Z] 16:08:58     INFO - PID 869 | 	15  XUL                                 0x0000000105f7883d _ZThn32_N12nsJARChannel13OnStopRequestEP10nsIRequest8nsresult + 13
[task 2024-05-02T16:08:58.077Z] 16:08:58     INFO - PID 869 | 	16  XUL                                 0x0000000105546780 _ZN17nsInputStreamPump11OnStateStopEv + 832
[task 2024-05-02T16:08:58.077Z] 16:08:58     INFO - PID 869 | 	17  XUL                                 0x00000001055458af _ZN17nsInputStreamPump18OnInputStreamReadyEP19nsIAsyncInputStream + 287
[task 2024-05-02T16:08:58.077Z] 16:08:58     INFO - PID 869 | 	18  XUL                                 0x0000000105546a6d _ZThn24_N17nsInputStreamPump18OnInputStreamReadyEP19nsIAsyncInputStream + 13
[task 2024-05-02T16:08:58.078Z] 16:08:58     INFO - PID 869 | 	19  XUL                                 0x00000001052c6750 _ZZ32NS_NewCancelableRunnableFunctionIZN14CallbackHolderC1EP19nsIAsyncInputStreamP22nsIInputStreamCallbackjP14nsIEventTargetEUlvE_E16already_AddRefedIN7mozilla18CancelableRunnableEEPKcOT_EN22FuncCancelableRunnable3RunEv + 32
[task 2024-05-02T16:08:58.078Z] 16:08:58     INFO - PID 869 | 	20  XUL                                 0x000000010530e4a8 _ZN7mozilla12RunnableTask3RunEv + 24
[task 2024-05-02T16:08:58.079Z] 16:08:58     INFO - PID 869 | 	21  XUL                                 0x00000001053037e6 _ZN7mozilla14TaskController39DoExecuteNextTaskOnlyMainThreadInternalERKNS_6detail12BaseAutoLockIRNS_5MutexEEE + 1990
[task 2024-05-02T16:08:58.080Z] 16:08:58     INFO - PID 869 | 	22  XUL                                 0x00000001053021c9 _ZN7mozilla14TaskController37ExecuteNextTaskOnlyMainThreadInternalERKNS_6detail12BaseAutoLockIRNS_5MutexEEE + 89
[task 2024-05-02T16:08:58.080Z] 16:08:58     INFO - PID 869 | 	23  XUL                                 0x00000001053026a7 _ZN7mozilla14TaskController20ProcessPendingMTTaskEb + 103
[task 2024-05-02T16:08:58.081Z] 16:08:58     INFO - PID 869 | 	24  XUL                                 0x0000000105313787 _ZN7mozilla6detail16RunnableFunctionIZNS_14TaskControllerC1EvE3$_0E3RunEv + 23
[task 2024-05-02T16:08:58.081Z] 16:08:58     INFO - PID 869 | 	25  XUL                                 0x0000000105328e98 _ZN8nsThread16ProcessNextEventEbPb + 1912
[task 2024-05-02T16:08:58.082Z] 16:08:58     INFO - PID 869 | 	26  XUL                                 0x000000010532530c _Z23NS_ProcessPendingEventsP9nsIThreadj + 172
[task 2024-05-02T16:08:58.082Z] 16:08:58     INFO - PID 869 | 	27  XUL                                 0x0000000109eced62 _ZN14nsBaseAppShell19NativeEventCallbackEv + 114
[task 2024-05-02T16:08:58.083Z] 16:08:58     INFO - PID 869 | 	28  XUL                                 0x0000000109f5cda0 _ZN10nsAppShell18ProcessGeckoEventsEPv + 304
[task 2024-05-02T16:08:58.083Z] 16:08:58     INFO - PID 869 | 	29  CoreFoundation                      0x00007fff2e855d52 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17
[task 2024-05-02T16:08:58.084Z] 16:08:58     INFO - PID 869 | 	30  CoreFoundation                      0x00007fff2e855cf1 __CFRunLoopDoSource0 + 103
[task 2024-05-02T16:08:58.085Z] 16:08:58     INFO - PID 869 | 	31  CoreFoundation                      0x00007fff2e855b0b __CFRunLoopDoSources0 + 209
[task 2024-05-02T16:08:58.085Z] 16:08:58     INFO - PID 869 | 	32  CoreFoundation                      0x00007fff2e85483a __CFRunLoopRun + 927
[task 2024-05-02T16:08:58.086Z] 16:08:58     INFO - PID 869 | 	33  CoreFoundation                      0x00007fff2e853e3e CFRunLoopRunSpecific + 462
[task 2024-05-02T16:08:58.086Z] 16:08:58     INFO - PID 869 | 	34  HIToolbox                           0x00007fff2d480abd RunCurrentEventLoopInMode + 292
[task 2024-05-02T16:08:58.087Z] 16:08:58     INFO - PID 869 | 	35  HIToolbox                           0x00007fff2d4807d5 ReceiveNextEventCommon + 584
[task 2024-05-02T16:08:58.087Z] 16:08:58     INFO - PID 869 | 	36  HIToolbox                           0x00007fff2d480579 _BlockUntilNextEventMatchingListInModeWithFilter + 64
[task 2024-05-02T16:08:58.088Z] 16:08:58     INFO - PID 869 | 	37  AppKit                              0x00007fff2bac6039 _DPSNextEvent + 883
[task 2024-05-02T16:08:58.088Z] 16:08:58     INFO - PID 869 | 	38  AppKit                              0x00007fff2bac4880 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 1352
[task 2024-05-02T16:08:58.089Z] 16:08:58     INFO - PID 869 | 	39  XUL                                 0x0000000109f5c0bf -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 175
[task 2024-05-02T16:08:58.089Z] 16:08:58     INFO - PID 869 | 	40  AppKit                              0x00007fff2bab658e -[NSApplication run] + 658
[task 2024-05-02T16:08:58.090Z] 16:08:58     INFO - PID 869 | 	41  XUL                                 0x0000000109f5bed0 -[GeckoNSApplication run] + 64
[task 2024-05-02T16:08:58.090Z] 16:08:58     INFO - PID 869 | 	42  XUL                                 0x0000000109f5d580 _ZN10nsAppShell3RunEv + 576
[task 2024-05-02T16:08:58.091Z] 16:08:58     INFO - PID 869 | 	43  XUL                                 0x000000010b875a8c _ZN12nsAppStartup3RunEv + 108
[task 2024-05-02T16:08:58.091Z] 16:08:58     INFO - PID 869 | 	44  XUL                                 0x000000010b9f6410 _ZN7XREMain11XRE_mainRunEv + 4272
[task 2024-05-02T16:08:58.092Z] 16:08:58     INFO - PID 869 | 	45  XUL                                 0x000000010b9f7b5d _ZN7XREMain8XRE_mainEiPPcRKN7mozilla15BootstrapConfigE + 1949
[task 2024-05-02T16:08:58.093Z] 16:08:58     INFO - PID 869 | 	46  XUL                                 0x000000010b9f883e _Z8XRE_mainiPPcRKN7mozilla15BootstrapConfigE + 142
[task 2024-05-02T16:08:58.093Z] 16:08:58     INFO - PID 869 | 	47  firefox                             0x00000001010f7c80 main + 1040
[task 2024-05-02T16:08:58.094Z] 16:08:58     INFO - PID 869 | 	48  libdyld.dylib                       0x00007fff6875dcc9 start + 1
[task 2024-05-02T16:08:58.094Z] 16:08:58     INFO - PID 869 | )

https://treeherder.mozilla.org/logviewer?job_id=456706405&repo=try

This seems to have been fixed by

Two Try runs with a test-verify run for this test:, based off of two consecutive changesets:

So this was fixed by 30598180cf6b21d1492ebdad809c3b734eb80850 (a backout of the initial landing of bug 1887063, with the backout-reason being some other test failures). This was just another manifestation of some issues in the initially-landed version of that patch.

But in any case, this isn't an issue with up-to-date mozilla-central, where bug 1887063 has long since been re-landed with the issues addressed.

--> Resolving as FIXED, and adding dependency on bug 1887063 to tie them together (since this was sort-of a followup for that bug, albeit one that was resolved immediately, it turns out).

Status: NEW → RESOLVED
Closed: 2 months ago
Depends on: 1887063
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.