time: Remove all usages of chrono::*::now() and instead plumb in Time…

…System or TimeSource (#4434)

In order to fully control time during tests, direct calls to system-provided time functions must not be used. These had previously not been fixed. In at least one case I think there was real-time deltas being compared in a test, which really needed to be mocked, so that change had to occur in this PR. Another step toward resolution of #4160

Risk Level: medium, due to size of PR.
Testing: //test/...
Docs Changes: n/a
Release Notes: n/a

Signed-off-by: Joshua Marantz <jmarantz@google.com>

include/envoy/stats/timespan.h

@@ -15,8 +15,8 @@ namespace Stats {
  */
 class Timespan {
 public:
-  Timespan(Histogram& histogram)
-      : histogram_(histogram), start_(std::chrono::steady_clock::now()) {}
+  Timespan(Histogram& histogram, TimeSource& time_source)
+      : time_source_(time_source), histogram_(histogram), start_(time_source.monotonicTime()) {}
 
   /**
    * Complete the timespan and send the time to the histogram.
@@ -27,11 +27,12 @@ class Timespan {
    * Get duration since the creation of the span.
    */
   std::chrono::milliseconds getRawDuration() {
-    return std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::steady_clock::now() -
+    return std::chrono::duration_cast<std::chrono::milliseconds>(time_source_.monotonicTime() -
                                                                  start_);
   }
 
 private:
+  TimeSource& time_source_;
   Histogram& histogram_;
   const MonotonicTime start_;
 };

source/common/http/async_client_impl.cc

@@ -78,7 +78,7 @@ AsyncStreamImpl::AsyncStreamImpl(AsyncClientImpl& parent, AsyncClient::StreamCal
                                  const absl::optional<std::chrono::milliseconds>& timeout,
                                  bool buffer_body_for_retry)
     : parent_(parent), stream_callbacks_(callbacks), stream_id_(parent.config_.random_.random()),
-      router_(parent.config_), request_info_(Protocol::Http11),
+      router_(parent.config_), request_info_(Protocol::Http11, parent.dispatcher().timeSystem()),
       tracing_config_(Tracing::EgressConfig::get()),
       route_(std::make_shared<RouteImpl>(parent_.cluster_.name(), timeout)) {
   if (buffer_body_for_retry) {

source/common/http/conn_manager_impl.cc

@@ -59,16 +59,18 @@ ConnectionManagerImpl::ConnectionManagerImpl(ConnectionManagerConfig& config,
                                              Tracing::HttpTracer& tracer, Runtime::Loader& runtime,
                                              const LocalInfo::LocalInfo& local_info,
                                              Upstream::ClusterManager& cluster_manager,
-                                             Server::OverloadManager* overload_manager)
+                                             Server::OverloadManager* overload_manager,
+                                             Event::TimeSystem& time_system)
     : config_(config), stats_(config_.stats()),
-      conn_length_(new Stats::Timespan(stats_.named_.downstream_cx_length_ms_)),
+      conn_length_(new Stats::Timespan(stats_.named_.downstream_cx_length_ms_, time_system)),
       drain_close_(drain_close), random_generator_(random_generator), tracer_(tracer),
       runtime_(runtime), local_info_(local_info), cluster_manager_(cluster_manager),
       listener_stats_(config_.listenerStats()),
       overload_stop_accepting_requests_(
           overload_manager ? overload_manager->getThreadLocalOverloadState().getState(
                                  Server::OverloadActionNames::get().StopAcceptingRequests)
-                           : Server::OverloadManager::getInactiveState()) {}
+                           : Server::OverloadManager::getInactiveState()),
+      time_system_(time_system) {}
 
 const HeaderMapImpl& ConnectionManagerImpl::continueHeader() {
   CONSTRUCT_ON_FIRST_USE(HeaderMapImpl,
@@ -360,8 +362,9 @@ ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connect
     : connection_manager_(connection_manager),
       snapped_route_config_(connection_manager.config_.routeConfigProvider().config()),
       stream_id_(connection_manager.random_generator_.random()),
-      request_timer_(new Stats::Timespan(connection_manager_.stats_.named_.downstream_rq_time_)),
-      request_info_(connection_manager_.codec_->protocol()) {
+      request_timer_(new Stats::Timespan(connection_manager_.stats_.named_.downstream_rq_time_,
+                                         connection_manager_.timeSystem())),
+      request_info_(connection_manager_.codec_->protocol(), connection_manager_.timeSystem()) {
   connection_manager_.stats_.named_.downstream_rq_total_.inc();
   connection_manager_.stats_.named_.downstream_rq_active_.inc();
   if (connection_manager_.codec_->protocol() == Protocol::Http2) {

source/common/http/conn_manager_impl.h

@@ -51,7 +51,7 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
                         Runtime::RandomGenerator& random_generator, Tracing::HttpTracer& tracer,
                         Runtime::Loader& runtime, const LocalInfo::LocalInfo& local_info,
                         Upstream::ClusterManager& cluster_manager,
-                        Server::OverloadManager* overload_manager);
+                        Server::OverloadManager* overload_manager, Event::TimeSystem& time_system);
   ~ConnectionManagerImpl();
 
   static ConnectionManagerStats generateStats(const std::string& prefix, Stats::Scope& scope);
@@ -84,6 +84,8 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
     codec_->onUnderlyingConnectionBelowWriteBufferLowWatermark();
   }
 
+  Event::TimeSystem& timeSystem() { return time_system_; }
+
 private:
   struct ActiveStream;
 
@@ -459,6 +461,7 @@ class ConnectionManagerImpl : Logger::Loggable<Logger::Id::http>,
   Network::ReadFilterCallbacks* read_callbacks_{};
   ConnectionManagerListenerStats& listener_stats_;
   const Server::OverloadActionState& overload_stop_accepting_requests_;
+  Event::TimeSystem& time_system_;
 };
 
 } // namespace Http

source/common/http/http1/conn_pool.cc

@@ -312,8 +312,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
       connect_timer_(parent_.dispatcher_.createTimer([this]() -> void { onConnectTimeout(); })),
       remaining_requests_(parent_.host_->cluster().maxRequestsPerConnection()) {
 
-  parent_.conn_connect_ms_.reset(
-      new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_connect_ms_));
+  parent_.conn_connect_ms_.reset(new Stats::Timespan(
+      parent_.host_->cluster().stats().upstream_cx_connect_ms_, parent_.dispatcher_.timeSystem()));
   Upstream::Host::CreateConnectionData data =
       parent_.host_->createConnection(parent_.dispatcher_, parent_.socket_options_);
   real_host_description_ = data.host_description_;
@@ -325,7 +325,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
   parent_.host_->cluster().stats().upstream_cx_http1_total_.inc();
   parent_.host_->stats().cx_total_.inc();
   parent_.host_->stats().cx_active_.inc();
-  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_));
+  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_,
+                                         parent_.dispatcher_.timeSystem()));
   connect_timer_->enableTimer(parent_.host_->cluster().connectTimeout());
   parent_.host_->cluster().resourceManager(parent_.priority_).connections().inc();
 

