Closed Bug 1020707 Opened 10 years ago Closed 8 years ago

Intermittent test_playback_rate.html | Test timed out or application timed out after 330 seconds with no output

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Version:
29 Branch
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: RyanVM, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure) 

https://tbpl.mozilla.org/php/getParsedLog.php?id=41072207&tree=Try

Android 4.0 Panda try opt test mochitest-3 on 2014-06-04 17:02:27 PDT for push f9ae9b880cb0
slave: panda-0700

17:21:45     INFO -  1180 INFO TEST-START | /tests/content/media/test/test_playback_rate.html
17:26:47     INFO -  1181 INFO TEST-INFO | dumping last 47 message(s)
17:26:47     INFO -  1182 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
17:26:47     INFO -  1183 INFO TEST-INFO | /tests/content/media/test/test_playback_rate.html | Started Wed Jun 04 2014 17:21:14 GMT+0000 (GMT) (1401902474.711s)
17:26:47     INFO -  1184 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started big.wav-0] Length of array should match number of running tests
17:26:47     INFO -  1185 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:26:47     INFO -  1186 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started seek.ogv-1] Length of array should match number of running tests
17:26:47     INFO -  1187 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:26:47     INFO -  1188 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:26:47     INFO -  1189 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:26:47     INFO -  1190 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:26:47     INFO -  1191 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:26:47     INFO -  1192 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:26:47     INFO -  1193 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:26:47     INFO -  1194 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:26:47     INFO -  1195 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.seek.ogv-1
17:26:47     INFO -  1196 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (8.275, 2.009963) for seek.ogv-1
17:26:47     INFO -  1197 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (2.009963 2.009963).
17:26:47     INFO -  1198 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The element should not be in paused state.
17:26:47     INFO -  1199 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Paused event should not have been received.
17:26:47     INFO -  1200 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Playback rate should be clamped to 5.
17:26:47     INFO -  1201 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate should still be 5.
17:26:47     INFO -  1202 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The audio should be muted when playing at high speed, but should not appear as such.
17:26:47     INFO -  1203 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should be equal to the duration (not change by playback rate).
17:26:47     INFO -  1204 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished seek.ogv-1] Length of array should match number of running tests
17:26:47     INFO -  1205 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started seek.webm-2] Length of array should match number of running tests
17:26:47     INFO -  1206 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:26:47     INFO -  1207 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:26:47     INFO -  1208 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:26:47     INFO -  1209 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:26:47     INFO -  1210 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:26:47     INFO -  1211 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.big.wav-0
17:26:47     INFO -  1212 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (18.748, 4.649728) for big.wav-0
17:26:47     INFO -  1213 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (4.649728 4.649728).
17:26:47     INFO -  1214 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The element should not be in paused state.
17:26:47     INFO -  1215 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Paused event should not have been received.
17:26:47     INFO -  1216 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Playback rate should be clamped to 5.
17:26:47     INFO -  1217 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate should still be 5.
17:26:47     INFO -  1218 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The audio should be muted when playing at high speed, but should not appear as such.
17:26:47     INFO -  1219 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should be equal to the duration (not change by playback rate).
17:26:47     INFO -  1220 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished big.wav-0] Length of array should match number of running tests
17:26:47     INFO -  1221 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started bug495794.ogg-6] Length of array should match number of running tests
17:26:47     INFO -  1222 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:26:47     INFO -  1223 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:26:47     INFO -  1224 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:26:47     INFO -  1225 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:26:47     INFO -  1226 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:26:47     INFO -  1227 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.bug495794.ogg-6
17:26:47     INFO -  1228 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (1.085, 0.300104) for bug495794.ogg-6
17:26:47     INFO -  1229 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished bug495794.ogg-6] Length of array should match number of running tests
17:26:47     INFO -  1230 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | Test timed out.
17:26:47     INFO -  1231 INFO TEST-INFO | MEMORY STAT vsize after test: 838684672
17:26:47     INFO -  1232 INFO TEST-INFO | MEMORY STAT residentFast after test: 202985472
17:26:47     INFO -  1233 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 35682952
17:26:47     INFO -  1234 INFO TEST-END | /tests/content/media/test/test_playback_rate.html | finished in 307135ms

