extensions/browser/api/cast_channel/logger.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 "extensions/browser/api/cast_channel/logger.h"
   6
   7 #include <string>
   8
   9 #include "base/strings/string_util.h"
  10 #include "base/time/tick_clock.h"
  11 #include "extensions/browser/api/cast_channel/cast_auth_util.h"
  12 #include "extensions/browser/api/cast_channel/logger_util.h"
  13 #include "net/base/net_errors.h"
  14 #include "third_party/zlib/zlib.h"
  15
  16 namespace extensions {
  17 namespace core_api {
  18 namespace cast_channel {
  19
  20 using net::IPEndPoint;
  21 using proto::AggregatedSocketEvent;
  22 using proto::EventType;
  23 using proto::Log;
  24 using proto::SocketEvent;
  25
  26 namespace {
  27
  28 const char* kInternalNamespacePrefix = "com.google.cast";
  29
  30 proto::ChallengeReplyErrorType ChallegeReplyErrorToProto(
  31     AuthResult::ErrorType error_type) {
  32   switch (error_type) {
  33     case AuthResult::ERROR_NONE:
  34       return proto::CHALLENGE_REPLY_ERROR_NONE;
  35     case AuthResult::ERROR_PEER_CERT_EMPTY:
  36       return proto::CHALLENGE_REPLY_ERROR_PEER_CERT_EMPTY;
  37     case AuthResult::ERROR_WRONG_PAYLOAD_TYPE:
  38       return proto::CHALLENGE_REPLY_ERROR_WRONG_PAYLOAD_TYPE;
  39     case AuthResult::ERROR_NO_PAYLOAD:
  40       return proto::CHALLENGE_REPLY_ERROR_NO_PAYLOAD;
  41     case AuthResult::ERROR_PAYLOAD_PARSING_FAILED:
  42       return proto::CHALLENGE_REPLY_ERROR_PAYLOAD_PARSING_FAILED;
  43     case AuthResult::ERROR_MESSAGE_ERROR:
  44       return proto::CHALLENGE_REPLY_ERROR_MESSAGE_ERROR;
  45     case AuthResult::ERROR_NO_RESPONSE:
  46       return proto::CHALLENGE_REPLY_ERROR_NO_RESPONSE;
  47     case AuthResult::ERROR_FINGERPRINT_NOT_FOUND:
  48       return proto::CHALLENGE_REPLY_ERROR_FINGERPRINT_NOT_FOUND;
  49     case AuthResult::ERROR_NSS_CERT_PARSING_FAILED:
  50       return proto::CHALLENGE_REPLY_ERROR_NSS_CERT_PARSING_FAILED;
  51     case AuthResult::ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA:
  52       return proto::CHALLENGE_REPLY_ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA;
  53     case AuthResult::ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY:
  54       return proto::CHALLENGE_REPLY_ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY;
  55     case AuthResult::ERROR_NSS_SIGNED_BLOBS_MISMATCH:
  56       return proto::CHALLENGE_REPLY_ERROR_NSS_SIGNED_BLOBS_MISMATCH;
  57     default:
  58       NOTREACHED();
  59       return proto::CHALLENGE_REPLY_ERROR_NONE;
  60   }
  61 }
  62
  63 scoped_ptr<char[]> Compress(const std::string& input, size_t* length) {
  64   *length = 0;
  65   z_stream stream = {0};
  66   int result = deflateInit2(&stream,
  67                             Z_DEFAULT_COMPRESSION,
  68                             Z_DEFLATED,
  69                             // 16 is added to produce a gzip header + trailer.
  70                             MAX_WBITS + 16,
  71                             8,  // memLevel = 8 is default.
  72                             Z_DEFAULT_STRATEGY);
  73   DCHECK_EQ(Z_OK, result);
  74
  75   size_t out_size = deflateBound(&stream, input.size());
  76   scoped_ptr<char[]> out(new char[out_size]);
  77
  78   COMPILE_ASSERT(sizeof(uint8) == sizeof(char), uint8_char_different_sizes);
  79
  80   stream.next_in = reinterpret_cast<uint8*>(const_cast<char*>(input.data()));
  81   stream.avail_in = input.size();
  82   stream.next_out = reinterpret_cast<uint8*>(out.get());
  83   stream.avail_out = out_size;
  84
  85   // Do a one-shot compression. This will return Z_STREAM_END only if |output|
  86   // is large enough to hold all compressed data.
  87   result = deflate(&stream, Z_FINISH);
  88
  89   bool success = (result == Z_STREAM_END);
  90
  91   if (!success)
  92     VLOG(2) << "deflate() failed. Result: " << result;
  93
  94   result = deflateEnd(&stream);
  95   DCHECK(result == Z_OK || result == Z_DATA_ERROR);
  96
  97   if (success)
  98     *length = out_size - stream.avail_out;
  99
 100   return out.Pass();
 101 }
 102
 103 // Propagate any error fields set in |event| to |last_errors|.  If any error
 104 // field in |event| is set, then also set |last_errors->event_type|.
 105 void MaybeSetLastErrors(const SocketEvent& event, LastErrors* last_errors) {
 106   if (event.has_net_return_value() &&
 107       event.net_return_value() < net::ERR_IO_PENDING) {
 108     last_errors->net_return_value = event.net_return_value();
 109     last_errors->event_type = event.type();
 110   }
 111   if (event.has_challenge_reply_error_type()) {
 112     last_errors->challenge_reply_error_type =
 113         event.challenge_reply_error_type();
 114     last_errors->event_type = event.type();
 115   }
 116   if (event.has_nss_error_code()) {
 117     last_errors->nss_error_code = event.nss_error_code();
 118     last_errors->event_type = event.type();
 119   }
 120 }
 121
 122 }  // namespace
 123
 124 Logger::AggregatedSocketEventLog::AggregatedSocketEventLog() {
 125 }
 126
 127 Logger::AggregatedSocketEventLog::~AggregatedSocketEventLog() {
 128 }
 129
 130 Logger::Logger(scoped_ptr<base::TickClock> clock,
 131                base::TimeTicks unix_epoch_time_ticks)
 132     : clock_(clock.Pass()), unix_epoch_time_ticks_(unix_epoch_time_ticks) {
 133   DCHECK(clock_);
 134
 135   // Logger may not be necessarily be created on the IO thread, but logging
 136   // happens exclusively there.
 137   thread_checker_.DetachFromThread();
 138 }
 139
 140 Logger::~Logger() {
 141 }
 142
 143 void Logger::LogNewSocketEvent(const CastSocket& cast_socket) {
 144   DCHECK(thread_checker_.CalledOnValidThread());
 145
 146   int channel_id = cast_socket.id();
 147   SocketEvent event = CreateEvent(proto::CAST_SOCKET_CREATED);
 148   AggregatedSocketEvent& aggregated_socket_event =
 149       LogSocketEvent(channel_id, event);
 150
 151   const net::IPAddressNumber& ip = cast_socket.ip_endpoint().address();
 152   aggregated_socket_event.set_endpoint_id(ip.back());
 153   aggregated_socket_event.set_channel_auth_type(cast_socket.channel_auth() ==
 154                                                         CHANNEL_AUTH_TYPE_SSL
 155                                                     ? proto::SSL
 156                                                     : proto::SSL_VERIFIED);
 157 }
 158
 159 void Logger::LogSocketEvent(int channel_id, EventType event_type) {
 160   DCHECK(thread_checker_.CalledOnValidThread());
 161
 162   LogSocketEventWithDetails(channel_id, event_type, std::string());
 163 }
 164
 165 void Logger::LogSocketEventWithDetails(int channel_id,
 166                                        EventType event_type,
 167                                        const std::string& details) {
 168   DCHECK(thread_checker_.CalledOnValidThread());
 169
 170   SocketEvent event = CreateEvent(event_type);
 171   if (!details.empty())
 172     event.set_details(details);
 173
 174   LogSocketEvent(channel_id, event);
 175 }
 176
 177 void Logger::LogSocketEventWithRv(int channel_id,
 178                                   EventType event_type,
 179                                   int rv) {
 180   DCHECK(thread_checker_.CalledOnValidThread());
 181
 182   SocketEvent event = CreateEvent(event_type);
 183   event.set_net_return_value(rv);
 184
 185   AggregatedSocketEvent& aggregated_socket_event =
 186       LogSocketEvent(channel_id, event);
 187
 188   if ((event_type == proto::SOCKET_READ || event_type == proto::SOCKET_WRITE) &&
 189       rv > 0) {
 190     if (event_type == proto::SOCKET_READ) {
 191       aggregated_socket_event.set_bytes_read(
 192           aggregated_socket_event.bytes_read() + rv);
 193     } else {
 194       aggregated_socket_event.set_bytes_written(
 195           aggregated_socket_event.bytes_written() + rv);
 196     }
 197   }
 198 }
 199
 200 void Logger::LogSocketReadyState(int channel_id, proto::ReadyState new_state) {
 201   DCHECK(thread_checker_.CalledOnValidThread());
 202
 203   SocketEvent event = CreateEvent(proto::READY_STATE_CHANGED);
 204   event.set_ready_state(new_state);
 205
 206   LogSocketEvent(channel_id, event);
 207 }
 208
 209 void Logger::LogSocketConnectState(int channel_id,
 210                                    proto::ConnectionState new_state) {
 211   DCHECK(thread_checker_.CalledOnValidThread());
 212
 213   SocketEvent event = CreateEvent(proto::CONNECTION_STATE_CHANGED);
 214   event.set_connection_state(new_state);
 215
 216   LogSocketEvent(channel_id, event);
 217 }
 218
 219 void Logger::LogSocketReadState(int channel_id, proto::ReadState new_state) {
 220   DCHECK(thread_checker_.CalledOnValidThread());
 221
 222   SocketEvent event = CreateEvent(proto::READ_STATE_CHANGED);
 223   event.set_read_state(new_state);
 224
 225   LogSocketEvent(channel_id, event);
 226 }
 227
 228 void Logger::LogSocketWriteState(int channel_id, proto::WriteState new_state) {
 229   DCHECK(thread_checker_.CalledOnValidThread());
 230
 231   SocketEvent event = CreateEvent(proto::WRITE_STATE_CHANGED);
 232   event.set_write_state(new_state);
 233
 234   LogSocketEvent(channel_id, event);
 235 }
 236
 237 void Logger::LogSocketErrorState(int channel_id, proto::ErrorState new_state) {
 238   DCHECK(thread_checker_.CalledOnValidThread());
 239
 240   SocketEvent event = CreateEvent(proto::ERROR_STATE_CHANGED);
 241   event.set_error_state(new_state);
 242
 243   LogSocketEvent(channel_id, event);
 244 }
 245
 246 void Logger::LogSocketEventForMessage(int channel_id,
 247                                       EventType event_type,
 248                                       const std::string& message_namespace,
 249                                       const std::string& details) {
 250   DCHECK(thread_checker_.CalledOnValidThread());
 251
 252   SocketEvent event = CreateEvent(event_type);
 253   if (StartsWithASCII(message_namespace, kInternalNamespacePrefix, false))
 254     event.set_message_namespace(message_namespace);
 255   event.set_details(details);
 256
 257   LogSocketEvent(channel_id, event);
 258 }
 259
 260 void Logger::LogSocketChallengeReplyEvent(int channel_id,
 261                                           const AuthResult& auth_result) {
 262   DCHECK(thread_checker_.CalledOnValidThread());
 263
 264   SocketEvent event = CreateEvent(proto::AUTH_CHALLENGE_REPLY);
 265   event.set_challenge_reply_error_type(
 266       ChallegeReplyErrorToProto(auth_result.error_type));
 267   if (auth_result.nss_error_code != 0)
 268     event.set_nss_error_code(auth_result.nss_error_code);
 269
 270   LogSocketEvent(channel_id, event);
 271 }
 272
 273 SocketEvent Logger::CreateEvent(EventType event_type) {
 274   SocketEvent event;
 275   event.set_type(event_type);
 276   event.set_timestamp_micros(clock_->NowTicks().ToInternalValue() -
 277                              unix_epoch_time_ticks_.ToInternalValue());
 278   return event;
 279 }
 280
 281 AggregatedSocketEvent& Logger::LogSocketEvent(int channel_id,
 282                                               const SocketEvent& socket_event) {
 283   AggregatedSocketEventLogMap::iterator it =
 284       aggregated_socket_events_.find(channel_id);
 285   if (it == aggregated_socket_events_.end()) {
 286     if (aggregated_socket_events_.size() >= kMaxSocketsToLog) {
 287       AggregatedSocketEventLogMap::iterator erase_it =
 288           aggregated_socket_events_.begin();
 289
 290       log_.set_num_evicted_aggregated_socket_events(
 291           log_.num_evicted_aggregated_socket_events() + 1);
 292       log_.set_num_evicted_socket_events(
 293           log_.num_evicted_socket_events() +
 294           erase_it->second->socket_events.size());
 295
 296       aggregated_socket_events_.erase(erase_it);
 297     }
 298
 299     it = aggregated_socket_events_
 300              .insert(std::make_pair(
 301                  channel_id, make_linked_ptr(new AggregatedSocketEventLog)))
 302              .first;
 303     it->second->aggregated_socket_event.set_id(channel_id);
 304   }
 305
 306   std::deque<proto::SocketEvent>& socket_events = it->second->socket_events;
 307   if (socket_events.size() >= kMaxEventsPerSocket) {
 308     socket_events.pop_front();
 309     log_.set_num_evicted_socket_events(log_.num_evicted_socket_events() + 1);
 310   }
 311   socket_events.push_back(socket_event);
 312
 313   MaybeSetLastErrors(socket_event, &(it->second->last_errors));
 314
 315   return it->second->aggregated_socket_event;
 316 }
 317
 318 scoped_ptr<char[]> Logger::GetLogs(size_t* length) const {
 319   *length = 0;
 320
 321   Log log;
 322   // Copy "global" values from |log_|. Don't use |log_| directly since this
 323   // function is const.
 324   log.CopyFrom(log_);
 325
 326   for (AggregatedSocketEventLogMap::const_iterator it =
 327            aggregated_socket_events_.begin();
 328        it != aggregated_socket_events_.end();
 329        ++it) {
 330     AggregatedSocketEvent* new_aggregated_socket_event =
 331         log.add_aggregated_socket_event();
 332     new_aggregated_socket_event->CopyFrom(it->second->aggregated_socket_event);
 333
 334     const std::deque<SocketEvent>& socket_events = it->second->socket_events;
 335     for (std::deque<SocketEvent>::const_iterator socket_event_it =
 336              socket_events.begin();
 337          socket_event_it != socket_events.end();
 338          ++socket_event_it) {
 339       SocketEvent* socket_event =
 340           new_aggregated_socket_event->add_socket_event();
 341       socket_event->CopyFrom(*socket_event_it);
 342     }
 343   }
 344
 345   std::string serialized;
 346   if (!log.SerializeToString(&serialized)) {
 347     VLOG(2) << "Failed to serialized proto to string.";
 348     return scoped_ptr<char[]>();
 349   }
 350
 351   return Compress(serialized, length);
 352 }
 353
 354 void Logger::Reset() {
 355   aggregated_socket_events_.clear();
 356   log_.Clear();
 357 }
 358
 359 LastErrors Logger::GetLastErrors(int channel_id) const {
 360   AggregatedSocketEventLogMap::const_iterator it =
 361       aggregated_socket_events_.find(channel_id);
 362   if (it != aggregated_socket_events_.end()) {
 363     return it->second->last_errors;
 364   } else {
 365     return LastErrors();
 366   }
 367 }
 368
 369 }  // namespace cast_channel
 370 }  // namespace core_api
 371 }  // namespace extensions