Source release 19.5.0

core/test/http_socket.cpp

@@ -1,13 +1,13 @@
 // Copyright 2018 Google LLC. All Rights Reserved. This file and proprietary
 // source code may only be used and distributed under the Widevine License
 // Agreement.
-
 #include "http_socket.h"
 
 #include <errno.h>
 #include <fcntl.h>
 #include <stdlib.h>
 #include <string.h>
+#include <time.h>
 
 #include <chrono>
 #include <mutex>
@@ -32,9 +32,7 @@
 #include "platform.h"
 
 namespace wvcdm {
-
 namespace {
-
 // Number of attempts to identify an Internet host and a service should the
 // host's nameserver be temporarily unavailable.  See getaddrinfo(3) for
 // more info.
@@ -138,6 +136,98 @@ const char* GetErrorString() {
 #endif
 }
 
+// Formats the provided time point to ISO 8601 format with space
+// date-time separator (Google's recommended format).
+std::string FormatTimePoint(const HttpSocket::TimePoint& time_point) {
+  const std::time_t epoch_time =
+      std::chrono::system_clock::to_time_t(time_point);
+  struct tm time_parts = {};
+  if (::gmtime_r(&epoch_time, &time_parts) == nullptr) {
+    const int saved_errno = GetError();
+    if (saved_errno == EOVERFLOW) {
+      LOGE("Overflow when converting to time parts: epoch_time = %zu",
+           static_cast<size_t>(epoch_time));
+    } else {
+      LOGE(
+          "Failed to convert time point to time parts: "
+          "epoch_time = %zu, errno = %d",
+          static_cast<size_t>(epoch_time), saved_errno);
+    }
+    // Just convert to epoch seconds.
+    return std::to_string(epoch_time);
+  }
+  static constexpr size_t kMaxLength = 127;
+  static constexpr char kTimeFormat[] = "%F %T";
+  char time_buffer[kMaxLength + 1];
+  const size_t res =
+      ::strftime(time_buffer, kMaxLength, kTimeFormat, &time_parts);
+  if (res == 0) {
+    LOGE("Failed to format time");
+    return std::to_string(epoch_time);
+  }
+  if (res > kMaxLength) {
+    // Very unlikely situation, but cannot trust the contents of
+    // |buffer| in this case.
+    LOGE("Unexpected output from strftime: max = %zu, res = %zu", kMaxLength,
+         res);
+    return std::to_string(epoch_time);
+  }
+  return std::string(time_buffer, &time_buffer[res]);
+}
+
+// Formats the provided duration to Google style duration format,
+// with microsecond accuracy.
+// The template parameter D should be a std::chrono::duration
+// type.  This is template to support C++ system_clock which
+// which duration accuracy may vary by platform.
+template <class D>
+std::string FormatDuration(const D& duration) {
+  D working_duration = duration;
+  std::string res;
+
+  // If duration is negative, add a '-' and continue with absolute.
+  if (working_duration < D::zero()) {
+    res.push_back('-');
+    working_duration = -working_duration;
+  }
+
+  // Format hours (if non-zero).
+  using Hours = std::chrono::hours;
+  const Hours h = std::chrono::floor<Hours>(working_duration);
+  if (h != Hours::zero()) {
+    res.append(std::to_string(h.count()));
+    res.push_back('h');
+    working_duration -= h;
+  }
+
+  // Format minutes (if non-zero).
+  using Minutes = std::chrono::minutes;
+  const Minutes m = std::chrono::floor<Minutes>(working_duration);
+  if (m != Minutes::zero()) {
+    res.append(std::to_string(m.count()));
+    res.push_back('m');
+    working_duration -= m;
+  }
+
+  // Format seconds (if non-zero).
+  using Seconds = std::chrono::seconds;
+  const Seconds s = std::chrono::floor<Seconds>(working_duration);
+  if (s != Seconds::zero()) {
+    res.append(std::to_string(s.count()));
+    res.push_back('s');
+    working_duration -= s;
+  }
+
+  // Format microseconds (if non-zero).
+  using Microseconds = std::chrono::microseconds;
+  const Microseconds us = std::chrono::floor<Microseconds>(working_duration);
+  if (us != Microseconds::zero()) {
+    res.append(std::to_string(us.count()));
+    res.append("us");
+  }
+
+  return res;
+}
 }  // namespace
 
 // Parses the URL and extracts all relevant information.
@@ -204,25 +294,22 @@ bool HttpSocket::ParseUrl(const std::string& url, std::string* scheme,
   return true;
 }
 
-HttpSocket::HttpSocket(const std::string& url)
-    : url_(url), socket_fd_(-1), ssl_(nullptr), ssl_ctx_(nullptr) {
+HttpSocket::HttpSocket(const std::string& url) : url_(url) {
   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();
 }
 
 HttpSocket::~HttpSocket() { CloseSocket(); }
 
 void HttpSocket::CloseSocket() {
-  if (socket_fd_ != -1) {
+  if (socket_fd_ != kClosedFd) {
 #ifdef _WIN32
     closesocket(socket_fd_);
 #else
     close(socket_fd_);
 #endif
-    socket_fd_ = -1;
+    socket_fd_ = kClosedFd;
   }
   if (ssl_) {
     SSL_free(ssl_);
@@ -235,12 +322,10 @@ 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);
+  const TimePoint start = GetNowTimePoint();
+  const bool result = Connect(timeout_in_ms);
+  const TimePoint end = GetNowTimePoint();
+  if (!result) LogTime("Socket connect error", start, end);
   return result;
 }
 
@@ -250,7 +335,7 @@ bool HttpSocket::Connect(int timeout_in_ms) {
     return false;
   }
 
-  if (socket_fd_ != -1) {
+  if (socket_fd_ != kClosedFd) {
     LOGE("Socket already connected");
     return false;
   }
@@ -416,12 +501,10 @@ bool HttpSocket::Connect(int timeout_in_ms) {
 // 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);
+  const TimePoint start = GetNowTimePoint();
+  const int result = Read(data, len, timeout_in_ms);
+  const TimePoint end = GetNowTimePoint();
+  if (result < 0) LogTime("Read error", start, end);
   return result;
 }
 
@@ -429,7 +512,7 @@ int HttpSocket::Read(char* data, int len, int timeout_in_ms) {
   int total_read = 0;
   int to_read = len;
 
-  if (socket_fd_ == -1) {
+  if (socket_fd_ == kClosedFd) {
     LOGE("Socket to %s not open.  Cannot read.", domain_name_.c_str());
     return -1;
   }
@@ -494,12 +577,10 @@ int HttpSocket::Read(char* data, int len, int timeout_in_ms) {
 // 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);
+  const TimePoint start = GetNowTimePoint();
+  const int result = Write(data, len, timeout_in_ms);
+  const TimePoint end = GetNowTimePoint();
+  if (result < 0) LogTime("Write error", start, end);
   return result;
 }
 
@@ -507,7 +588,7 @@ int HttpSocket::Write(const char* data, int len, int timeout_in_ms) {
   int total_sent = 0;
   int to_send = len;
 
-  if (socket_fd_ == -1) {
+  if (socket_fd_ == kClosedFd) {
     LOGE("Socket to %s not open. Cannot write.", domain_name_.c_str());
     return -1;
   }
@@ -555,13 +636,11 @@ bool HttpSocket::Wait(bool for_read, int timeout_in_ms) {
     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());
+  const TimePoint start = GetNowTimePoint();
+  const int ret = select(socket_fd_ + 1, read_fds, write_fds, nullptr, &tv);
+  const TimePoint end = GetNowTimePoint();
   if (ret == 0) {
-    LogTime("socket select timeout", start, finish);
+    LogTime("Socket select timeout", start, end);
     // 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);
@@ -575,13 +654,18 @@ bool HttpSocket::Wait(bool for_read, int timeout_in_ms) {
   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));
-}
+void HttpSocket::LogTime(const char* note, const TimePoint& start_time,
+                         const TimePoint& end_time) const {
+  const std::string start_string = FormatTimePoint(start_time);
+  const std::string create_start_diff_string =
+      FormatDuration(start_time - create_time_);
+  const std::string end_string = FormatTimePoint(end_time);
+  const std::string start_end_diff_string =
+      FormatDuration(end_time - start_time);
 
+  LOGE("%s: start = %s = create + %s, end = %s = start + %s",
+       note ? note : "<unspecified>", start_string.c_str(),
+       create_start_diff_string.c_str(), end_string.c_str(),
+       start_end_diff_string.c_str());
+}
 }  // namespace wvcdm