access log formatter: use new formatter context rather than multiple …

…parameters (3/3) (envoyproxy#30758) access log formatter: use new formatter context rather than multiple parameters (3/3) Additional Description: Continuous work of envoyproxy#30757. Waiting envoyproxy#30757 to be landed first. The PR update the log Instance interface to be a specialization of InstanceBase with context type HttpFormatterContext. And by this way, the log() method of Filter is updated to take a HttpFormatterContext reference as parameter. This PR also do similar update to the AccessLogInstanceFactory and make it a specialization of AccessLogInstanceFactoryBase. By this way, log instances of different modules will share the same code base. Note, to ensure the backwards compatibility, the extension category of log instance should be kept as envoy.access_loggers. This is the last PR of this big refactoring. After landed this PR, we will finally completely migrate our formatter/logger to use the context based interface. This will bring two obvious benefits: it's easier to make the common part of these code be a template. All formatter-based loggers could be shared by different modules like dubbo proxy, generic proxy or even redis/mysql if necessary (some minor update is still necessary, but it's simple and minor). it's easier to extend the logger/formatter to add new feature like request trailer support. We needn't to change almost every log()/format() call to add a feature that only used in part of positions anymore. (think of the access log type 😥 ). Risk Level: low. Testing: n/a. Docs Changes: n/a. Release Notes: n/a. Platform Specific Features: n/a. Signed-off-by: wbpcode <[email protected]>
fredyw · Nov 9, 2023 · 8dff697 · 8dff697
1 parent e93e556
commit 8dff697
Show file tree

Hide file tree

Showing 48 changed files with 448 additions and 622 deletions.
diff --git a/contrib/golang/filters/http/source/golang_filter.cc b/contrib/golang/filters/http/source/golang_filter.cc
@@ -211,11 +211,10 @@ void Filter::onDestroy() {
 }
 
 // access_log is executed before the log of the stream filter
-void Filter::log(const Http::RequestHeaderMap* headers, const Http::ResponseHeaderMap*,
-                 const Http::ResponseTrailerMap*, const StreamInfo::StreamInfo&,
-                 Envoy::AccessLog::AccessLogType type) {
+void Filter::log(const Formatter::HttpFormatterContext& log_context,
+                 const StreamInfo::StreamInfo&) {
   // `log` may be called multiple times with different log type
-  switch (type) {
+  switch (log_context.accessLogType()) {
   case Envoy::AccessLog::AccessLogType::DownstreamStart:
   case Envoy::AccessLog::AccessLogType::DownstreamPeriodic:
   case Envoy::AccessLog::AccessLogType::DownstreamEnd: {
@@ -226,12 +225,12 @@ void Filter::log(const Http::RequestHeaderMap* headers, const Http::ResponseHead
       initRequest(state);
 
       request_headers_ = static_cast<Http::RequestOrResponseHeaderMap*>(
-          const_cast<Http::RequestHeaderMap*>(headers));
+          const_cast<Http::RequestHeaderMap*>(&log_context.requestHeaders()));
     }
 
     state.enterLog();
     req_->phase = static_cast<int>(state.phase());
-    dynamic_lib_->envoyGoFilterOnHttpLog(req_, int(type));
+    dynamic_lib_->envoyGoFilterOnHttpLog(req_, int(log_context.accessLogType()));
     state.leaveLog();
   } break;
   default:

diff --git a/contrib/golang/filters/http/source/golang_filter.h b/contrib/golang/filters/http/source/golang_filter.h
@@ -204,11 +204,8 @@ class Filter : public Http::StreamFilter,
   }
 
   // AccessLog::Instance
-  void log(const Http::RequestHeaderMap* request_headers,
-           const Http::ResponseHeaderMap* response_headers,
-           const Http::ResponseTrailerMap* response_trailers,
-           const StreamInfo::StreamInfo& stream_info,
-           Envoy::AccessLog::AccessLogType access_log_type) override;
+  void log(const Formatter::HttpFormatterContext& log_context,
+           const StreamInfo::StreamInfo& info) override;
 
   void onStreamComplete() override {}
 

diff --git a/envoy/access_log/access_log.h b/envoy/access_log/access_log.h
@@ -99,28 +99,9 @@ using Filter = FilterBase<Formatter::HttpFormatterContext>;
 using FilterPtr = std::unique_ptr<Filter>;
 
 /**
- * Abstract access logger for requests and connections.
+ * Abstract access logger for HTTP requests and TCP connections.
  */
-class Instance {
-public:
-  virtual ~Instance() = default;
-
-  /**
-   * Log a completed request.
-   * @param request_headers supplies the incoming request headers after filtering.
-   * @param response_headers supplies response headers.
-   * @param response_trailers supplies response trailers.
-   * @param stream_info supplies additional information about the request not
-   * contained in the request headers.
-   * @param access_log_type supplies additional information about the type of the
-   * log record, i.e the location in the code which recorded the log.
-   */
-  virtual void log(const Http::RequestHeaderMap* request_headers,
-                   const Http::ResponseHeaderMap* response_headers,
-                   const Http::ResponseTrailerMap* response_trailers,
-                   const StreamInfo::StreamInfo& stream_info, AccessLogType access_log_type) PURE;
-};
-
+using Instance = InstanceBase<Formatter::HttpFormatterContext>;
 using InstanceSharedPtr = std::shared_ptr<Instance>;
 
 } // namespace AccessLog

diff --git a/envoy/access_log/access_log_config.h b/envoy/access_log/access_log_config.h
@@ -58,8 +58,7 @@ using ExtensionFilterFactory = ExtensionFilterFactoryBase<Formatter::HttpFormatt
  */
 template <class Context> class AccessLogInstanceFactoryBase : public Config::TypedFactory {
 public:
-  AccessLogInstanceFactoryBase()
-      : category_(fmt::format("envoy.{}.access_loggers", Context::category())) {}
+  AccessLogInstanceFactoryBase() : category_(categoryByType()) {}
 
   ~AccessLogInstanceFactoryBase() override = default;
 
@@ -94,45 +93,19 @@ template <class Context> class AccessLogInstanceFactoryBase : public Config::Typ
   std::string category() const override { return category_; }
 
 private:
+  std::string categoryByType() {
+    if constexpr (std::is_same_v<Context, Formatter::HttpFormatterContext>) {
+      // This is a special case for the HTTP formatter context to ensure backwards compatibility.
+      return "envoy.access_loggers";
+    } else {
+      return fmt::format("envoy.{}.access_loggers", Context::category());
+    }
+  }
+
   const std::string category_;
 };
 
-/**
- * Implemented for each AccessLog::Instance and registered via Registry::registerFactory or the
- * convenience class RegisterFactory.
- */
-class AccessLogInstanceFactory : public Config::TypedFactory {
-public:
-  ~AccessLogInstanceFactory() override = default;
-
-  /**
-   * Create a particular AccessLog::Instance implementation from a config proto. If the
-   * implementation is unable to produce a factory with the provided parameters, it should throw an
-   * EnvoyException. The returned pointer should never be nullptr.
-   * @param config the custom configuration for this access log type.
-   * @param filter filter to determine whether a particular request should be logged. If no filter
-   * was specified in the configuration, argument will be nullptr.
-   * @param context access log context through which persistent resources can be accessed.
-   */
-  virtual AccessLog::InstanceSharedPtr
-  createAccessLogInstance(const Protobuf::Message& config, AccessLog::FilterPtr&& filter,
-                          Server::Configuration::ListenerAccessLogFactoryContext& context) PURE;
-
-  /**
-   * Create a particular AccessLog::Instance implementation from a config proto. If the
-   * implementation is unable to produce a factory with the provided parameters, it should throw an
-   * EnvoyException. The returned pointer should never be nullptr.
-   * @param config the custom configuration for this access log type.
-   * @param filter filter to determine whether a particular request should be logged. If no filter
-   * was specified in the configuration, argument will be nullptr.
-   * @param context general filter context through which persistent resources can be accessed.
-   */
-  virtual AccessLog::InstanceSharedPtr
-  createAccessLogInstance(const Protobuf::Message& config, AccessLog::FilterPtr&& filter,
-                          Server::Configuration::CommonFactoryContext& context) PURE;
-
-  std::string category() const override { return "envoy.access_loggers"; }
-};
+using AccessLogInstanceFactory = AccessLogInstanceFactoryBase<Formatter::HttpFormatterContext>;
 
 } // namespace AccessLog
 } // namespace Envoy
