Can't get video capture working

[callumacrae]

I'm using a private instance of WPT running in an Ubuntu VM and a Nexus 5, and I'm trying to get video capture to work so that I can get speed index working.

It's enabled; this is the command I'm using to start the agent:

Code:

./wptdriver.sh --browser android:0cfe40ea1408275a --serverUrl http://localhost:80/ --location Nexus5 --processvideo yes

However, I'm getting this error in the output:

Code:

I Sep_07_12:27:11.202 wd_server.js:1300 WebDriverServer.<anonymous> : Video processing error: python lib/video/visualmetrics.py -i runtmp/0cfe40ea1408275a/video.mp4 -d runtmp/0cfe40ea1408275a/video --orange --viewport --force --quality 75 --histogram runtmp/0cfe40ea1408275a/histograms.json --timeline runtmp/0cfe40ea1408275a/trace.json failed, code 1, stderr[210] CRITICAL:root:Error extracting the video frames from /home/vagrant/wpt/agent/js/runtmp/0cfe40ea1408275a/video.mp4

What could be causing this and how can I fix it?

Thanks!

[pmeenan]

tyr running "python lib/video/visualmetrics.py --check" and see if all of the dependencies check out ok. It's also possible that the video file itself didn't get captured but more likely that ffmpeg, imagemagick or pillow aren't installed and in the path correctly.

[callumacrae]

Pillow failed to install the first time and I didn't notice, have fixed that now and the error has changed.

Code:

vagrant@precise32:~/wpt/agent/js$ python lib/video/visualmetrics.py --check
ffmpeg:   FAIL
convert:  OK
compare:  OK
Pillow:   OK
SSIM:     FAIL
vagrant@precise32:~/wpt/agent/js$ ffmpeg -version
ffmpeg version 0.8.17-4:0.8.17-0ubuntu0.12.04.1, Copyright (c) 2000-2014 the Libav developers
  built on Mar 16 2015 13:28:23 with gcc 4.6.3

Are all of them essential? I'm struggling to install pyssim (which is what I'm assuming is requested).

And the new error: (more if you scroll)

Code:

I Sep_10_15:11:03.182 wd_server.js:1300 WebDriverServer.<anonymous> : Video processing error: python lib/video/visualmetrics.py -i runtmp/0cfe40ea1408275a/video.mp4 -d runtmp/0cfe40ea1408275a/video --orange --viewport --force --quality 75 --histogram runtmp/0cfe40ea1408275a/histograms.json --timeline runtmp/0cfe40ea1408275a/trace.json failed, code 1, stderr[1332] ffmpeg version 0.8.17-4:0.8.17-0ubuntu0.12.04.1, Copyright (c) 2000-2014 the Libav developers
  built on Mar 16 2015 13:28:23 with gcc 4.6.3
The ffmpeg program is only provided for script compatibility and will be removed
in a future release. It has been deprecated in the Libav project to allow for
incompatible command line syntax improvements in its replacement called avconv
(see Changelog for details). Please use avconv instead.

Seems stream 0 codec frame rate differs from container frame rate: 180000.00 (180000/1) -> 90000.00 (180000/2)
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from '/home/vagrant/wpt/agent/js/runtmp/0cfe40ea1408275a/video.mp4':
  Metadata:
    major_brand     : mp42
    minor_version   : 0
    compatible_brands: isommp42
    creation_time   : 2015-09-10 15:10:57
  Duration: 00:00:25.28, start: 0.000000, bitrate: 250 kb/s
    Stream #0.0(eng): Video: h264 (Baseline), yuv420p, 1080x1920, 249 kb/s, PAR 65536:65536 DAR 9:16, 4.83 fps, 90k tbr, 90k tbn, 180k tbc
    Metadata:
      creation_time ...

[pmeenan]

Ignore pyssim but ffmpeg is critical to video processing. ffmpeg and ubuntu have a weird relationship because they used to alias it to avconv. I usually grab the static build from here: http://johnvansickle.com/ffmpeg/

