Closed Bug 962949 Opened 10 years ago Closed 5 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: 10 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: 10 years ago → 5 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: