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
