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