diff --git a/libwvdrmengine/cdm/core/test/http_socket.cpp b/libwvdrmengine/cdm/core/test/http_socket.cpp index 886ec687..eaff0520 100644 --- a/libwvdrmengine/cdm/core/test/http_socket.cpp +++ b/libwvdrmengine/cdm/core/test/http_socket.cpp @@ -9,6 +9,7 @@ #include #include +#include #include #ifdef _WIN32 @@ -108,40 +109,6 @@ void ShowServerCertificate(const SSL* ssl) { } #endif -// Wait for a socket to be ready for reading or writing. -// Establishing a connection counts as "ready for write". -// Returns false on select error or timeout. -// Returns true when the socket is ready. -bool SocketWait(int fd, bool for_read, int timeout_in_ms) { - fd_set fds; - FD_ZERO(&fds); - FD_SET(fd, &fds); - - struct timeval tv; - tv.tv_sec = timeout_in_ms / 1000; - tv.tv_usec = (timeout_in_ms % 1000) * 1000; - - fd_set* read_fds = nullptr; - fd_set* write_fds = nullptr; - if (for_read) { - read_fds = &fds; - } else { - write_fds = &fds; - } - - int ret = select(fd + 1, read_fds, write_fds, nullptr, &tv); - if (ret == 0) { - LOGE("socket timed out"); - return false; - } else if (ret == -1) { - LOGE("select failed, errno = %d", errno); - return false; - } - - // socket ready. - return true; -} - int GetError() { #ifdef _WIN32 return WSAGetLastError(); @@ -228,6 +195,8 @@ HttpSocket::HttpSocket(const std::string& url) : socket_fd_(-1), ssl_(nullptr), ssl_ctx_(nullptr) { valid_url_ = ParseUrl(url, &scheme_, &secure_connect_, &domain_name_, &port_, &resource_path_); + create_time_ = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); InitSslLibrary(); } @@ -252,6 +221,16 @@ void HttpSocket::CloseSocket() { } } +bool HttpSocket::ConnectAndLogErrors(int timeout_in_ms) { + std::time_t start = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + bool result = Connect(timeout_in_ms); + std::time_t finish = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + if (!result) LogTime("socket connect error", start, finish); + return result; +} + bool HttpSocket::Connect(int timeout_in_ms) { if (!valid_url_) { LOGE("URL is invalid"); @@ -355,7 +334,7 @@ bool HttpSocket::Connect(int timeout_in_ms) { return false; } else { // in progress. block until timeout expired or connection established. - if (!SocketWait(socket_fd_, /* for_read */ false, timeout_in_ms)) { + if (!Wait(/* for_read */ false, timeout_in_ms)) { LOGE("cannot connect to %s", domain_name_.c_str()); CloseSocket(); return false; @@ -399,7 +378,7 @@ bool HttpSocket::Connect(int timeout_in_ms) { return false; } const bool for_read = (ssl_err == SSL_ERROR_WANT_READ); - if (!SocketWait(socket_fd_, for_read, timeout_in_ms)) { + if (!Wait(for_read, timeout_in_ms)) { LOGE("Cannot connect securely to %s", domain_name_.c_str()); CloseSocket(); return false; @@ -414,6 +393,16 @@ bool HttpSocket::Connect(int timeout_in_ms) { // Returns -1 for error, number of bytes read for success. // The timeout here only applies to the span between packets of data, for the // sake of simplicity. +int HttpSocket::ReadAndLogErrors(char* data, int len, int timeout_in_ms) { + std::time_t start = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + int result = Read(data, len, timeout_in_ms); + std::time_t finish = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + if (result < 0) LogTime("read error", start, finish); + return result; +} + int HttpSocket::Read(char* data, int len, int timeout_in_ms) { int total_read = 0; int to_read = len; @@ -423,8 +412,9 @@ int HttpSocket::Read(char* data, int len, int timeout_in_ms) { return -1; } while (to_read > 0) { - if (!SocketWait(socket_fd_, /* for_read */ true, timeout_in_ms)) { - LOGE("unable to read from %s", domain_name_.c_str()); + if (!Wait(/* for_read */ true, timeout_in_ms)) { + LOGE("unable to read from %s. len=%d, to_read=%d", domain_name_.c_str(), + len, to_read); return -1; } @@ -480,6 +470,17 @@ int HttpSocket::Read(char* data, int len, int timeout_in_ms) { // Returns -1 for error, number of bytes written for success. // The timeout here only applies to the span between packets of data, for the // sake of simplicity. +int HttpSocket::WriteAndLogErrors(const char* data, int len, + int timeout_in_ms) { + std::time_t start = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + int result = Write(data, len, timeout_in_ms); + std::time_t finish = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + if (result < 0) LogTime("write error", start, finish); + return result; +} + int HttpSocket::Write(const char* data, int len, int timeout_in_ms) { int total_sent = 0; int to_send = len; @@ -502,7 +503,7 @@ int HttpSocket::Write(const char* data, int len, int timeout_in_ms) { total_sent += sent; } else if (sent == 0) { // We filled up the pipe. Wait for room to write. - if (!SocketWait(socket_fd_, /* for_read */ false, timeout_in_ms)) { + if (!Wait(/* for_read */ false, timeout_in_ms)) { LOGE("unable to write to %s", domain_name_.c_str()); return -1; } @@ -515,4 +516,50 @@ int HttpSocket::Write(const char* data, int len, int timeout_in_ms) { return total_sent; } +bool HttpSocket::Wait(bool for_read, int timeout_in_ms) { + fd_set fds; + FD_ZERO(&fds); + FD_SET(socket_fd_, &fds); + + struct timeval tv; + tv.tv_sec = timeout_in_ms / 1000; + tv.tv_usec = (timeout_in_ms % 1000) * 1000; + + fd_set* read_fds = nullptr; + fd_set* write_fds = nullptr; + if (for_read) { + read_fds = &fds; + } else { + write_fds = &fds; + } + + const std::time_t start = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + int ret = select(socket_fd_ + 1, read_fds, write_fds, nullptr, &tv); + const std::time_t finish = + std::chrono::system_clock::to_time_t(std::chrono::system_clock::now()); + if (ret == 0) { + LogTime("socket select timeout", start, finish); + // TODO(b/186031735): Remove this when the bug is fixed. + LOGE("Timeout = %0.3f. Consider adding a comment to http://b/186031735", + 0.001 * timeout_in_ms); + return false; + } else if (ret == -1) { + LOGE("select failed, errno = %d", errno); + return false; + } + + // socket ready. + return true; +} + +void HttpSocket::LogTime(const char* note, const std::time_t& start, + const std::time_t& finish) { + std::string start_string = std::string(std::ctime(&start)); + start_string.pop_back(); // Remove new line character. + LOGE("%s: start = %s = create + %0.3f, end = start + %0.3f", note, + start_string.c_str(), difftime(start, create_time_), + difftime(finish, start)); +} + } // namespace wvcdm diff --git a/libwvdrmengine/cdm/core/test/http_socket.h b/libwvdrmengine/cdm/core/test/http_socket.h index 4c7bc305..f32612a1 100644 --- a/libwvdrmengine/cdm/core/test/http_socket.h +++ b/libwvdrmengine/cdm/core/test/http_socket.h @@ -7,6 +7,7 @@ #include +#include #include #include @@ -23,7 +24,7 @@ class HttpSocket { explicit HttpSocket(const std::string& url); ~HttpSocket(); - bool Connect(int timeout_in_ms); + bool ConnectAndLogErrors(int timeout_in_ms); void CloseSocket(); const std::string& scheme() const { return scheme_; } @@ -32,13 +33,25 @@ class HttpSocket { int port() const { return atoi(port_.c_str()); } const std::string& resource_path() const { return resource_path_; } - int Read(char* data, int len, int timeout_in_ms); - int Write(const char* data, int len, int timeout_in_ms); + int ReadAndLogErrors(char* data, int len, int timeout_in_ms); + int WriteAndLogErrors(const char* data, int len, int timeout_in_ms); private: static bool ParseUrl(const std::string& url, std::string* scheme, bool* secure_connect, std::string* domain_name, std::string* port, std::string* path); + // The following three functions do the work without logging errors. + bool Connect(int timeout_in_ms); + int Read(char* data, int len, int timeout_in_ms); + int Write(const char* data, int len, int timeout_in_ms); + // Log times with a note as an error. + void LogTime(const char* note, const std::time_t& start, + const std::time_t& finish); + // Wait for a socket to be ready for reading or writing. + // Establishing a connection counts as "ready for write". + // Returns false on select error or timeout. + // Returns true when the socket is ready. + bool Wait(bool for_read, int timeout_in_ms); FRIEND_TEST(HttpSocketTest, ParseUrlTest); std::string scheme_; @@ -52,6 +65,10 @@ class HttpSocket { SSL* ssl_; SSL_CTX* ssl_ctx_; + // When the socket was created. Logged on error to help debug flaky + // tests. e.g. b/186031735 + std::time_t create_time_; + CORE_DISALLOW_COPY_AND_ASSIGN(HttpSocket); }; diff --git a/libwvdrmengine/cdm/core/test/http_socket_test.cpp b/libwvdrmengine/cdm/core/test/http_socket_test.cpp index 34a9f375..974a1e38 100644 --- a/libwvdrmengine/cdm/core/test/http_socket_test.cpp +++ b/libwvdrmengine/cdm/core/test/http_socket_test.cpp @@ -36,7 +36,7 @@ class HttpSocketTest : public testing::Test { bool Connect(const std::string& server_url) { socket_.reset(new HttpSocket(server_url)); - if (socket_->Connect(kTimeout)) { + if (socket_->ConnectAndLogErrors(kTimeout)) { LOGD("connected to %s", socket_->domain_name().c_str()); return true; } else { @@ -73,7 +73,7 @@ class HttpSocketTest : public testing::Test { // append data request.append(data); - socket_->Write(request.c_str(), request.size(), kTimeout); + socket_->WriteAndLogErrors(request.c_str(), request.size(), kTimeout); LOGD("request: %s", request.c_str()); return true; @@ -81,7 +81,7 @@ class HttpSocketTest : public testing::Test { bool GetResponse(std::string* response) { char buffer[kHttpBufferSize]; - int bytes = socket_->Read(buffer, sizeof(buffer), kTimeout); + int bytes = socket_->ReadAndLogErrors(buffer, sizeof(buffer), kTimeout); if (bytes < 0) { LOGE("read error, errno = %d", errno); return false; diff --git a/libwvdrmengine/cdm/core/test/url_request.cpp b/libwvdrmengine/cdm/core/test/url_request.cpp index c2fb1ec9..42a4c126 100644 --- a/libwvdrmengine/cdm/core/test/url_request.cpp +++ b/libwvdrmengine/cdm/core/test/url_request.cpp @@ -87,7 +87,7 @@ UrlRequest::~UrlRequest() {} void UrlRequest::Reconnect() { for (uint32_t i = 0; i < kMaxConnectAttempts && !is_connected_; ++i) { socket_.CloseSocket(); - if (socket_.Connect(kConnectTimeoutMs)) { + if (socket_.ConnectAndLogErrors(kConnectTimeoutMs)) { is_connected_ = true; } else { LOGE("Failed to connect: url = %s, port = %d, attempt = %u", @@ -104,8 +104,8 @@ bool UrlRequest::GetResponse(std::string* message) { // non-blocking mode. while (true) { char read_buffer[kReadBufferSize]; - const int bytes = - socket_.Read(read_buffer, sizeof(read_buffer), kReadTimeoutMs); + const int bytes = socket_.ReadAndLogErrors(read_buffer, sizeof(read_buffer), + kReadTimeoutMs); if (bytes > 0) { response.append(read_buffer, bytes); } else if (bytes < 0) { @@ -203,8 +203,8 @@ bool UrlRequest::PostRequestWithPath(const std::string& path, request.append(data); - const int ret = - socket_.Write(request.c_str(), request.size(), kWriteTimeoutMs); + const int ret = socket_.WriteAndLogErrors(request.c_str(), request.size(), + kWriteTimeoutMs); LOGV("HTTP request: (%zu): %s", request.size(), b2a_hex(request).c_str()); return ret != -1; }