source/common/http/http2/conn_pool.cc

@@ -219,8 +219,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
     : parent_(parent),
       connect_timer_(parent_.dispatcher_.createTimer([this]() -> void { onConnectTimeout(); })) {
 
-  parent_.conn_connect_ms_.reset(
-      new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_connect_ms_));
+  parent_.conn_connect_ms_.reset(new Stats::Timespan(
+      parent_.host_->cluster().stats().upstream_cx_connect_ms_, parent_.dispatcher_.timeSystem()));
   Upstream::Host::CreateConnectionData data =
       parent_.host_->createConnection(parent_.dispatcher_, parent_.socket_options_);
   real_host_description_ = data.host_description_;
@@ -235,7 +235,8 @@ ConnPoolImpl::ActiveClient::ActiveClient(ConnPoolImpl& parent)
   parent_.host_->cluster().stats().upstream_cx_total_.inc();
   parent_.host_->cluster().stats().upstream_cx_active_.inc();
   parent_.host_->cluster().stats().upstream_cx_http2_total_.inc();
-  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_));
+  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_,
+                                         parent_.dispatcher_.timeSystem()));
 
   client_->setConnectionStats({parent_.host_->cluster().stats().upstream_cx_rx_bytes_total_,
                                parent_.host_->cluster().stats().upstream_cx_rx_bytes_buffered_,

source/common/http/websocket/ws_handler_impl.cc

@@ -47,8 +47,8 @@ WsHandlerImpl::WsHandlerImpl(HeaderMap& request_headers, RequestInfo::RequestInf
                              WebSocketProxyCallbacks& callbacks,
                              Upstream::ClusterManager& cluster_manager,
                              Network::ReadFilterCallbacks* read_callbacks,
-                             TcpProxy::ConfigSharedPtr config)
-    : TcpProxy::Filter(config, cluster_manager), request_headers_(request_headers),
+                             TcpProxy::ConfigSharedPtr config, Event::TimeSystem& time_system)
+    : TcpProxy::Filter(config, cluster_manager, time_system), request_headers_(request_headers),
       request_info_(request_info), route_entry_(route_entry), ws_callbacks_(callbacks) {
 
   // set_connection_stats == false because the http connection manager has already set them

source/common/http/websocket/ws_handler_impl.h

@@ -35,7 +35,8 @@ class WsHandlerImpl : public TcpProxy::Filter, public Http::WebSocketProxy {
   WsHandlerImpl(HeaderMap& request_headers, RequestInfo::RequestInfo& request_info,
                 const Router::RouteEntry& route_entry, WebSocketProxyCallbacks& callbacks,
                 Upstream::ClusterManager& cluster_manager,
-                Network::ReadFilterCallbacks* read_callbacks, TcpProxy::ConfigSharedPtr config);
+                Network::ReadFilterCallbacks* read_callbacks, TcpProxy::ConfigSharedPtr config,
+                Event::TimeSystem& time_system);
 
   // Upstream::LoadBalancerContext
   const Router::MetadataMatchCriteria* metadataMatchCriteria() override {

source/common/request_info/request_info_impl.h

@@ -3,6 +3,7 @@
 #include <chrono>
 #include <cstdint>
 
+#include "envoy/common/time.h"
 #include "envoy/request_info/request_info.h"
 
 #include "common/common/assert.h"
@@ -12,11 +13,13 @@ namespace Envoy {
 namespace RequestInfo {
 
 struct RequestInfoImpl : public RequestInfo {
-  RequestInfoImpl()
-      : start_time_(std::chrono::system_clock::now()),
-        start_time_monotonic_(std::chrono::steady_clock::now()) {}
+  explicit RequestInfoImpl(TimeSource& time_source)
+      : time_source_(time_source), start_time_(time_source.systemTime()),
+        start_time_monotonic_(time_source.monotonicTime()) {}
 
-  RequestInfoImpl(Http::Protocol protocol) : RequestInfoImpl() { protocol_ = protocol; }
+  RequestInfoImpl(Http::Protocol protocol, TimeSource& time_source) : RequestInfoImpl(time_source) {
+    protocol_ = protocol;
+  }
 
   SystemTime startTime() const override { return start_time_; }
 
@@ -37,7 +40,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onLastDownstreamRxByteReceived() override {
     ASSERT(!last_downstream_rx_byte_received);
-    last_downstream_rx_byte_received = std::chrono::steady_clock::now();
+    last_downstream_rx_byte_received = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> firstUpstreamTxByteSent() const override {
@@ -46,7 +49,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onFirstUpstreamTxByteSent() override {
     ASSERT(!first_upstream_tx_byte_sent_);
-    first_upstream_tx_byte_sent_ = std::chrono::steady_clock::now();
+    first_upstream_tx_byte_sent_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> lastUpstreamTxByteSent() const override {
@@ -55,7 +58,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onLastUpstreamTxByteSent() override {
     ASSERT(!last_upstream_tx_byte_sent_);
-    last_upstream_tx_byte_sent_ = std::chrono::steady_clock::now();
+    last_upstream_tx_byte_sent_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> firstUpstreamRxByteReceived() const override {
@@ -64,7 +67,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onFirstUpstreamRxByteReceived() override {
     ASSERT(!first_upstream_rx_byte_received_);
-    first_upstream_rx_byte_received_ = std::chrono::steady_clock::now();
+    first_upstream_rx_byte_received_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> lastUpstreamRxByteReceived() const override {
@@ -73,7 +76,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onLastUpstreamRxByteReceived() override {
     ASSERT(!last_upstream_rx_byte_received_);
-    last_upstream_rx_byte_received_ = std::chrono::steady_clock::now();
+    last_upstream_rx_byte_received_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> firstDownstreamTxByteSent() const override {
@@ -82,7 +85,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onFirstDownstreamTxByteSent() override {
     ASSERT(!first_downstream_tx_byte_sent_);
-    first_downstream_tx_byte_sent_ = std::chrono::steady_clock::now();
+    first_downstream_tx_byte_sent_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> lastDownstreamTxByteSent() const override {
@@ -91,7 +94,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onLastDownstreamTxByteSent() override {
     ASSERT(!last_downstream_tx_byte_sent_);
-    last_downstream_tx_byte_sent_ = std::chrono::steady_clock::now();
+    last_downstream_tx_byte_sent_ = time_source_.monotonicTime();
   }
 
   absl::optional<std::chrono::nanoseconds> requestComplete() const override {
@@ -100,7 +103,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   void onRequestComplete() override {
     ASSERT(!final_time_);
-    final_time_ = std::chrono::steady_clock::now();
+    final_time_ = time_source_.monotonicTime();
   }
 
   void resetUpstreamTimings() override {
@@ -188,6 +191,7 @@ struct RequestInfoImpl : public RequestInfo {
 
   const std::string& requestedServerName() const override { return requested_server_name_; }
 
+  TimeSource& time_source_;
   const SystemTime start_time_;
   const MonotonicTime start_time_monotonic_;
 

source/common/router/config_impl.cc

@@ -267,7 +267,8 @@ RouteEntryImplBase::RouteEntryImplBase(const VirtualHostImpl& vhost,
       opaque_config_(parseOpaqueConfig(route)), decorator_(parseDecorator(route)),
       direct_response_code_(ConfigUtility::parseDirectResponseCode(route)),
       direct_response_body_(ConfigUtility::parseDirectResponseBody(route)),
-      per_filter_configs_(route.per_filter_config(), factory_context) {
+      per_filter_configs_(route.per_filter_config(), factory_context),
+      time_system_(factory_context.dispatcher().timeSystem()) {
   if (route.route().has_metadata_match()) {
     const auto filter_it = route.route().metadata_match().filter_metadata().find(
         Envoy::Config::MetadataFilters::get().ENVOY_LB);
@@ -352,9 +353,9 @@ Http::WebSocketProxyPtr RouteEntryImplBase::createWebSocketProxy(
     Http::HeaderMap& request_headers, RequestInfo::RequestInfo& request_info,
     Http::WebSocketProxyCallbacks& callbacks, Upstream::ClusterManager& cluster_manager,
     Network::ReadFilterCallbacks* read_callbacks) const {
-  return std::make_unique<Http::WebSocket::WsHandlerImpl>(request_headers, request_info, *this,
-                                                          callbacks, cluster_manager,
-                                                          read_callbacks, websocket_config_);
+  return std::make_unique<Http::WebSocket::WsHandlerImpl>(
+      request_headers, request_info, *this, callbacks, cluster_manager, read_callbacks,
+      websocket_config_, time_system_);
 }
 
 void RouteEntryImplBase::finalizeRequestHeaders(Http::HeaderMap& headers,

source/common/router/config_impl.h

@@ -558,6 +558,7 @@ class RouteEntryImplBase : public RouteEntry,
   const absl::optional<Http::Code> direct_response_code_;
   std::string direct_response_body_;
   PerFilterConfigs per_filter_configs_;
+  Event::TimeSystem& time_system_;
 };
 
 /**

source/common/router/router.cc

@@ -409,7 +409,8 @@ void Filter::maybeDoShadowing() {
 
 void Filter::onRequestComplete() {
   downstream_end_stream_ = true;
-  downstream_request_complete_time_ = std::chrono::steady_clock::now();
+  Event::Dispatcher& dispatcher = callbacks_->dispatcher();
+  downstream_request_complete_time_ = dispatcher.timeSystem().monotonicTime();
 
   // Possible that we got an immediate reset.
   if (upstream_request_) {
@@ -419,8 +420,7 @@ void Filter::onRequestComplete() {
 
     upstream_request_->setupPerTryTimeout();
     if (timeout_.global_timeout_.count() > 0) {
-      response_timeout_ =
-          callbacks_->dispatcher().createTimer([this]() -> void { onResponseTimeout(); });
+      response_timeout_ = dispatcher.createTimer([this]() -> void { onResponseTimeout(); });
       response_timeout_->enableTimer(timeout_.global_timeout_);
     }
   }
@@ -617,7 +617,8 @@ void Filter::onUpstreamHeaders(const uint64_t response_code, Http::HeaderMapPtr&
   // Only send upstream service time if we received the complete request and this is not a
   // premature response.
   if (DateUtil::timePointValid(downstream_request_complete_time_)) {
-    MonotonicTime response_received_time = std::chrono::steady_clock::now();
+    Event::Dispatcher& dispatcher = callbacks_->dispatcher();
+    MonotonicTime response_received_time = dispatcher.timeSystem().monotonicTime();
     std::chrono::milliseconds ms = std::chrono::duration_cast<std::chrono::milliseconds>(
         response_received_time - downstream_request_complete_time_);
     if (!config_.suppress_envoy_headers_) {
@@ -684,8 +685,9 @@ void Filter::onUpstreamComplete() {
 
   if (config_.emit_dynamic_stats_ && !callbacks_->requestInfo().healthCheck() &&
       DateUtil::timePointValid(downstream_request_complete_time_)) {
+    Event::Dispatcher& dispatcher = callbacks_->dispatcher();
     std::chrono::milliseconds response_time = std::chrono::duration_cast<std::chrono::milliseconds>(
-        std::chrono::steady_clock::now() - downstream_request_complete_time_);
+        dispatcher.timeSystem().monotonicTime() - downstream_request_complete_time_);
 
     upstream_request_->upstream_host_->outlierDetector().putResponseTime(response_time);
 
@@ -780,8 +782,9 @@ void Filter::doRetry() {
 
 Filter::UpstreamRequest::UpstreamRequest(Filter& parent, Http::ConnectionPool::Instance& pool)
     : parent_(parent), conn_pool_(pool), grpc_rq_success_deferred_(false),
-      request_info_(pool.protocol()), calling_encode_headers_(false), upstream_canary_(false),
-      encode_complete_(false), encode_trailers_(false) {
+      request_info_(pool.protocol(), parent_.callbacks_->dispatcher().timeSystem()),
+      calling_encode_headers_(false), upstream_canary_(false), encode_complete_(false),
+      encode_trailers_(false) {
 
   if (parent_.config_.start_child_span_) {
     span_ = parent_.callbacks_->activeSpan().spawnChild(

source/common/tcp/conn_pool.cc

@@ -309,8 +309,8 @@ ConnPoolImpl::ActiveConn::ActiveConn(ConnPoolImpl& parent)
       connect_timer_(parent_.dispatcher_.createTimer([this]() -> void { onConnectTimeout(); })),
       remaining_requests_(parent_.host_->cluster().maxRequestsPerConnection()), timed_out_(false) {
 
-  parent_.conn_connect_ms_.reset(
-      new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_connect_ms_));
+  parent_.conn_connect_ms_.reset(new Stats::Timespan(
+      parent_.host_->cluster().stats().upstream_cx_connect_ms_, parent_.dispatcher_.timeSystem()));
 
   Upstream::Host::CreateConnectionData data =
       parent_.host_->createConnection(parent_.dispatcher_, parent_.socket_options_);
@@ -329,7 +329,8 @@ ConnPoolImpl::ActiveConn::ActiveConn(ConnPoolImpl& parent)
   parent_.host_->cluster().stats().upstream_cx_active_.inc();
   parent_.host_->stats().cx_total_.inc();
   parent_.host_->stats().cx_active_.inc();
-  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_));
+  conn_length_.reset(new Stats::Timespan(parent_.host_->cluster().stats().upstream_cx_length_ms_,
+                                         parent_.dispatcher_.timeSystem()));
   connect_timer_->enableTimer(parent_.host_->cluster().connectTimeout());
   parent_.host_->cluster().resourceManager(parent_.priority_).connections().inc();