extensions/browser/api/cast_channel/logger_unittest.cc

   1 // Copyright 2014 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 <string>
   6
   7 #include "base/test/simple_test_tick_clock.h"
   8 #include "extensions/browser/api/cast_channel/cast_auth_util.h"
   9 #include "extensions/browser/api/cast_channel/logger.h"
  10 #include "extensions/browser/api/cast_channel/logger_util.h"
  11 #include "net/base/net_errors.h"
  12 #include "testing/gtest/include/gtest/gtest.h"
  13 #include "third_party/zlib/zlib.h"
  14
  15 namespace extensions {
  16 namespace api {
  17 namespace cast_channel {
  18
  19 const int kTestNssErrorCode = -8164;
  20
  21 using proto::AggregatedSocketEvent;
  22 using proto::EventType;
  23 using proto::Log;
  24 using proto::SocketEvent;
  25
  26 class CastChannelLoggerTest : public testing::Test {
  27  public:
  28   // |logger_| will take ownership of |clock_|.
  29   CastChannelLoggerTest()
  30       : clock_(new base::SimpleTestTickClock),
  31         logger_(new Logger(scoped_ptr<base::TickClock>(clock_),
  32                            base::TimeTicks())) {}
  33   ~CastChannelLoggerTest() override {}
  34
  35   bool Uncompress(const char* input, int length, std::string* output) {
  36     z_stream stream = {0};
  37
  38     stream.next_in = reinterpret_cast<uint8*>(const_cast<char*>(input));
  39     stream.avail_in = length;
  40     stream.next_out = reinterpret_cast<uint8*>(&(*output)[0]);
  41     stream.avail_out = output->size();
  42
  43     bool success = false;
  44     while (stream.avail_in > 0 && stream.avail_out > 0) {
  45       // 16 is added to read in gzip format.
  46       int result = inflateInit2(&stream, MAX_WBITS + 16);
  47       DCHECK_EQ(Z_OK, result);
  48
  49       result = inflate(&stream, Z_FINISH);
  50       success = (result == Z_STREAM_END);
  51       if (!success) {
  52         DVLOG(2) << "inflate() failed. Result: " << result;
  53         break;
  54       }
  55
  56       result = inflateEnd(&stream);
  57       DCHECK(result == Z_OK);
  58     }
  59
  60     if (stream.avail_in == 0) {
  61       success = true;
  62       output->resize(output->size() - stream.avail_out);
  63     }
  64     return success;
  65   }
  66
  67   scoped_ptr<Log> GetLog() {
  68     size_t length = 0;
  69     scoped_ptr<char[]> output = logger_->GetLogs(&length);
  70     if (!output.get())
  71       return scoped_ptr<Log>();
  72
  73     // 20kb should be enough for test purposes.
  74     std::string uncompressed(20000, 0);
  75     if (!Uncompress(output.get(), length, &uncompressed))
  76       return scoped_ptr<Log>();
  77
  78     scoped_ptr<Log> log(new Log);
  79     if (!log->ParseFromString(uncompressed))
  80       return scoped_ptr<Log>();
  81
  82     return log.Pass();
  83   }
  84
  85  protected:
  86   base::SimpleTestTickClock* clock_;
  87   scoped_refptr<Logger> logger_;
  88 };
  89
  90 TEST_F(CastChannelLoggerTest, BasicLogging) {
  91   logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED);
  92   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
  93   logger_->LogSocketEventWithDetails(
  94       1, EventType::TCP_SOCKET_CONNECT, "TCP socket");
  95   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
  96   logger_->LogSocketEvent(2, EventType::CAST_SOCKET_CREATED);
  97   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
  98   logger_->LogSocketEventWithRv(1, EventType::SSL_SOCKET_CONNECT, -1);
  99   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 100   logger_->LogSocketEventForMessage(
 101       2, EventType::MESSAGE_ENQUEUED, "foo_namespace", "details");
 102   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 103
 104   AuthResult auth_result = AuthResult::CreateWithParseError(
 105       "No response", AuthResult::ERROR_NO_RESPONSE);
 106
 107   logger_->LogSocketChallengeReplyEvent(2, auth_result);
 108   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 109
 110   auth_result =
 111       AuthResult::CreateWithNSSError("Parsing failed",
 112                                      AuthResult::ERROR_CERT_PARSING_FAILED,
 113                                      kTestNssErrorCode);
 114   logger_->LogSocketChallengeReplyEvent(2, auth_result);
 115
 116   LastErrors last_errors = logger_->GetLastErrors(2);
 117   EXPECT_EQ(last_errors.event_type, proto::AUTH_CHALLENGE_REPLY);
 118   EXPECT_EQ(last_errors.net_return_value, net::OK);
 119   EXPECT_EQ(last_errors.challenge_reply_error_type,
 120             proto::CHALLENGE_REPLY_ERROR_CERT_PARSING_FAILED);
 121   EXPECT_EQ(last_errors.nss_error_code, kTestNssErrorCode);
 122
 123   scoped_ptr<Log> log = GetLog();
 124   ASSERT_TRUE(log);
 125
 126   ASSERT_EQ(2, log->aggregated_socket_event_size());
 127   {
 128     const AggregatedSocketEvent& aggregated_socket_event =
 129         log->aggregated_socket_event(0);
 130     EXPECT_EQ(1, aggregated_socket_event.id());
 131     EXPECT_EQ(3, aggregated_socket_event.socket_event_size());
 132     {
 133       const SocketEvent& event = aggregated_socket_event.socket_event(0);
 134       EXPECT_EQ(EventType::CAST_SOCKET_CREATED, event.type());
 135       EXPECT_EQ(0, event.timestamp_micros());
 136     }
 137     {
 138       const SocketEvent& event = aggregated_socket_event.socket_event(1);
 139       EXPECT_EQ(EventType::TCP_SOCKET_CONNECT, event.type());
 140       EXPECT_EQ(1, event.timestamp_micros());
 141       EXPECT_EQ("TCP socket", event.details());
 142     }
 143     {
 144       const SocketEvent& event = aggregated_socket_event.socket_event(2);
 145       EXPECT_EQ(EventType::SSL_SOCKET_CONNECT, event.type());
 146       EXPECT_EQ(3, event.timestamp_micros());
 147       EXPECT_EQ(-1, event.net_return_value());
 148     }
 149   }
 150   {
 151     const AggregatedSocketEvent& aggregated_socket_event =
 152         log->aggregated_socket_event(1);
 153     EXPECT_EQ(2, aggregated_socket_event.id());
 154     EXPECT_EQ(4, aggregated_socket_event.socket_event_size());
 155     {
 156       const SocketEvent& event = aggregated_socket_event.socket_event(0);
 157       EXPECT_EQ(EventType::CAST_SOCKET_CREATED, event.type());
 158       EXPECT_EQ(2, event.timestamp_micros());
 159     }
 160     {
 161       const SocketEvent& event = aggregated_socket_event.socket_event(1);
 162       EXPECT_EQ(EventType::MESSAGE_ENQUEUED, event.type());
 163       EXPECT_EQ(4, event.timestamp_micros());
 164       EXPECT_FALSE(event.has_message_namespace());
 165       EXPECT_EQ("details", event.details());
 166     }
 167     {
 168       const SocketEvent& event = aggregated_socket_event.socket_event(2);
 169       EXPECT_EQ(EventType::AUTH_CHALLENGE_REPLY, event.type());
 170       EXPECT_EQ(5, event.timestamp_micros());
 171       EXPECT_EQ(proto::CHALLENGE_REPLY_ERROR_NO_RESPONSE,
 172                 event.challenge_reply_error_type());
 173       EXPECT_FALSE(event.has_net_return_value());
 174       EXPECT_FALSE(event.has_nss_error_code());
 175     }
 176     {
 177       const SocketEvent& event = aggregated_socket_event.socket_event(3);
 178       EXPECT_EQ(EventType::AUTH_CHALLENGE_REPLY, event.type());
 179       EXPECT_EQ(6, event.timestamp_micros());
 180       EXPECT_EQ(proto::CHALLENGE_REPLY_ERROR_CERT_PARSING_FAILED,
 181                 event.challenge_reply_error_type());
 182       EXPECT_FALSE(event.has_net_return_value());
 183       EXPECT_EQ(kTestNssErrorCode, event.nss_error_code());
 184     }
 185   }
 186 }
 187
 188 TEST_F(CastChannelLoggerTest, LogLastErrorEvents) {
 189   // Net return value is set to an error
 190   logger_->LogSocketEventWithRv(
 191       1, EventType::TCP_SOCKET_CONNECT, net::ERR_CONNECTION_FAILED);
 192
 193   LastErrors last_errors = logger_->GetLastErrors(1);
 194   EXPECT_EQ(last_errors.event_type, proto::TCP_SOCKET_CONNECT);
 195   EXPECT_EQ(last_errors.net_return_value, net::ERR_CONNECTION_FAILED);
 196
 197   // Challenge reply error set
 198   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 199   AuthResult auth_result = AuthResult::CreateWithParseError(
 200       "Some error", AuthResult::ErrorType::ERROR_PEER_CERT_EMPTY);
 201
 202   logger_->LogSocketChallengeReplyEvent(2, auth_result);
 203   last_errors = logger_->GetLastErrors(2);
 204   EXPECT_EQ(last_errors.event_type, proto::AUTH_CHALLENGE_REPLY);
 205   EXPECT_EQ(last_errors.challenge_reply_error_type,
 206             proto::CHALLENGE_REPLY_ERROR_PEER_CERT_EMPTY);
 207
 208   // Logging a non-error event does not set the LastErrors for the channel.
 209   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 210   logger_->LogSocketEventWithRv(3, EventType::TCP_SOCKET_CONNECT, net::OK);
 211   last_errors = logger_->GetLastErrors(3);
 212   EXPECT_EQ(last_errors.event_type, proto::EVENT_TYPE_UNKNOWN);
 213   EXPECT_EQ(last_errors.net_return_value, net::OK);
 214   EXPECT_EQ(last_errors.challenge_reply_error_type,
 215             proto::CHALLENGE_REPLY_ERROR_NONE);
 216   EXPECT_EQ(last_errors.nss_error_code, 0);
 217
 218   // Now log a challenge reply error with NSS error code.  LastErrors will be
 219   // set.
 220   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 221   auth_result = AuthResult::CreateWithNSSError(
 222       "Some error",
 223       AuthResult::ErrorType::ERROR_WRONG_PAYLOAD_TYPE,
 224       kTestNssErrorCode);
 225   logger_->LogSocketChallengeReplyEvent(3, auth_result);
 226   last_errors = logger_->GetLastErrors(3);
 227   EXPECT_EQ(last_errors.event_type, proto::AUTH_CHALLENGE_REPLY);
 228   EXPECT_EQ(last_errors.challenge_reply_error_type,
 229             proto::CHALLENGE_REPLY_ERROR_WRONG_PAYLOAD_TYPE);
 230   EXPECT_EQ(last_errors.nss_error_code, kTestNssErrorCode);
 231
 232   // Logging a non-error event does not change the LastErrors for the channel.
 233   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 234   logger_->LogSocketEventWithRv(3, EventType::TCP_SOCKET_CONNECT, net::OK);
 235   last_errors = logger_->GetLastErrors(3);
 236   EXPECT_EQ(last_errors.event_type, proto::AUTH_CHALLENGE_REPLY);
 237   EXPECT_EQ(last_errors.challenge_reply_error_type,
 238             proto::CHALLENGE_REPLY_ERROR_WRONG_PAYLOAD_TYPE);
 239   EXPECT_EQ(last_errors.nss_error_code, kTestNssErrorCode);
 240 }
 241
 242 TEST_F(CastChannelLoggerTest, LogSocketReadWrite) {
 243   logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, 50);
 244   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 245   logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, 30);
 246   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 247   logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, -1);
 248   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 249   logger_->LogSocketEventWithRv(1, EventType::SOCKET_WRITE, 20);
 250   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 251
 252   logger_->LogSocketEventWithRv(2, EventType::SOCKET_READ, 100);
 253   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 254   logger_->LogSocketEventWithRv(2, EventType::SOCKET_WRITE, 100);
 255   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 256   logger_->LogSocketEventWithRv(2, EventType::SOCKET_WRITE, -5);
 257   clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 258
 259   scoped_ptr<Log> log = GetLog();
 260   ASSERT_TRUE(log);
 261
 262   ASSERT_EQ(2, log->aggregated_socket_event_size());
 263   {
 264     const AggregatedSocketEvent& aggregated_socket_event =
 265         log->aggregated_socket_event(0);
 266     EXPECT_EQ(1, aggregated_socket_event.id());
 267     EXPECT_EQ(4, aggregated_socket_event.socket_event_size());
 268     EXPECT_EQ(80, aggregated_socket_event.bytes_read());
 269     EXPECT_EQ(20, aggregated_socket_event.bytes_written());
 270   }
 271   {
 272     const AggregatedSocketEvent& aggregated_socket_event =
 273         log->aggregated_socket_event(1);
 274     EXPECT_EQ(2, aggregated_socket_event.id());
 275     EXPECT_EQ(3, aggregated_socket_event.socket_event_size());
 276     EXPECT_EQ(100, aggregated_socket_event.bytes_read());
 277     EXPECT_EQ(100, aggregated_socket_event.bytes_written());
 278   }
 279 }
 280
 281 TEST_F(CastChannelLoggerTest, TooManySockets) {
 282   for (int i = 0; i < kMaxSocketsToLog + 5; i++) {
 283     logger_->LogSocketEvent(i, EventType::CAST_SOCKET_CREATED);
 284   }
 285
 286   scoped_ptr<Log> log = GetLog();
 287   ASSERT_TRUE(log);
 288
 289   ASSERT_EQ(kMaxSocketsToLog, log->aggregated_socket_event_size());
 290   EXPECT_EQ(5, log->num_evicted_aggregated_socket_events());
 291   EXPECT_EQ(5, log->num_evicted_socket_events());
 292
 293   const AggregatedSocketEvent& aggregated_socket_event =
 294       log->aggregated_socket_event(0);
 295   EXPECT_EQ(5, aggregated_socket_event.id());
 296 }
 297
 298 TEST_F(CastChannelLoggerTest, TooManyEvents) {
 299   for (int i = 0; i < kMaxEventsPerSocket + 5; i++) {
 300     logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED);
 301     clock_->Advance(base::TimeDelta::FromMicroseconds(1));
 302   }
 303
 304   scoped_ptr<Log> log = GetLog();
 305   ASSERT_TRUE(log);
 306
 307   ASSERT_EQ(1, log->aggregated_socket_event_size());
 308   EXPECT_EQ(0, log->num_evicted_aggregated_socket_events());
 309   EXPECT_EQ(5, log->num_evicted_socket_events());
 310
 311   const AggregatedSocketEvent& aggregated_socket_event =
 312       log->aggregated_socket_event(0);
 313   ASSERT_EQ(kMaxEventsPerSocket, aggregated_socket_event.socket_event_size());
 314   EXPECT_EQ(5, aggregated_socket_event.socket_event(0).timestamp_micros());
 315 }
 316
 317 TEST_F(CastChannelLoggerTest, Reset) {
 318   logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED);
 319
 320   scoped_ptr<Log> log = GetLog();
 321   ASSERT_TRUE(log);
 322
 323   EXPECT_EQ(1, log->aggregated_socket_event_size());
 324
 325   logger_->Reset();
 326
 327   log = GetLog();
 328   ASSERT_TRUE(log);
 329
 330   EXPECT_EQ(0, log->aggregated_socket_event_size());
 331 }
 332
 333 }  // namespace cast_channel
 334 }  // namespace api
 335 }  // namespace extensions