diff --git a/source/common/access_log/BUILD b/source/common/access_log/BUILD
@@ -26,6 +26,7 @@ envoy_cc_library(
         "//source/common/common:assert_lib",
         "//source/common/common:utility_lib",
         "//source/common/config:utility_lib",
+        "//source/common/formatter:substitution_formatter_lib",
         "//source/common/http:header_map_lib",
         "//source/common/http:header_utility_lib",
         "//source/common/http:headers_lib",

diff --git a/source/common/http/filter_manager.h b/source/common/http/filter_manager.h
@@ -688,22 +688,15 @@ class FilterManager : public ScopeTrackedObject,
   void applyFilterFactoryCb(FilterContext context, FilterFactoryCb& factory) override;
 
   void log(AccessLog::AccessLogType access_log_type) {
-    RequestHeaderMap* request_headers = nullptr;
-    if (filter_manager_callbacks_.requestHeaders()) {
-      request_headers = filter_manager_callbacks_.requestHeaders().ptr();
-    }
-    ResponseHeaderMap* response_headers = nullptr;
-    if (filter_manager_callbacks_.responseHeaders()) {
-      response_headers = filter_manager_callbacks_.responseHeaders().ptr();
-    }
-    ResponseTrailerMap* response_trailers = nullptr;
-    if (filter_manager_callbacks_.responseTrailers()) {
-      response_trailers = filter_manager_callbacks_.responseTrailers().ptr();
-    }
+    const Formatter::HttpFormatterContext log_context{
+        filter_manager_callbacks_.requestHeaders().ptr(),
+        filter_manager_callbacks_.responseHeaders().ptr(),
+        filter_manager_callbacks_.responseTrailers().ptr(),
+        {},
+        access_log_type};
 
     for (const auto& log_handler : access_log_handlers_) {
-      log_handler->log(request_headers, response_headers, response_trailers, streamInfo(),
-                       access_log_type);
+      log_handler->log(log_context, streamInfo());
     }
   }
 

diff --git a/source/common/quic/quic_stats_gatherer.cc b/source/common/quic/quic_stats_gatherer.cc
@@ -28,12 +28,15 @@ void QuicStatsGatherer::maybeDoDeferredLog(bool record_ack_timing) {
   }
   stream_info_->addBytesRetransmitted(retransmitted_bytes_);
   stream_info_->addPacketsRetransmitted(retransmitted_packets_);
-  const Http::RequestHeaderMap* request_headers = request_header_map_.get();
-  const Http::ResponseHeaderMap* response_headers = response_header_map_.get();
-  const Http::ResponseTrailerMap* response_trailers = response_trailer_map_.get();
+
+  const Formatter::HttpFormatterContext log_context{request_header_map_.get(),
+                                                    response_header_map_.get(),
+                                                    response_trailer_map_.get(),
+                                                    {},
+                                                    AccessLog::AccessLogType::DownstreamEnd};
+
   for (const AccessLog::InstanceSharedPtr& log_handler : access_log_handlers_) {
-    log_handler->log(request_headers, response_headers, response_trailers, *stream_info_,
-                     AccessLog::AccessLogType::DownstreamEnd);
+    log_handler->log(log_context, *stream_info_);
   }
 }
 

