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