Closed Bug 1020707 Opened 11 years ago Closed 9 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: 9 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.