Logcat dump:
17:31:12     INFO -  06-04 17:21:14.593 I/GeckoDump( 2233): 1180 INFO TEST-START | /tests/content/media/test/test_playback_rate.html
17:31:12     INFO -  06-04 17:21:14.703 E/GeckoConsole( 2233): [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/content/media/test/test_playback_rate.html" line: 0}]
17:31:12     INFO -  06-04 17:21:16.187 V/tiny_hw ( 1294): out_write(0x111d160) opening PCM
17:31:12     INFO -  06-04 17:21:24.875 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:21:26.562 E/GeckoConsole( 2233): [JavaScript Warning: "Invalid URI. Load of media resource  failed." {file: "http://mochi.test:8888/tests/content/media/test/test_playback_rate.html" line: 0}]
17:31:12     INFO -  06-04 17:21:36.562 E/GeckoConsole( 2233): [JavaScript Warning: "Invalid URI. Load of media resource  failed." {file: "http://mochi.test:8888/tests/content/media/test/test_playback_rate.html" line: 0}]
17:31:12     INFO -  06-04 17:21:38.320 E/GeckoConsole( 2233): [JavaScript Warning: "Invalid URI. Load of media resource  failed." {file: "http://mochi.test:8888/tests/content/media/test/test_playback_rate.html" line: 0}]
17:31:12     INFO -  06-04 17:21:41.273 V/tiny_hw ( 1294): out_standby(0x111d160) closing PCM
17:31:12     INFO -  06-04 17:21:44.898 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:21:44.945 I/SUTAgentAndroid( 1891): 10.12.135.17 : isdir /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:21:44.968 I/SUTAgentAndroid( 1891): 10.12.135.17 : cd /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:21:45.023 I/SUTAgentAndroid( 1891): 10.12.135.17 : ls
17:31:12     INFO -  06-04 17:21:45.054 I/SUTAgentAndroid( 1891): 10.12.135.17 : pull /mnt/sdcard/tests/logs/mochitest.log 87086
17:31:12     INFO -  06-04 17:22:05.085 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:22:11.570 I/IdleService( 2233): Get idle time: time since reset 56712 msec
17:31:12     INFO -  06-04 17:22:11.570 I/IdleService( 2233): Idle timer callback: current idle time 56712 msec
17:31:12     INFO -  06-04 17:22:11.570 I/IdleService( 2233): next timeout 123287 msec from now
17:31:12     INFO -  06-04 17:22:11.570 I/IdleService( 2233): SetTimerExpiryIfBefore: next timeout 123287 msec from now
17:31:12     INFO -  06-04 17:22:11.570 I/IdleService( 2233): reset timer expiry to 123297 msec from now
17:31:12     INFO -  06-04 17:22:25.101 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:22:45.125 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:22:45.171 I/SUTAgentAndroid( 1891): 10.12.135.17 : isdir /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:22:45.187 I/SUTAgentAndroid( 1891): 10.12.135.17 : cd /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:22:45.250 I/SUTAgentAndroid( 1891): 10.12.135.17 : ls
17:31:12     INFO -  06-04 17:22:45.289 I/SUTAgentAndroid( 1891): 10.12.135.17 : pull /mnt/sdcard/tests/logs/mochitest.log 88554
17:31:12     INFO -  06-04 17:23:05.351 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): problem reading network stats
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): java.lang.IllegalStateException: problem parsing idx 1
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:300)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.server.NetworkManagementService.getNetworkStatsUidDetail(NetworkManagementService.java:1282)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.server.net.NetworkStatsService.performPollLocked(NetworkStatsService.java:831)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.server.net.NetworkStatsService.performPoll(NetworkStatsService.java:799)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.server.net.NetworkStatsService.access$100(NetworkStatsService.java:128)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.server.net.NetworkStatsService$3.onReceive(NetworkStatsService.java:633)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:728)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at android.os.Handler.handleCallback(Handler.java:605)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at android.os.Handler.dispatchMessage(Handler.java:92)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at android.os.Looper.loop(Looper.java:137)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at android.os.HandlerThread.run(HandlerThread.java:60)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): Caused by: java.io.FileNotFoundException: /proc/net/xt_qtaguid/stats: open failed: ENOENT (No such file or directory)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at libcore.io.IoBridge.open(IoBridge.java:406)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at java.io.FileInputStream.<init>(FileInputStream.java:78)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at com.android.internal.net.NetworkStatsFactory.readNetworkStatsDetail(NetworkStatsFactory.java:269)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	... 10 more
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): Caused by: libcore.io.ErrnoException: open failed: ENOENT (No such file or directory)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at libcore.io.Posix.open(Native Method)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	at libcore.io.IoBridge.open(IoBridge.java:390)
17:31:12     INFO -  06-04 17:23:11.000 F/NetworkStats( 1401): 	... 12 more
17:31:12     INFO -  06-04 17:23:25.375 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:23:45.398 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:23:45.437 I/SUTAgentAndroid( 1891): 10.12.135.17 : isdir /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:23:45.476 I/SUTAgentAndroid( 1891): 10.12.135.17 : cd /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:23:45.507 I/SUTAgentAndroid( 1891): 10.12.135.17 : ls
17:31:12     INFO -  06-04 17:23:45.546 I/SUTAgentAndroid( 1891): 10.12.135.17 : pull /mnt/sdcard/tests/logs/mochitest.log 88554
17:31:12     INFO -  06-04 17:24:05.617 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): Get idle time: time since reset 180011 msec
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): Idle timer callback: current idle time 180011 msec
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): next timeout 4294967114988 msec from now
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): SetTimerExpiryIfBefore: next timeout 4294967114988 msec from now
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): reset timer expiry to 4294967114998 msec from now
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): Idle timer callback: tell observer 0x6bb8f5c0 user is idle
17:31:12     INFO -  06-04 17:24:14.867 I/IdleService( 2233): Notifying idle-daily observers
17:31:12     INFO -  06-04 17:24:14.875 I/IdleService( 2233): Remove observer 0x6bb8f5c0 (180 seconds), 0 remain idle
17:31:12     INFO -  06-04 17:24:14.898 I/IdleService( 2233): Storing last idle time as 1401902654
17:31:12     INFO -  06-04 17:24:14.929 I/IdleService( 2233): Register idle observer 0x69bbcf40 for 300 seconds
17:31:12     INFO -  06-04 17:24:14.929 I/IdleService( 2233): Register: adjusting next switch from -1 to 300 seconds
17:31:12     INFO -  06-04 17:24:14.929 I/IdleService( 2233): next timeout 119924 msec from now
17:31:12     INFO -  06-04 17:24:14.929 I/IdleService( 2233): SetTimerExpiryIfBefore: next timeout 119924 msec from now
17:31:12     INFO -  06-04 17:24:14.929 I/IdleService( 2233): reset timer expiry to 119934 msec from now
17:31:12     INFO -  06-04 17:24:25.632 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:24:45.664 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:24:45.695 I/SUTAgentAndroid( 1891): 10.12.135.17 : isdir /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:24:45.734 I/SUTAgentAndroid( 1891): 10.12.135.17 : cd /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:24:45.781 I/SUTAgentAndroid( 1891): 10.12.135.17 : ls
17:31:12     INFO -  06-04 17:24:45.812 I/SUTAgentAndroid( 1891): 10.12.135.17 : pull /mnt/sdcard/tests/logs/mochitest.log 88554
17:31:12     INFO -  06-04 17:25:05.882 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:25:25.906 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:25:45.929 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:25:45.968 I/SUTAgentAndroid( 1891): 10.12.135.17 : isdir /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:25:46.007 I/SUTAgentAndroid( 1891): 10.12.135.17 : cd /mnt/sdcard/tests/logs
17:31:12     INFO -  06-04 17:25:46.046 I/SUTAgentAndroid( 1891): 10.12.135.17 : ls
17:31:12     INFO -  06-04 17:25:46.085 I/SUTAgentAndroid( 1891): 10.12.135.17 : pull /mnt/sdcard/tests/logs/mochitest.log 88554
17:31:12     INFO -  06-04 17:26:06.148 I/SUTAgentAndroid( 1891): 10.12.135.17 : activity
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): Get idle time: time since reset 300015 msec
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): Idle timer callback: current idle time 300015 msec
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): next timeout 4294966994984 msec from now
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): SetTimerExpiryIfBefore: next timeout 4294966994984 msec from now
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): reset timer expiry to 4294966994994 msec from now
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): Idle timer callback: tell observer 0x69bbcf40 user is idle
17:31:12     INFO -  06-04 17:26:14.875 I/IdleService( 2233): Remove observer 0x69bbcf40 (300 seconds), 0 remain idle
17:31:12     INFO -  06-04 17:26:20.492 I/GeckoDump( 2233): 1181 INFO TEST-INFO | dumping last 47 message(s)
17:31:12     INFO -  06-04 17:26:20.507 I/GeckoDump( 2233): 1182 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
17:31:12     INFO -  06-04 17:26:20.507 I/GeckoDump( 2233): 1183 INFO TEST-INFO | /tests/content/media/test/test_playback_rate.html | Started Wed Jun 04 2014 17:21:14 GMT+0000 (GMT) (1401902474.711s)
17:31:12     INFO -  06-04 17:26:20.507 I/GeckoDump( 2233): 1184 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started big.wav-0] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1185 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1186 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started seek.ogv-1] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1187 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1188 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1189 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.515 I/GeckoDump( 2233): 1190 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:31:12     INFO -  06-04 17:26:20.531 I/GeckoDump( 2233): 1191 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.531 I/GeckoDump( 2233): 1192 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.531 I/GeckoDump( 2233): 1193 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:31:12     INFO -  06-04 17:26:20.531 I/GeckoDump( 2233): 1194 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1195 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.seek.ogv-1
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1196 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (8.275, 2.009963) for seek.ogv-1
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1197 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (2.009963 2.009963).
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1198 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The element should not be in paused state.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1199 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Paused event should not have been received.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1200 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Playback rate should be clamped to 5.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1201 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate should still be 5.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1202 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The audio should be muted when playing at high speed, but should not appear as such.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1203 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should be equal to the duration (not change by playback rate).
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1204 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished seek.ogv-1] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1205 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started seek.webm-2] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1206 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1207 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.539 I/GeckoDump( 2233): 1208 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1209 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1210 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1211 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.big.wav-0
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1212 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (18.748, 4.649728) for big.wav-0
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1213 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (4.649728 4.649728).
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1214 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The element should not be in paused state.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1215 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Paused event should not have been received.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1216 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Playback rate should be clamped to 5.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1217 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate should still be 5.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1218 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The audio should be muted when playing at high speed, but should not appear as such.
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1219 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Current time should be equal to the duration (not change by playback rate).
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1220 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished big.wav-0] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1221 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [started bug495794.ogg-6] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.546 I/GeckoDump( 2233): 1222 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | Pitch preservation should be enabled by default.
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1223 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1224 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1225 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1226 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | If we disable the pitch preservation, it should appear as such.
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1227 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | The playback rate shoud be 0.25.bug495794.ogg-6
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1228 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | We are effectively slowing down playback. (1.085, 0.300104) for bug495794.ogg-6
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1229 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | [finished bug495794.ogg-6] Length of array should match number of running tests
17:31:12     INFO -  06-04 17:26:20.554 I/GeckoDump( 2233): 1230 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | Test timed out.
17:31:12     INFO -  06-04 17:26:21.609 I/GeckoDump( 2233): 1231 INFO TEST-INFO | MEMORY STAT vsize after test: 838684672
17:31:12     INFO -  06-04 17:26:21.609 I/GeckoDump( 2233): 1232 INFO TEST-INFO | MEMORY STAT residentFast after test: 202985472
17:31:12     INFO -  06-04 17:26:21.609 I/GeckoDump( 2233): 1233 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 35682952
17:31:12     INFO -  06-04 17:26:21.718 I/GeckoDump( 2233): 1234 INFO TEST-END | /tests/content/media/test/test_playback_rate.html | finished in 307135ms
What the hell, let's star the OSX ones here too.
https://tbpl.mozilla.org/php/getParsedLog.php?id=41086691&tree=Try
OS: Android → All
Hardware: ARM → All
Summary: Intermittent Android test_playback_rate.html | Test timed out. → Intermittent test_playback_rate.html | Test timed out or application timed out after 330 seconds with no output
This is frequent enough on Android that I think we should consider re-disabling it there.
Flags: needinfo?(jwwang)
Yes, please disable it on Android. I found out the xpcom timer sometimes didn't fire on Android and resulted in test case timeout. I am still trying to find the root cause...
Flags: needinfo?(jwwang)
It turns out that we have a problem in the XPCOM timer which could cause timeout in the tests.
Depends on: 1033121
Assignee: nobody → jwwang
Since bug 1033121 is fixed, let wait and see if failure rate decreases.
(In reply to TBPL Robot from comment #114)
> edmorley
> https://tbpl.mozilla.org/php/getParsedLog.php?id=49117636&tree=Mozilla-
> Central
> b2g_emulator_vm mozilla-central opt test mochitest-3 on 2014-09-29 08:05:43
> revision: f57209ddc739
> slave: tst-linux64-spot-922
> 
> DeviceRunner TEST-UNEXPECTED-FAIL |
> /tests/content/media/test/test_playback_rate.html | application timed out
> after 330.0 seconds with no output
> PROCESS-CRASH | /tests/content/media/test/test_playback_rate.html |
> application crashed [@ __libc_android_abort]
> Return code: 247
> Return code: 1

It might be the same cause as bug 945335 comment 7 where buffer callback fired after cubeb stream instance deleted.
Depends on: 945335
(In reply to Robert Strong [:rstrong] (use needinfo to contact me) from comment #117)
> https://tbpl.mozilla.org/php/getParsedLog.php?id=49261719&tree=Mozilla-
> Central

18:35:49     INFO -  assertion "res == SL_RESULT_SUCCESS" failed: file "../../../../gecko/media/libcubeb/src/cubeb_opensl.c", line 128, function "bufferqueue_callback"

The same assertion as comment 114.
Depends on: 1150128
Component: Audio/Video → Audio/Video: MSG/cubeb/GMP
Component: Audio/Video: MediaStreamGraph → Audio/Video: Playback
P5
Priority: -- → P5
WFM for no timeout for a long time.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.