net-internals: When viewing a loaded log, display time

how long it's been since idle sources have logged their
most recent event.

BUG=139830

Review URL: https://chromiumcodereview.appspot.com/10825116

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@149341 0039d316-1c4b-4281-b951-d872f2087c98

4 files changed, 135 insertions, 21 deletions

diff --git a/chrome/browser/resources/net_internals/log_view_painter.js b/chrome/browser/resources/net_internals/log_view_painter.js
index 18cc89a..42b6819 100644
--- a/chrome/browser/resources/net_internals/log_view_painter.js
+++ b/chrome/browser/resources/net_internals/log_view_painter.js
@@ -24,7 +24,8 @@ function canCollapseBeginWithEnd(beginEntry) {
  * Adds a child pre element to the end of |parent|, and writes the
  * formatted contents of |logEntries| to it.
  */
-printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping) {
+printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping,
+                                 logCreationTime) {
   var entries = LogGroupEntry.createArrayFrom(logEntries);
   var tablePrinter = new TablePrinter();
   var parameterOutputter = new ParameterOutputter(tablePrinter);
@@ -32,8 +33,7 @@ printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping) {
   if (entries.length == 0)
     return;
 
-  var startDate = timeutil.convertTimeTicksToDate(entries[0].orig.time);
-  var startTime = startDate.getTime();
+  var startTime = timeutil.convertTimeTicksToTime(entries[0].orig.time);
 
   for (var i = 0; i < entries.length; ++i) {
     var entry = entries[i];
@@ -41,16 +41,8 @@ printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping) {
     // Avoid printing the END for a BEGIN that was immediately before, unless
     // both have extra parameters.
     if (!entry.isEnd() || !canCollapseBeginWithEnd(entry.begin)) {
-      tablePrinter.addRow();
-
-      tablePrinter.addCell('t=');
-      var date = timeutil.convertTimeTicksToDate(entry.orig.time);
-      var tCell = tablePrinter.addCell(date.getTime());
-      tCell.alignRight = true;
-      tablePrinter.addCell(' [st=');
-      var stCell = tablePrinter.addCell(date.getTime() - startTime);
-      stCell.alignRight = true;
-      tablePrinter.addCell('] ');
+      var entryTime = timeutil.convertTimeTicksToTime(entry.orig.time);
+      addRowWithTime(tablePrinter, entryTime, startTime);
 
       for (var j = entry.getDepth(); j > 0; --j)
         tablePrinter.addCell('  ');
@@ -62,6 +54,8 @@ printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping) {
         // Definite time.
         if (entry.end) {
           dt = entry.end.orig.time - entry.orig.time;
+        } else if (logCreationTime != undefined) {
+          dt = (logCreationTime - entryTime) + '+';
         }
         eventText += '  [dt=' + dt + ']';
       }
@@ -80,11 +74,39 @@ printLogEntriesAsText = function(logEntries, parent, enableSecurityStripping) {
     }
   }
 
+  // If viewing a saved log file, add row with just the time the log was
+  // created, if the event never completed.
+  if (logCreationTime != undefined &&
+      entries[entries.length - 1].getDepth() > 0) {
+    addRowWithTime(tablePrinter, logCreationTime, startTime);
+  }
+
   // Format the table for fixed-width text.
   tablePrinter.toText(0, parent);
 }
 
 /**
+ * Adds a new row to the given TablePrinter, and adds five cells containing
+ * information about the time an event occured.
+ * Format is '[t=<UTC time in ms>] [st=<ms since the source started>]'.
+ * @param {TablePrinter} tablePrinter The table printer to add the cells to.
+ * @param {number} eventTime The time the event occured, as a UTC time in
+ *     milliseconds.
+ * @param {number} startTime The time the first event for the source occured,
+ *     as a UTC time in milliseconds.
+ */
+function addRowWithTime(tablePrinter, eventTime, startTime) {
+  tablePrinter.addRow();
+  tablePrinter.addCell('t=');
+  var tCell = tablePrinter.addCell(eventTime);
+  tCell.alignRight = true;
+  tablePrinter.addCell(' [st=');
+  var stCell = tablePrinter.addCell(eventTime - startTime);
+  stCell.alignRight = true;
+  tablePrinter.addCell('] ');
+}
+
+/**
  * |hexString| must be a string of hexadecimal characters with no whitespace,
  * whose length is a multiple of two.  Writes multiple lines to |out| with
  * the hexadecimal characters from |hexString| on the left, in groups of
diff --git a/chrome/browser/resources/net_internals/source_entry.js b/chrome/browser/resources/net_internals/source_entry.js
index 6a05da4..509a4a8 100644
--- a/chrome/browser/resources/net_internals/source_entry.js
+++ b/chrome/browser/resources/net_internals/source_entry.js
@@ -288,7 +288,7 @@ var SourceEntry = (function() {
         return timeutil.getCurrentTime();
       } else {
         var endTicks = this.entries_[this.entries_.length - 1].time;
-        return timeutil.convertTimeTicksToDate(endTicks).getTime();
+        return timeutil.convertTimeTicksToTime(endTicks);
       }
     },
 
@@ -299,7 +299,7 @@ var SourceEntry = (function() {
      */
     getDuration: function() {
       var startTicks = this.entries_[0].time;
-      var startTime = timeutil.convertTimeTicksToDate(startTicks).getTime();
+      var startTime = timeutil.convertTimeTicksToTime(startTicks);
       var endTime = this.getEndTime();
       return endTime - startTime;
     },
