Home | History | Annotate | Download | only in debug 
      1 // Copyright (c) 2010 The Chromium Authors. All rights reserved.
      2 // Use of this source code is governed by a BSD-style license that can be
      3 // found in the LICENSE file.
      4 
      5 #include "base/debug/trace_event.h"
      6 
      7 #include <strstream>
      8 
      9 #include "base/at_exit.h"
     10 #include "base/basictypes.h"
     11 #include "base/file_util.h"
     12 #include "base/win/event_trace_consumer.h"
     13 #include "base/win/event_trace_controller.h"
     14 #include "base/win/windows_version.h"
     15 #include "testing/gmock/include/gmock/gmock.h"
     16 #include "testing/gtest/include/gtest/gtest.h"
     17 #include <initguid.h>  // NOLINT - must be last include.
     18 
     19 namespace base {
     20 namespace debug {
     21 
     22 namespace {
     23 
     24 using testing::_;
     25 using testing::AnyNumber;
     26 using testing::InSequence;
     27 using testing::Ge;
     28 using testing::Le;
     29 using testing::NotNull;
     30 
     31 using base::win::EtwEventType;
     32 using base::win::EtwTraceConsumerBase;
     33 using base::win::EtwTraceController;
     34 using base::win::EtwTraceProperties;
     35 
     36 // Data for unittests traces.
     37 const char kEmpty[] = "";
     38 const char kName[] = "unittest.trace_name";
     39 const char kExtra[] = "UnittestDummyExtraString";
     40 const void* kId = kName;
     41 
     42 const wchar_t kTestSessionName[] = L"TraceEvent unittest session";
     43 
     44 MATCHER_P(BufferStartsWith, str, "Buffer starts with") {
     45   return memcmp(arg, str.c_str(), str.length()) == 0;
     46 }
     47 
     48 // Duplicated from <evntrace.h> to fix link problems.
     49 DEFINE_GUID( /* 68fdd900-4a3e-11d1-84f4-0000f80464e3 */
     50     kEventTraceGuid,
     51     0x68fdd900,
     52     0x4a3e,
     53     0x11d1,
     54     0x84, 0xf4, 0x00, 0x00, 0xf8, 0x04, 0x64, 0xe3);
     55 
     56 class TestEventConsumer: public EtwTraceConsumerBase<TestEventConsumer> {
     57  public:
     58   TestEventConsumer() {
     59     EXPECT_TRUE(current_ == NULL);
     60     current_ = this;
     61   }
     62 
     63   ~TestEventConsumer() {
     64     EXPECT_TRUE(current_ == this);
     65     current_ = NULL;
     66   }
     67 
     68   MOCK_METHOD4(Event, void(REFGUID event_class,
     69                       EtwEventType event_type,
     70                       size_t buf_len,
     71                       const void* buf));
     72 
     73   static void ProcessEvent(EVENT_TRACE* event) {
     74     ASSERT_TRUE(current_ != NULL);
     75     current_->Event(event->Header.Guid,
     76                     event->Header.Class.Type,
     77                     event->MofLength,
     78                     event->MofData);
     79   }
     80 
     81  private:
     82   static TestEventConsumer* current_;
     83 };
     84 
     85 TestEventConsumer* TestEventConsumer::current_ = NULL;
     86 
     87 class TraceEventTest: public testing::Test {
     88  public:
     89   TraceEventTest() {
     90   }
     91 
     92   void SetUp() {
     93     bool is_xp = win::GetVersion() < base::win::VERSION_VISTA;
     94 
     95     if (is_xp) {
     96       // Tear down any dangling session from an earlier failing test.
     97       EtwTraceProperties ignore;
     98       EtwTraceController::Stop(kTestSessionName, &ignore);
     99     }
    100 
    101     // Resurrect and initialize the TraceLog singleton instance.
    102     // On Vista and better, we need the provider registered before we
    103     // start the private, in-proc session, but on XP we need the global
    104     // session created and the provider enabled before we register our
    105     // provider.
    106     TraceLog* tracelog = NULL;
    107     if (!is_xp) {
    108       TraceLog::Resurrect();
    109       tracelog = TraceLog::GetInstance();
    110       ASSERT_TRUE(tracelog != NULL);
    111       ASSERT_FALSE(tracelog->IsTracing());
    112     }
    113 
    114     // Create the log file.
    115     ASSERT_TRUE(file_util::CreateTemporaryFile(&log_file_));
    116 
    117     // Create a private log session on the file.
    118     EtwTraceProperties prop;
    119     ASSERT_HRESULT_SUCCEEDED(prop.SetLoggerFileName(log_file_.value().c_str()));
    120     EVENT_TRACE_PROPERTIES& p = *prop.get();
    121     p.Wnode.ClientContext = 1;  // QPC timer accuracy.
    122     p.LogFileMode = EVENT_TRACE_FILE_MODE_SEQUENTIAL;   // Sequential log.
    123 
    124     // On Vista and later, we create a private in-process log session, because
    125     // otherwise we'd need administrator privileges. Unfortunately we can't
    126     // do the same on XP and better, because the semantics of a private
    127     // logger session are different, and the IN_PROC flag is not supported.
    128     if (!is_xp) {
    129       p.LogFileMode |= EVENT_TRACE_PRIVATE_IN_PROC |  // In-proc for non-admin.
    130           EVENT_TRACE_PRIVATE_LOGGER_MODE;  // Process-private log.
    131     }
    132 
    133     p.MaximumFileSize = 100;  // 100M file size.
    134     p.FlushTimer = 1;  // 1 second flush lag.
    135     ASSERT_HRESULT_SUCCEEDED(controller_.Start(kTestSessionName, &prop));
    136 
    137     // Enable the TraceLog provider GUID.
    138     ASSERT_HRESULT_SUCCEEDED(
    139         controller_.EnableProvider(kChromeTraceProviderName,
    140                                    TRACE_LEVEL_INFORMATION,
    141                                    0));
    142 
    143     if (is_xp) {
    144       TraceLog::Resurrect();
    145       tracelog = TraceLog::GetInstance();
    146     }
    147     ASSERT_TRUE(tracelog != NULL);
    148     EXPECT_TRUE(tracelog->IsTracing());
    149   }
    150 
    151   void TearDown() {
    152     EtwTraceProperties prop;
    153     if (controller_.session() != 0)
    154       EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
    155 
    156     if (!log_file_.value().empty())
    157       file_util::Delete(log_file_, false);
    158   }
    159 
    160   void ExpectEvent(REFGUID guid,
    161                    EtwEventType type,
    162                    const char* name,
    163                    size_t name_len,
    164                    const void* id,
    165                    const char* extra,
    166                    size_t extra_len) {
    167     // Build the trace event buffer we expect will result from this.
    168     std::stringbuf str;
    169     str.sputn(name, name_len + 1);
    170     str.sputn(reinterpret_cast<const char*>(&id), sizeof(id));
    171     str.sputn(extra, extra_len + 1);
    172 
    173     // And set up the expectation for the event callback.
    174     EXPECT_CALL(consumer_, Event(guid,
    175                                  type,
    176                                  testing::Ge(str.str().length()),
    177                                  BufferStartsWith(str.str())));
    178   }
    179 
    180   void ExpectPlayLog() {
    181     // Ignore EventTraceGuid events.
    182     EXPECT_CALL(consumer_, Event(kEventTraceGuid, _, _, _))
    183         .Times(AnyNumber());
    184   }
    185 
    186   void PlayLog() {
    187     EtwTraceProperties prop;
    188     EXPECT_HRESULT_SUCCEEDED(controller_.Flush(&prop));
    189     EXPECT_HRESULT_SUCCEEDED(controller_.Stop(&prop));
    190     ASSERT_HRESULT_SUCCEEDED(
    191         consumer_.OpenFileSession(log_file_.value().c_str()));
    192 
    193     ASSERT_HRESULT_SUCCEEDED(consumer_.Consume());
    194   }
    195 
    196  private:
    197   // We want our singleton torn down after each test.
    198   ShadowingAtExitManager at_exit_manager_;
    199   EtwTraceController controller_;
    200   FilePath log_file_;
    201   TestEventConsumer consumer_;
    202 };
    203 
    204 }  // namespace
    205 
    206 
    207 TEST_F(TraceEventTest, TraceLog) {
    208   ExpectPlayLog();
    209 
    210   // The events should arrive in the same sequence as the expects.
    211   InSequence in_sequence;
    212 
    213   // Full argument version, passing lengths explicitly.
    214   TraceLog::Trace(kName,
    215                         strlen(kName),
    216                         TraceLog::EVENT_BEGIN,
    217                         kId,
    218                         kExtra,
    219                         strlen(kExtra));
    220 
    221   ExpectEvent(kTraceEventClass32,
    222               kTraceEventTypeBegin,
    223               kName, strlen(kName),
    224               kId,
    225               kExtra, strlen(kExtra));
    226 
    227   // Const char* version.
    228   TraceLog::Trace(static_cast<const char*>(kName),
    229                         TraceLog::EVENT_END,
    230                         kId,
    231                         static_cast<const char*>(kExtra));
    232 
    233   ExpectEvent(kTraceEventClass32,
    234               kTraceEventTypeEnd,
    235               kName, strlen(kName),
    236               kId,
    237               kExtra, strlen(kExtra));
    238 
    239   // std::string extra version.
    240   TraceLog::Trace(static_cast<const char*>(kName),
    241                         TraceLog::EVENT_INSTANT,
    242                         kId,
    243                         std::string(kExtra));
    244 
    245   ExpectEvent(kTraceEventClass32,
    246               kTraceEventTypeInstant,
    247               kName, strlen(kName),
    248               kId,
    249               kExtra, strlen(kExtra));
    250 
    251 
    252   // Test for sanity on NULL inputs.
    253   TraceLog::Trace(NULL,
    254                         0,
    255                         TraceLog::EVENT_BEGIN,
    256                         kId,
    257                         NULL,
    258                         0);
    259 
    260   ExpectEvent(kTraceEventClass32,
    261               kTraceEventTypeBegin,
    262               kEmpty, 0,
    263               kId,
    264               kEmpty, 0);
    265 
    266   TraceLog::Trace(NULL,
    267                         -1,
    268                         TraceLog::EVENT_END,
    269                         kId,
    270                         NULL,
    271                         -1);
    272 
    273   ExpectEvent(kTraceEventClass32,
    274               kTraceEventTypeEnd,
    275               kEmpty, 0,
    276               kId,
    277               kEmpty, 0);
    278 
    279   PlayLog();
    280 }
    281 
    282 TEST_F(TraceEventTest, Macros) {
    283   ExpectPlayLog();
    284 
    285   // The events should arrive in the same sequence as the expects.
    286   InSequence in_sequence;
    287 
    288   TRACE_EVENT_BEGIN(kName, kId, kExtra);
    289   ExpectEvent(kTraceEventClass32,
    290               kTraceEventTypeBegin,
    291               kName, strlen(kName),
    292               kId,
    293               kExtra, strlen(kExtra));
    294 
    295   TRACE_EVENT_END(kName, kId, kExtra);
    296   ExpectEvent(kTraceEventClass32,
    297               kTraceEventTypeEnd,
    298               kName, strlen(kName),
    299               kId,
    300               kExtra, strlen(kExtra));
    301 
    302   TRACE_EVENT_INSTANT(kName, kId, kExtra);
    303   ExpectEvent(kTraceEventClass32,
    304               kTraceEventTypeInstant,
    305               kName, strlen(kName),
    306               kId,
    307               kExtra, strlen(kExtra));
    308 
    309   PlayLog();
    310 }
    311 
    312 }  // namespace debug
    313 }  // namespace base
    314