services/tracing/coordinator_unittest.cc

// Copyright 2017 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 "services/tracing/coordinator.h"

#include <algorithm>
#include <memory>
#include <set>
#include <string>
#include <utility>
#include <vector>

#include "base/bind.h"
#include "base/run_loop.h"
#include "base/strings/string_split.h"
#include "base/test/scoped_task_environment.h"
#include "mojo/public/cpp/system/data_pipe.h"
#include "mojo/public/cpp/system/data_pipe_drainer.h"
#include "services/service_manager/public/cpp/service_context_ref.h"
#include "services/tracing/public/mojom/tracing.mojom.h"
#include "services/tracing/test_util.h"
#include "testing/gtest/include/gtest/gtest.h"

namespace tracing {

class CoordinatorTest : public testing::Test,
                        public mojo::DataPipeDrainer::Client {
 public:
  // testing::Test
  void SetUp() override {
    agent_registry_ = std::make_unique<AgentRegistry>();
    coordinator_ = std::make_unique<Coordinator>(agent_registry_.get(),
                                                 base::RepeatingClosure());
    output_ = "";
  }

  // testing::Test
  void TearDown() override {
    agents_.clear();
    coordinator_.reset();
    agent_registry_.reset();
  }

  // mojo::DataPipeDrainer::Client
  void OnDataAvailable(const void* data, size_t num_bytes) override {
    output_.append(static_cast<const char*>(data), num_bytes);
  }

  // mojo::DataPipeDrainer::Client
  void OnDataComplete() override { std::move(quit_closure_).Run(); }

  MockAgent* AddArrayAgent(base::ProcessId pid) {
    auto agent = std::make_unique<MockAgent>();
    agent_registry_->RegisterAgent(agent->CreateAgentPtr(), "traceEvents",
                                   mojom::TraceDataType::ARRAY, pid);
    agents_.push_back(std::move(agent));
    return agents_.back().get();
  }

  MockAgent* AddArrayAgent() { return AddArrayAgent(base::kNullProcessId); }

  MockAgent* AddObjectAgent() {
    auto agent = std::make_unique<MockAgent>();
    agent_registry_->RegisterAgent(agent->CreateAgentPtr(), "systemTraceEvents",
                                   mojom::TraceDataType::OBJECT,
                                   base::kNullProcessId);
    agents_.push_back(std::move(agent));
    return agents_.back().get();
  }

  MockAgent* AddStringAgent() {
    auto agent = std::make_unique<MockAgent>();
    agent_registry_->RegisterAgent(agent->CreateAgentPtr(), "power",
                                   mojom::TraceDataType::STRING,
                                   base::kNullProcessId);
    agents_.push_back(std::move(agent));
    return agents_.back().get();
  }

  void StartTracing(std::string config) { coordinator_->StartTracing(config); }

  void StopAndFlush() {
    mojo::DataPipe data_pipe;
    auto dummy_callback = [](base::Value metadata) {};
    coordinator_->StopAndFlush(std::move(data_pipe.producer_handle),
                               base::BindRepeating(dummy_callback));
    drainer_.reset(
        new mojo::DataPipeDrainer(this, std::move(data_pipe.consumer_handle)));
  }

  void IsTracing(bool expected_response) {
    coordinator_->IsTracing(base::BindRepeating(
        [](bool expected, bool actual) { EXPECT_EQ(expected, actual); },
        expected_response));
  }

  void RequestBufferUsage(float expected_usage, uint32_t expected_count) {
    coordinator_->RequestBufferUsage(base::BindRepeating(
        [](float expected_usage, uint32_t expected_count, bool success,
           float usage, uint32_t count) {
          EXPECT_TRUE(success);
          EXPECT_EQ(expected_usage, usage);
          EXPECT_EQ(expected_count, count);
        },
        expected_usage, expected_count));
  }

  void CheckDisconnectClosures(size_t num_agents) {
    // Verify that all disconnect closures are cleared up. This means that, for
    // each agent, either the tracing service is notified that the agent is
    // disconnected or the agent has answered to all requests.
    size_t count = 0;
    agent_registry_->ForAllAgents([&count](AgentRegistry::AgentEntry* entry) {
      count++;
      EXPECT_EQ(0u, entry->num_disconnect_closures_for_testing());
    });
    EXPECT_EQ(num_agents, count);
  }

  base::test::ScopedTaskEnvironment scoped_task_environment_;
  std::unique_ptr<AgentRegistry> agent_registry_;
  std::unique_ptr<Coordinator> coordinator_;
  std::vector<std::unique_ptr<MockAgent>> agents_;
  std::unique_ptr<mojo::DataPipeDrainer> drainer_;
  base::RepeatingClosure quit_closure_;
  std::string output_;
};

TEST_F(CoordinatorTest, StartTracingSimple) {
  base::RunLoop run_loop;
  auto* agent = AddArrayAgent();
  StartTracing("*");
  run_loop.RunUntilIdle();

  // The agent should have received exactly one call from the coordinator.
  EXPECT_EQ(1u, agent->call_stat().size());
  EXPECT_EQ("StartTracing", agent->call_stat()[0]);
}

TEST_F(CoordinatorTest, StartTracingTwoAgents) {
  base::RunLoop run_loop;
  auto* agent1 = AddArrayAgent();
  StartTracing("*");
  auto* agent2 = AddStringAgent();
  run_loop.RunUntilIdle();

  // Each agent should have received exactly one call from the coordinator.
  EXPECT_EQ(1u, agent1->call_stat().size());
  EXPECT_EQ("StartTracing", agent1->call_stat()[0]);
  EXPECT_EQ(1u, agent2->call_stat().size());
  EXPECT_EQ("StartTracing", agent2->call_stat()[0]);
}

TEST_F(CoordinatorTest, StartTracingWithProcessFilter) {
  base::RunLoop run_loop1;
  auto* agent1 = AddArrayAgent(static_cast<base::ProcessId>(1));
  auto* agent2 = AddArrayAgent(static_cast<base::ProcessId>(2));
  StartTracing("{\"included_process_ids\":[2,4]}");
  run_loop1.RunUntilIdle();

  base::RunLoop run_loop2;
  auto* agent3 = AddArrayAgent(static_cast<base::ProcessId>(3));
  auto* agent4 = AddArrayAgent(static_cast<base::ProcessId>(4));
  StartTracing("{\"included_process_ids\":[4,6]}");
  run_loop2.RunUntilIdle();

  base::RunLoop run_loop3;
  auto* agent5 = AddArrayAgent(static_cast<base::ProcessId>(5));
  auto* agent6 = AddArrayAgent(static_cast<base::ProcessId>(6));
  run_loop3.RunUntilIdle();

  // StartTracing should only be received by agents 2, 4, and 6.
  // Agent 4 should receive StartTracing twice, as it's
  // included in both configs.
  EXPECT_EQ(0u, agent1->call_stat().size());
  EXPECT_EQ(1u, agent2->call_stat().size());
  EXPECT_EQ("StartTracing", agent2->call_stat()[0]);
  EXPECT_EQ(0u, agent3->call_stat().size());
  EXPECT_EQ(2u, agent4->call_stat().size());
  EXPECT_EQ("StartTracing", agent4->call_stat()[0]);
  EXPECT_EQ("StartTracing", agent4->call_stat()[1]);
  EXPECT_EQ(0u, agent5->call_stat().size());
  EXPECT_EQ(1u, agent6->call_stat().size());
  EXPECT_EQ("StartTracing", agent6->call_stat()[0]);
}

TEST_F(CoordinatorTest, StartTracingWithSameConfigs) {
  base::RunLoop run_loop;
  auto* agent = AddArrayAgent();
  StartTracing("config");
  // The 2nd |StartTracing| should succeed when we are not trying to change
  // the config.
  StartTracing("config");
  run_loop.RunUntilIdle();

  // The agent should have received exactly one call from the coordinator
  // because the 2nd |StartTracing| was a no-op.
  EXPECT_EQ(1u, agent->call_stat().size());
  EXPECT_EQ("StartTracing", agent->call_stat()[0]);
}

TEST_F(CoordinatorTest, StopAndFlushObjectAgent) {
  base::RunLoop run_loop;
  quit_closure_ = run_loop.QuitClosure();

  auto* agent = AddObjectAgent();
  agent->data_.push_back("\"content\":{\"a\":1}");
  agent->data_.push_back("\"name\":\"etw\"");

  StartTracing("config");
  StopAndFlush();
  if (!quit_closure_.is_null())
    run_loop.Run();

  EXPECT_EQ("{\"systemTraceEvents\":{\"content\":{\"a\":1},\"name\":\"etw\"}}",
            output_);

  // Each agent should have received exactly two calls.
  EXPECT_EQ(2u, agent->call_stat().size());
  EXPECT_EQ("StartTracing", agent->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent->call_stat()[1]);
}

TEST_F(CoordinatorTest, StopAndFlushTwoArrayAgents) {
  base::RunLoop run_loop;
  quit_closure_ = run_loop.QuitClosure();

  auto* agent1 = AddArrayAgent();
  agent1->data_.push_back("e1");
  agent1->data_.push_back("e2");

  auto* agent2 = AddArrayAgent();
  agent2->data_.push_back("e3");
  agent2->data_.push_back("e4");

  StartTracing("config");
  StopAndFlush();
  if (!quit_closure_.is_null())
    run_loop.Run();

  // |output_| should be of the form {"traceEvents":[ei,ej,ek,el]}, where
  // ei,ej,ek,el is a permutation of e1,e2,e3,e4 such that e1 is before e2 and
  // e3 is before e4 since e1 and 2 come from the same agent and their order
  // should be preserved and, similarly, the order of e3 and e4 should be
  // preserved, too.
  EXPECT_TRUE(output_ == "{\"traceEvents\":[e1,e2,e3,e4]}" ||
              output_ == "{\"traceEvents\":[e1,e3,e2,e4]}" ||
              output_ == "{\"traceEvents\":[e1,e3,e4,e2]}" ||
              output_ == "{\"traceEvents\":[e3,e1,e2,e4]}" ||
              output_ == "{\"traceEvents\":[e3,e1,e4,e2]}" ||
              output_ == "{\"traceEvents\":[e3,e4,e1,e2]}");

  // Each agent should have received exactly two calls.
  EXPECT_EQ(2u, agent1->call_stat().size());
  EXPECT_EQ("StartTracing", agent1->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent1->call_stat()[1]);

  EXPECT_EQ(2u, agent2->call_stat().size());
  EXPECT_EQ("StartTracing", agent2->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent2->call_stat()[1]);
}

TEST_F(CoordinatorTest, StopAndFlushDifferentTypeAgents) {
  base::RunLoop run_loop;
  quit_closure_ = run_loop.QuitClosure();

  auto* agent1 = AddArrayAgent();
  agent1->data_.push_back("e1");
  agent1->data_.push_back("e2");

  auto* agent2 = AddStringAgent();
  agent2->data_.push_back("e3");
  agent2->data_.push_back("e4");

  StartTracing("config");
  StopAndFlush();
  if (!quit_closure_.is_null())
    run_loop.Run();

  EXPECT_TRUE(output_ == "{\"traceEvents\":[e1,e2],\"power\":\"e3e4\"}" ||
              output_ == "{\"power\":\"e3e4\",\"traceEvents\":[e1,e2]}");

  // Each agent should have received exactly two calls.
  EXPECT_EQ(2u, agent1->call_stat().size());
  EXPECT_EQ("StartTracing", agent1->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent1->call_stat()[1]);

  EXPECT_EQ(2u, agent2->call_stat().size());
  EXPECT_EQ("StartTracing", agent2->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent2->call_stat()[1]);
}

TEST_F(CoordinatorTest, StopAndFlushWithMetadata) {
  base::RunLoop run_loop;
  quit_closure_ = run_loop.QuitClosure();

  auto* agent = AddArrayAgent();
  agent->data_.push_back("event");
  agent->metadata_.SetString("key", "value");

  StartTracing("config");
  StopAndFlush();
  if (!quit_closure_.is_null())
    run_loop.Run();

  // Metadata is written at after trace data.
  EXPECT_EQ("{\"traceEvents\":[event],\"metadata\":{\"key\":\"value\"}}",
            output_);
  EXPECT_EQ(2u, agent->call_stat().size());
  EXPECT_EQ("StartTracing", agent->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent->call_stat()[1]);
}

TEST_F(CoordinatorTest, IsTracing) {
  base::RunLoop run_loop;
  AddArrayAgent();
  StartTracing("config");
  IsTracing(true);
  run_loop.RunUntilIdle();
}

TEST_F(CoordinatorTest, IsNotTracing) {
  base::RunLoop run_loop;
  IsTracing(false);
  run_loop.RunUntilIdle();
}

TEST_F(CoordinatorTest, RequestBufferUsage) {
  auto* agent1 = AddArrayAgent();
  agent1->trace_log_status_.event_capacity = 4;
  agent1->trace_log_status_.event_count = 1;
  RequestBufferUsage(0.25, 1);
  base::RunLoop().RunUntilIdle();
  CheckDisconnectClosures(1);

  auto* agent2 = AddArrayAgent();
  agent2->trace_log_status_.event_capacity = 8;
  agent2->trace_log_status_.event_count = 1;
  // The buffer usage of |agent2| is less than the buffer usage of |agent1| and
  // so the total buffer usage, i.e 0.25, does not change. But the approximate
  // count will be increased from 1 to 2.
  RequestBufferUsage(0.25, 2);
  base::RunLoop().RunUntilIdle();
  CheckDisconnectClosures(2);

  base::RunLoop run_loop3;
  auto* agent3 = AddArrayAgent();
  agent3->trace_log_status_.event_capacity = 8;
  agent3->trace_log_status_.event_count = 4;
  // |agent3| has the worst buffer usage of 0.5.
  RequestBufferUsage(0.5, 6);
  base::RunLoop().RunUntilIdle();
  CheckDisconnectClosures(3);

  // At the end |agent1| receives 3 calls, |agent2| receives 2 calls, and
  // |agent3| receives 1 call.
  EXPECT_EQ(3u, agent1->call_stat().size());
  EXPECT_EQ(2u, agent2->call_stat().size());
  EXPECT_EQ(1u, agent3->call_stat().size());
}

TEST_F(CoordinatorTest, LateAgents) {
  base::RunLoop run_loop1;
  quit_closure_ = run_loop1.QuitClosure();
  auto* agent1 = AddArrayAgent();
  StartTracing("config");
  StopAndFlush();
  if (!quit_closure_.is_null())
    run_loop1.Run();

  base::RunLoop run_loop2;
  auto* agent2 = AddArrayAgent();
  agent2->data_.push_back("discarded data");
  run_loop2.RunUntilIdle();

  EXPECT_EQ(2u, agent1->call_stat().size());
  EXPECT_EQ("StartTracing", agent1->call_stat()[0]);
  EXPECT_EQ("StopAndFlush", agent1->call_stat()[1]);

  // The second agent that registers after the end of a tracing session should
  // receive a StopAndFlush message.
  EXPECT_EQ(1u, agent2->call_stat().size());
  EXPECT_EQ("StopAndFlush", agent2->call_stat()[0]);
}

}  // namespace tracing