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