Closed Bug 1608963 Opened 5 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount initial value should be 0 for both peers - Test timed out

Categories

(Core :: WebRTC, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=284717190&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Rwx4wp6TTEa1B0HHOqX6_g/runs/0/artifacts/public/logs/live_backing.log


[task 2020-01-13T19:41:57.353Z] 19:41:57 INFO - TEST-START | /webrtc/RTCDataChannel-bufferedAmount.html
[task 2020-01-13T19:41:57.364Z] 19:41:57 INFO - Clearing pref media.navigator.permission.disabled
[task 2020-01-13T19:41:57.385Z] 19:41:57 INFO - PID 9540 | C:1578944508422000 (id=214748364[Child 5160: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2863: GetStats: Found no pipelines matching selector.
[task 2020-01-13T19:41:57.393Z] 19:41:57 INFO - Clearing pref privacy.resistFingerprinting.reduceTimerPrecision.jitter
[task 2020-01-13T19:41:57.414Z] 19:41:57 INFO - Clearing pref media.navigator.streams.fake
[task 2020-01-13T19:41:57.426Z] 19:41:57 INFO - PID 9540 | 82 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonech[Child 5160: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2863: GetStats: Found no pipelines matching selector.
[task 2020-01-13T19:41:57.431Z] 19:41:57 INFO - Clearing pref privacy.reduceTimerPrecision
[task 2020-01-13T19:41:57.472Z] 19:41:57 INFO - PID 9540 | ange.https.html)):[Child 5160: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2863: GetStats: Found no pipelines matching selector.
[task 2020-01-13T19:41:57.479Z] 19:41:57 INFO - Setting pref media.navigator.permission.disabled (true)
[task 2020-01-13T19:41:57.507Z] 19:41:57 INFO - PID 9540 | peer (PC:1578944508422000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html):default) no checks to start
[task 2020-01-13T19:41:57.519Z] 19:41:57 INFO - Setting pref privacy.resistFingerprinting.reduceTimerPrecision.jitter (false)
[task 2020-01-13T19:41:57.563Z] 19:41:57 INFO - Setting pref media.navigator.streams.fake (true)
[task 2020-01-13T19:41:57.570Z] 19:41:57 INFO - PID 9540 | [Child 5160: Socket Thread]: D/mtransport Couldn't start peer checks on PC:1578944508422000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html), assuming trickle ICE
[task 2020-01-13T19:41:57.612Z] 19:41:57 INFO - Setting pref privacy.reduceTimerPrecision (false)
[task 2020-01-13T19:41:57.634Z] 19:41:57 INFO - Closing window 43
[task 2020-01-13T19:41:57.661Z] 19:41:57 INFO - PID 9540 | (ice/INFO) ICE(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html)): peer (PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html):default) Trickle grace period is over; marking every component with only failed pairs as failed.
[task 2020-01-13T19:41:57.753Z] 19:41:57 INFO - PID 9540 | (ice/INFO) ICE-PEER(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html):default)/STREAM(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html) transport-id=transport_0 - 204f1389:38f48382601b8649c480a75f6f3eaf67)/COMP(1): All pairs are failed, and grace period has elapsed. Marking component as failed.
[task 2020-01-13T19:41:57.814Z] 19:41:57 INFO - PID 9540 | (ice/ERR) ICE(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html))/STREAM(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html) transport-id=transport_0 - 204f1389:38f48382601b8649c480a75f6f3eaf67): state dump
[task 2020-01-13T19:41:57.857Z] 19:41:57 INFO - PID 9540 | (ice/ERR) ICE(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html))/ICE-STREAM(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html) transport-id=transport_0 - 204f1389:38f48382601b8649c480a75f6f3eaf67): Local component 1 - dumping candidates
[task 2020-01-13T19:41:57.899Z] 19:41:57 INFO - PID 9540 | (ice/ERR) ICE(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html))/ICE-STREAM(PC:1578944503409000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html) transport-id=transport_0 - 204f1389:38f48382601b8649c480a75f6f3eaf67)/CAND(H3g5): host(IP4:10.7.204.47:55004/UDP)
[task 2020-01-13T19:41:57.911Z] 19:41:57 INFO - PID 9540 | (ice/ERR) ICE(PC:1578944503409[Child 5160: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2192: CloseInt: Closing PeerConnectionImpl 0a732fda890f809e; ending call
[task 2020-01-13T19:41:57.932Z] 19:41:57 INFO - PID 9540 | 000 (id[Child 5160: Main Thread]: I/jsep [1578944515837000 (id=21474836482 url=https://web-platform.test:8443/webrtc/RTCDTMFSender-ontonechange.https.html)]: stable -> closed

[task 2020-01-13T19:45:58.670Z] 19:45:58 INFO - PID 9540 | [Child 1892: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2876: GetStats: Found no pipelines matching selector.
[task 2020-01-13T19:45:58.701Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.701Z] 19:45:58 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount initial value should be 0 for both peers - Test timed out
[task 2020-01-13T19:45:58.704Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.705Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should increase to byte length of encoded unicode string sent - expected PASS
[task 2020-01-13T19:45:58.710Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.711Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should increase to byte length of buffer sent - expected PASS
[task 2020-01-13T19:45:58.714Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.715Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should increase to size of blob sent - expected PASS
[task 2020-01-13T19:45:58.718Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.719Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should increase by byte length for each message sent - expected PASS
[task 2020-01-13T19:45:58.723Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.724Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should not decrease immediately after initiating closure - expected PASS
[task 2020-01-13T19:45:58.728Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.729Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | bufferedAmount should not decrease after closing the peer connection - expected PASS
[task 2020-01-13T19:45:58.733Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.733Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | Data channel bufferedamountlow event fires after send() is complete - expected PASS
[task 2020-01-13T19:45:58.736Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.737Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | Data channel bufferedamount is data.length on send(data) - expected PASS
[task 2020-01-13T19:45:58.742Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.742Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | Data channel bufferedamount returns the same amount if no more data is sent on the channel - expected PASS
[task 2020-01-13T19:45:58.746Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.747Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | Data channel bufferedamountlow event fires only once after multiple consecutive send() calls - expected PASS
[task 2020-01-13T19:45:58.751Z] 19:45:58 INFO -
[task 2020-01-13T19:45:58.753Z] 19:45:58 INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | Data channel bufferedamountlow event fires after each sent message - expected PASS
[task 2020-01-13T19:45:58.756Z] 19:45:58 INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-bufferedAmount.html | expected OK
[task 2020-01-13T19:45:58.756Z] 19:45:58 INFO - TEST-INFO took 241388ms
[task 2020-01-13T19:45:58.792Z] 19:45:58 INFO - PID 9540 | 1578944758769 Marionette INFO Stopped listening on port 49950

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306997046&repo=autoland&lineNumber=20384

INFO - TEST-START | /css/css-cascade/revert-val-010.html
[task 2020-06-21T14:19:59.677Z] 14:19:59     INFO - Closing window 39
[task 2020-06-21T14:19:59.952Z] 14:19:59     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:19:59.952Z] 14:19:59     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:20:00.306Z] 14:20:00     INFO - .
[task 2020-06-21T14:20:00.306Z] 14:20:00     INFO - TEST-OK | /css/css-cascade/revert-val-010.html | took 634ms
[task 2020-06-21T14:20:00.313Z] 14:20:00     INFO - Restarting browser for new test group
[task 2020-06-21T14:20:00.328Z] 14:20:00     INFO - PID 2300 | 1592749200318	Marionette	INFO	Stopped listening on port 53146
[task 2020-06-21T14:20:00.604Z] 14:20:00     INFO - PID 2300 | [Child 4480, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:00.719Z] 14:20:00     INFO - PID 2300 | [Child 4952, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:00.830Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.835Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.844Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.844Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.848Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.848Z] 14:20:00     INFO - PID 2300 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:00.868Z] 14:20:00     INFO - PID 2300 | [Child 5572, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:00.915Z] 14:20:00     INFO - PID 2300 | [2020-06-21T14:20:00Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-06-21T14:20:00.915Z] 14:20:00     INFO - PID 2300 | [2020-06-21T14:20:00Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-06-21T14:20:00.972Z] 14:20:00     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:20:00.972Z] 14:20:00     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:20:01.044Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.045Z] 14:20:01     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount initial value should be 0 for both peers - Test timed out
[task 2020-06-21T14:20:01.045Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.046Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should increase to byte length of encodedunicode string sent - expected PASS
[task 2020-06-21T14:20:01.046Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.047Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should increase to byte length of buffer sent - expected PASS
[task 2020-06-21T14:20:01.048Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.048Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should increase to size of blob sent - expected PASS
[task 2020-06-21T14:20:01.049Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.049Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should increase by byte length for each message sent - expected PASS
[task 2020-06-21T14:20:01.050Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.052Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should not decrease immediately after initiating closure - expected PASS
[task 2020-06-21T14:20:01.053Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.053Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedAmount should not decrease after closing the peer connection - expected PASS
[task 2020-06-21T14:20:01.054Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.054Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedamountlow event fires after send() is complete - expected PASS
[task 2020-06-21T14:20:01.055Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.055Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedamount is data.length on send(data) - expected PASS
[task 2020-06-21T14:20:01.056Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.057Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedamount returns the same amount if no more data is - expected PASS
[task 2020-06-21T14:20:01.057Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.057Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedamountlow event fires only once after multiple consecutive send() calls - expected PASS
[task 2020-06-21T14:20:01.058Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.058Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | datachannel bufferedamountlow event fires after each sent message - expected PASS
[task 2020-06-21T14:20:01.058Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.058Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount initial value should be 0 for both peers - expected PASS
[task 2020-06-21T14:20:01.059Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.059Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should increase to byte length of encodedunicode string sent - expected PASS
[task 2020-06-21T14:20:01.059Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.059Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should increase to byte length of buffer sent - expected PASS
[task 2020-06-21T14:20:01.060Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.060Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should increase to size of blob sent - expected PASS
[task 2020-06-21T14:20:01.060Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.060Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should increase by byte length for each message sent - expected PASS
[task 2020-06-21T14:20:01.061Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.061Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should not decrease immediately after initiating closure - expected PASS
[task 2020-06-21T14:20:01.061Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.062Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedAmount should not decrease after closing the peer connection - expected PASS
[task 2020-06-21T14:20:01.062Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.062Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedamountlow event fires after send() is complete - expected PASS
[task 2020-06-21T14:20:01.062Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.063Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedamount is data.length on send(data) - expected PASS
[task 2020-06-21T14:20:01.063Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.063Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedamount returns the same amount if no more data is - expected PASS
[task 2020-06-21T14:20:01.063Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.064Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedamountlow event fires only once after multiple consecutive send() calls - expected PASS
[task 2020-06-21T14:20:01.064Z] 14:20:01     INFO - 
[task 2020-06-21T14:20:01.064Z] 14:20:01     INFO - TEST-UNEXPECTED-NOTRUN | /webrtc/RTCDataChannel-bufferedAmount.html | negotiated datachannel bufferedamountlow event fires after each sent message - expected PASS
[task 2020-06-21T14:20:01.064Z] 14:20:01     INFO - TEST-UNEXPECTED-TIMEOUT | /webrtc/RTCDataChannel-bufferedAmount.html | expected OK
[task 2020-06-21T14:20:01.064Z] 14:20:01     INFO - TEST-INFO took 181179ms
[task 2020-06-21T14:20:01.080Z] 14:20:01     INFO - PID 6364 | 1592749201076	Marionette	INFO	Stopped listening on port 51912
[task 2020-06-21T14:20:01.099Z] 14:20:01     INFO - PID 2300 | [Child 6392, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.218Z] 14:20:01     INFO - PID 2300 | [Parent 5340, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/checkouts/gecko/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1279
[task 2020-06-21T14:20:01.285Z] 14:20:01     INFO - PID 2300 | [Parent 5340, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 227
[task 2020-06-21T14:20:01.285Z] 14:20:01     INFO - PID 2300 | [Parent 5340, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 254
[task 2020-06-21T14:20:01.305Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:20:01.305Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2116: CloseInt: Closing PeerConnectionImpl 4850430d2ace40fc; ending call
[task 2020-06-21T14:20:01.306Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/jsep [1592749020910000 (id=12884901890 url=http://web-platform.test:8000/webrtc/RTCDataChannel-bufferedAmount.html)]: stable -> closed
[task 2020-06-21T14:20:01.306Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2122: CloseInt: Destroying DataChannelConnection 00B92690 for 4850430d2ace40fc
[task 2020-06-21T14:20:01.307Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Destroying DataChannelConnection 00B92690
[task 2020-06-21T14:20:01.307Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Closing all channels (connection 00B92690)
[task 2020-06-21T14:20:01.308Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (00B92690) switching connection state CLOSED -> CLOSED
[task 2020-06-21T14:20:01.308Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Connection 00B92690: Sending outgoing stream reset for 1 streams
[task 2020-06-21T14:20:01.310Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: E/DataChannel ***failed: setsockopt RESET, errno 2
[task 2020-06-21T14:20:01.310Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Clearing resets for 1 streams
[task 2020-06-21T14:20:01.311Z] 14:20:01     INFO - PID 6364 | [Child 6172: Socket Thread]: D/DataChannel Deregistered 00000001 from the SCTP stack.
[task 2020-06-21T14:20:01.311Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2751: GetStats: Found no pipelines matching selector.
[task 2020-06-21T14:20:01.312Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2116: CloseInt: Closing PeerConnectionImpl ad0fa19a1d482c95; ending call
[task 2020-06-21T14:20:01.312Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/jsep [1592749020916000 (id=12884901890 url=http://web-platform.test:8000/webrtc/RTCDataChannel-bufferedAmount.html)]: stable -> closed
[task 2020-06-21T14:20:01.312Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:2122: CloseInt: Destroying DataChannelConnection 00B93AE0 for ad0fa19a1d482c95
[task 2020-06-21T14:20:01.313Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Destroying DataChannelConnection 00B93AE0
[task 2020-06-21T14:20:01.313Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Closing all channels (connection 00B93AE0)
[task 2020-06-21T14:20:01.313Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel DataChannelConnection labeled transport_0 (00B93AE0) switching connection state CLOSED -> CLOSED
[task 2020-06-21T14:20:01.314Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Connection 00B93AE0: Sending outgoing stream reset for 0 streams
[task 2020-06-21T14:20:01.314Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel No streams to reset
[task 2020-06-21T14:20:01.315Z] 14:20:01     INFO - PID 6364 | [Child 6172: Socket Thread]: D/DataChannel Deregistered 00000002 from the SCTP stack.
[task 2020-06-21T14:20:01.315Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Deleting DataChannelConnection 00B92690
[task 2020-06-21T14:20:01.315Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Deleting DataChannelConnection 00B93AE0
[task 2020-06-21T14:20:01.335Z] 14:20:01     INFO - PID 6364 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:01.335Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel Shutting down SCTP
[task 2020-06-21T14:20:01.355Z] 14:20:01     INFO - PID 6364 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-06-21T14:20:01.390Z] 14:20:01     INFO - PID 6364 | Timecard created 1592749020.907000
[task 2020-06-21T14:20:01.390Z] 14:20:01     INFO - PID 6364 |  Timestamp   | Delta       | Event                             | File                         | Function
[task 2020-06-21T14:20:01.391Z] 14:20:01     INFO - PID 6364 | =========================================================================================================================
[task 2020-06-21T14:20:01.391Z] 14:20:01     INFO - PID 6364 |     0.000000 |    0.000000 | Constructor Completed             | PeerConnectionImpl.cpp:332   | PeerConnectionImpl
[task 2020-06-21T14:20:01.391Z] 14:20:01     INFO - PID 6364 |     0.003000 |    0.003000 | Initializing PC Ctx               | PeerConnectionImpl.cpp:458   | Initialize
[task 2020-06-21T14:20:01.392Z] 14:20:01     INFO - PID 6364 |     0.029000 |    0.026000 | Deferring CreateOffer (not ready) | PeerConnectionImpl.cpp:1227  | CreateOffer
[task 2020-06-21T14:20:01.392Z] 14:20:01     INFO - PID 6364 |     0.029000 |    0.000000 | Create Offer                      | PeerConnectionImpl.cpp:1239  | CreateOffer
[task 2020-06-21T14:20:01.393Z] 14:20:01     INFO - PID 6364 |     0.050000 |    0.021000 | Set Local Description             | PeerConnectionImpl.cpp:1308  | SetLocalDescription
[task 2020-06-21T14:20:01.393Z] 14:20:01     INFO - PID 6364 |     0.080000 |    0.030000 | Set Remote Description            | PeerConnectionImpl.cpp:1403  | SetRemoteDescription
[task 2020-06-21T14:20:01.394Z] 14:20:01     INFO - PID 6364 |     0.101000 |    0.021000 | Ice gathering state: gathering    | PeerConnectionImpl.cpp:2525  | IceGatheringStateChange
[task 2020-06-21T14:20:01.395Z] 14:20:01     INFO - PID 6364 |     0.162000 |    0.061000 | Ice gathering state: complete     | PeerConnectionImpl.cpp:2528  | IceGatheringStateChange
[task 2020-06-21T14:20:01.398Z] 14:20:01     INFO - PID 6364 |     0.164000 |    0.002000 | Add Ice Candidate                 | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.398Z] 14:20:01     INFO - PID 6364 |     0.170000 |    0.006000 | Add Ice Candidate                 | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.400Z] 14:20:01     INFO - PID 6364 |     0.175000 |    0.005000 | Add Ice Candidate                 | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.400Z] 14:20:01     INFO - PID 6364 |    10.176000 |   10.001000 | Ice state: failed                 | PeerConnectionImpl.cpp:2479  | IceConnectionStateChange
[task 2020-06-21T14:20:01.401Z] 14:20:01     INFO - PID 6364 |   180.472000 |  170.296000 | Destructor Invoked                | PeerConnectionImpl.cpp:341   | ~PeerConnectionImpl
[task 2020-06-21T14:20:01.402Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:362: PeerConnectionCtx is already gone. Ignoring...
[task 2020-06-21T14:20:01.402Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 4850430d2ace40fc
[task 2020-06-21T14:20:01.402Z] 14:20:01     INFO - PID 6364 | Timecard created 1592749020.915000
[task 2020-06-21T14:20:01.403Z] 14:20:01     INFO - PID 6364 |  Timestamp   | Delta       | Event                          | File                         | Function
[task 2020-06-21T14:20:01.403Z] 14:20:01     INFO - PID 6364 | ======================================================================================================================
[task 2020-06-21T14:20:01.404Z] 14:20:01     INFO - PID 6364 |     0.000000 |    0.000000 | Constructor Completed          | PeerConnectionImpl.cpp:332   | PeerConnectionImpl
[task 2020-06-21T14:20:01.404Z] 14:20:01     INFO - PID 6364 |     0.001000 |    0.001000 | Initializing PC Ctx            | PeerConnectionImpl.cpp:458   | Initialize
[task 2020-06-21T14:20:01.404Z] 14:20:01     INFO - PID 6364 |     0.057000 |    0.056000 | Set Remote Description         | PeerConnectionImpl.cpp:1403  | SetRemoteDescription
[task 2020-06-21T14:20:01.405Z] 14:20:01     INFO - PID 6364 |     0.068000 |    0.011000 | Create Answer                  | PeerConnectionImpl.cpp:1270  | CreateAnswer
[task 2020-06-21T14:20:01.405Z] 14:20:01     INFO - PID 6364 |     0.069000 |    0.001000 | Set Local Description          | PeerConnectionImpl.cpp:1308  | SetLocalDescription
[task 2020-06-21T14:20:01.405Z] 14:20:01     INFO - PID 6364 |     0.103000 |    0.034000 | Ice gathering state: gathering | PeerConnectionImpl.cpp:2525  | IceGatheringStateChange
[task 2020-06-21T14:20:01.406Z] 14:20:01     INFO - PID 6364 |     0.144000 |    0.041000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.406Z] 14:20:01     INFO - PID 6364 |     0.148000 |    0.004000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.406Z] 14:20:01     INFO - PID 6364 |     0.153000 |    0.005000 | Add Ice Candidate              | PeerConnectionImpl.cpp:1548  | AddIceCandidate
[task 2020-06-21T14:20:01.406Z] 14:20:01     INFO - PID 6364 |     0.168000 |    0.015000 | Ice gathering state: complete  | PeerConnectionImpl.cpp:2528  | IceGatheringStateChange
[task 2020-06-21T14:20:01.406Z] 14:20:01     INFO - PID 6364 |    10.214000 |   10.046000 | Ice state: failed              | PeerConnectionImpl.cpp:2479  | IceConnectionStateChange
[task 2020-06-21T14:20:01.407Z] 14:20:01     INFO - PID 6364 |   180.472000 |  170.258000 | Destructor Invoked             | PeerConnectionImpl.cpp:341   | ~PeerConnectionImpl
[task 2020-06-21T14:20:01.407Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:362: PeerConnectionCtx is already gone. Ignoring...
[task 2020-06-21T14:20:01.407Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:366: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for ad0fa19a1d482c95
[task 2020-06-21T14:20:01.462Z] 14:20:01     INFO - PID 6364 | [Child 6172: Main Thread]: D/DataChannel 08F42EE0: Close()ing 06E993A0
[task 2020-06-21T14:20:01.481Z] 14:20:01     INFO - PID 6364 | [2020-06-21T14:20:01Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-06-21T14:20:01.481Z] 14:20:01     INFO - PID 6364 | [2020-06-21T14:20:01Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2020-06-21T14:20:01.496Z] 14:20:01     INFO - PID 6364 | [Child 6496, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.516Z] 14:20:01     INFO - PID 6364 | [Child 6172, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.519Z] 14:20:01     INFO - PID 6364 | [Child 8140, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.559Z] 14:20:01     INFO - PID 2300 | [Child 7360, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.754Z] 14:20:01     INFO - PID 6364 | [Child 2408, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:01.909Z] 14:20:01     INFO - PID 6364 | [Child 7536, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:02.032Z] 14:20:02     INFO - PID 6364 | [Parent 6792, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/checkouts/gecko/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1279
[task 2020-06-21T14:20:02.087Z] 14:20:02     INFO - PID 6364 | [Parent 6792, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 227
[task 2020-06-21T14:20:02.088Z] 14:20:02     INFO - PID 6364 | [Parent 6792, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp, line 254
[task 2020-06-21T14:20:02.163Z] 14:20:02     INFO - PID 2300 | [Parent 5340, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-06-21T14:20:02.278Z] 14:20:02     INFO - Browser exited with return code 0
[task 2020-06-21T14:20:02.278Z] 14:20:02     INFO - PROCESS LEAKS c:\users\task_1592747412\appdata\local\temp\tmpckqwie\runtests_leaks_2804.log
[task 2020-06-21T14:20:02.278Z] 14:20:02     INFO - leakcheck | Processing log file c:\users\task_1592747412\appdata\local\temp\tmpckqwie\runtests_leaks_2804.log for scope /css/css-cascade
[task 2020-06-21T14:20:02.278Z] 14:20:02     INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.279Z] 14:20:02     INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 10000 bytes
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO - leakcheck | Processing leak log file c:\users\task_1592747412\appdata\local\temp\tmpckqwie\runtests_leaks_2804.log
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO - 
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 5340
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO - 
[task 2020-06-21T14:20:02.280Z] 14:20:02     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-21T14:20:02.281Z] 14:20:02     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-06-21T14:20:02.281Z] 14:20:02     INFO -    0 |TOTAL                                 |       23        0| 6381292        0|
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - 
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - nsTraceRefcnt::DumpStatistics: 2044 entries
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - TEST-PASS | leakcheck | default no leaks detected!
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - leakcheck | Processing leak log file c:\users\task_1592747412\appdata\local\temp\tmpckqwie\runtests_leaks_2804_tab_pid4480.log
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - 
[task 2020-06-21T14:20:02.288Z] 14:20:02     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 4480
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.