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