widevine-partner/android
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add timestamp when socket times out

Browse Source 
Merge from Widevine repo of http://go/wvgerrit/123407
and http://go/wvgerrit/130983

This should help us debug flaky tests.

Bug: 186031735
Change-Id: I5229176c80dad5875b6ef01ea167e4e26d48506d
This commit is contained in:
Fred Gylys-Colwell
2021-10-13 22:06:56 +00:00
parent c7e237eb00
commit 1a93b9f1cc
4 changed files with 114 additions and 50 deletions
Download Patch File Download Diff File Expand all files Collapse all files

125
libwvdrmengine/cdm/core/test/http_socket.cpp
View File

@@ -9,6 +9,7 @@
#include <stdlib.h>
#include <string.h>
#include <chrono>
#include <mutex>
#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