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