Closed Bug 1783287 Opened 2 years ago Closed 1 month ago

Intermittent dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | single tracking bug

Categories

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

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [retriggered][stockwell disabled])

Attachments

(1 file, 1 obsolete file)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=386452177&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VJwNb_M2ShykqoYciXU1nQ/runs/0/artifacts/public/logs/live_backing.log


[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | pcRemote should have one stream 
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - Run step 50: CHECK_AUDIO
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - Checking local audio enabled
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - TEST-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - Buffered messages finished
[task 2022-08-04T21:06:05.609Z] 21:06:05     INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Test timed out. - 
[task 2022-08-04T21:06:06.041Z] 21:06:06     INFO - GECKO(10312) | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2022-08-04T21:06:06.044Z] 21:06:06     INFO - GECKO(10312) | (ice/INFO) ICE(PC:{5e02a2eb-d278-4e99-8020-89d39111a525} 1659646857923578 (id=8589934845 url=https://example.com/tests/dom/media/webrtc/tests/moc)/STREAM(PC:{5e02a2eb-d278-4e99-8020-89d39111a525} 1659646857923578 (id=8589934845 url=https://example.com/tests/dom/media/webrtc/tests/moc transport-id=transport_0 - eb34487d:c5db99607a20c73ffc94efa7e7e8a543)/COMP(1): Consent refreshed
[task 2022-08-04T21:06:06.377Z] 21:06:06     INFO - GECKO(10312) | MEMORY STAT | vsize 2864MB | residentFast 228MB | heapAllocated 86MB
[task 2022-08-04T21:06:06.387Z] 21:06:06     INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | took 308560ms
[task 2022-08-04T21:06:06.403Z] 21:06:06     INFO - GECKO(10312) | [Child 10459: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2045: Close: Closing PeerConnectionImpl {c0192d6a-b235-4460-8933-2776732dc057}; ending call
[task 2022-08-04T21:06:06.403Z] 21:06:06     INFO - GECKO(10312) | [Child 10459: Main Thread]: I/jsep [{c0192d6a-b235-4460-8933-2776732dc057} 1659646857922236 (id=8589934845 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> closed
[task 2022-08-04T21:06:06.405Z] 21:06:06     INFO - GECKO(10312) | [Child 10459: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2045: Close: Closing PeerConnectionImpl {5e02a2eb-d278-4e99-8020-89d39111a525}; ending call
[task 2022-08-04T21:06:06.406Z] 21:06:06     INFO - GECKO(10312) | [Child 10459: Main Thread]: I/jsep [{5e02a2eb-d278-4e99-8020-89d39111a525} 1659646857923578 (id=8589934845 url=https://example.com/tests/dom/media/webrtc/tests/moc]: stable -> closed
[task 2022-08-04T21:06:06.409Z] 21:06:06     INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyDescriptions.html

Backfills and retriggers indicate it's started when patch 96644f389a58 landed

@Florian, can you take a look at these failures?

Flags: needinfo?(florian)

I'm surprised about this test failure happening only on Android. Doug, do you know if BHR is enabled on Android? If so, can we see the data somewhere? If not, any idea about how my patch could have triggered these android-only failures?

Flags: needinfo?(dothayer)
Whiteboard: [retriggered][stockwell needswork:owner]
See Also: → 1791678

There are 96 total failures in the last 7 days on

[task 2022-09-27T05:40:23.978Z] 05:40:23     INFO -  TEST-START | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  <snipped 850 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  Buffered messages logged at 05:40:23
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Got remote candidate ID 16580aad for selected pair
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  checkStatsIceConnectionType verifying: local={"id":"229050d9","timestamp":1664257223715,"type":"local-candidate","address":"192.168.100.188","candidateType":"host","port":43717,"priority":2122187007,"protocol":"udp"} remote={"id":"16580aad","timestamp":1664257223715,"type":"remote-candidate","address":"192.168.100.188","candidateType":"host","port":48642,"priority":2122187007,"protocol":"udp"}
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Local candidate type is what we expected for selected pair
[task 2022-09-27T05:47:06.956Z] 05:47:06     INFO -  Run step 78: PC_LOCAL_CHECK_ICE_CONNECTIONS
[task 2022-09-27T05:47:06.958Z] 05:47:06     INFO -  PeerConnectionWrapper (pcLocal): Got stats: {"f983e7ac":{"id":"f983e7ac","timestamp":1664257223767,"type":"outbound-rtp","codecId":"a640d66","kind":"audio","mediaType":"audio","ssrc":3353205633,"bytesSent":11815,"packetsSent":187,"headerBytesSent":3740,"nackCount":0,"retransmittedBytesSent":0,"retransmittedPacketsSent":0},"db179ba4":{"id":"db179ba4","timestamp":1664257223768,"type":"outbound-rtp","codecId":"a640d66","kind":"audio","mediaType":"audio","ssrc":501487808,"bytesSent":11109,"packetsSent":69,"headerBytesSent":1380,"nackCount":0,"retransmittedBytesSent":0,"retransmittedPacketsSent":0},"92624c3a":{"id":"92624c3a","timestamp":1664257223765,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"9382e46a","nominated":false,"priority":9114723795305497000,"readable":true,"remoteCandidateId":"59abc036","selected":false,"state":"cancelled","transportId":"transport_0","writable":true},"2f92438d":{"id":"2f92438d","timestamp":1664257223765,"type":"candidate-pair","bytesReceived":850,"bytesSent":33193,"lastPacketReceivedTimestamp":1664257222321,"lastPacketSentTimestamp":1664257223758,"localCandidateId":"9382e46a","nominated":true,"priority":7961802290698650000,"readable":true,"remoteCandidateId":"60d319e0","selected":true,"state":"succeeded","transportId":"transport_0","writable":true},"9382e46a":{"id":"9382e46a","timestamp":1664257223765,"type":"local-candidate","address":"192.168.100.188","candidateType":"host","port":48642,"priority":2122187007,"protocol":"udp"},"9bba9d91":{"id":"9bba9d91","timestamp":1664257223765,"type":"local-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":44220,"priority":2122252543,"protocol":"udp"},"76d4a2ec":{"id":"76d4a2ec","timestamp":1664257223765,"type":"local-candidate","address":"192.168.100.188","candidateType":"host","port":53314,"priority":2105458943,"protocol":"tcp"},"5252c98f":{"id":"5252c98f","timestamp":1664257223765,"type":"local-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":63456,"priority":2105524479,"protocol":"tcp"},"60d319e0":{"id":"60d319e0","timestamp":1664257223765,"type":"remote-candidate","address":"192.168.100.188","candidateType":"prflx","port":43717,"priority":1853751551,"protocol":"udp"},"59abc036":{"id":"59abc036","timestamp":1664257223765,"type":"remote-candidate","address":"192.168.100.188","candidateType":"host","port":43717,"priority":2122187007,"protocol":"udp"},"a640d66":{"id":"a640d66","timestamp":1664257223765,"type":"codec","channels":2,"clockRate":48000,"codecType":"encode","mimeType":"audio/opus","payloadType":109,"sdpFmtpLine":"maxplaybackrate=48000;stereo=1;useinbandfec=1","transportId":"transport_0"}}
[task 2022-09-27T05:47:06.958Z] 05:47:06     INFO -  ICE connections according to stats: 1
[task 2022-09-27T05:47:06.959Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Number of ICE connections according to stats is not zero
[task 2022-09-27T05:47:06.959Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | stats reports exactly 1 ICE connection
[task 2022-09-27T05:47:06.959Z] 05:47:06     INFO -  Run step 79: PC_REMOTE_CHECK_ICE_CONNECTIONS
[task 2022-09-27T05:47:06.962Z] 05:47:06     INFO -  PeerConnectionWrapper (pcRemote): Got stats: {"6f3b329c":{"id":"6f3b329c","timestamp":1664257223810,"type":"inbound-rtp","codecId":"d86a0024","kind":"audio","mediaType":"audio","ssrc":3353205633,"jitter":0.006,"packetsDiscarded":0,"packetsLost":0,"packetsReceived":188,"audioLevel":0,"bytesReceived":11818,"concealedSamples":1280,"concealmentEvents":1,"fecPacketsDiscarded":0,"fecPacketsReceived":0,"headerBytesReceived":3760,"insertedSamplesForDeceleration":1968,"jitterBufferDelay":5990.4,"jitterBufferEmittedCount":179520,"lastPacketReceivedTimestamp":1664257223778,"remoteId":"d64e91b6","removedSamplesForAcceleration":432,"silentConcealedSamples":760,"totalAudioEnergy":0.014603819131186965,"totalSamplesDuration":3.839999999999962,"totalSamplesReceived":181760},"85cac4eb":{"id":"85cac4eb","timestamp":1664257223810,"type":"inbound-rtp","codecId":"d86a0024","kind":"audio","mediaType":"audio","ssrc":501487808,"jitter":0.005,"packetsDiscarded":0,"packetsLost":0,"packetsReceived":71,"audioLevel":0.10043641468550676,"bytesReceived":11431,"concealedSamples":2496,"concealmentEvents":2,"fecPacketsDiscarded":0,"fecPacketsReceived":0,"headerBytesReceived":1420,"insertedSamplesForDeceleration":1776,"jitterBufferDelay":2380.8,"jitterBufferEmittedCount":67200,"lastPacketReceivedTimestamp":1664257223795,"remoteId":"3a6a873f","removedSamplesForAcceleration":576,"silentConcealedSamples":1400,"totalAudioEnergy":0.01346528060470192,"totalSamplesDuration":1.5400000000000011,"totalSamplesReceived":70080},"d64e91b6":{"id":"d64e91b6","timestamp":1664257220045,"type":"remote-outbound-rtp","codecId":"d86a0024","kind":"audio","mediaType":"audio","ssrc":3353205633,"bytesSent":0,"packetsSent":0,"localId":"6f3b329c","remoteTimestamp":1664257220036},"3a6a873f":{"id":"3a6a873f","timestamp":1664257222399,"type":"remote-outbound-rtp","codecId":"d86a0024","kind":"audio","mediaType":"audio","ssrc":501487808,"bytesSent":0,"packetsSent":0,"localId":"85cac4eb","remoteTimestamp":1664257222391},"a8bee2dc":{"id":"a8bee2dc","timestamp":1664257223807,"type":"candidate-pair","bytesReceived":0,"bytesSent":0,"lastPacketReceivedTimestamp":0,"lastPacketSentTimestamp":0,"localCandidateId":"4fa0f023","nominated":false,"priority":9115005270282338000,"readable":true,"remoteCandidateId":"a68f35f3","selected":false,"state":"cancelled","transportId":"transport_0","writable":true},"f3a23c57":{"id":"f3a23c57","timestamp":1664257223807,"type":"candidate-pair","bytesReceived":33626,"bytesSent":850,"lastPacketReceivedTimestamp":1664257223793,"lastPacketSentTimestamp":1664257222318,"localCandidateId":"229050d9","nominated":true,"priority":9114723795305497000,"readable":true,"remoteCandidateId":"16580aad","selected":true,"state":"succeeded","transportId":"transport_0","writable":true},"229050d9":{"id":"229050d9","timestamp":1664257223807,"type":"local-candidate","address":"192.168.100.188","candidateType":"host","port":43717,"priority":2122187007,"protocol":"udp"},"4fa0f023":{"id":"4fa0f023","timestamp":1664257223807,"type":"local-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":49089,"priority":2122252543,"protocol":"udp"},"f52bf8b6":{"id":"f52bf8b6","timestamp":1664257223807,"type":"local-candidate","address":"192.168.100.188","candidateType":"host","port":51114,"priority":2105458943,"protocol":"tcp"},"cd5270c9":{"id":"cd5270c9","timestamp":1664257223807,"type":"local-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":50390,"priority":2105524479,"protocol":"tcp"},"16580aad":{"id":"16580aad","timestamp":1664257223807,"type":"remote-candidate","address":"192.168.100.188","candidateType":"host","port":48642,"priority":2122187007,"protocol":"udp"},"a68f35f3":{"id":"a68f35f3","timestamp":1664257223807,"type":"remote-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":44220,"priority":2122252543,"protocol":"udp"},"9a6cea08":{"id":"9a6cea08","timestamp":1664257223807,"type":"remote-candidate","address":"192.168.100.188","candidateType":"host","port":9,"priority":2105458943,"protocol":"tcp"},"78abb68":{"id":"78abb68","timestamp":1664257223807,"type":"remote-candidate","address":"2001:2::752a:d3e9:c57b:ccfe","candidateType":"host","port":9,"priority":2105524479,"protocol":"tcp"},"d86a0024":{"id":"d86a0024","timestamp":1664257223807,"type":"codec","channels":2,"clockRate":48000,"codecType":"decode","mimeType":"audio/opus","payloadType":109,"sdpFmtpLine":"maxplaybackrate=48000;stereo=1;useinbandfec=1","transportId":"transport_0"}}
[task 2022-09-27T05:47:06.962Z] 05:47:06     INFO -  ICE connections according to stats: 1
[task 2022-09-27T05:47:06.962Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Number of ICE connections according to stats is not zero
[task 2022-09-27T05:47:06.962Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | stats reports exactly 1 ICE connection
[task 2022-09-27T05:47:06.962Z] 05:47:06     INFO -  Run step 80: PC_LOCAL_CHECK_MSID

[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Event target should be the correct track
[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  PeerConnectionWrapper (pcLocal) ended fired for track {e2697b59-8cd9-46bb-8c1c-a5a1f8c534de}
[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Event target should be the correct track
[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  PeerConnectionWrapper (pcRemote) ended fired for track {666f6b65-162e-4881-9e9c-9be4343c79a9}
[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  TEST-PASS | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Event target should be the correct track
[task 2022-09-27T05:47:06.981Z] 05:47:06     INFO -  PeerConnectionWrapper (pcRemote) ended fired for track {a524c4f0-b6b1-4d3f-83c6-e159003b1302}
[task 2022-09-27T05:47:06.982Z] 05:47:06     INFO -  Buffered messages finished
[task 2022-09-27T05:47:06.982Z] 05:47:06  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Test timed out. -
[task 2022-09-27T05:49:42.158Z] 05:49:42     INFO -  TEST-OK | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | took 554045ms
[task 2022-09-27T05:50:23.568Z] 05:50:23  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2022-09-27T05:50:23.568Z] 05:50:23  WARNING -  TEST-UNEXPECTED-ERROR | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | called finish() multiple times
[task 2022-09-27T05:50:23.568Z] 05:50:23     INFO -  TEST-INFO
[task 2022-09-27T05:52:07.060Z] 05:52:07  WARNING -  TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_peerConnection_verifyAudioAfterRenegotiation.html | Test timed out. -

There have been 70 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • android-em-7-0-x86_64-lite-qr
  • android-em-7-0-x86_64-qr
  • android-em-7-0-x86_64-shippable-lite-qr
  • android-em-7-0-x86_64-shippable-qr

looking at the total runs we have had on central/autoland in the last week (oct 7-14):

job type ifv total runs % failed ifv
test-android-em-7.0-x86_64-lite-qr/opt-geckoview-mochitest-media-nofis 90 245 36.73%
test-android-em-7.0-x86_64-qr/opt-geckoview-mochitest-media-nofis 19 47 40.43%
test-android-em-7.0-x86_64-shippable-lite-qr/opt-geckoview-mochitest-media-nofis 5 25 20.00%
test-android-em-7.0-x86_64-shippable-qr/opt-geckoview-mochitest-media-nofis 8 25 32.00%

Given that this has been ni? for 22+ days and it is failing 20-40% of the time depending on the configuration, we should disable it on os == "android" && !debug

Eugh - sorry for the lack of response to the needinfo here, though. To answer your question, Florian, I believe it is enabled on Android, and I don't see any reason in code why it wouldn't be.

Flags: needinfo?(dothayer)
Keywords: leave-open
Attachment #9298731 - Attachment description: Bug 1783287 - disable test_peerConnection_verifyAudioAfterRenegotiation.html on android opt for frequent failures. r=#intermittent-reviewers → Bug 1783287 - disable test_peerConnection_verifyAudioAfterRenegotiation.html on android x86_64 opt for frequent failures. r=#intermittent-reviewers
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Pushed by imoraru@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/adea2691db4f disable test_peerConnection_verifyAudioAfterRenegotiation.html on android x86_64 opt for frequent failures. r=intermittent-reviewers,MasterWayZ

Clearing needinfo as I don't know anything about this test, and investigating here doesn't seem to be a high priority.

Flags: needinfo?(florian)
Attachment #9387019 - Attachment is obsolete: true
Status: NEW → RESOLVED
Closed: 1 month ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: