Bug 1071482 - Add more logging to help debug rare intermittent failures. r=edwin
authorChris Pearce <cpearce@mozilla.com>
Thu, 30 Oct 2014 15:05:49 +1300
changeset 213055 e72c87749c0f0bf5b005844e0bc23641d02c9e1b
parent 213054 8839a3db64216f6ee1853649ee47d1c53a4d4a77
child 213056 0fd81599968665168cf6cfaa000300ed39097b4d
push id27738
push usercbook@mozilla.com
push dateThu, 30 Oct 2014 13:46:07 +0000
treeherdermozilla-central@1aa1b23d799e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersedwin
bugs1071482
milestone36.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1071482 - Add more logging to help debug rare intermittent failures. r=edwin
dom/media/test/eme.js
dom/media/test/test_eme_canvas_blocked.html
dom/media/test/test_eme_playback.html
--- a/dom/media/test/eme.js
+++ b/dom/media/test/eme.js
@@ -45,54 +45,54 @@ function HexToBase64(hex)
 {
   var bin = "";
   for (var i = 0; i < hex.length; i += 2) {
     bin += String.fromCharCode(parseInt(hex.substr(i, 2), 16));
   }
   return window.btoa(bin).replace(/=/g, "").replace(/\+/g, "-").replace(/\//g, "_");
 }
 
-function UpdateSessionFunc(test) {
+function UpdateSessionFunc(test, token) {
   return function(ev) {
     var msgStr = ArrayBufferToString(ev.message);
     var msg = JSON.parse(msgStr);
 
-    info("got message from CDM: " + msgStr);
-    is(msg.type, test.sessionType, "Key session type should match");
-    ok(msg.kids, "message event should contain key ID array");
+    info(token + " got message from CDM: " + msgStr);
+    is(msg.type, test.sessionType, token + " key session type should match");
+    ok(msg.kids, token + " message event should contain key ID array");
 
     var outKeys = [];
 
     for (var i = 0; i < msg.kids.length; i++) {
       var id64 = msg.kids[i];
       var idHex = Base64ToHex(msg.kids[i]).toLowerCase();
       var key = test.keys[idHex];
 
       if (key) {
-        info("found key " + key + " for key id " + idHex);
+        info(token + " found key " + key + " for key id " + idHex);
         outKeys.push({
           "kty":"oct",
           "alg":"A128KW",
           "kid":id64,
           "k":HexToBase64(key)
         });
       } else {
-        bail("Couldn't find key for key id " + idHex);
+        bail(token + " Couldn't find key for key id " + idHex);
       }
     }
 
     var update = JSON.stringify({
       "keys" : outKeys,
       "type" : msg.type
     });
-    info("sending update message to CDM: " + update);
+    info(token + " sending update message to CDM: " + update);
 
     ev.target.update(StringToArrayBuffer(update)).then(function() {
-      info("MediaKeySession update ok!");
-    }, bail("MediaKeySession update failed"));
+      info(token + " MediaKeySession update ok!");
+    }, bail(token + " MediaKeySession update failed"));
   }
 }
 
 function PlayFragmented(test, elem)
 {
   return new Promise(function(resolve, reject) {
     var ms = new MediaSource();
     elem.src = URL.createObjectURL(ms);
@@ -109,19 +109,23 @@ function PlayFragmented(test, elem)
 
       var fragmentFile = test.fragments[curFragment++];
 
       var req = new XMLHttpRequest();
       req.open("GET", fragmentFile);
       req.responseType = "arraybuffer";
 
       req.addEventListener("load", function() {
+        info("fetch of " + fragmentFile + " complete");
         sb.appendBuffer(new Uint8Array(req.response));
       });
 
+      req.addEventListener("error", bail("Error fetching " + fragmentFile));
+      req.addEventListener("abort", bail("Aborted fetching " + fragmentFile));
+
       info("fetching resource " + fragmentFile);
       req.send(null);
     }
 
     ms.addEventListener("sourceopen", function () {
       sb = ms.addSourceBuffer(test.type);
       sb.addEventListener("updateend", addNextFragment);
 
@@ -145,34 +149,42 @@ function LoadTest(test, elem)
     resolve();
   });
 }
 
 function SetupEME(test, token, params)
 {
   var v = document.createElement("video");
 
+  // Log events dispatched to make debugging easier...
+  ["loadstart", "loadedmetadata", "loadeddata", "ended",
+    "play", "canplay", "playing", "canplaythrough"].forEach(function (e) {
+    v.addEventListener(e, function(event) {
+      info(token + " " + e);
+    }, false);
+  });
+
   var onSetKeysFail = (params && params.onSetKeysFail)
     ? params.onSetKeysFail
     : bail(token + " Failed to set MediaKeys on <video> element");
-  
+
   v.addEventListener("encrypted", function(ev) {
     info(token + " got encrypted event");
     MediaKeys.create(KEYSYSTEM_TYPE).then(function(mediaKeys) {
       info(token + " created MediaKeys object ok");
       mediaKeys.sessions = [];
       return v.setMediaKeys(mediaKeys);
     }, bail("failed to create MediaKeys object")).then(function() {
       info(token + " set MediaKeys on <video> element ok");
 
       var session = v.mediaKeys.createSession(test.sessionType);
       if (params && params.onsessioncreated) {
         params.onsessioncreated(session);
       }
-      session.addEventListener("message", UpdateSessionFunc(test));
+      session.addEventListener("message", UpdateSessionFunc(test, token));
       session.generateRequest(ev.initDataType, ev.initData).then(function() {
       }, bail(token + " Failed to initialise MediaKeySession"));
 
     }, onSetKeysFail);
   });
 
   return v;
 }
--- a/dom/media/test/test_eme_canvas_blocked.html
+++ b/dom/media/test/test_eme_canvas_blocked.html
@@ -16,17 +16,17 @@ function startTest(test, token)
 {
   manager.started(token);
 
   var sessions = [];
 
   var v = SetupEME(test, token);
   v.preload = "auto"; // Required due to "canplay" not firing for MSE unless we do this.
 
-  v.addEventListener("canplay", function(ev) {
+  v.addEventListener("loadeddata", function(ev) {
     var video = ev.target;
     var canvas = document.createElement("canvas");
     canvas.width = video.videoWidth;
     canvas.height = video.videoHeight;
     document.body.appendChild(canvas);
     var ctx = canvas.getContext("2d");
     var threwError = false;
     try {
--- a/dom/media/test/test_eme_playback.html
+++ b/dom/media/test/test_eme_playback.html
@@ -55,37 +55,37 @@ function startTest(test, token)
        token + " MediaKeys should support this keysystem");
     gotEncrypted = true;
   });
 
   v.addEventListener("playing", function () { gotPlaying = true; });
 
   v.addEventListener("ended", function(ev) {
     ok(true, token + " got ended event");
-    manager.finished(token);
 
     ok(gotEncrypted, token + " encrypted event should have fired");
     ok(gotPlaying, token + " playing event should have fired");
 
     ok(Math.abs(test.duration - v.duration) < 0.1,
        token + " Duration of video should be corrrect");
     ok(Math.abs(test.duration - v.currentTime) < 0.1,
        token + " Current time should be same as duration");
 
     // Verify all sessions had all keys went sent the to the CDM usable, and thus
     // that we received keyschange event(s).
-    is(sessions.length, 1, "should have 1 session");
+    is(sessions.length, 1, token + " should have 1 session");
     for (var i = 0; i < sessions.length; i++) {
       var session = sessions[i];
       ok(session.gotKeysChanged, token + " should have received at least one keychange event");
       for (var kid in session.keyIdsReceived) {
         ok(session.keyIdsReceived[kid], token + " key with id " + kid + " was usable as expected");
       }
     }
 
+    manager.finished(token);
    });
 
   v.addEventListener("error", bail(token + " got error event"));
 
   LoadTest(test, v).then(function(){v.play();}, bail(token + " failed to load"));
 }
 
 function testIsTypeSupported()