Then you need to extract it and put ffmpeg in /usr/local/bin

[callumacrae]

I've done that now.

There's no error anymore, but I still have no video:

Code:

$ ./wptdriver.sh --browser android:0cfe40ea1408275a --serverUrl http://localhost:80/ --location Nexus5 --processvideo yes
node --expose-gc src/agent_main --serverUrl http://localhost:80/ --location Nexus5 --browser browser_android_chrome.BrowserAndroidChrome --deviceSerial 0cfe40ea1408275a --chromedriver /home/vagrant/wpt/agent/js/lib/webdriver/chromedriver/Linux i686/chromedriver-* --captureDir /home/vagrant/wpt/agent/js/lib/capture --processvideo yes
I Sep_10_16:45:12.632 browser_android_chrome.js:108 new BrowserAndroidChrome : BrowserAndroidChrome({"flags":{"serverUrl":"http://localhost:80/","location":"Nexus5","browser":"browser_android_chrome.BrowserAndroidChrome","deviceSerial":"0cfe40ea1408275a","chromedriver":"/home/vagrant/wpt/agent/js/lib/webdriver/chromedriver/Linux i686/chromedriver-*","captureDir":"/home/vagrant/wpt/agent/js/lib/capture","processvideo":"yes"},"task":{}})
I Sep_10_16:45:12.888 wpt_client.js:490 Client.<anonymous> : Get work: http://localhost:80/work/getwork.php?location=Nexus5&pc=0cfe40ea1408275a&f=json
.I Sep_10_16:45:25.156 wpt_client.js:558 Client.processJobResponse_ : Got job: {"Test ID":"150910_85_A","url":"https:\/\/www.lostmy.name\/","runs":1,"browser":"Nexus5 - Chrome","orientation":"default"}
I Sep_10_16:45:25.169 agent_main.js:394 Agent.<anonymous> : Starting run 1a/1 of job 150910_85_A
I Sep_10_16:45:25.491 browser_android_chrome.js:108 new BrowserAndroidChrome : BrowserAndroidChrome({"cmd":"run","runNumber":1,"isCacheWarm":false,"exitWhenDone":false,"timeout":120000,"runTempDir":"runtmp/0cfe40ea1408275a","workDir":"work/0cfe40ea1408275a","flags":{"captureDir":"/home/vagrant/wpt/agent/js/lib/capture","serverUrl":"http://localhost:80/","browser":"browser_android_chrome.BrowserAndroidChrome","processvideo":"yes","chromedriver":"/home/vagrant/wpt/agent/js/lib/webdriver/chromedriver/Linux i686/chromedriver-*","location":"Nexus5","deviceSerial":"0cfe40ea1408275a"},"task":{"Test ID":"150910_85_A","url":"https://www.lostmy.name/","runs":1,"browser":"Nexus5 - Chrome","orientation":"default","hostsFile":"127.0.0.1 localhost\n"}})
.I Sep_10_16:45:32.912 wd_server.js:385 WebDriverServer.<anonymous> : Test started
I Sep_10_16:45:50.207 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Page.loadEventFired","params":{"timestamp":21154.869625}}
I Sep_10_16:45:50.209 wd_server.js:1107 WebDriverServer.<anonymous> : Test finished, waiting for browser to coalesce
W Sep_10_16:45:52.526 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.123","timestamp":21157.29397,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:45:52.906 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.126","timestamp":21157.66908,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:45:53.032 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.130","timestamp":21157.79106,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:45:53.079 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.131","timestamp":21157.850873,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:45:53.094 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.132","timestamp":21157.862135,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:45:53.303 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"8387.133","timestamp":21158.064657,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
I Sep_10_16:46:00.248 wd_server.js:1323 WebDriverServer.<anonymous> : Test passed
A Sep_10_16:46:09.470 wpt_client.js:659 Client.finishRun_ : Finished run 1a/1 of job 150910_85_A
I Sep_10_16:46:10.145 agent_main.js:394 Agent.<anonymous> : Starting run 1b/1 of job 150910_85_A
I Sep_10_16:46:10.242 browser_android_chrome.js:108 new BrowserAndroidChrome : BrowserAndroidChrome({"cmd":"run","runNumber":1,"isCacheWarm":true,"exitWhenDone":true,"timeout":120000,"runTempDir":"runtmp/0cfe40ea1408275a","workDir":"work/0cfe40ea1408275a","flags":{"captureDir":"/home/vagrant/wpt/agent/js/lib/capture","serverUrl":"http://localhost:80/","browser":"browser_android_chrome.BrowserAndroidChrome","processvideo":"yes","chromedriver":"/home/vagrant/wpt/agent/js/lib/webdriver/chromedriver/Linux i686/chromedriver-*","location":"Nexus5","deviceSerial":"0cfe40ea1408275a"},"task":{"Test ID":"150910_85_A","url":"https://www.lostmy.name/","runs":1,"browser":"Nexus5 - Chrome","orientation":"default","hostsFile":"127.0.0.1 localhost\n"}})
.
I Sep_10_16:46:16.625 wd_server.js:385 WebDriverServer.<anonymous> : Test started
I Sep_10_16:46:22.173 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Page.loadEventFired","params":{"timestamp":21186.907739}}
I Sep_10_16:46:22.175 wd_server.js:1107 WebDriverServer.<anonymous> : Test finished, waiting for browser to coalesce
W Sep_10_16:46:24.020 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.104","timestamp":21188.772622,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:46:24.368 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.107","timestamp":21189.112883,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:46:24.412 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.111","timestamp":21189.133064,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:46:24.467 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.112","timestamp":21189.222102,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:46:24.717 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.113","timestamp":21189.472081,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
W Sep_10_16:46:24.732 wd_server.js:341 WebDriverServer.onDevToolsMessage_ : DevTools message: {"method":"Network.loadingFailed","params":{"requestId":"9083.114","timestamp":21189.479027,"type":"XHR","errorText":"net::ERR_UNKNOWN_URL_SCHEME"}}
I Sep_10_16:46:32.214 wd_server.js:1323 WebDriverServer.<anonymous> : Test passed
I Sep_10_16:46:45.075 agent_main.js:149 Agent.<anonymous> : wd_server child process exit code null signal SIGKILL
A Sep_10_16:46:45.217 wpt_client.js:659 Client.finishRun_ : Finished run 1b/1 of finished job 150910_85_A
I Sep_10_16:46:45.796 wpt_client.js:490 Client.<anonymous> : Get work: http://localhost:80/work/getwork.php?location=Nexus5&pc=0cfe40ea1408275a&f=json

