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