diff --git a/source/common/router/upstream_request.cc b/source/common/router/upstream_request.cc
@@ -231,9 +231,14 @@ void UpstreamRequest::cleanUp() {
 }
 
 void UpstreamRequest::upstreamLog(AccessLog::AccessLogType access_log_type) {
+  const Formatter::HttpFormatterContext log_context{parent_.downstreamHeaders(),
+                                                    upstream_headers_.get(),
+                                                    upstream_trailers_.get(),
+                                                    {},
+                                                    access_log_type};
+
   for (const auto& upstream_log : parent_.config().upstream_logs_) {
-    upstream_log->log(parent_.downstreamHeaders(), upstream_headers_.get(),
-                      upstream_trailers_.get(), stream_info_, access_log_type);
+    upstream_log->log(log_context, stream_info_);
   }
 }
 

diff --git a/source/common/tcp_proxy/tcp_proxy.cc b/source/common/tcp_proxy/tcp_proxy.cc
@@ -223,10 +223,12 @@ Filter::~Filter() {
   // Disable access log flush timer if it is enabled.
   disableAccessLogFlushTimer();
 
+  const Formatter::HttpFormatterContext log_context{
+      nullptr, nullptr, nullptr, {}, AccessLog::AccessLogType::TcpConnectionEnd};
+
   // Flush the final end stream access log entry.
   for (const auto& access_log : config_->accessLogs()) {
-    access_log->log(nullptr, nullptr, nullptr, getStreamInfo(),
-                    AccessLog::AccessLogType::TcpConnectionEnd);
+    access_log->log(log_context, getStreamInfo());
   }
 
   ASSERT(generic_conn_pool_ == nullptr);
@@ -852,9 +854,11 @@ void Filter::onUpstreamConnection() {
   }
 
   if (config_->flushAccessLogOnConnected()) {
+    const Formatter::HttpFormatterContext log_context{
+        nullptr, nullptr, nullptr, {}, AccessLog::AccessLogType::TcpUpstreamConnected};
+
     for (const auto& access_log : config_->accessLogs()) {
-      access_log->log(nullptr, nullptr, nullptr, getStreamInfo(),
-                      AccessLog::AccessLogType::TcpUpstreamConnected);
+      access_log->log(log_context, getStreamInfo());
     }
   }
 }
