Closed Bug 962949 Opened 11 years ago Closed 6 years ago

Intermittent test_preload_actions.html | (14) NetworkState must be NETWORK_IDLE - got 2, expected 1

Categories

(Core :: Audio/Video: Playback, defect, P5)

Product:
Core
Component:
Audio/Video: Playback
Platform:
x86_64
Windows 8
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME
Milestone:
mozilla30
Tracking Flags:
Tracking Status
firefox28 --- unaffected
firefox29 --- disabled
firefox30 --- disabled
firefox-esr24 --- unaffected

People

(Reporter: KWierso, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [part of test disabled])

Attachments

(2 files)

logs
197.94 KB, application/x-zip
Details
disable, v1
8.37 KB, patch
roc
: review+
mayhemer
: checkin+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=33428198&tree=Fx-Team slave: t-w864-ix-125 17:40:52 INFO - 127801 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (13) ReadyState must be HAVE_NOTHING 17:40:52 INFO - 127802 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (13) NetworkState must be NETWORK_IDLE 17:40:52 INFO - 127803 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | [finished 29] Length of array should match number of running tests 17:40:52 INFO - 127804 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | [started 30] Length of array should match number of running tests 17:40:52 INFO - 127805 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (14) Must get loadstart. 17:40:52 INFO - 127806 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (14) Must get loadedmetadata. 17:40:52 INFO - 127807 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (14) ReadyState must be >= HAVE_CURRENT_DATA 17:40:52 INFO - 127808 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_preload_actions.html | (14) NetworkState must be NETWORK_IDLE - got 2, expected 1 17:40:52 INFO - 127809 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (11) Must get loadedmetadata. 17:40:52 INFO - 127810 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (11) ReadyState must be >= HAVE_CURRENT_DATA. 17:40:52 INFO - 127811 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (11) NetworkState must be NETWORK_IDLE. 17:40:52 INFO - 127812 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | [finished 27] Length of array should match number of running tests 17:40:52 INFO - 127813 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | [started 31] Length of array should match number of running tests 17:40:56 INFO - 127814 INFO TEST-PASS | /tests/content/media/test/test_preload_actions.html | (14) Got playback ended
I can reproduce this reliably on Windows if I crank PARALLEL_TESTS to 20.
A lot of this will probably be resolved by the backout of bug 967693.
And while that most recent instance is on my backout push, I triggered something like 170 mochitest-1 runs on it, so for a four-per-day intermittent one isn't horribly surprising.
I think it's a blind luck the test even works in most cases. The event 'loadeddata' where we check the state is posted. Between post and fire happens a lot of stuff on the underlying decoder (is it shared?) and the state of the element may change in between. In logs (combination of VS tracing and console output) I can see the network state is at 2 when we post the event, and is set to 1 before it actually fires because we receive HTMLMediaElement::DownloadSuspended. In case of a failure, this is missing. Is that something always expected? I don't known the media element that well.. The code is really complicated and the number of events and "asynchronicity" makes it hard to track. I tend to just disable the checks for network state for now (in all of the sub-tests - since it failed for me sometimes even in different tests then 11 and 14). Any objections?
Flags: needinfo?(martijn.martijn)
In the bad case the log looks like (the element 0x12cfb8e0 is reused by other sub-tests running before): MIGHT BE A CLUE: Looks like the DownloadResumed/DownloadSuspended calls are simply missing. this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=3, xul.dll!mozilla::dom::HTMLMediaElement::SelectResource this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::SuspendLoad this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::ResumeLoad this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::FinishDecoderSetup this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, Dispatch loadeddata xul.dll!mozilla::dom::HTMLMediaElement::ChangeReadyState this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData this=0x12cfb8e0 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData TEST-PASS | unknown test url | (11) Must get loadedmetadata. TEST-PASS | unknown test url | (11) ReadyState must be >= HAVE_CURRENT_DATA. TEST-UNEXPECTED-FAIL | unknown test url | (11) NetworkState must be NETWORK_IDLE. - got 2, expected 1 In the passing case, the log looks like: this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=3, xul.dll!mozilla::dom::HTMLMediaElement::SelectResource this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::SuspendLoad this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::ResumeLoad this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::FinishDecoderSetup this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::DownloadResumed this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::DownloadResumed this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, Dispatch loadeddata xul.dll!mozilla::dom::HTMLMediaElement::ChangeReadyState this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::DownloadSuspended this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData TEST-PASS | unknown test url | (11) Must get loadedmetadata. TEST-PASS | unknown test url | (11) ReadyState must be >= HAVE_CURRENT_DATA. TEST-PASS | unknown test url | (11) NetworkState must be NETWORK_IDLE. DownloadSuspended is called from: this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::DownloadSuspended xul.dll!mozilla::ChannelMediaResource::Suspend xul.dll!mozilla::MediaDecoder::Suspend xul.dll!mozilla::dom::HTMLMediaElement::FirstFrameLoaded xul.dll!mozilla::MediaDecoder::MetadataLoaded xul.dll!mozilla::AudioMetadataEventRunner::Run xul.dll!nsThread::ProcessNextEvent where AudioMetadataEventRunner is posted from: this=0x12be5e60 {mDecoder={mRawPtr=0x13562e34 {...} } mChannels=2 mRate=44100 ...}, xul.dll!mozilla::AudioMetadataEventRunner::AudioMetadataEventRunner xul.dll!mozilla::MediaDecoderStateMachine::DecodeMetadata xul.dll!mozilla::MediaDecoderStateMachine::DecodeThreadRun xul.dll!nsRunnableMethodImpl<void (__thiscall mozilla::MediaDecoderStateMachine::*)(void),void,1>::Run there are only two places this event gets posted: http://mxr.mozilla.org/mozilla-central/search?string=%26MediaDecoderStateMachine%3A%3ADecodeThreadRun and there I'm lost... DownloadResumed is called from (in both cases): this=0x12867058 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::DownloadResumed xul.dll!mozilla::ChannelMediaResource::OpenChannel xul.dll!mozilla::ChannelMediaResource::CacheClientSeek xul.dll!mozilla::MediaCache::Update xul.dll!mozilla::UpdateEvent::Run xul.dll!nsThread::ProcessNextEvent
Hona, I'm sorry, but I can't help you with this, I have no idea why this would be failing.
Flags: needinfo?(martijn.martijn)
Attached file logs —
Here are logs I was able to capture + some tooling around. I'm completely lost since there is no channel association at the media element. base-changeset - the m-c cset I was testing on bash-nspr-console - NSPR log merged with TEST-* logs (bash console) content.patch - small nits to make traces work vs-console - VS Output window, merge of trace point and TEST-* logs, 0x12cb3958 - the element responsible for bad test run*) vs-traces.xml - trace/break points added (vs2013) *) Line 50254: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::SelectResource Line 50312: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::SuspendLoad Line 50491: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=1, xul.dll!mozilla::dom::HTMLMediaElement::ResumeLoad Line 50546: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::FinishDecoderSetup Line 50870: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::ChangeReadyState Line 50922: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData Line 51006: this=0x12cb3958 {mScreenWakeLock={mRawPtr=0x00000000 <NULL> } }, mChannel=0x00000000 <NULL>, mNetworkState=2, xul.dll!mozilla::dom::HTMLMediaElement::UpdateReadyStateForData Line 51118: TEST-PASS | unknown test url | (11) Must get loadedmetadata. Line 51119: TEST-PASS | unknown test url | (11) ReadyState must be >= HAVE_CURRENT_DATA. Line 51120: TEST-UNEXPECTED-FAIL | unknown test url | (11) NetworkState must be NETWORK_IDLE. - got 2, expected 1
For now I'm going to disable all the netstate check in this test since those are apparently unreliable. I'll leave this up to someone who knows this test and the media decoder code better then me.
Attached patch disable, v1 — — Splinter Review
All sub-tests for networkState disabled. I was able to hit this not just with 11 and 14 sub-tests locally. I've spent too much time on this already, and I'm apparently not that familiar with the code.
Attachment #8372323 - Flags: review?(roc)
Blocks: 967693
https://hg.mozilla.org/mozilla-central/rev/987400b6b818
Assignee: nobody → honzab.moz
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
Sorry, forgot to set LEAVE OPEN. There is still a work to do (or to decide whether to remove the v.networkState sub-tests completely).
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
We (necko people) believe these test failures are caused by problems in the actual tests rather then in the new http cache, hence moving to the A/V component.
No longer blocks: cache2tests
Summary: Intermittent TEST-UNEXPECTED-FAIL | test_preload_actions.html | (14) NetworkState must be NETWORK_IDLE - got 2, expected 1 → Intermittent test_preload_actions.html | (14) NetworkState must be NETWORK_IDLE - got 2, expected 1
Assignee: honzab.moz → nobody
Keywords: leave-open
Whiteboard: [part of test disabled]
Component: Audio/Video → Audio/Video: Playback
P5
Priority: -- → P5
The leave-open keyword is there and there is no activity for 6 months. :drno, maybe it's time to close this bug?
Flags: needinfo?(drno)
Status: REOPENED → RESOLVED
Closed: 11 years ago → 6 years ago
Resolution: --- → WORKSFORME
Flags: needinfo?(drno)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: