diff options
author | imcheng@chromium.org <imcheng@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-08-10 01:22:23 +0000 |
---|---|---|
committer | imcheng@chromium.org <imcheng@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-08-10 01:24:04 +0000 |
commit | ec2cbc3974c9a4dc8a8fbab25fb304efaaab4c75 (patch) | |
tree | fb2924f4c37b7940cb6fec60d30501276b63cfd3 /extensions/browser | |
parent | f09f968f9f0ba892cadca8574a382c41d4a979f9 (diff) | |
download | chromium_src-ec2cbc3974c9a4dc8a8fbab25fb304efaaab4c75.zip chromium_src-ec2cbc3974c9a4dc8a8fbab25fb304efaaab4c75.tar.gz chromium_src-ec2cbc3974c9a4dc8a8fbab25fb304efaaab4c75.tar.bz2 |
Cast channel: Add logging to the cast channel API / cast sockets.
The logging system in cast channel API records:
- lifetime of individual sockets created / closed
- error codes from underlying socket / crypto operations
- timeline view of cast socket's connection flow / read/write loop by
defining and logging individual events for sockets
Future patch will include overall statistics (e.g. # message / bytes).
The logging system provides a single function GetLog() that will
return a serialized version of the log. The log is in protocol buffer
format.
A couple of minor behavior changes:
- Refactored the reset/state change logic in Close() into a DoClose() helper function. Make sure CloseWithError() also calls DoClose().
- If DoReadCallback() encounters error, change error_state_ so that it gets propagated back to delete_->OnError().
TODO: add cast channel API so that logs can be exported to extension.
BUG=343228
Review URL: https://codereview.chromium.org/429443002
Cr-Commit-Position: refs/heads/master@{#288604}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@288604 0039d316-1c4b-4281-b951-d872f2087c98
Diffstat (limited to 'extensions/browser')
-rw-r--r-- | extensions/browser/api/cast_channel/BUILD.gn | 5 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_auth_util.cc | 40 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_auth_util.h | 43 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_auth_util_nss.cc | 106 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_auth_util_openssl.cc | 6 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_channel_api.cc | 26 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_channel_api.h | 15 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_channel_apitest.cc | 19 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_socket.cc | 385 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_socket.h | 82 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/cast_socket_unittest.cc | 40 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/logger.cc | 277 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/logger.h | 132 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/logger_unittest.cc | 196 | ||||
-rw-r--r-- | extensions/browser/api/cast_channel/logging.proto | 147 |
15 files changed, 1352 insertions, 167 deletions
diff --git a/extensions/browser/api/cast_channel/BUILD.gn b/extensions/browser/api/cast_channel/BUILD.gn index e5a46da..8a8dc36 100644 --- a/extensions/browser/api/cast_channel/BUILD.gn +++ b/extensions/browser/api/cast_channel/BUILD.gn @@ -6,5 +6,8 @@ import("//third_party/protobuf/proto_library.gni") # GYP version: extensions/extensions.gyp:cast_channel_proto proto_library("cast_channel_proto") { - sources = [ "cast_channel.proto" ] + sources = [ + "cast_channel.proto", + "logging.proto", + ] } diff --git a/extensions/browser/api/cast_channel/cast_auth_util.cc b/extensions/browser/api/cast_channel/cast_auth_util.cc new file mode 100644 index 0000000..767ef48 --- /dev/null +++ b/extensions/browser/api/cast_channel/cast_auth_util.cc @@ -0,0 +1,40 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "extensions/browser/api/cast_channel/cast_auth_util.h" + +namespace extensions { +namespace core_api { +namespace cast_channel { + +AuthResult::AuthResult() : error_type(ERROR_NONE), nss_error_code(0) { +} + +AuthResult::~AuthResult() { +} + +// static +AuthResult AuthResult::Create(const std::string& error_message, + ErrorType error_type) { + return AuthResult(error_message, error_type, 0); +} + +// static +AuthResult AuthResult::CreateWithNSSError(const std::string& error_message, + ErrorType error_type, + int nss_error_code) { + return AuthResult(error_message, error_type, nss_error_code); +} + +AuthResult::AuthResult(const std::string& error_message, + ErrorType error_type, + int nss_error_code) + : error_message(error_message), + error_type(error_type), + nss_error_code(nss_error_code) { +} + +} // namespace cast_channel +} // namespace core_api +} // namespace extensions diff --git a/extensions/browser/api/cast_channel/cast_auth_util.h b/extensions/browser/api/cast_channel/cast_auth_util.h index 9fac2f4..560f698 100644 --- a/extensions/browser/api/cast_channel/cast_auth_util.h +++ b/extensions/browser/api/cast_channel/cast_auth_util.h @@ -13,11 +13,50 @@ namespace cast_channel { class CastMessage; +struct AuthResult { + public: + enum ErrorType { + ERROR_NONE, + ERROR_PEER_CERT_EMPTY, + ERROR_WRONG_PAYLOAD_TYPE, + ERROR_NO_PAYLOAD, + ERROR_PAYLOAD_PARSING_FAILED, + ERROR_MESSAGE_ERROR, + ERROR_NO_RESPONSE, + ERROR_FINGERPRINT_NOT_FOUND, + ERROR_NSS_CERT_PARSING_FAILED, + ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA, + ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY, + ERROR_NSS_SIGNED_BLOBS_MISMATCH + }; + + // Constructs a AuthResult that corresponds to success. + AuthResult(); + ~AuthResult(); + + static AuthResult Create(const std::string& error_message, + ErrorType error_type); + static AuthResult CreateWithNSSError(const std::string& error_message, + ErrorType error_type, + int nss_error_code); + + bool success() const { return error_type == ERROR_NONE; } + + std::string error_message; + ErrorType error_type; + int nss_error_code; + + private: + AuthResult(const std::string& error_message, + ErrorType error_type, + int nss_error_code); +}; + // Authenticates the given |challenge_reply|: // 1. Signature contained in the reply is valid. // 2. Certficate used to sign is rooted to a trusted CA. -bool AuthenticateChallengeReply(const CastMessage& challenge_reply, - const std::string& peer_cert); +AuthResult AuthenticateChallengeReply(const CastMessage& challenge_reply, + const std::string& peer_cert); } // namespace cast_channel } // namespace core_api diff --git a/extensions/browser/api/cast_channel/cast_auth_util_nss.cc b/extensions/browser/api/cast_channel/cast_auth_util_nss.cc index 9937286..34d2ab2 100644 --- a/extensions/browser/api/cast_channel/cast_auth_util_nss.cc +++ b/extensions/browser/api/cast_channel/cast_auth_util_nss.cc @@ -11,6 +11,7 @@ #include <string> #include "base/logging.h" +#include "base/strings/stringprintf.h" #include "crypto/nss_util.h" #include "crypto/scoped_nss_types.h" #include "extensions/browser/api/cast_channel/cast_channel.pb.h" @@ -187,37 +188,49 @@ static int GetICAWithFingerprint(const net::SHA1HashValue& fingerprint) { } // Parses out DeviceAuthMessage from CastMessage -static bool ParseAuthMessage(const CastMessage& challenge_reply, - DeviceAuthMessage* auth_message) { +static AuthResult ParseAuthMessage(const CastMessage& challenge_reply, + DeviceAuthMessage* auth_message) { + const std::string kErrorPrefix("Failed to parse auth message: "); if (challenge_reply.payload_type() != CastMessage_PayloadType_BINARY) { - VLOG(1) << "Wrong payload type in challenge reply"; - return false; + return AuthResult::Create( + kErrorPrefix + "Wrong payload type in challenge reply", + AuthResult::ERROR_WRONG_PAYLOAD_TYPE); } if (!challenge_reply.has_payload_binary()) { - VLOG(1) << "Payload type is binary but payload_binary field not set"; - return false; + return AuthResult::Create( + kErrorPrefix + + "Payload type is binary but payload_binary field not set", + AuthResult::ERROR_NO_PAYLOAD); } if (!auth_message->ParseFromString(challenge_reply.payload_binary())) { - VLOG(1) << "Cannot parse binary payload into DeviceAuthMessage"; - return false; + return AuthResult::Create( + kErrorPrefix + "Cannot parse binary payload into DeviceAuthMessage", + AuthResult::ERROR_PAYLOAD_PARSING_FAILED); } + VLOG(1) << "Auth message: " << AuthMessageToString(*auth_message); + if (auth_message->has_error()) { - VLOG(1) << "Auth message error: " << auth_message->error().error_type(); - return false; + std::string error_format_str = kErrorPrefix + "Auth message error: %d"; + return AuthResult::Create( + base::StringPrintf(error_format_str.c_str(), + auth_message->error().error_type()), + AuthResult::ERROR_MESSAGE_ERROR); } if (!auth_message->has_response()) { - VLOG(1) << "Auth message has no response field"; - return false; + return AuthResult::Create( + kErrorPrefix + "Auth message has no response field", + AuthResult::ERROR_NO_RESPONSE); } - return true; + return AuthResult(); } // Authenticates the given credentials: // 1. |signature| verification of |data| using |certificate|. // 2. |certificate| is signed by a trusted CA. -bool VerifyCredentials(const AuthResponse& response, - const std::string& data) { +AuthResult VerifyCredentials(const AuthResponse& response, + const std::string& data) { + const std::string kErrorPrefix("Failed to verify credentials: "); const std::string& certificate = response.client_auth_certificate(); const std::string& signature = response.signature(); @@ -228,7 +241,9 @@ bool VerifyCredentials(const AuthResponse& response, // Otherwise, use the first intermediate in the list as long as it // is in the allowed list of intermediates. int num_intermediates = response.intermediate_certificate_size(); + VLOG(1) << "Response has " << num_intermediates << " intermediates"; + if (num_intermediates <= 0) { trusted_ca_key_der = &kAllowedICAs[0].public_key; } else { @@ -237,8 +252,8 @@ bool VerifyCredentials(const AuthResponse& response, = net::X509Certificate::CreateFromBytes(ica.data(), ica.length()); int index = GetICAWithFingerprint(ica_cert->fingerprint()); if (index == -1) { - VLOG(1) << "Disallowed intermdiate cert"; - return false; + return AuthResult::Create(kErrorPrefix + "Disallowed intermediate cert", + AuthResult::ERROR_FINGERPRINT_NOT_FOUND); } trusted_ca_key_der = &kAllowedICAs[index].public_key; } @@ -255,8 +270,10 @@ bool VerifyCredentials(const AuthResponse& response, ScopedCERTCertificate cert(CERT_NewTempCertificate( CERT_GetDefaultCertDB(), &der_cert, NULL, PR_FALSE, PR_TRUE)); if (!cert.get()) { - VLOG(1) << "Failed to parse certificate."; - return false; + return AuthResult::CreateWithNSSError( + kErrorPrefix + "Failed to parse certificate.", + AuthResult::ERROR_NSS_CERT_PARSING_FAILED, + PORT_GetError()); } // Check that the certificate is signed by trusted CA. @@ -269,16 +286,21 @@ bool VerifyCredentials(const AuthResponse& response, SECStatus verified = CERT_VerifySignedDataWithPublicKey( &cert->signatureWrap, ca_public_key.get(), NULL); if (verified != SECSuccess) { - VLOG(1)<< "Cert not signed by trusted CA"; - return false; + return AuthResult::CreateWithNSSError( + kErrorPrefix + "Cert not signed by trusted CA", + AuthResult::ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA, + PORT_GetError()); } + VLOG(1) << "Cert signed by trusted CA"; // Verify that the |signature| matches |data|. crypto::ScopedSECKEYPublicKey public_key(CERT_ExtractPublicKey(cert.get())); if (!public_key.get()) { - VLOG(1) << "Unable to extract public key from certificate."; - return false; + return AuthResult::CreateWithNSSError( + kErrorPrefix + "Unable to extract public key from certificate", + AuthResult::ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY, + PORT_GetError()); } SECItem signature_item; signature_item.type = siBuffer; @@ -294,27 +316,45 @@ bool VerifyCredentials(const AuthResponse& response, SEC_OID_SHA1, NULL, NULL); if (verified != SECSuccess) { - VLOG(1) << "Signed blobs did not match."; - return false; + return AuthResult::CreateWithNSSError( + kErrorPrefix + "Signed blobs did not match", + AuthResult::ERROR_NSS_SIGNED_BLOBS_MISMATCH, + PORT_GetError()); } + VLOG(1) << "Signature verification succeeded"; - return true; + + return AuthResult(); } } // namespace -bool AuthenticateChallengeReply(const CastMessage& challenge_reply, - const std::string& peer_cert) { - if (peer_cert.empty()) - return false; +AuthResult AuthenticateChallengeReply(const CastMessage& challenge_reply, + const std::string& peer_cert) { + if (peer_cert.empty()) { + AuthResult result = AuthResult::Create("Peer cert was empty.", + AuthResult::ERROR_PEER_CERT_EMPTY); + VLOG(1) << result.error_message; + return result; + } VLOG(1) << "Challenge reply: " << CastMessageToString(challenge_reply); DeviceAuthMessage auth_message; - if (!ParseAuthMessage(challenge_reply, &auth_message)) - return false; + AuthResult result = ParseAuthMessage(challenge_reply, &auth_message); + if (!result.success()) { + VLOG(1) << result.error_message; + return result; + } const AuthResponse& response = auth_message.response(); - return VerifyCredentials(response, peer_cert); + result = VerifyCredentials(response, peer_cert); + if (!result.success()) { + VLOG(1) << result.error_message + << ", NSS error code: " << result.nss_error_code; + return result; + } + + return AuthResult(); } } // namespace cast_channel diff --git a/extensions/browser/api/cast_channel/cast_auth_util_openssl.cc b/extensions/browser/api/cast_channel/cast_auth_util_openssl.cc index 04795ca..3ebceed 100644 --- a/extensions/browser/api/cast_channel/cast_auth_util_openssl.cc +++ b/extensions/browser/api/cast_channel/cast_auth_util_openssl.cc @@ -10,10 +10,10 @@ namespace extensions { namespace core_api { namespace cast_channel { -bool AuthenticateChallengeReply(const CastMessage& challenge_reply, - const std::string& peer_cert) { +AuthResult AuthenticateChallengeReply(const CastMessage& challenge_reply, + const std::string& peer_cert) { NOTREACHED(); - return false; + return AuthResult(); } } // namespace cast_channel diff --git a/extensions/browser/api/cast_channel/cast_channel_api.cc b/extensions/browser/api/cast_channel/cast_channel_api.cc index bf71053..e992a49 100644 --- a/extensions/browser/api/cast_channel/cast_channel_api.cc +++ b/extensions/browser/api/cast_channel/cast_channel_api.cc @@ -10,9 +10,12 @@ #include "base/json/json_writer.h" #include "base/memory/scoped_ptr.h" #include "base/strings/string_number_conversions.h" +#include "base/time/default_tick_clock.h" #include "base/values.h" #include "content/public/browser/browser_thread.h" #include "extensions/browser/api/cast_channel/cast_socket.h" +#include "extensions/browser/api/cast_channel/logger.h" +#include "extensions/browser/api/cast_channel/logging.pb.h" #include "extensions/browser/event_router.h" #include "net/base/ip_endpoint.h" #include "net/base/net_errors.h" @@ -35,6 +38,7 @@ using cast_channel::ChannelAuthType; using cast_channel::ChannelError; using cast_channel::ChannelInfo; using cast_channel::ConnectInfo; +using cast_channel::Logger; using cast_channel::MessageInfo; using cast_channel::ReadyState; using content::BrowserThread; @@ -81,7 +85,10 @@ bool IsValidConnectInfoIpAddress(const ConnectInfo& connect_info) { } // namespace CastChannelAPI::CastChannelAPI(content::BrowserContext* context) - : browser_context_(context) { + : browser_context_(context), + logger_( + new Logger(scoped_ptr<base::TickClock>(new base::DefaultTickClock), + base::TimeTicks::UnixEpoch())) { DCHECK(browser_context_); } @@ -90,6 +97,10 @@ CastChannelAPI* CastChannelAPI::Get(content::BrowserContext* context) { return BrowserContextKeyedAPIFactory<CastChannelAPI>::Get(context); } +scoped_refptr<Logger> CastChannelAPI::GetLogger() { + return logger_; +} + static base::LazyInstance<BrowserContextKeyedAPIFactory<CastChannelAPI> > g_factory = LAZY_INSTANCE_INITIALIZER; @@ -106,9 +117,13 @@ scoped_ptr<CastSocket> CastChannelAPI::CreateCastSocket( return socket_for_test_.Pass(); } else { return scoped_ptr<CastSocket>( - new CastSocket(extension_id, ip_endpoint, channel_auth, this, + new CastSocket(extension_id, + ip_endpoint, + channel_auth, + this, ExtensionsBrowserClient::Get()->GetNetLog(), - timeout)); + timeout, + logger_)); } } @@ -335,8 +350,9 @@ void CastChannelOpenFunction::AsyncWorkStart() { ? *connect_info_->timeout : kDefaultConnectTimeoutMillis)); new_channel_id_ = AddSocket(socket.release()); - GetSocket(new_channel_id_)->Connect( - base::Bind(&CastChannelOpenFunction::OnOpen, this)); + CastSocket* new_socket = GetSocket(new_channel_id_); + api_->GetLogger()->LogNewSocketEvent(*new_socket); + new_socket->Connect(base::Bind(&CastChannelOpenFunction::OnOpen, this)); } void CastChannelOpenFunction::OnOpen(int result) { diff --git a/extensions/browser/api/cast_channel/cast_channel_api.h b/extensions/browser/api/cast_channel/cast_channel_api.h index 3e07711..4abeff3 100644 --- a/extensions/browser/api/cast_channel/cast_channel_api.h +++ b/extensions/browser/api/cast_channel/cast_channel_api.h @@ -8,6 +8,7 @@ #include <string> #include "base/basictypes.h" +#include "base/memory/ref_counted.h" #include "base/memory/scoped_ptr.h" #include "base/threading/thread_checker.h" #include "extensions/browser/api/api_resource_manager.h" @@ -29,6 +30,12 @@ class IPEndPoint; namespace extensions { +namespace core_api { +namespace cast_channel { +class Logger; +} // namespace cast_channel +} // namespace core_api + namespace cast_channel = core_api::cast_channel; class CastChannelAPI : public BrowserContextKeyedAPI, @@ -49,6 +56,13 @@ class CastChannelAPI : public BrowserContextKeyedAPI, cast_channel::ChannelAuthType channel_auth, const base::TimeDelta& timeout); + // Returns a pointer to the Logger member variable. + // TODO(imcheng): Consider whether it is possible for this class to own the + // CastSockets and make this class the sole owner of Logger. Alternatively, + // consider making Logger not ref-counted by passing a weak + // reference of Logger to the CastSockets instead. + scoped_refptr<cast_channel::Logger> GetLogger(); + // Sets the CastSocket instance to be returned by CreateCastSocket for // testing. void SetSocketForTest(scoped_ptr<cast_channel::CastSocket> socket_for_test); @@ -69,6 +83,7 @@ class CastChannelAPI : public BrowserContextKeyedAPI, static const char* service_name() { return "CastChannelAPI"; } content::BrowserContext* const browser_context_; + scoped_refptr<cast_channel::Logger> logger_; scoped_ptr<cast_channel::CastSocket> socket_for_test_; DISALLOW_COPY_AND_ASSIGN(CastChannelAPI); diff --git a/extensions/browser/api/cast_channel/cast_channel_apitest.cc b/extensions/browser/api/cast_channel/cast_channel_apitest.cc index 9f56d2d..69e2d8f 100644 --- a/extensions/browser/api/cast_channel/cast_channel_apitest.cc +++ b/extensions/browser/api/cast_channel/cast_channel_apitest.cc @@ -12,6 +12,7 @@ #include "content/public/browser/browser_thread.h" #include "extensions/browser/api/cast_channel/cast_channel_api.h" #include "extensions/browser/api/cast_channel/cast_socket.h" +#include "extensions/browser/api/cast_channel/logger.h" #include "extensions/common/api/cast_channel.h" #include "extensions/common/switches.h" #include "net/base/capturing_net_log.h" @@ -26,6 +27,7 @@ namespace cast_channel = extensions::core_api::cast_channel; using cast_channel::CastSocket; using cast_channel::ChannelError; +using cast_channel::Logger; using cast_channel::MessageInfo; using cast_channel::ReadyState; using extensions::Extension; @@ -66,10 +68,15 @@ class MockCastSocket : public CastSocket { public: explicit MockCastSocket(CastSocket::Delegate* delegate, net::IPEndPoint ip_endpoint, - net::NetLog* net_log) - : CastSocket(kTestExtensionId, ip_endpoint, - cast_channel::CHANNEL_AUTH_TYPE_SSL, delegate, net_log, - base::TimeDelta::FromMilliseconds(kTimeoutMs)) {} + net::NetLog* net_log, + Logger* logger) + : CastSocket(kTestExtensionId, + ip_endpoint, + cast_channel::CHANNEL_AUTH_TYPE_SSL, + delegate, + net_log, + base::TimeDelta::FromMilliseconds(kTimeoutMs), + logger) {} virtual ~MockCastSocket() {} MOCK_METHOD1(Connect, void(const net::CompletionCallback& callback)); @@ -98,8 +105,8 @@ class CastChannelAPITest : public ExtensionApiTest { net::IPAddressNumber ip_number; net::ParseIPLiteralToNumber("192.168.1.1", &ip_number); net::IPEndPoint ip_endpoint(ip_number, 8009); - mock_cast_socket_ = new MockCastSocket(api, ip_endpoint, - &capturing_net_log_); + mock_cast_socket_ = new MockCastSocket( + api, ip_endpoint, &capturing_net_log_, api->GetLogger()); // Transfers ownership of the socket. api->SetSocketForTest( make_scoped_ptr<CastSocket>(mock_cast_socket_).Pass()); diff --git a/extensions/browser/api/cast_channel/cast_socket.cc b/extensions/browser/api/cast_channel/cast_socket.cc index 80c9e85..e29d492 100644 --- a/extensions/browser/api/cast_channel/cast_socket.cc +++ b/extensions/browser/api/cast_channel/cast_socket.cc @@ -9,13 +9,16 @@ #include "base/bind.h" #include "base/callback_helpers.h" +#include "base/format_macros.h" #include "base/lazy_instance.h" #include "base/numerics/safe_conversions.h" #include "base/strings/string_number_conversions.h" +#include "base/strings/stringprintf.h" #include "base/sys_byteorder.h" #include "extensions/browser/api/cast_channel/cast_auth_util.h" #include "extensions/browser/api/cast_channel/cast_channel.pb.h" #include "extensions/browser/api/cast_channel/cast_message_util.h" +#include "extensions/browser/api/cast_channel/logger.h" #include "net/base/address_list.h" #include "net/base/host_port_pair.h" #include "net/base/net_errors.h" @@ -63,28 +66,140 @@ ApiResourceManager<core_api::cast_channel::CastSocket>::GetFactoryInstance() { namespace core_api { namespace cast_channel { +namespace { + +proto::ReadyState ReadyStateToProto(ReadyState state) { + switch (state) { + case READY_STATE_NONE: + return proto::READY_STATE_NONE; + case READY_STATE_CONNECTING: + return proto::READY_STATE_CONNECTING; + case READY_STATE_OPEN: + return proto::READY_STATE_OPEN; + case READY_STATE_CLOSING: + return proto::READY_STATE_CLOSING; + case READY_STATE_CLOSED: + return proto::READY_STATE_CLOSED; + default: + NOTREACHED(); + return proto::READY_STATE_NONE; + } +} + +proto::ConnectionState ConnectStateToProto(CastSocket::ConnectionState state) { + switch (state) { + case CastSocket::CONN_STATE_NONE: + return proto::CONN_STATE_NONE; + case CastSocket::CONN_STATE_TCP_CONNECT: + return proto::CONN_STATE_TCP_CONNECT; + case CastSocket::CONN_STATE_TCP_CONNECT_COMPLETE: + return proto::CONN_STATE_TCP_CONNECT_COMPLETE; + case CastSocket::CONN_STATE_SSL_CONNECT: + return proto::CONN_STATE_SSL_CONNECT; + case CastSocket::CONN_STATE_SSL_CONNECT_COMPLETE: + return proto::CONN_STATE_SSL_CONNECT_COMPLETE; + case CastSocket::CONN_STATE_AUTH_CHALLENGE_SEND: + return proto::CONN_STATE_AUTH_CHALLENGE_SEND; + case CastSocket::CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE: + return proto::CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE; + case CastSocket::CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE: + return proto::CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE; + default: + NOTREACHED(); + return proto::CONN_STATE_NONE; + } +} + +proto::ReadState ReadStateToProto(CastSocket::ReadState state) { + switch (state) { + case CastSocket::READ_STATE_NONE: + return proto::READ_STATE_NONE; + case CastSocket::READ_STATE_READ: + return proto::READ_STATE_READ; + case CastSocket::READ_STATE_READ_COMPLETE: + return proto::READ_STATE_READ_COMPLETE; + case CastSocket::READ_STATE_DO_CALLBACK: + return proto::READ_STATE_DO_CALLBACK; + case CastSocket::READ_STATE_ERROR: + return proto::READ_STATE_ERROR; + default: + NOTREACHED(); + return proto::READ_STATE_NONE; + } +} + +proto::WriteState WriteStateToProto(CastSocket::WriteState state) { + switch (state) { + case CastSocket::WRITE_STATE_NONE: + return proto::WRITE_STATE_NONE; + case CastSocket::WRITE_STATE_WRITE: + return proto::WRITE_STATE_WRITE; + case CastSocket::WRITE_STATE_WRITE_COMPLETE: + return proto::WRITE_STATE_WRITE_COMPLETE; + case CastSocket::WRITE_STATE_DO_CALLBACK: + return proto::WRITE_STATE_DO_CALLBACK; + case CastSocket::WRITE_STATE_ERROR: + return proto::WRITE_STATE_ERROR; + default: + NOTREACHED(); + return proto::WRITE_STATE_NONE; + } +} + +proto::ErrorState ErrorStateToProto(ChannelError state) { + switch (state) { + case CHANNEL_ERROR_NONE: + return proto::CHANNEL_ERROR_NONE; + case CHANNEL_ERROR_CHANNEL_NOT_OPEN: + return proto::CHANNEL_ERROR_CHANNEL_NOT_OPEN; + case CHANNEL_ERROR_AUTHENTICATION_ERROR: + return proto::CHANNEL_ERROR_AUTHENTICATION_ERROR; + case CHANNEL_ERROR_CONNECT_ERROR: + return proto::CHANNEL_ERROR_CONNECT_ERROR; + case CHANNEL_ERROR_SOCKET_ERROR: + return proto::CHANNEL_ERROR_SOCKET_ERROR; + case CHANNEL_ERROR_TRANSPORT_ERROR: + return proto::CHANNEL_ERROR_TRANSPORT_ERROR; + case CHANNEL_ERROR_INVALID_MESSAGE: + return proto::CHANNEL_ERROR_INVALID_MESSAGE; + case CHANNEL_ERROR_INVALID_CHANNEL_ID: + return proto::CHANNEL_ERROR_INVALID_CHANNEL_ID; + case CHANNEL_ERROR_CONNECT_TIMEOUT: + return proto::CHANNEL_ERROR_CONNECT_TIMEOUT; + case CHANNEL_ERROR_UNKNOWN: + return proto::CHANNEL_ERROR_UNKNOWN; + default: + NOTREACHED(); + return proto::CHANNEL_ERROR_NONE; + } +} + +} // namespace + CastSocket::CastSocket(const std::string& owner_extension_id, const net::IPEndPoint& ip_endpoint, ChannelAuthType channel_auth, CastSocket::Delegate* delegate, net::NetLog* net_log, - const base::TimeDelta& timeout) : - ApiResource(owner_extension_id), - channel_id_(0), - ip_endpoint_(ip_endpoint), - channel_auth_(channel_auth), - delegate_(delegate), - current_message_size_(0), - current_message_(new CastMessage()), - net_log_(net_log), - connect_timeout_(timeout), - connect_timeout_timer_(new base::OneShotTimer<CastSocket>), - is_canceled_(false), - connect_state_(CONN_STATE_NONE), - write_state_(WRITE_STATE_NONE), - read_state_(READ_STATE_NONE), - error_state_(CHANNEL_ERROR_NONE), - ready_state_(READY_STATE_NONE) { + const base::TimeDelta& timeout, + const scoped_refptr<Logger>& logger) + : ApiResource(owner_extension_id), + channel_id_(0), + ip_endpoint_(ip_endpoint), + channel_auth_(channel_auth), + delegate_(delegate), + current_message_size_(0), + current_message_(new CastMessage()), + net_log_(net_log), + logger_(logger), + connect_timeout_(timeout), + connect_timeout_timer_(new base::OneShotTimer<CastSocket>), + is_canceled_(false), + connect_state_(CONN_STATE_NONE), + write_state_(WRITE_STATE_NONE), + read_state_(READ_STATE_NONE), + error_state_(CHANNEL_ERROR_NONE), + ready_state_(READY_STATE_NONE) { DCHECK(net_log_); DCHECK(channel_auth_ == CHANNEL_AUTH_TYPE_SSL || channel_auth_ == CHANNEL_AUTH_TYPE_SSL_VERIFIED); @@ -132,6 +247,7 @@ scoped_ptr<net::SSLClientSocket> CastSocket::CreateSslSocket( cert_and_status.cert_status = net::CERT_STATUS_AUTHORITY_INVALID; cert_and_status.der_cert = peer_cert_; ssl_config.allowed_bad_certs.push_back(cert_and_status); + logger_->LogSocketEvent(channel_id_, proto::SSL_CERT_WHITELISTED); } cert_verifier_.reset(net::CertVerifier::CreateDefault()); @@ -157,32 +273,44 @@ bool CastSocket::ExtractPeerCert(std::string* cert) { net::SSLInfo ssl_info; if (!socket_->GetSSLInfo(&ssl_info) || !ssl_info.cert.get()) return false; + + logger_->LogSocketEvent(channel_id_, proto::SSL_INFO_OBTAINED); + bool result = net::X509Certificate::GetDEREncoded( ssl_info.cert->os_cert_handle(), cert); if (result) VLOG_WITH_CONNECTION(1) << "Successfully extracted peer certificate: " << *cert; + + logger_->LogSocketEventWithRv( + channel_id_, proto::DER_ENCODED_CERT_OBTAIN, result ? 1 : 0); return result; } bool CastSocket::VerifyChallengeReply() { - return AuthenticateChallengeReply(*challenge_reply_, peer_cert_); + AuthResult result = AuthenticateChallengeReply(*challenge_reply_, peer_cert_); + logger_->LogSocketChallengeReplyEvent(channel_id_, result); + return result.success(); } void CastSocket::Connect(const net::CompletionCallback& callback) { DCHECK(CalledOnValidThread()); VLOG_WITH_CONNECTION(1) << "Connect readyState = " << ready_state_; if (ready_state_ != READY_STATE_NONE) { + logger_->LogSocketEventWithDetails( + channel_id_, proto::CONNECT_FAILED, "ReadyState not NONE"); callback.Run(net::ERR_CONNECTION_FAILED); return; } - ready_state_ = READY_STATE_CONNECTING; + connect_callback_ = callback; - connect_state_ = CONN_STATE_TCP_CONNECT; + SetReadyState(READY_STATE_CONNECTING); + SetConnectState(CONN_STATE_TCP_CONNECT); + if (connect_timeout_.InMicroseconds() > 0) { DCHECK(connect_timeout_callback_.IsCancelled()); - connect_timeout_callback_.Reset(base::Bind(&CastSocket::CancelConnect, - base::Unretained(this))); + connect_timeout_callback_.Reset( + base::Bind(&CastSocket::OnConnectTimeout, base::Unretained(this))); GetTimer()->Start(FROM_HERE, connect_timeout_, connect_timeout_callback_.callback()); @@ -200,10 +328,11 @@ void CastSocket::PostTaskToStartConnectLoop(int result) { connect_loop_callback_.callback()); } -void CastSocket::CancelConnect() { +void CastSocket::OnConnectTimeout() { DCHECK(CalledOnValidThread()); // Stop all pending connection setup tasks and report back to the client. is_canceled_ = true; + logger_->LogSocketEvent(channel_id_, proto::CONNECT_TIMED_OUT); VLOG_WITH_CONNECTION(1) << "Timeout while establishing a connection."; DoConnectCallback(net::ERR_TIMED_OUT); } @@ -260,6 +389,13 @@ void CastSocket::DoConnectLoop(int result) { // a. A network operation is pending, OR // b. The Do* method called did not change state + // No state change occurred in do-while loop above. This means state has + // transitioned to NONE. + if (connect_state_ == CONN_STATE_NONE) { + logger_->LogSocketConnectState(channel_id_, + ConnectStateToProto(connect_state_)); + } + // Connect loop is finished: if there is no pending IO invoke the callback. if (rv != net::ERR_IO_PENDING) { GetTimer()->Stop(); @@ -270,10 +406,13 @@ void CastSocket::DoConnectLoop(int result) { int CastSocket::DoTcpConnect() { DCHECK(connect_loop_callback_.IsCancelled()); VLOG_WITH_CONNECTION(1) << "DoTcpConnect"; - connect_state_ = CONN_STATE_TCP_CONNECT_COMPLETE; + SetConnectState(CONN_STATE_TCP_CONNECT_COMPLETE); tcp_socket_ = CreateTcpSocket(); - return tcp_socket_->Connect( + + int rv = tcp_socket_->Connect( base::Bind(&CastSocket::DoConnectLoop, base::Unretained(this))); + logger_->LogSocketEventWithRv(channel_id_, proto::TCP_SOCKET_CONNECT, rv); + return rv; } int CastSocket::DoTcpConnectComplete(int result) { @@ -282,7 +421,9 @@ int CastSocket::DoTcpConnectComplete(int result) { // Enable TCP protocol-level keep-alive. bool result = tcp_socket_->SetKeepAlive(true, kTcpKeepAliveDelaySecs); LOG_IF(WARNING, !result) << "Failed to SetKeepAlive."; - connect_state_ = CONN_STATE_SSL_CONNECT; + logger_->LogSocketEventWithRv( + channel_id_, proto::TCP_SOCKET_SET_KEEP_ALIVE, result ? 1 : 0); + SetConnectState(CONN_STATE_SSL_CONNECT); } return result; } @@ -290,27 +431,31 @@ int CastSocket::DoTcpConnectComplete(int result) { int CastSocket::DoSslConnect() { DCHECK(connect_loop_callback_.IsCancelled()); VLOG_WITH_CONNECTION(1) << "DoSslConnect"; - connect_state_ = CONN_STATE_SSL_CONNECT_COMPLETE; + SetConnectState(CONN_STATE_SSL_CONNECT_COMPLETE); socket_ = CreateSslSocket(tcp_socket_.PassAs<net::StreamSocket>()); - return socket_->Connect( + + int rv = socket_->Connect( base::Bind(&CastSocket::DoConnectLoop, base::Unretained(this))); + logger_->LogSocketEventWithRv(channel_id_, proto::SSL_SOCKET_CONNECT, rv); + return rv; } int CastSocket::DoSslConnectComplete(int result) { VLOG_WITH_CONNECTION(1) << "DoSslConnectComplete: " << result; if (result == net::ERR_CERT_AUTHORITY_INVALID && peer_cert_.empty() && ExtractPeerCert(&peer_cert_)) { - connect_state_ = CONN_STATE_TCP_CONNECT; + SetConnectState(CONN_STATE_TCP_CONNECT); } else if (result == net::OK && channel_auth_ == CHANNEL_AUTH_TYPE_SSL_VERIFIED) { - connect_state_ = CONN_STATE_AUTH_CHALLENGE_SEND; + SetConnectState(CONN_STATE_AUTH_CHALLENGE_SEND); } return result; } int CastSocket::DoAuthChallengeSend() { VLOG_WITH_CONNECTION(1) << "DoAuthChallengeSend"; - connect_state_ = CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE; + SetConnectState(CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE); + CastMessage challenge_message; CreateAuthChallengeMessage(&challenge_message); VLOG_WITH_CONNECTION(1) << "Sending challenge: " @@ -344,7 +489,8 @@ int CastSocket::DoAuthChallengeSendComplete(int result) { VLOG_WITH_CONNECTION(1) << "DoAuthChallengeSendComplete: " << result; if (result < 0) return result; - connect_state_ = CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE; + SetConnectState(CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE); + // Post a task to start read loop so that DoReadLoop is not nested inside // DoConnectLoop. This is not strictly necessary but keeps the read loop // code decoupled from connect loop code. @@ -364,15 +510,17 @@ int CastSocket::DoAuthChallengeReplyComplete(int result) { } void CastSocket::DoConnectCallback(int result) { - ready_state_ = (result == net::OK) ? READY_STATE_OPEN : READY_STATE_CLOSED; + SetReadyState((result == net::OK) ? READY_STATE_OPEN : READY_STATE_CLOSED); + if (result == net::OK) { - error_state_ = CHANNEL_ERROR_NONE; + SetErrorState(CHANNEL_ERROR_NONE); PostTaskToStartReadLoop(); } else if (result == net::ERR_TIMED_OUT) { - error_state_ = CHANNEL_ERROR_CONNECT_TIMEOUT; + SetErrorState(CHANNEL_ERROR_CONNECT_TIMEOUT); } else { - error_state_ = CHANNEL_ERROR_CONNECT_ERROR; + SetErrorState(CHANNEL_ERROR_CONNECT_ERROR); } + VLOG_WITH_CONNECTION(1) << "Calling Connect_Callback"; base::ResetAndReturn(&connect_callback_).Run(result); } @@ -391,6 +539,7 @@ void CastSocket::CloseInternal() { if (ready_state_ == READY_STATE_CLOSED) { return; } + VLOG_WITH_CONNECTION(1) << "Close ReadyState = " << ready_state_; tcp_socket_.reset(); socket_.reset(); @@ -404,7 +553,8 @@ void CastSocket::CloseInternal() { send_auth_challenge_callback_.Cancel(); read_loop_callback_.Cancel(); connect_timeout_callback_.Cancel(); - ready_state_ = READY_STATE_CLOSED; + SetReadyState(READY_STATE_CLOSED); + logger_->LogSocketEvent(channel_id_, proto::SOCKET_CLOSED); } void CastSocket::RunPendingCallbacksOnClose() { @@ -424,11 +574,19 @@ void CastSocket::SendMessage(const MessageInfo& message, const net::CompletionCallback& callback) { DCHECK(CalledOnValidThread()); if (ready_state_ != READY_STATE_OPEN) { + logger_->LogSocketEventForMessage(channel_id_, + proto::SEND_MESSAGE_FAILED, + message.namespace_, + "Ready state not OPEN"); callback.Run(net::ERR_FAILED); return; } CastMessage message_proto; if (!MessageInfoToCastMessage(message, &message_proto)) { + logger_->LogSocketEventForMessage(channel_id_, + proto::SEND_MESSAGE_FAILED, + message.namespace_, + "Failed to convert to CastMessage"); callback.Run(net::ERR_FAILED); return; } @@ -440,13 +598,22 @@ void CastSocket::SendCastMessageInternal( const net::CompletionCallback& callback) { WriteRequest write_request(callback); if (!write_request.SetContent(message)) { + logger_->LogSocketEventForMessage(channel_id_, + proto::SEND_MESSAGE_FAILED, + message.namespace_(), + "SetContent failed"); callback.Run(net::ERR_FAILED); return; } write_queue_.push(write_request); + logger_->LogSocketEventForMessage( + channel_id_, + proto::MESSAGE_ENQUEUED, + message.namespace_(), + base::StringPrintf("Queue size: %" PRIuS, write_queue_.size())); if (write_state_ == WRITE_STATE_NONE) { - write_state_ = WRITE_STATE_WRITE; + SetWriteState(WRITE_STATE_WRITE); DoWriteLoop(net::OK); } } @@ -456,7 +623,7 @@ void CastSocket::DoWriteLoop(int result) { VLOG_WITH_CONNECTION(1) << "DoWriteLoop queue size: " << write_queue_.size(); if (write_queue_.empty()) { - write_state_ = WRITE_STATE_NONE; + SetWriteState(WRITE_STATE_NONE); return; } @@ -489,14 +656,20 @@ void CastSocket::DoWriteLoop(int result) { rv != net::ERR_IO_PENDING && write_state_ != WRITE_STATE_NONE); + // No state change occurred in do-while loop above. This means state has + // transitioned to NONE. + if (write_state_ == WRITE_STATE_NONE) { + logger_->LogSocketWriteState(channel_id_, WriteStateToProto(write_state_)); + } + // If write loop is done because the queue is empty then set write // state to NONE if (write_queue_.empty()) - write_state_ = WRITE_STATE_NONE; + SetWriteState(WRITE_STATE_NONE); // Write loop is done - if the result is ERR_FAILED then close with error. if (rv == net::ERR_FAILED) - CloseWithError(error_state_); + CloseWithError(); } int CastSocket::DoWrite() { @@ -507,18 +680,22 @@ int CastSocket::DoWrite() { << request.io_buffer->size() << " bytes_written " << request.io_buffer->BytesConsumed(); - write_state_ = WRITE_STATE_WRITE_COMPLETE; - return socket_->Write( + SetWriteState(WRITE_STATE_WRITE_COMPLETE); + + int rv = socket_->Write( request.io_buffer.get(), request.io_buffer->BytesRemaining(), base::Bind(&CastSocket::DoWriteLoop, base::Unretained(this))); + logger_->LogSocketEventWithRv(channel_id_, proto::SOCKET_WRITE, rv); + + return rv; } int CastSocket::DoWriteComplete(int result) { DCHECK(!write_queue_.empty()); if (result <= 0) { // NOTE that 0 also indicates an error - error_state_ = CHANNEL_ERROR_SOCKET_ERROR; - write_state_ = WRITE_STATE_ERROR; + SetErrorState(CHANNEL_ERROR_SOCKET_ERROR); + SetWriteState(WRITE_STATE_ERROR); return result == 0 ? net::ERR_FAILED : result; } @@ -527,9 +704,9 @@ int CastSocket::DoWriteComplete(int result) { scoped_refptr<net::DrainableIOBuffer> io_buffer = request.io_buffer; io_buffer->DidConsume(result); if (io_buffer->BytesRemaining() == 0) // Message fully sent - write_state_ = WRITE_STATE_DO_CALLBACK; + SetWriteState(WRITE_STATE_DO_CALLBACK); else - write_state_ = WRITE_STATE_WRITE; + SetWriteState(WRITE_STATE_WRITE); return net::OK; } @@ -537,8 +714,14 @@ int CastSocket::DoWriteComplete(int result) { int CastSocket::DoWriteCallback() { DCHECK(!write_queue_.empty()); write_state_ = WRITE_STATE_WRITE; + logger_->LogSocketWriteState(channel_id_, WriteStateToProto(write_state_)); WriteRequest& request = write_queue_.front(); int bytes_consumed = request.io_buffer->BytesConsumed(); + logger_->LogSocketEventForMessage( + channel_id_, + proto::MESSAGE_WRITTEN, + request.message_namespace, + base::StringPrintf("Bytes: %d", bytes_consumed)); request.callback.Run(bytes_consumed); write_queue_.pop(); return net::OK; @@ -580,7 +763,7 @@ void CastSocket::StartReadLoop() { read_loop_callback_.Cancel(); // Read loop would have already been started if read state is not NONE if (read_state_ == READ_STATE_NONE) { - read_state_ = READ_STATE_READ; + SetReadState(READ_STATE_READ); DoReadLoop(net::OK); } } @@ -616,6 +799,12 @@ void CastSocket::DoReadLoop(int result) { } } while (rv != net::ERR_IO_PENDING && read_state_ != READ_STATE_NONE); + // No state change occurred in do-while loop above. This means state has + // transitioned to NONE. + if (read_state_ == READ_STATE_NONE) { + logger_->LogSocketReadState(channel_id_, ReadStateToProto(read_state_)); + } + if (rv == net::ERR_FAILED) { if (ready_state_ == READY_STATE_CONNECTING) { // Read errors during the handshake should notify the caller via @@ -624,13 +813,13 @@ void CastSocket::DoReadLoop(int result) { } else { // Connection is already established. // Close and send error status via the message event delegate. - CloseWithError(error_state_); + CloseWithError(); } } } int CastSocket::DoRead() { - read_state_ = READ_STATE_READ_COMPLETE; + SetReadState(READ_STATE_READ_COMPLETE); // Figure out whether to read header or body, and the remaining bytes. uint32 num_bytes_to_read = 0; if (header_read_buffer_->RemainingCapacity() > 0) { @@ -646,10 +835,13 @@ int CastSocket::DoRead() { CHECK_GT(num_bytes_to_read, 0U); // Read up to num_bytes_to_read into |current_read_buffer_|. - return socket_->Read( + int rv = socket_->Read( current_read_buffer_.get(), num_bytes_to_read, base::Bind(&CastSocket::DoReadLoop, base::Unretained(this))); + logger_->LogSocketEventWithRv(channel_id_, proto::SOCKET_READ, rv); + + return rv; } int CastSocket::DoReadComplete(int result) { @@ -659,8 +851,8 @@ int CastSocket::DoReadComplete(int result) { << " body offset = " << body_read_buffer_->offset(); if (result <= 0) { // 0 means EOF: the peer closed the socket VLOG_WITH_CONNECTION(1) << "Read error, peer closed the socket"; - error_state_ = CHANNEL_ERROR_SOCKET_ERROR; - read_state_ = READ_STATE_ERROR; + SetErrorState(CHANNEL_ERROR_SOCKET_ERROR); + SetReadState(READ_STATE_ERROR); return result == 0 ? net::ERR_FAILED : result; } @@ -668,41 +860,55 @@ int CastSocket::DoReadComplete(int result) { CHECK_LE(current_read_buffer_->offset() + result, current_read_buffer_->capacity()); current_read_buffer_->set_offset(current_read_buffer_->offset() + result); - read_state_ = READ_STATE_READ; if (current_read_buffer_.get() == header_read_buffer_.get() && current_read_buffer_->RemainingCapacity() == 0) { // A full header is read, process the contents. if (!ProcessHeader()) { - error_state_ = cast_channel::CHANNEL_ERROR_INVALID_MESSAGE; - read_state_ = READ_STATE_ERROR; + SetErrorState(CHANNEL_ERROR_INVALID_MESSAGE); + SetReadState(READ_STATE_ERROR); + } else { + // Processed header, now read the body. + SetReadState(READ_STATE_READ); } } else if (current_read_buffer_.get() == body_read_buffer_.get() && static_cast<uint32>(current_read_buffer_->offset()) == current_message_size_) { + // Store a copy of current_message_size_ since it will be reset by + // ProcessBody(). + uint32 message_size = current_message_size_; // Full body is read, process the contents. if (ProcessBody()) { - read_state_ = READ_STATE_DO_CALLBACK; + logger_->LogSocketEventForMessage( + channel_id_, + proto::MESSAGE_READ, + current_message_->namespace_(), + base::StringPrintf("Message size: %u", message_size)); + SetReadState(READ_STATE_DO_CALLBACK); } else { - error_state_ = cast_channel::CHANNEL_ERROR_INVALID_MESSAGE; - read_state_ = READ_STATE_ERROR; + SetErrorState(CHANNEL_ERROR_INVALID_MESSAGE); + SetReadState(READ_STATE_ERROR); } + } else { + // Have not received full header or full body yet; keep reading. + SetReadState(READ_STATE_READ); } return net::OK; } int CastSocket::DoReadCallback() { - read_state_ = READ_STATE_READ; + SetReadState(READ_STATE_READ); const CastMessage& message = *current_message_; if (ready_state_ == READY_STATE_CONNECTING) { if (IsAuthMessage(message)) { challenge_reply_.reset(new CastMessage(message)); + logger_->LogSocketEvent(channel_id_, proto::RECEIVED_CHALLENGE_REPLY); PostTaskToStartConnectLoop(net::OK); return net::OK; } else { - // Expected an auth message, got something else instead. Handle as error. - read_state_ = READ_STATE_ERROR; + SetReadState(READ_STATE_ERROR); + SetErrorState(CHANNEL_ERROR_INVALID_MESSAGE); return net::ERR_INVALID_RESPONSE; } } @@ -710,11 +916,18 @@ int CastSocket::DoReadCallback() { MessageInfo message_info; if (!CastMessageToMessageInfo(message, &message_info)) { current_message_->Clear(); - read_state_ = READ_STATE_ERROR; + SetReadState(READ_STATE_ERROR); + SetErrorState(CHANNEL_ERROR_INVALID_MESSAGE); return net::ERR_INVALID_RESPONSE; } + + logger_->LogSocketEventForMessage(channel_id_, + proto::NOTIFY_ON_MESSAGE, + message.namespace_(), + std::string()); delegate_->OnMessage(this, message_info); current_message_->Clear(); + return net::OK; } @@ -767,13 +980,14 @@ bool CastSocket::Serialize(const CastMessage& message_proto, return true; } -void CastSocket::CloseWithError(ChannelError error) { +void CastSocket::CloseWithError() { DCHECK(CalledOnValidThread()); CloseInternal(); - error_state_ = error; RunPendingCallbacksOnClose(); - if (delegate_) - delegate_->OnError(this, error); + if (delegate_) { + logger_->LogSocketEvent(channel_id_, proto::NOTIFY_ON_ERROR); + delegate_->OnError(this, error_state_); + } } std::string CastSocket::CastUrl() const { @@ -789,6 +1003,42 @@ base::Timer* CastSocket::GetTimer() { return connect_timeout_timer_.get(); } +void CastSocket::SetConnectState(ConnectionState connect_state) { + if (connect_state_ != connect_state) { + connect_state_ = connect_state; + logger_->LogSocketConnectState(channel_id_, + ConnectStateToProto(connect_state_)); + } +} + +void CastSocket::SetReadyState(ReadyState ready_state) { + if (ready_state_ != ready_state) { + ready_state_ = ready_state; + logger_->LogSocketReadyState(channel_id_, ReadyStateToProto(ready_state_)); + } +} + +void CastSocket::SetErrorState(ChannelError error_state) { + if (error_state_ != error_state) { + error_state_ = error_state; + logger_->LogSocketErrorState(channel_id_, ErrorStateToProto(error_state_)); + } +} + +void CastSocket::SetReadState(ReadState read_state) { + if (read_state_ != read_state) { + read_state_ = read_state; + logger_->LogSocketReadState(channel_id_, ReadStateToProto(read_state_)); + } +} + +void CastSocket::SetWriteState(WriteState write_state) { + if (write_state_ != write_state) { + write_state_ = write_state; + logger_->LogSocketWriteState(channel_id_, WriteStateToProto(write_state_)); + } +} + CastSocket::MessageHeader::MessageHeader() : message_size(0) { } void CastSocket::MessageHeader::SetMessageSize(size_t size) { @@ -833,6 +1083,7 @@ bool CastSocket::WriteRequest::SetContent(const CastMessage& message_proto) { std::string message_data; if (!Serialize(message_proto, &message_data)) return false; + message_namespace = message_proto.namespace_(); io_buffer = new net::DrainableIOBuffer(new net::StringIOBuffer(message_data), message_data.size()); return true; diff --git a/extensions/browser/api/cast_channel/cast_socket.h b/extensions/browser/api/cast_channel/cast_socket.h index 5ff1714..1c12feb 100644 --- a/extensions/browser/api/cast_channel/cast_socket.h +++ b/extensions/browser/api/cast_channel/cast_socket.h @@ -36,6 +36,7 @@ namespace core_api { namespace cast_channel { class CastMessage; +class Logger; // This class implements a channel between Chrome and a Cast device using a TCP // socket with SSL. The channel may authenticate that the receiver is a genuine @@ -68,7 +69,8 @@ class CastSocket : public ApiResource { ChannelAuthType channel_auth, CastSocket::Delegate* delegate, net::NetLog* net_log, - const base::TimeDelta& connect_timeout); + const base::TimeDelta& connect_timeout, + const scoped_refptr<Logger>& logger); // Ensures that the socket is closed. virtual ~CastSocket(); @@ -119,6 +121,36 @@ class CastSocket : public ApiResource { // It is fine to delete the CastSocket object in |callback|. virtual void Close(const net::CompletionCallback& callback); + // Internal connection states. + enum ConnectionState { + CONN_STATE_NONE, + CONN_STATE_TCP_CONNECT, + CONN_STATE_TCP_CONNECT_COMPLETE, + CONN_STATE_SSL_CONNECT, + CONN_STATE_SSL_CONNECT_COMPLETE, + CONN_STATE_AUTH_CHALLENGE_SEND, + CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE, + CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE, + }; + + // Internal write states. + enum WriteState { + WRITE_STATE_NONE, + WRITE_STATE_WRITE, + WRITE_STATE_WRITE_COMPLETE, + WRITE_STATE_DO_CALLBACK, + WRITE_STATE_ERROR, + }; + + // Internal read states. + enum ReadState { + READ_STATE_NONE, + READ_STATE_READ, + READ_STATE_READ_COMPLETE, + READ_STATE_DO_CALLBACK, + READ_STATE_ERROR, + }; + protected: // Message header struct. If fields are added, be sure to update // header_size(). Protected to allow use of *_size() methods in unit tests. @@ -150,36 +182,6 @@ class CastSocket : public ApiResource { static const char* service_name() { return "CastSocketManager"; } - // Internal connection states. - enum ConnectionState { - CONN_STATE_NONE, - CONN_STATE_TCP_CONNECT, - CONN_STATE_TCP_CONNECT_COMPLETE, - CONN_STATE_SSL_CONNECT, - CONN_STATE_SSL_CONNECT_COMPLETE, - CONN_STATE_AUTH_CHALLENGE_SEND, - CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE, - CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE, - }; - - // Internal write states. - enum WriteState { - WRITE_STATE_NONE, - WRITE_STATE_WRITE, - WRITE_STATE_WRITE_COMPLETE, - WRITE_STATE_DO_CALLBACK, - WRITE_STATE_ERROR, - }; - - // Internal read states. - enum ReadState { - READ_STATE_NONE, - READ_STATE_READ, - READ_STATE_READ_COMPLETE, - READ_STATE_DO_CALLBACK, - READ_STATE_ERROR, - }; - // Creates an instance of TCPClientSocket. virtual scoped_ptr<net::TCPClientSocket> CreateTcpSocket(); // Creates an instance of SSLClientSocket with the given underlying |socket|. @@ -196,7 +198,7 @@ class CastSocket : public ApiResource { // Invoked by a cancelable closure when connection setup time // exceeds the interval specified at |connect_timeout|. - void CancelConnect(); + void OnConnectTimeout(); ///////////////////////////////////////////////////////////////////////////// // Following methods work together to implement the following flow: @@ -266,9 +268,8 @@ class CastSocket : public ApiResource { // Parses the contents of body_read_buffer_ and sets current_message_ to // the message received. bool ProcessBody(); - // Closes the socket, sets |error_state_| to |error| and signals the - // delegate that |error| has occurred. - void CloseWithError(ChannelError error); + // Closes socket, signaling the delegate that |error| has occurred. + void CloseWithError(); // Frees resources and cancels pending callbacks. |ready_state_| will be set // READY_STATE_CLOSED on completion. A no-op if |ready_state_| is already // READY_STATE_CLOSED. @@ -276,7 +277,6 @@ class CastSocket : public ApiResource { // Runs pending callbacks that are passed into us to notify API clients that // pending operations will fail because the socket has been closed. void RunPendingCallbacksOnClose(); - // Serializes the content of message_proto (with a header) to |message_data|. static bool Serialize(const CastMessage& message_proto, std::string* message_data); @@ -285,6 +285,12 @@ class CastSocket : public ApiResource { virtual base::Timer* GetTimer(); + void SetConnectState(ConnectionState connect_state); + void SetReadyState(ReadyState ready_state); + void SetErrorState(ChannelError error_state); + void SetReadState(ReadState read_state); + void SetWriteState(WriteState write_state); + base::ThreadChecker thread_checker_; // The id of the channel. @@ -313,6 +319,9 @@ class CastSocket : public ApiResource { // The NetLog source for this service. net::NetLog::Source net_log_source_; + // Logger used to track multiple CastSockets. Does NOT own this object. + scoped_refptr<Logger> logger_; + // CertVerifier is owned by us but should be deleted AFTER SSLClientSocket // since in some cases the destructor of SSLClientSocket may call a method // to cancel a cert verification request. @@ -373,6 +382,7 @@ class CastSocket : public ApiResource { bool SetContent(const CastMessage& message_proto); net::CompletionCallback callback; + std::string message_namespace; scoped_refptr<net::DrainableIOBuffer> io_buffer; }; // Queue of pending writes. The message at the front of the queue is the one diff --git a/extensions/browser/api/cast_channel/cast_socket_unittest.cc b/extensions/browser/api/cast_channel/cast_socket_unittest.cc index 7a2b724..1068a23 100644 --- a/extensions/browser/api/cast_channel/cast_socket_unittest.cc +++ b/extensions/browser/api/cast_channel/cast_socket_unittest.cc @@ -9,9 +9,11 @@ #include "base/run_loop.h" #include "base/strings/string_number_conversions.h" #include "base/sys_byteorder.h" +#include "base/test/simple_test_tick_clock.h" #include "base/timer/mock_timer.h" #include "extensions/browser/api/cast_channel/cast_channel.pb.h" #include "extensions/browser/api/cast_channel/cast_message_util.h" +#include "extensions/browser/api/cast_channel/logger.h" #include "net/base/address_list.h" #include "net/base/capturing_net_log.h" #include "net/base/net_errors.h" @@ -143,32 +145,38 @@ class CompleteHandler { class TestCastSocket : public CastSocket { public: - static scoped_ptr<TestCastSocket> Create( - MockCastSocketDelegate* delegate) { - return scoped_ptr<TestCastSocket>( - new TestCastSocket(delegate, CreateIPEndPoint(), - CHANNEL_AUTH_TYPE_SSL, - kDistantTimeoutMillis)); + static scoped_ptr<TestCastSocket> Create(MockCastSocketDelegate* delegate, + Logger* logger) { + return scoped_ptr<TestCastSocket>(new TestCastSocket(delegate, + CreateIPEndPoint(), + CHANNEL_AUTH_TYPE_SSL, + kDistantTimeoutMillis, + logger)); } static scoped_ptr<TestCastSocket> CreateSecure( - MockCastSocketDelegate* delegate) { + MockCastSocketDelegate* delegate, + Logger* logger) { return scoped_ptr<TestCastSocket>( - new TestCastSocket(delegate, CreateIPEndPoint(), + new TestCastSocket(delegate, + CreateIPEndPoint(), CHANNEL_AUTH_TYPE_SSL_VERIFIED, - kDistantTimeoutMillis)); + kDistantTimeoutMillis, + logger)); } explicit TestCastSocket(MockCastSocketDelegate* delegate, const net::IPEndPoint& ip_endpoint, ChannelAuthType channel_auth, - int64 timeout_ms) + int64 timeout_ms, + Logger* logger) : CastSocket("abcdefg", ip_endpoint, channel_auth, delegate, &capturing_net_log_, - base::TimeDelta::FromMilliseconds(timeout_ms)), + base::TimeDelta::FromMilliseconds(timeout_ms), + logger), ip_(ip_endpoint), connect_index_(0), extract_cert_result_(true), @@ -334,7 +342,10 @@ class TestCastSocket : public CastSocket { class CastSocketTest : public testing::Test { public: - CastSocketTest() {} + CastSocketTest() + : logger_(new Logger( + scoped_ptr<base::TickClock>(new base::SimpleTestTickClock), + base::TimeTicks())) {} virtual ~CastSocketTest() {} virtual void SetUp() OVERRIDE { @@ -373,11 +384,11 @@ class CastSocketTest : public testing::Test { } void CreateCastSocket() { - socket_ = TestCastSocket::Create(&mock_delegate_); + socket_ = TestCastSocket::Create(&mock_delegate_, logger_); } void CreateCastSocketSecure() { - socket_ = TestCastSocket::CreateSecure(&mock_delegate_); + socket_ = TestCastSocket::CreateSecure(&mock_delegate_, logger_); } // Sets up CastSocket::Connect to succeed. @@ -403,6 +414,7 @@ class CastSocketTest : public testing::Test { base::MessageLoop message_loop_; MockCastSocketDelegate mock_delegate_; + scoped_refptr<Logger> logger_; scoped_ptr<TestCastSocket> socket_; CompleteHandler handler_; MessageInfo test_messages_[arraysize(kTestData)]; diff --git a/extensions/browser/api/cast_channel/logger.cc b/extensions/browser/api/cast_channel/logger.cc new file mode 100644 index 0000000..c1e8c9b --- /dev/null +++ b/extensions/browser/api/cast_channel/logger.cc @@ -0,0 +1,277 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "extensions/browser/api/cast_channel/logger.h" + +#include "base/strings/string_util.h" +#include "base/time/tick_clock.h" +#include "extensions/browser/api/cast_channel/cast_auth_util.h" + +namespace extensions { +namespace core_api { +namespace cast_channel { + +using net::IPEndPoint; +using proto::AggregatedSocketEvent; +using proto::EventType; +using proto::Log; +using proto::SocketEvent; + +namespace { + +const char* kInternalNamespacePrefix = "com.google.cast"; + +proto::ChallengeReplyErrorType ChannegeReplyErrorToProto( + AuthResult::ErrorType error_type) { + switch (error_type) { + case AuthResult::ERROR_NONE: + return proto::CHALLENGE_REPLY_ERROR_NONE; + case AuthResult::ERROR_PEER_CERT_EMPTY: + return proto::CHALLENGE_REPLY_ERROR_PEER_CERT_EMPTY; + case AuthResult::ERROR_WRONG_PAYLOAD_TYPE: + return proto::CHALLENGE_REPLY_ERROR_WRONG_PAYLOAD_TYPE; + case AuthResult::ERROR_NO_PAYLOAD: + return proto::CHALLENGE_REPLY_ERROR_NO_PAYLOAD; + case AuthResult::ERROR_PAYLOAD_PARSING_FAILED: + return proto::CHALLENGE_REPLY_ERROR_PAYLOAD_PARSING_FAILED; + case AuthResult::ERROR_MESSAGE_ERROR: + return proto::CHALLENGE_REPLY_ERROR_MESSAGE_ERROR; + case AuthResult::ERROR_NO_RESPONSE: + return proto::CHALLENGE_REPLY_ERROR_NO_RESPONSE; + case AuthResult::ERROR_FINGERPRINT_NOT_FOUND: + return proto::CHALLENGE_REPLY_ERROR_FINGERPRINT_NOT_FOUND; + case AuthResult::ERROR_NSS_CERT_PARSING_FAILED: + return proto::CHALLENGE_REPLY_ERROR_NSS_CERT_PARSING_FAILED; + case AuthResult::ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA: + return proto::CHALLENGE_REPLY_ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA; + case AuthResult::ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY: + return proto::CHALLENGE_REPLY_ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY; + case AuthResult::ERROR_NSS_SIGNED_BLOBS_MISMATCH: + return proto::CHALLENGE_REPLY_ERROR_NSS_SIGNED_BLOBS_MISMATCH; + default: + NOTREACHED(); + return proto::CHALLENGE_REPLY_ERROR_NONE; + } +} + +} // namespace + +Logger::AggregatedSocketEventLog::AggregatedSocketEventLog() { +} +Logger::AggregatedSocketEventLog::~AggregatedSocketEventLog() { +} + +Logger::Logger(scoped_ptr<base::TickClock> clock, + base::TimeTicks unix_epoch_time_ticks) + : clock_(clock.Pass()), + unix_epoch_time_ticks_(unix_epoch_time_ticks), + num_evicted_aggregated_socket_events_(0), + num_evicted_socket_events_(0) { + DCHECK(clock_); + + // Logger may not be necessarily be created on the IO thread, but logging + // happens exclusively there. + thread_checker_.DetachFromThread(); +} + +Logger::~Logger() { +} + +void Logger::LogNewSocketEvent(const CastSocket& cast_socket) { + DCHECK(thread_checker_.CalledOnValidThread()); + + int channel_id = cast_socket.id(); + SocketEvent event = CreateEvent(proto::CAST_SOCKET_CREATED); + LogSocketEvent(channel_id, event); + + AggregatedSocketEvent& aggregated_socket_event = + aggregated_socket_events_.find(channel_id) + ->second->aggregated_socket_event; + const net::IPAddressNumber& ip = cast_socket.ip_endpoint().address(); + aggregated_socket_event.set_endpoint_id(ip.back()); + aggregated_socket_event.set_channel_auth_type(cast_socket.channel_auth() == + CHANNEL_AUTH_TYPE_SSL + ? proto::SSL + : proto::SSL_VERIFIED); +} + +void Logger::LogSocketEvent(int channel_id, EventType event_type) { + DCHECK(thread_checker_.CalledOnValidThread()); + + LogSocketEventWithDetails(channel_id, event_type, std::string()); +} + +void Logger::LogSocketEventWithDetails(int channel_id, + EventType event_type, + const std::string& details) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(event_type); + if (!details.empty()) + event.set_details(details); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketEventWithRv(int channel_id, + EventType event_type, + int rv) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(event_type); + event.set_return_value(rv); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketReadyState(int channel_id, proto::ReadyState new_state) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::READY_STATE_CHANGED); + event.set_ready_state(new_state); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketConnectState(int channel_id, + proto::ConnectionState new_state) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::CONNECTION_STATE_CHANGED); + event.set_connection_state(new_state); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketReadState(int channel_id, proto::ReadState new_state) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::READ_STATE_CHANGED); + event.set_read_state(new_state); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketWriteState(int channel_id, proto::WriteState new_state) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::WRITE_STATE_CHANGED); + event.set_write_state(new_state); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketErrorState(int channel_id, proto::ErrorState new_state) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::ERROR_STATE_CHANGED); + event.set_error_state(new_state); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketEventForMessage(int channel_id, + EventType event_type, + const std::string& message_namespace, + const std::string& details) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(event_type); + if (StartsWithASCII(message_namespace, kInternalNamespacePrefix, false)) + event.set_message_namespace(message_namespace); + event.set_details(details); + + LogSocketEvent(channel_id, event); +} + +void Logger::LogSocketChallengeReplyEvent(int channel_id, + const AuthResult& auth_result) { + DCHECK(thread_checker_.CalledOnValidThread()); + + SocketEvent event = CreateEvent(proto::AUTH_CHALLENGE_REPLY); + event.set_challenge_reply_error_type( + ChannegeReplyErrorToProto(auth_result.error_type)); + if (auth_result.nss_error_code != 0) + event.set_return_value(auth_result.nss_error_code); + + LogSocketEvent(channel_id, event); +} + +SocketEvent Logger::CreateEvent(EventType event_type) { + SocketEvent event; + event.set_type(event_type); + event.set_timestamp_micros(clock_->NowTicks().ToInternalValue() + + unix_epoch_time_ticks_.ToInternalValue()); + return event; +} + +void Logger::LogSocketEvent(int channel_id, const SocketEvent& socket_event) { + AggregatedSocketEventLogMap::iterator it = + aggregated_socket_events_.find(channel_id); + if (it == aggregated_socket_events_.end()) { + if (aggregated_socket_events_.size() >= kMaxSocketsToLog) { + AggregatedSocketEventLogMap::iterator erase_it = + aggregated_socket_events_.begin(); + + num_evicted_aggregated_socket_events_++; + num_evicted_socket_events_ += erase_it->second->socket_events.size(); + + aggregated_socket_events_.erase(erase_it); + } + + it = aggregated_socket_events_ + .insert(std::make_pair( + channel_id, make_linked_ptr(new AggregatedSocketEventLog))) + .first; + it->second->aggregated_socket_event.set_id(channel_id); + } + + std::deque<proto::SocketEvent>& socket_events = it->second->socket_events; + if (socket_events.size() >= kMaxEventsPerSocket) { + socket_events.pop_front(); + num_evicted_socket_events_++; + } + + socket_events.push_back(socket_event); +} + +bool Logger::LogToString(std::string* output) const { + output->clear(); + + Log log; + log.set_num_evicted_aggregated_socket_events( + num_evicted_aggregated_socket_events_); + log.set_num_evicted_socket_events(num_evicted_socket_events_); + + for (AggregatedSocketEventLogMap::const_iterator it = + aggregated_socket_events_.begin(); + it != aggregated_socket_events_.end(); + ++it) { + AggregatedSocketEvent* new_aggregated_socket_event = + log.add_aggregated_socket_event(); + new_aggregated_socket_event->CopyFrom(it->second->aggregated_socket_event); + + const std::deque<SocketEvent>& socket_events = it->second->socket_events; + for (std::deque<SocketEvent>::const_iterator socket_event_it = + socket_events.begin(); + socket_event_it != socket_events.end(); + ++socket_event_it) { + SocketEvent* socket_event = + new_aggregated_socket_event->add_socket_event(); + socket_event->CopyFrom(*socket_event_it); + } + } + + return log.SerializeToString(output); +} + +void Logger::Reset() { + aggregated_socket_events_.clear(); + num_evicted_aggregated_socket_events_ = 0; + num_evicted_socket_events_ = 0; +} + +} // namespace cast_channel +} // namespace api +} // namespace extensions diff --git a/extensions/browser/api/cast_channel/logger.h b/extensions/browser/api/cast_channel/logger.h new file mode 100644 index 0000000..fc301ca --- /dev/null +++ b/extensions/browser/api/cast_channel/logger.h @@ -0,0 +1,132 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef EXTENSIONS_BROWSER_API_CAST_CHANNEL_LOGGER_H_ +#define EXTENSIONS_BROWSER_API_CAST_CHANNEL_LOGGER_H_ + +#include <deque> +#include <map> + +#include "base/basictypes.h" +#include "base/memory/linked_ptr.h" +#include "base/memory/scoped_ptr.h" +#include "base/threading/thread_checker.h" +#include "extensions/browser/api/cast_channel/cast_socket.h" +#include "extensions/browser/api/cast_channel/logging.pb.h" +#include "net/base/ip_endpoint.h" + +namespace base { +class TickClock; +} + +namespace extensions { +namespace core_api { +namespace cast_channel { + +struct AuthResult; + +static const int kMaxSocketsToLog = 50; +static const int kMaxEventsPerSocket = 2000; + +// Logs information of each channel and sockets and exports the log as +// a blob. Logger is done on the IO thread. +class Logger : public base::RefCounted<Logger> { + public: + // |clock|: Clock used for generating timestamps for the events. Owned by + // this class. + // |unix_epoch_time_ticks|: The TimeTicks that corresponds to Unix epoch. + Logger(scoped_ptr<base::TickClock> clock, + base::TimeTicks unix_epoch_time_ticks); + + // For newly created sockets. Will create an event and log a + // CAST_SOCKET_CREATED event. + void LogNewSocketEvent(const CastSocket& cast_socket); + + void LogSocketEvent(int channel_id, proto::EventType event_type); + void LogSocketEventWithDetails(int channel_id, + proto::EventType event_type, + const std::string& details); + + // For events that involves socket / crypto operations that returns a value. + void LogSocketEventWithRv(int channel_id, + proto::EventType event_type, + int rv); + + // For *_STATE_CHANGED events. + void LogSocketReadyState(int channel_id, proto::ReadyState new_state); + void LogSocketConnectState(int channel_id, proto::ConnectionState new_state); + void LogSocketReadState(int channel_id, proto::ReadState new_state); + void LogSocketWriteState(int channel_id, proto::WriteState new_state); + void LogSocketErrorState(int channel_id, proto::ErrorState new_state); + + // For AUTH_CHALLENGE_REPLY event. + void LogSocketChallengeReplyEvent(int channel_id, + const AuthResult& auth_result); + + void LogSocketEventForMessage(int channel_id, + proto::EventType event_type, + const std::string& message_namespace, + const std::string& details); + + // Assembles logs collected so far and return it as a serialized Log proto. + // |output|: Where serialized contents will be assigned to. + // Returns true if serialization is successful. + // Contents in |output| is valid only if function returns true. + // TODO(imcheng): Add compression. + bool LogToString(std::string* output) const; + + // Clears the internal map. + void Reset(); + + private: + friend class base::RefCounted<Logger>; + ~Logger(); + + struct AggregatedSocketEventLog { + public: + AggregatedSocketEventLog(); + ~AggregatedSocketEventLog(); + + // Partially constructed AggregatedSocketEvent proto populated by Logger. + // Contains top level info such as channel ID, IP end point and channel + // auth type. + proto::AggregatedSocketEvent aggregated_socket_event; + // Events to be assigned to the AggregatedSocketEvent proto. Contains the + // most recent |kMaxEventsPerSocket| entries. The oldest events are + // evicted as new events are logged. + std::deque<proto::SocketEvent> socket_events; + }; + + typedef std::map<int, linked_ptr<AggregatedSocketEventLog> > + AggregatedSocketEventLogMap; + + // Returns a SocketEvent proto with common fields (EventType, timestamp) + // populated. + proto::SocketEvent CreateEvent(proto::EventType event_type); + + // Records |event| associated with |channel_id|. + // If the internal map is already logging maximum number of sockets and this + // is a new socket, the socket with the smallest channel id will be discarded. + // Returns a pointer to the Event proto with |event_type| and + // timestamp populated. + void LogSocketEvent(int channel_id, const proto::SocketEvent& socket_event); + + scoped_ptr<base::TickClock> clock_; + AggregatedSocketEventLogMap aggregated_socket_events_; + base::TimeTicks unix_epoch_time_ticks_; + + // Number of socket / event entries evicted by the logger due to size + // constraints. + int num_evicted_aggregated_socket_events_; + int num_evicted_socket_events_; + + base::ThreadChecker thread_checker_; + + DISALLOW_COPY_AND_ASSIGN(Logger); +}; +} // namespace cast_channel +} // namespace api +} // namespace extensions + +#endif // EXTENSIONS_BROWSER_API_CAST_CHANNEL_LOGGER_H_ diff --git a/extensions/browser/api/cast_channel/logger_unittest.cc b/extensions/browser/api/cast_channel/logger_unittest.cc new file mode 100644 index 0000000..d1ec5fc --- /dev/null +++ b/extensions/browser/api/cast_channel/logger_unittest.cc @@ -0,0 +1,196 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/test/simple_test_tick_clock.h" +#include "extensions/browser/api/cast_channel/cast_auth_util.h" +#include "extensions/browser/api/cast_channel/logger.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace extensions { +namespace core_api { +namespace cast_channel { + +using proto::AggregatedSocketEvent; +using proto::EventType; +using proto::Log; +using proto::SocketEvent; + +class CastChannelLoggerTest : public testing::Test { + public: + // |logger_| will take ownership of |clock_|. + CastChannelLoggerTest() + : clock_(new base::SimpleTestTickClock), + logger_(new Logger(scoped_ptr<base::TickClock>(clock_), + base::TimeTicks())) {} + virtual ~CastChannelLoggerTest() {} + + protected: + base::SimpleTestTickClock* clock_; + scoped_refptr<Logger> logger_; +}; + +TEST_F(CastChannelLoggerTest, BasicLogging) { + logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + logger_->LogSocketEventWithDetails( + 1, EventType::TCP_SOCKET_CONNECT, "TCP socket"); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + logger_->LogSocketEvent(2, EventType::CAST_SOCKET_CREATED); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + logger_->LogSocketEventWithRv(1, EventType::SSL_SOCKET_CONNECT, -1); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + logger_->LogSocketEventForMessage( + 2, EventType::MESSAGE_ENQUEUED, "foo_namespace", "details"); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + + AuthResult auth_result = + AuthResult::Create("No response", AuthResult::ERROR_NO_RESPONSE); + + logger_->LogSocketChallengeReplyEvent(2, auth_result); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + + auth_result = AuthResult::CreateWithNSSError( + "Parsing failed", AuthResult::ERROR_NSS_CERT_PARSING_FAILED, 4); + logger_->LogSocketChallengeReplyEvent(2, auth_result); + + std::string output; + bool success = logger_->LogToString(&output); + ASSERT_TRUE(success); + + Log log; + success = log.ParseFromString(output); + ASSERT_TRUE(success); + + ASSERT_EQ(2, log.aggregated_socket_event_size()); + { + const AggregatedSocketEvent& aggregated_socket_event = + log.aggregated_socket_event(0); + EXPECT_EQ(1, aggregated_socket_event.id()); + EXPECT_EQ(3, aggregated_socket_event.socket_event_size()); + { + const SocketEvent& event = aggregated_socket_event.socket_event(0); + EXPECT_EQ(EventType::CAST_SOCKET_CREATED, event.type()); + EXPECT_EQ(0, event.timestamp_micros()); + } + { + const SocketEvent& event = aggregated_socket_event.socket_event(1); + EXPECT_EQ(EventType::TCP_SOCKET_CONNECT, event.type()); + EXPECT_EQ(1, event.timestamp_micros()); + EXPECT_EQ("TCP socket", event.details()); + } + { + const SocketEvent& event = aggregated_socket_event.socket_event(2); + EXPECT_EQ(EventType::SSL_SOCKET_CONNECT, event.type()); + EXPECT_EQ(3, event.timestamp_micros()); + EXPECT_EQ(-1, event.return_value()); + } + } + { + const AggregatedSocketEvent& aggregated_socket_event = + log.aggregated_socket_event(1); + EXPECT_EQ(2, aggregated_socket_event.id()); + EXPECT_EQ(4, aggregated_socket_event.socket_event_size()); + { + const SocketEvent& event = aggregated_socket_event.socket_event(0); + EXPECT_EQ(EventType::CAST_SOCKET_CREATED, event.type()); + EXPECT_EQ(2, event.timestamp_micros()); + } + { + const SocketEvent& event = aggregated_socket_event.socket_event(1); + EXPECT_EQ(EventType::MESSAGE_ENQUEUED, event.type()); + EXPECT_EQ(4, event.timestamp_micros()); + EXPECT_FALSE(event.has_message_namespace()); + EXPECT_EQ("details", event.details()); + } + { + const SocketEvent& event = aggregated_socket_event.socket_event(2); + EXPECT_EQ(EventType::AUTH_CHALLENGE_REPLY, event.type()); + EXPECT_EQ(5, event.timestamp_micros()); + EXPECT_EQ(proto::CHALLENGE_REPLY_ERROR_NO_RESPONSE, + event.challenge_reply_error_type()); + EXPECT_FALSE(event.has_return_value()); + } + { + const SocketEvent& event = aggregated_socket_event.socket_event(3); + EXPECT_EQ(EventType::AUTH_CHALLENGE_REPLY, event.type()); + EXPECT_EQ(6, event.timestamp_micros()); + EXPECT_EQ(proto::CHALLENGE_REPLY_ERROR_NSS_CERT_PARSING_FAILED, + event.challenge_reply_error_type()); + EXPECT_EQ(4, event.return_value()); + } + } +} + +TEST_F(CastChannelLoggerTest, TooManySockets) { + for (int i = 0; i < kMaxSocketsToLog + 5; i++) { + logger_->LogSocketEvent(i, EventType::CAST_SOCKET_CREATED); + } + + std::string output; + bool success = logger_->LogToString(&output); + ASSERT_TRUE(success); + + Log log; + success = log.ParseFromString(output); + ASSERT_TRUE(success); + + ASSERT_EQ(kMaxSocketsToLog, log.aggregated_socket_event_size()); + EXPECT_EQ(5, log.num_evicted_aggregated_socket_events()); + EXPECT_EQ(5, log.num_evicted_socket_events()); + + const AggregatedSocketEvent& aggregated_socket_event = + log.aggregated_socket_event(0); + EXPECT_EQ(5, aggregated_socket_event.id()); +} + +TEST_F(CastChannelLoggerTest, TooManyEvents) { + for (int i = 0; i < kMaxEventsPerSocket + 5; i++) { + logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED); + clock_->Advance(base::TimeDelta::FromMicroseconds(1)); + } + + std::string output; + bool success = logger_->LogToString(&output); + ASSERT_TRUE(success); + + Log log; + success = log.ParseFromString(output); + ASSERT_TRUE(success); + + ASSERT_EQ(1, log.aggregated_socket_event_size()); + EXPECT_EQ(0, log.num_evicted_aggregated_socket_events()); + EXPECT_EQ(5, log.num_evicted_socket_events()); + + const AggregatedSocketEvent& aggregated_socket_event = + log.aggregated_socket_event(0); + ASSERT_EQ(kMaxEventsPerSocket, aggregated_socket_event.socket_event_size()); + EXPECT_EQ(5, aggregated_socket_event.socket_event(0).timestamp_micros()); +} + +TEST_F(CastChannelLoggerTest, Reset) { + logger_->LogSocketEvent(1, EventType::CAST_SOCKET_CREATED); + + std::string output; + bool success = logger_->LogToString(&output); + ASSERT_TRUE(success); + + Log log; + success = log.ParseFromString(output); + ASSERT_TRUE(success); + + EXPECT_EQ(1, log.aggregated_socket_event_size()); + + logger_->Reset(); + + success = logger_->LogToString(&output); + ASSERT_TRUE(success); + success = log.ParseFromString(output); + ASSERT_TRUE(success); + + EXPECT_EQ(0, log.aggregated_socket_event_size()); +} + +} // namespace cast_channel +} // namespace api +} // namespace extensions diff --git a/extensions/browser/api/cast_channel/logging.proto b/extensions/browser/api/cast_channel/logging.proto new file mode 100644 index 0000000..57bd461 --- /dev/null +++ b/extensions/browser/api/cast_channel/logging.proto @@ -0,0 +1,147 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +syntax = "proto2"; + +option optimize_for = LITE_RUNTIME; + +package extensions.core_api.cast_channel.proto; + +enum EventType { + CAST_SOCKET_CREATED = 1; + READY_STATE_CHANGED = 2; + CONNECTION_STATE_CHANGED = 3; + READ_STATE_CHANGED = 4; + WRITE_STATE_CHANGED = 5; + ERROR_STATE_CHANGED = 6; + CONNECT_FAILED = 7; + TCP_SOCKET_CONNECT = 8; // Logged with RV. + TCP_SOCKET_SET_KEEP_ALIVE = 9; + SSL_CERT_WHITELISTED = 10; + SSL_SOCKET_CONNECT = 11; // Logged with RV. + SSL_INFO_OBTAINED = 12; + DER_ENCODED_CERT_OBTAIN = 13; // Logged with RV. + RECEIVED_CHALLENGE_REPLY = 14; + AUTH_CHALLENGE_REPLY = 15; + CONNECT_TIMED_OUT = 16; + SEND_MESSAGE_FAILED = 17; + MESSAGE_ENQUEUED = 18; // Message + SOCKET_WRITE = 19; // Logged with RV. + MESSAGE_WRITTEN = 20; // Message + SOCKET_READ = 21; // Logged with RV. + MESSAGE_READ = 22; // Message + NOTIFY_ON_MESSAGE = 23; // Message + NOTIFY_ON_ERROR = 24; + SOCKET_CLOSED = 25; +} + +enum ChannelAuth { + // SSL over TCP. + SSL = 1; + // SSL over TCP with challenge and receiver signature verification. + SSL_VERIFIED = 2; +} + +enum ReadyState { + READY_STATE_NONE = 1; + READY_STATE_CONNECTING = 2; + READY_STATE_OPEN = 3; + READY_STATE_CLOSING = 4; + READY_STATE_CLOSED = 5; +} + +enum ConnectionState { + CONN_STATE_NONE = 1; + CONN_STATE_TCP_CONNECT = 2; + CONN_STATE_TCP_CONNECT_COMPLETE = 3; + CONN_STATE_SSL_CONNECT = 4; + CONN_STATE_SSL_CONNECT_COMPLETE = 5; + CONN_STATE_AUTH_CHALLENGE_SEND = 6; + CONN_STATE_AUTH_CHALLENGE_SEND_COMPLETE = 7; + CONN_STATE_AUTH_CHALLENGE_REPLY_COMPLETE = 8; +} + +enum ReadState { + READ_STATE_NONE = 1; + READ_STATE_READ = 2; + READ_STATE_READ_COMPLETE = 3; + READ_STATE_DO_CALLBACK = 4; + READ_STATE_ERROR = 5; +} + +enum WriteState { + WRITE_STATE_NONE = 1; + WRITE_STATE_WRITE = 2; + WRITE_STATE_WRITE_COMPLETE = 3; + WRITE_STATE_DO_CALLBACK = 4; + WRITE_STATE_ERROR = 5; +} + +enum ErrorState { + CHANNEL_ERROR_NONE = 1; + CHANNEL_ERROR_CHANNEL_NOT_OPEN = 2; + CHANNEL_ERROR_AUTHENTICATION_ERROR = 3; + CHANNEL_ERROR_CONNECT_ERROR = 4; + CHANNEL_ERROR_SOCKET_ERROR = 5; + CHANNEL_ERROR_TRANSPORT_ERROR = 6; + CHANNEL_ERROR_INVALID_MESSAGE = 7; + CHANNEL_ERROR_INVALID_CHANNEL_ID = 8; + CHANNEL_ERROR_CONNECT_TIMEOUT = 9; + CHANNEL_ERROR_UNKNOWN = 10; +} + +enum ChallengeReplyErrorType { + CHALLENGE_REPLY_ERROR_NONE = 1; + CHALLENGE_REPLY_ERROR_PEER_CERT_EMPTY = 2; + CHALLENGE_REPLY_ERROR_WRONG_PAYLOAD_TYPE = 3; + CHALLENGE_REPLY_ERROR_NO_PAYLOAD = 4; + CHALLENGE_REPLY_ERROR_PAYLOAD_PARSING_FAILED = 5; + CHALLENGE_REPLY_ERROR_MESSAGE_ERROR = 6; + CHALLENGE_REPLY_ERROR_NO_RESPONSE = 7; + CHALLENGE_REPLY_ERROR_FINGERPRINT_NOT_FOUND = 8; + CHALLENGE_REPLY_ERROR_NSS_CERT_PARSING_FAILED = 9; + CHALLENGE_REPLY_ERROR_NSS_CERT_NOT_SIGNED_BY_TRUSTED_CA = 10; + CHALLENGE_REPLY_ERROR_NSS_CANNOT_EXTRACT_PUBLIC_KEY = 11; + CHALLENGE_REPLY_ERROR_NSS_SIGNED_BLOBS_MISMATCH = 12; +} + +message SocketEvent { + // Required + optional EventType type = 1; + optional int64 timestamp_micros = 2; + + optional string details = 3; + + optional int32 return_value = 4; + + optional string message_namespace = 5; + + optional ReadyState ready_state = 6; + optional ConnectionState connection_state = 7; + optional ReadState read_state = 8; + optional WriteState write_state = 9; + optional ErrorState error_state = 10; + + optional ChallengeReplyErrorType challenge_reply_error_type = 11; +} + +message AggregatedSocketEvent { + optional int32 id = 1; + optional int32 endpoint_id = 2; + optional ChannelAuth channel_auth_type = 3; + repeated SocketEvent socket_event = 4; +} + +message Log { + // Each AggregatedSocketEvent represents events recorded for a socket. + repeated AggregatedSocketEvent aggregated_socket_event = 1; + + // Number of socket log entries evicted by the logger due to size constraints. + optional int32 num_evicted_aggregated_socket_events = 2; + + // Number of event log entries evicted by the logger due to size constraints. + optional int32 num_evicted_socket_events = 3; + + // TODO(imcheng): Add other stats, such as bytes read/written across sockets. +} |