@@ -878,9 +882,11 @@ void Filter::onMaxDownstreamConnectionDuration() {
 }
 
 void Filter::onAccessLogFlushInterval() {
+  const Formatter::HttpFormatterContext log_context{
+      nullptr, nullptr, nullptr, {}, AccessLog::AccessLogType::TcpPeriodic};
+
   for (const auto& access_log : config_->accessLogs()) {
-    access_log->log(nullptr, nullptr, nullptr, getStreamInfo(),
-                    AccessLog::AccessLogType::TcpPeriodic);
+    access_log->log(log_context, getStreamInfo());
   }
   const SystemTime now = read_callbacks_->connection().dispatcher().timeSource().systemTime();
   getStreamInfo().getDownstreamBytesMeter()->takeDownstreamPeriodicLoggingSnapshot(now);

diff --git a/source/extensions/access_loggers/common/access_log_base.cc b/source/extensions/access_loggers/common/access_log_base.cc
@@ -8,13 +8,8 @@ namespace Extensions {
 namespace AccessLoggers {
 namespace Common {
 
-void ImplBase::log(const Http::RequestHeaderMap* request_headers,
-                   const Http::ResponseHeaderMap* response_headers,
-                   const Http::ResponseTrailerMap* response_trailers,
-                   const StreamInfo::StreamInfo& stream_info,
-                   AccessLog::AccessLogType access_log_type) {
-  Formatter::HttpFormatterContext log_context{
-      request_headers, response_headers, response_trailers, {}, access_log_type};
+void ImplBase::log(const Formatter::HttpFormatterContext& log_context,
+                   const StreamInfo::StreamInfo& stream_info) {
 
   if (filter_ && !filter_->evaluate(log_context, stream_info)) {
     return;

diff --git a/source/extensions/access_loggers/common/access_log_base.h b/source/extensions/access_loggers/common/access_log_base.h
@@ -26,11 +26,8 @@ class ImplBase : public AccessLog::Instance {
   /**
    * Log a completed request if the underlying AccessLog `filter_` allows it.
    */
-  void log(const Http::RequestHeaderMap* request_headers,
-           const Http::ResponseHeaderMap* response_headers,
-           const Http::ResponseTrailerMap* response_trailers,
-           const StreamInfo::StreamInfo& stream_info,
-           AccessLog::AccessLogType access_log_type) override;
+  void log(const Formatter::HttpFormatterContext& log_context,
+           const StreamInfo::StreamInfo& stream_info) override;
 
 private:
   /**

diff --git a/source/extensions/access_loggers/wasm/wasm_access_log_impl.h b/source/extensions/access_loggers/wasm/wasm_access_log_impl.h
@@ -20,30 +20,20 @@ class WasmAccessLog : public AccessLog::Instance {
                 AccessLog::FilterPtr filter)
       : plugin_(plugin), tls_slot_(std::move(tls_slot)), filter_(std::move(filter)) {}
 
-  void log(const Http::RequestHeaderMap* request_headers,
-           const Http::ResponseHeaderMap* response_headers,
-           const Http::ResponseTrailerMap* response_trailers,
-           const StreamInfo::StreamInfo& stream_info,
-           AccessLog::AccessLogType access_log_type) override {
+  void log(const Formatter::HttpFormatterContext& log_context,
+           const StreamInfo::StreamInfo& stream_info) override {
     if (filter_) {
-      const Formatter::HttpFormatterContext log_context{
-          request_headers, response_headers, response_trailers, {}, access_log_type};
-
       if (!filter_->evaluate(log_context, stream_info)) {
         return;
       }
     }
 
-    if (!tls_slot_) {
-      return;
-    }
-    auto handle = tls_slot_->get()->handle();
-    if (!handle) {
-      return;
-    }
-    if (handle->wasmHandle()) {
-      handle->wasmHandle()->wasm()->log(plugin_, request_headers, response_headers,
-                                        response_trailers, stream_info, access_log_type);
+    if (tls_slot_ != nullptr) {
+      if (auto handle = tls_slot_->get()->handle(); handle != nullptr) {
+        if (handle->wasmHandle()) {
+          handle->wasmHandle()->wasm()->log(plugin_, log_context, stream_info);
+        }
+      }
     }
   }
 

diff --git a/source/extensions/common/wasm/context.cc b/source/extensions/common/wasm/context.cc
@@ -1476,10 +1476,8 @@ void Context::initializeWriteFilterCallbacks(Network::WriteFilterCallbacks& call
   network_write_filter_callbacks_ = &callbacks;
 }
 
-void Context::log(const Http::RequestHeaderMap* request_headers,
-                  const Http::ResponseHeaderMap* response_headers,
-                  const Http::ResponseTrailerMap* response_trailers,
-                  const StreamInfo::StreamInfo& stream_info, AccessLog::AccessLogType) {
+void Context::log(const Formatter::HttpFormatterContext& log_context,
+                  const StreamInfo::StreamInfo& stream_info) {
   // `log` may be called multiple times due to mid-request logging -- we only want to run on the
   // last call.
   if (!stream_info.requestComplete().has_value()) {
@@ -1495,10 +1493,10 @@ void Context::log(const Http::RequestHeaderMap* request_headers,
   }
 
   access_log_phase_ = true;
-  access_log_request_headers_ = request_headers;
+  access_log_request_headers_ = &log_context.requestHeaders();
   // ? request_trailers  ?
-  access_log_response_headers_ = response_headers;
-  access_log_response_trailers_ = response_trailers;
+  access_log_response_headers_ = &log_context.responseHeaders();
+  access_log_response_trailers_ = &log_context.responseTrailers();
   access_log_stream_info_ = &stream_info;
 
   onLog();

diff --git a/source/extensions/common/wasm/context.h b/source/extensions/common/wasm/context.h
@@ -148,11 +148,8 @@ class Context : public proxy_wasm::ContextBase,
                                      const std::shared_ptr<PluginBase>& plugin); // deprecated
 
   // AccessLog::Instance
-  void log(const Http::RequestHeaderMap* request_headers,
-           const Http::ResponseHeaderMap* response_headers,
-           const Http::ResponseTrailerMap* response_trailers,
-           const StreamInfo::StreamInfo& stream_info,
-           AccessLog::AccessLogType access_log_type) override;
+  void log(const Formatter::HttpFormatterContext& log_context,
+           const StreamInfo::StreamInfo& info) override;
 
   uint32_t getLogLevel() override;
 

diff --git a/source/extensions/common/wasm/wasm.cc b/source/extensions/common/wasm/wasm.cc
@@ -226,13 +226,10 @@ ContextBase* Wasm::createRootContext(const std::shared_ptr<PluginBase>& plugin)
 
 ContextBase* Wasm::createVmContext() { return new Context(this); }
 
-void Wasm::log(const PluginSharedPtr& plugin, const Http::RequestHeaderMap* request_headers,
-               const Http::ResponseHeaderMap* response_headers,
-               const Http::ResponseTrailerMap* response_trailers,
-               const StreamInfo::StreamInfo& stream_info,
-               AccessLog::AccessLogType access_log_type) {
+void Wasm::log(const PluginSharedPtr& plugin, const Formatter::HttpFormatterContext& log_context,
+               const StreamInfo::StreamInfo& info) {
   auto context = getRootContext(plugin, true);
-  context->log(request_headers, response_headers, response_trailers, stream_info, access_log_type);
+  context->log(log_context, info);
 }
 
 void Wasm::onStatsUpdate(const PluginSharedPtr& plugin, Envoy::Stats::MetricSnapshot& snapshot) {

diff --git a/source/extensions/common/wasm/wasm.h b/source/extensions/common/wasm/wasm.h
@@ -66,10 +66,8 @@ class Wasm : public WasmBase, Logger::Loggable<Logger::Id::wasm> {
   void getFunctions() override;
 
   // AccessLog::Instance
-  void log(const PluginSharedPtr& plugin, const Http::RequestHeaderMap* request_headers,
-           const Http::ResponseHeaderMap* response_headers,
-           const Http::ResponseTrailerMap* response_trailers,
-           const StreamInfo::StreamInfo& stream_info, AccessLog::AccessLogType access_log_type);
+  void log(const PluginSharedPtr& plugin, const Formatter::HttpFormatterContext& log_context,
+           const StreamInfo::StreamInfo& info);
 
   void onStatsUpdate(const PluginSharedPtr& plugin, Envoy::Stats::MetricSnapshot& snapshot);