@@ -309,8 +309,10 @@ var SourceEntry = (function() {
      * of |parent|.
      */
     printAsText: function(parent) {
+      // The date will be undefined if not viewing a loaded log file.
       printLogEntriesAsText(this.entries_, parent,
-                            SourceTracker.getInstance().getSecurityStripping());
+                            SourceTracker.getInstance().getSecurityStripping(),
+                            Constants.clientInfo.numericDate);
     }
   };
 
diff --git a/chrome/browser/resources/net_internals/time_util.js b/chrome/browser/resources/net_internals/time_util.js
index c738468..9e412bbf 100644
--- a/chrome/browser/resources/net_internals/time_util.js
+++ b/chrome/browser/resources/net_internals/time_util.js
@@ -22,14 +22,25 @@ var timeutil = (function() {
 
   /**
    * The browser gives us times in terms of "time ticks" in milliseconds.
+   * This function converts the tick count to a Javascript "time", which is
+   * the UTC time in milliseconds.
+   *
+   * @param {String} timeTicks A time represented in "time ticks".
+   * @return {number} The Javascript time that |timeTicks| represents.
+   */
+  function convertTimeTicksToTime(timeTicks) {
+    return timeTickOffset + (timeTicks - 0);
+  }
+
+  /**
+   * The browser gives us times in terms of "time ticks" in milliseconds.
    * This function converts the tick count to a Date() object.
    *
    * @param {String} timeTicks A time represented in "time ticks".
    * @return {Date} The time that |timeTicks| represents.
    */
   function convertTimeTicksToDate(timeTicks) {
-    var timeStampMs = timeTickOffset + (timeTicks - 0);
-    return new Date(timeStampMs);
+    return new Date(convertTimeTicksToTime(timeTicks));
   }
 
   /**
@@ -88,6 +99,7 @@ var timeutil = (function() {
 
   return {
     setTimeTickOffset: setTimeTickOffset,
+    convertTimeTicksToTime: convertTimeTicksToTime,
     convertTimeTicksToDate: convertTimeTicksToDate,
     getCurrentTime: getCurrentTime,
     addNodeWithDate: addNodeWithDate,
diff --git a/chrome/test/data/webui/net_internals/log_view_painter.js b/chrome/test/data/webui/net_internals/log_view_painter.js
index 7d90d02..f9a5828 100644
--- a/chrome/test/data/webui/net_internals/log_view_painter.js
+++ b/chrome/test/data/webui/net_internals/log_view_painter.js
@@ -101,7 +101,8 @@ TEST_F('NetInternalsTest', 'netInternalsLogViewPainterPrintAsText', function() {
     div.innerHTML = '';
     timeutil.setTimeTickOffset(testCase.tickOffset);
     printLogEntriesAsText(testCase.logEntries, div,
-                          testCase.enableSecurityStripping);
+                          testCase.enableSecurityStripping,
+                          testCase.logCreationTime);
 
     // Strip any trailing newlines, since the whitespace when using innerText
     // can be a bit unpredictable.
@@ -112,6 +113,8 @@ TEST_F('NetInternalsTest', 'netInternalsLogViewPainterPrintAsText', function() {
   }
 
   runTestCase(painterTestURLRequest());
+  runTestCase(painterTestURLRequestIncomplete());
+  runTestCase(painterTestURLRequestIncompleteFromLoadedLog());
   runTestCase(painterTestNetError());
   runTestCase(painterTestHexEncodedBytes());
   runTestCase(painterTestCertVerifierJob());
@@ -130,11 +133,13 @@ TEST_F('NetInternalsTest', 'netInternalsLogViewPainterPrintAsText', function() {
 /**
  * Test case for a URLRequest. This includes custom formatting for load flags,
  * request/response HTTP headers, dependent sources, as well as basic
- * indentation and grouping.
+ * indentation and grouping.  Also makes sure that no extra event is logged
+ * for finished sources when there's a logCreationTime.
  */
 function painterTestURLRequest() {
   var testCase = {};
   testCase.tickOffset = '1337911098446';
+  testCase.logCreationTime = 1338864634013;
 
   testCase.logEntries = [
     {
@@ -746,6 +751,79 @@ function painterTestURLRequest() {
 }
 
 /**
+ * Test case for a URLRequest that was not completed that did not come from a
+ * loaded log file.
+ */
+function painterTestURLRequestIncomplete() {
+  var testCase = {};
+  testCase.tickOffset = '1337911098446';
+
+  testCase.logEntries = [
+    {
+      'phase': EventPhase.PHASE_BEGIN,
+      'source': {
+        'id': 146,
+        'type': EventSourceType.URL_REQUEST
+      },
+      'time': '953534778',
+      'type': EventType.REQUEST_ALIVE
+    },
+    {
+      'params': {
+        'load_flags': 128,
+        'method': 'GET',
+        'priority': 4,
+        'url': 'http://www.google.com/'
+      },
+      'phase': EventPhase.PHASE_BEGIN,
+      'source': {
+        'id': 146,
+        'type': EventSourceType.URL_REQUEST
+      },
+      'time': '953534910',
+      'type': EventType.URL_REQUEST_START_JOB
+    },
+    {
+      'phase': EventPhase.PHASE_END,
+      'source': {
+        'id': 146,
+        'type': EventSourceType.URL_REQUEST
+      },
+      'time': '953534970',
+      'type': EventType.URL_REQUEST_START_JOB
+    },
+  ];
+
+  testCase.expectedText =
+'t=1338864633224 [st=  0] +REQUEST_ALIVE  [dt=?]\n' +
+'t=1338864633356 [st=132]    URL_REQUEST_START_JOB  [dt=60]\n' +
+'                            --> load_flags = 128 (ENABLE_LOAD_TIMING)\n' +
+'                            --> method = "GET"\n' +
+'                            --> priority = 4\n' +
+'                            --> url = "http://www.google.com/"';
+
+  return testCase;
+}
+
+/**
+ * Test case for a URLRequest that was not completed that came from a loaded
+ * log file.
+ */
+function painterTestURLRequestIncompleteFromLoadedLog() {
+  var testCase = painterTestURLRequestIncomplete();
+  testCase.logCreationTime = 1338864634013;
+  testCase.expectedText =
+'t=1338864633224 [st=  0] +REQUEST_ALIVE  [dt=789+]\n' +
+'t=1338864633356 [st=132]    URL_REQUEST_START_JOB  [dt=60]\n' +
+'                            --> load_flags = 128 (ENABLE_LOAD_TIMING)\n' +
+'                            --> method = "GET"\n' +
+'                            --> priority = 4\n' +
+'                            --> url = "http://www.google.com/"\n' +
+'t=1338864634013 [st=789]';
+  return testCase;
+}
+
+/**
  * Tests the custom formatting of net_errors across several different event
  * types.
  */
@@ -1294,7 +1372,7 @@ function painterTestStripCookiesURLRequest() {
   var testCase = painterTestDontStripCookiesURLRequest();
   testCase.enableSecurityStripping = true;
   testCase.expectedText =
-    testCase.expectedText.replace(/MyMagicPony/g, '[value was stripped]');
+      testCase.expectedText.replace(/MyMagicPony/g, '[value was stripped]');
   return testCase;
 }