Start and stop RTC event logs from private extension API.

chrome/browser/extensions/api/webrtc_logging_private/webrtc_event_log_apitest.cc

+// Copyright 2016 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "base/command_line.h"
+#include "base/json/json_writer.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/threading/platform_thread.h"
+#include "base/time/time.h"
+#include "build/build_config.h"
+#include "chrome/browser/extensions/api/webrtc_logging_private/webrtc_logging_private_api.h"
+#include "chrome/browser/extensions/extension_function_test_utils.h"
+#include "chrome/browser/extensions/extension_tab_util.h"
+#include "chrome/browser/media/webrtc_browsertest_base.h"
+#include "chrome/browser/media/webrtc_browsertest_common.h"
+#include "chrome/common/chrome_switches.h"
+#include "content/public/common/content_switches.h"
+#include "content/public/test/browser_test_utils.h"
+#include "extensions/browser/api_test_utils.h"
+#include "extensions/common/test_util.h"
+#include "media/base/media_switches.h"
+#include "net/test/embedded_test_server/embedded_test_server.h"
+
+#if defined(OS_WIN)
+#define IntToStringType base::IntToString16
+#else
+#define IntToStringType base::IntToString
+#endif
+
+using extensions::WebrtcLoggingPrivateStartWebRtcEventLoggingFunction;
+using extensions::WebrtcLoggingPrivateStopWebRtcEventLoggingFunction;
+
+namespace utils = extension_function_test_utils;
+
+namespace {
+
+// Get the expected EventLog file name. The name will be
+// <temporary path>.<render process id>.event_log.<consumer id>, for example
+// "/tmp/.com.google.Chrome.Z6UC3P.12345.event_log.1".
+base::FilePath GetExpectedEventLogFileName(const base::FilePath& base_file,
+                                           int render_process_id) {
+  const int kExpectedConsumerId = 1;

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

nit: static const int kExpectedConsumerId = 1;
(kFooName constant naming style is for compile-time constants, not runtime)

[terelius-chromium, 2016/04/13 08:52:04]

Done.

+  return base_file.AddExtension(IntToStringType(render_process_id))
+      .AddExtension(FILE_PATH_LITERAL("event_log"))
+      .AddExtension(IntToStringType(kExpectedConsumerId));
+}
+
+static const char kMainWebrtcTestHtmlPage[] = "/webrtc/webrtc_jsep01_test.html";
+
+std::string ParamsToString(const base::ListValue& parameters) {
+  std::string parameter_string;
+  EXPECT_TRUE(base::JSONWriter::Write(parameters, &parameter_string));
+  return parameter_string;
+}
+
+class WebrtcEventLogApiTest : public WebRtcTestBase {
+ protected:
+  void SetUp() override {
+    WebRtcTestBase::SetUp();
+    extension_ = extensions::test_util::CreateEmptyExtension();
+  }
+
+  void SetUpInProcessBrowserTestFixture() override {
+    DetectErrorsInJavaScript();  // Look for errors in our rather complex js.
+  }
+
+  void SetUpCommandLine(base::CommandLine* command_line) override {
+    // Ensure the infobar is enabled, since we expect that in this test.
+    EXPECT_FALSE(command_line->HasSwitch(switches::kUseFakeUIForMediaStream));
+
+    // Always use fake devices.
+    command_line->AppendSwitch(switches::kUseFakeDeviceForMediaStream);
+
+    // Flag used by TestWebAudioMediaStream to force garbage collection.
+    command_line->AppendSwitchASCII(switches::kJavaScriptFlags, "--expose-gc");
+
+    // Enable the the event log in the extension API.
+    command_line->AppendSwitch(
+        switches::kEnableWebRtcEventLoggingFromExtension);
+  }
+
+  template <typename T>
+  scoped_refptr<T> CreateFunction() {

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

nit: CreateExtensionFunction

[terelius-chromium, 2016/04/13 08:52:05]

Done.

+    scoped_refptr<T> function(new T());
+    function->set_extension(extension_.get());
+    function->set_has_callback(true);
+    return function;
+  }
+
+  void AppendTabIdAndUrl(base::ListValue* parameters,
+                         content::WebContents* tab) {
+    base::DictionaryValue* request_info = new base::DictionaryValue();
+    request_info->SetInteger("tabId",
+                             extensions::ExtensionTabUtil::GetTabId(tab));
+    parameters->Append(request_info);
+    parameters->AppendString(tab->GetURL().GetOrigin().spec());
+  }
+
+ private:
+  scoped_refptr<extensions::Extension> extension_;
+};
+
+}  // namespace
+
+IN_PROC_BROWSER_TEST_F(WebrtcEventLogApiTest, TestStartStopWebRtcEventLogging) {
+  if (OnWinXp())

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

I don't think XP is supported any longer, so this shouldn't be necessary.
https://chrome.googleblog.com/2015/11/updates-to-chrome-platform-support.html

[terelius-chromium, 2016/04/13 08:52:04]

Done.

+    return;
+
+  ASSERT_TRUE(embedded_test_server()->Start());
+
+  content::WebContents* left_tab =
+      OpenTestPageAndGetUserMediaInNewTab(kMainWebrtcTestHtmlPage);
+  content::WebContents* right_tab =
+      OpenTestPageAndGetUserMediaInNewTab(kMainWebrtcTestHtmlPage);
+
+  SetupPeerconnectionWithLocalStream(left_tab);
+  SetupPeerconnectionWithLocalStream(right_tab);
+
+  NegotiateCall(left_tab, right_tab, "VP8");
+
+  StartDetectingVideo(left_tab, "remote-view");
+  StartDetectingVideo(right_tab, "remote-view");
+
+  // Start the event log.
+  const int seconds = 0;
+  base::ListValue start_params;
+  AppendTabIdAndUrl(&start_params, left_tab);
+  start_params.AppendInteger(seconds);
+  scoped_refptr<WebrtcLoggingPrivateStartWebRtcEventLoggingFunction>
+      start_function(CreateFunction<
+                     WebrtcLoggingPrivateStartWebRtcEventLoggingFunction>());
+  scoped_ptr<base::Value> start_result(utils::RunFunctionAndReturnSingleResult(
+      start_function.get(), ParamsToString(start_params), browser()));
+  ASSERT_TRUE(start_result.get());
+
+  // Get the file name.
+  scoped_ptr<extensions::api::webrtc_logging_private::RecordingInfo>
+      recordings_info_start(
+          extensions::api::webrtc_logging_private::RecordingInfo::FromValue(
+              *start_result.get()));
+  ASSERT_TRUE(recordings_info_start.get());
+  base::FilePath file_name_start(
+      base::FilePath::FromUTF8Unsafe(recordings_info_start->prefix_path));
+
+#if !defined(OS_MACOSX)
+  // Video is choppy on Mac OS X. http://crbug.com/443542.
+  WaitForVideoToPlay(left_tab);
+  WaitForVideoToPlay(right_tab);
+#endif
+
+  // Stop the event log.
+  base::ListValue stop_params;
+  AppendTabIdAndUrl(&stop_params, left_tab);
+  scoped_refptr<WebrtcLoggingPrivateStopWebRtcEventLoggingFunction>
+      stop_function(
+          CreateFunction<WebrtcLoggingPrivateStopWebRtcEventLoggingFunction>());
+  scoped_ptr<base::Value> stop_result(utils::RunFunctionAndReturnSingleResult(
+      stop_function.get(), ParamsToString(stop_params), browser()));
+
+  // Get the file name.
+  scoped_ptr<extensions::api::webrtc_logging_private::RecordingInfo>
+      recordings_info_stop(
+          extensions::api::webrtc_logging_private::RecordingInfo::FromValue(
+              *stop_result.get()));
+  ASSERT_TRUE(recordings_info_stop.get());
+  base::FilePath file_name_stop(
+      base::FilePath::FromUTF8Unsafe(recordings_info_stop->prefix_path));
+
+  HangUp(left_tab);
+  HangUp(right_tab);
+
+  EXPECT_EQ(file_name_start, file_name_stop);
+
+  // Check that the file exists and is non-empty.
+  base::ProcessId render_process_id =
+      base::GetProcId(left_tab->GetRenderProcessHost()->GetHandle());
+  EXPECT_NE(render_process_id, base::kNullProcessId);
+  base::FilePath full_file_name =
+      GetExpectedEventLogFileName(file_name_stop, render_process_id);

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

what if there were two tests running at the same time that call this function. 
Would they conflict?  Is there a way to instead use dynamically chosen temporary
files or folder? (there's code in base specifically to handle that)

[terelius-chromium, 2016/04/13 08:52:05]

The path is based on Profile::GetPath(). This path contains a 6 character
identifier that changes every time, at least when I run the test locally. I
don't know how this path is generated (there are multiple overrides) but
assuming that the 6 characters are chosen randomly from [A-Za-z0-9_], the
probability that two simultaneous tests would try to write to the same directory
is less than 10^(-10). In addition, the file name also uses the render process
id and some other values, so I think it is very unlikely that the  file names
will conflict.

There is currently no way to use choose a special file path from the testing
code. The test uses the same code as a real javascript call.

+  while (!base::PathExists(full_file_name)) {
+    LOG(INFO) << "Waiting for logfile to become available...";

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

I think 'INFO' is discouraged.  Instead use VLOG(1) << ...

[terelius-chromium, 2016/04/13 08:52:04]

Done.

+    base::PlatformThread::Sleep(base::TimeDelta::FromSeconds(1));

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

ehm... ok, I see now what this loop is about.  Sleep is generally less popular
than 'goto', so we should avoid this :)

Instead, use an event notification mechanism (e.g. check out use of RunLoop in
various tests), incorporating a timeout and an exact notification for when the
event has occurred.

[terelius-chromium, 2016/04/13 08:52:05]

I've updated the loop based on our offline discussion. During local tests it has
never entered the loop body.

Receiving an event would be preferable, but there is currently no way to send
events from the WebRTC event log object.

+  }
+  EXPECT_TRUE(base::PathExists(full_file_name));

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

should this be ASSERT_TRUE()?  As is, you'll continue to execute the below code
and it looks to me like it would surely fail.

[terelius-chromium, 2016/04/13 08:52:04]

Done. However, the loop above will not exit until the path exists, so this
EXPECT/ASSERT should never fail. I added it mostly to document the intention of
the test.

+  int64_t file_size = 0;
+  EXPECT_TRUE(base::GetFileSize(full_file_name, &file_size));
+  EXPECT_GT(file_size, 0);
+
+  // Clean up.
+  base::DeleteFile(full_file_name, false);

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

If you use some of the temporary file utilities in base/, this could be done
automatically.

[terelius-chromium, 2016/04/13 08:52:05]

Acknowledged. The idea was to exercise the same code path as a real javascript
call, so there is currently no way inject a temporary file for testing. Let's
discuss.

+}
+
+IN_PROC_BROWSER_TEST_F(WebrtcEventLogApiTest,
+                       TestStartTimedWebRtcEventLogging) {
+  if (OnWinXp())
+    return;
+
+  ASSERT_TRUE(embedded_test_server()->Start());
+
+  content::WebContents* left_tab =
+      OpenTestPageAndGetUserMediaInNewTab(kMainWebrtcTestHtmlPage);
+  content::WebContents* right_tab =
+      OpenTestPageAndGetUserMediaInNewTab(kMainWebrtcTestHtmlPage);
+
+  SetupPeerconnectionWithLocalStream(left_tab);
+  SetupPeerconnectionWithLocalStream(right_tab);
+
+  NegotiateCall(left_tab, right_tab, "VP8");
+
+  StartDetectingVideo(left_tab, "remote-view");
+  StartDetectingVideo(right_tab, "remote-view");
+
+  // Start the event log. RunFunctionAndReturnSingleResult will block until a
+  // result is available, which happens when the logging stops after 1 second.
+  const int seconds = 1;
+  base::ListValue start_params;
+  AppendTabIdAndUrl(&start_params, left_tab);
+  start_params.AppendInteger(seconds);
+  scoped_refptr<WebrtcLoggingPrivateStartWebRtcEventLoggingFunction>
+      start_function(CreateFunction<
+                     WebrtcLoggingPrivateStartWebRtcEventLoggingFunction>());
+  scoped_ptr<base::Value> start_result(utils::RunFunctionAndReturnSingleResult(
+      start_function.get(), ParamsToString(start_params), browser()));
+  ASSERT_TRUE(start_result.get());
+
+  // Get the file name.
+  scoped_ptr<extensions::api::webrtc_logging_private::RecordingInfo>
+      recordings_info_start(
+          extensions::api::webrtc_logging_private::RecordingInfo::FromValue(
+              *start_result.get()));
+  ASSERT_TRUE(recordings_info_start.get());
+  base::FilePath file_name_start(
+      base::FilePath::FromUTF8Unsafe(recordings_info_start->prefix_path));
+
+#if !defined(OS_MACOSX)
+  // Video is choppy on Mac OS X. http://crbug.com/443542.
+  WaitForVideoToPlay(left_tab);
+  WaitForVideoToPlay(right_tab);
+#endif
+
+  HangUp(left_tab);
+  HangUp(right_tab);
+
+  // The log has stopped automatically. Check that the file exists and is
+  // non-empty.
+  base::ProcessId render_process_id =
+      base::GetProcId(left_tab->GetRenderProcessHost()->GetHandle());
+  EXPECT_NE(render_process_id, base::kNullProcessId);
+  base::FilePath full_file_name =
+      GetExpectedEventLogFileName(file_name_start, render_process_id);
+  while (!base::PathExists(full_file_name)) {
+    LOG(INFO) << "Waiting for logfile to become available...";
+    base::PlatformThread::Sleep(base::TimeDelta::FromSeconds(1));

[tommi (sloooow) - chröme, 2016/04/07 12:44:29]

Use RunLoop instead

[terelius-chromium, 2016/04/13 08:52:04]

There is currently no easy way to get a callback from the event log. Let's
discuss this.

+  }
+  int64_t file_size = 0;
+  EXPECT_TRUE(base::GetFileSize(full_file_name, &file_size));
+  EXPECT_GT(file_size, 0);
+
+  // Clean up.
+  base::DeleteFile(full_file_name, false);
+}