Merge "Add timestamp when socket times out"

libwvdrmengine/cdm/core/test/http_socket.cpp

@@ -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)) {
+    if (!Wait(/* for_read */ true, timeout_in_ms)) {
-      LOGE("unable to read from %s", domain_name_.c_str());
+      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

libwvdrmengine/cdm/core/test/http_socket.h

@@ -7,6 +7,7 @@
 
 #include <stdlib.h>
 
+#include <ctime>
 #include <string>
 
 #include <gtest/gtest_prod.h>
@@ -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 ReadAndLogErrors(char* data, int len, int timeout_in_ms);
-  int Write(const 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);
 };
 

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;

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 =
+    const int bytes = socket_.ReadAndLogErrors(read_buffer, sizeof(read_buffer),
-        socket_.Read(read_buffer, sizeof(read_buffer), kReadTimeoutMs);
+                                               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 =
+  const int ret = socket_.WriteAndLogErrors(request.c_str(), request.size(),
-      socket_.Write(request.c_str(), request.size(), kWriteTimeoutMs);
+                                            kWriteTimeoutMs);
   LOGV("HTTP request: (%zu): %s", request.size(), b2a_hex(request).c_str());
   return ret != -1;
 }