[ChromeDriver] Enable Replay for Readable Timestamps

Add check for readable timestamp format in ChromeDriver's log reader.
This allows ChromeDriver to successfully replay Dev Tools commands for
log replay when logs were recorded with --readable-timestamps.

Bug: chromedriver:3095
Change-Id: I3a4a9bf0c43b346daece0aaf595c725a47904d21
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1766431Reviewed-by: John Chen <johnchen@chromium.org>
Commit-Queue: Tricia Crichton <triciac@chromium.org>
Cr-Commit-Position: refs/heads/master@{#691682}

chrome/test/chromedriver/log_replay/devtools_log_reader.cc

@@ -85,10 +85,15 @@ DevToolsLogReader::~DevToolsLogReader() {}
 bool DevToolsLogReader::IsHeader(std::istringstream& header_stream) const {
   std::string word;
   header_stream >> word;  // preamble
-  if (!base::MatchPattern(word, "[??????????.???][DEBUG]:")) {
+  if (!base::MatchPattern(word, "[??????????.???][DEBUG]:") &&
+      !base::MatchPattern(word, "[??????????")) {
     return false;
   }
   header_stream >> word;  // "DevTools" for DevTools commands/responses/events
+  // test for the second half of readable timestamp and read next token
+  if (base::MatchPattern(word, "????????.??????][DEBUG]:")) {
+    header_stream >> word;
+  }
   bool result = word == "DevTools";
   return result;
 }

chrome/test/chromedriver/log_replay/devtools_log_reader_unittest.cc

@@ -17,6 +17,8 @@ const char* const kTestDataPath[] = {"chrome", "test", "chromedriver",
 const char kTestGetTitlePath[] = "testGetTitle_simple.log";
 const char kOneEntryPath[] = "oneDevToolsEntry.log";
 const char kTruncatedJSONPath[] = "truncatedJSON.log";
+const char kReadableTimestampPathLinux[] = "testReadableTimestampLinux.log";
+const char kReadableTimestampPathWin[] = "testReadableTimestampWindows.log";
 
 base::FilePath GetLogFileFromLiteral(const char literal[]) {
   base::FilePath root_dir;
@@ -41,6 +43,30 @@ TEST(DevToolsLogReaderTest, Basic) {
   EXPECT_EQ(next->payload, "{\n   \"string_key\": \"string_value\"\n}\n");
 }
 
+TEST(DevToolsLogReaderTest, ReadableTimeStampLinux) {
+  base::FilePath path = GetLogFileFromLiteral(kReadableTimestampPathLinux);
+  DevToolsLogReader reader(path);
+  std::unique_ptr<LogEntry> next = reader.GetNext(LogEntry::kHTTP);
+  EXPECT_TRUE(next != nullptr);
+  EXPECT_EQ(next->protocol_type, LogEntry::kHTTP);
+  EXPECT_EQ(next->command_name, "http://localhost:38037/json/version");
+  next = reader.GetNext(LogEntry::kHTTP);
+  EXPECT_TRUE(next != nullptr);
+  EXPECT_EQ(next->payload, "{\n   \"string_key\": \"string_value\"\n}\n");
+}
+
+TEST(DevToolsLogReaderTest, ReadableTimeStampWindows) {
+  base::FilePath path = GetLogFileFromLiteral(kReadableTimestampPathWin);
+  DevToolsLogReader reader(path);
+  std::unique_ptr<LogEntry> next = reader.GetNext(LogEntry::kHTTP);
+  EXPECT_TRUE(next != nullptr);
+  EXPECT_EQ(next->protocol_type, LogEntry::kHTTP);
+  EXPECT_EQ(next->command_name, "http://localhost:38037/json/version");
+  next = reader.GetNext(LogEntry::kHTTP);
+  EXPECT_TRUE(next != nullptr);
+  EXPECT_EQ(next->payload, "{\n   \"string_key\": \"string_value\"\n}\n");
+}
+
 TEST(DevToolsLogReaderTest, Multiple) {
   base::FilePath path = GetLogFileFromLiteral(kTestGetTitlePath);
   DevToolsLogReader reader(path);

chrome/test/chromedriver/log_replay/test_data/testReadableTimestampLinux.log

+[08-20-2019 16:43:43.086749][DEBUG]: DevTools HTTP Request: http://localhost:38037/json/version
+[08-20-2019 16:43:43.087856][DEBUG]: DevTools HTTP Response: {
+   "string_key": "string_value"
+}
+
+[08-20-2019 16:43:44.264692][DEBUG]: DevTools HTTP Request: http://localhost:38037/json
+[08-20-2019 16:43:44.265875][DEBUG]: DevTools HTTP Response: [ {
+   "string_key1": "string_value1"
+}, {
+   "string_key2": "string_value2"
+} ]
+
+[08-20-2019 16:43:44.272071][DEBUG]: DevTools WebSocket Command: Log.enable (id=1) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+
+}
+[08-20-2019 16:43:44.276995][DEBUG]: DevTools WebSocket Command: DOM.getDocument (id=2) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+
+}
+[08-20-2019 16:43:44.278068][DEBUG]: DevTools WebSocket Command: Target.setAutoAttach (id=3) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+   "autoAttach": true,
+   "waitForDebuggerOnStart": false
+}

chrome/test/chromedriver/log_replay/test_data/testReadableTimestampWindows.log

+[08-20-2019 16:43:43.086][DEBUG]: DevTools HTTP Request: http://localhost:38037/json/version
+[08-20-2019 16:43:43.087][DEBUG]: DevTools HTTP Response: {
+   "string_key": "string_value"
+}
+
+[08-20-2019 16:43:44.264][DEBUG]: DevTools HTTP Request: http://localhost:38037/json
+[08-20-2019 16:43:44.265][DEBUG]: DevTools HTTP Response: [ {
+   "string_key1": "string_value1"
+}, {
+   "string_key2": "string_value2"
+} ]
+
+[08-20-2019 16:43:44.272][DEBUG]: DevTools WebSocket Command: Log.enable (id=1) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+
+}
+[08-20-2019 16:43:44.276][DEBUG]: DevTools WebSocket Command: DOM.getDocument (id=2) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+
+}
+[08-20-2019 16:43:44.278][DEBUG]: DevTools WebSocket Command: Target.setAutoAttach (id=3) 7A66E25ABD1F05841E3DEF9B221CBB42 {
+   "autoAttach": true,
+   "waitForDebuggerOnStart": false
+}