Also, I'm not getting screenshots.

Quote:ffmpeg: OK
convert: OK
compare: OK
Pillow: OK
SSIM: FAIL

[pmeenan]

Can you run wptdriver.sh with the "-m debug" flag? That will spew tons more information about what it is doing at every step. It could be an issue on the server side as well if the post requests are failing with the screen shots/video frames (might need to check the web server error log).

[callumacrae]

There are a few errors in here. Not sure which of them are significant, though: https://gist.github.com/callumacrae/a9ee...28ab65b902

I'm guessing all the timeouts aren't a great thing!

[pmeenan]

The debug log looks like everything worked fine on the agent side though the requested tests don't look like video capture was requested. Was the capture video checkbox checked for that test?

I see the screen shots got captured and attached to the result so you should have had screen shots and if not then it's a problem on the server side (does http://<wpt_server>/install/ look clean?)

[callumacrae]

Yep, the box was checked. Nothing that isn't optional is missing.

My latest test had a speed index! It was 77993, where running it on webpagetest.org is about 7000. Also, it had a load time of 0.000s—looks like something has gone wrong again.

video/create.php doesn't ever return a video (at least, not within a couple minutes). Filmstrip view worked, though. It also had a thumbnail.

EDIT: The reason the speed index was so high is that the internet went down while I was testing. Forgot about that.

EDIT 2: Everything seems to be working now. This is odd, because I haven't changed anything… Weird. Thanks for your help!