envoyproxy/envoy

The order of `access_log` handler settings may not be the best.

Open

#14,767 opened on Jan 20, 2021

View on GitHub
 (13 comments) (2 reactions) (0 assignees)C++ (5,373 forks)batch import
area/access_loghelp wanted

Repository metrics

Stars
 (27,997 stars)
PR merge metrics
 (Avg merge 8d) (378 merged PRs in 30d)

Description

Title: The order of access_log handler settings may not be the best

Description

Now access_log is always runs before each filter log phase of HTTP, which will cause some operations in the log phase of http filter to not take effect in the access_log handler. Forexample, if the metadata xxx :yy is set in the log phase of HTTP filter, then %DYNAMIC_METADATA(xxx :yy)% in access_log format does not work.

Analysis

access_log is registered at the ActiveStream.

ConnectionManagerImpl::ActiveStream::ActiveStream(ConnectionManagerImpl& connection_manager,
                                                  uint32_t buffer_limit) {
  ……
  for (const AccessLog::InstanceSharedPtr& access_log : connection_manager_.config_.accessLogs()) {
    filter_manager_.addAccessLogHandler(access_log); 
  }
  ……
}

each filter log handler of HTTP is registered at the decodeHeaders.

void ConnectionManagerImpl::ActiveStream::decodeHeaders(RequestHeaderMapPtr&& headers,
                                                        bool end_stream) {
……
 const bool upgrade_rejected = filter_manager_.createFilterChain() == false;   // will call filter_manager_.addAccessLogHandler
……
}

The log handler is registered using push_back, So it means FIFO.

void FilterManager::addAccessLogHandler(AccessLog::InstanceSharedPtr handler) {
  access_log_handlers_.push_back(handler);
}

So the access_log handler will be called first during the log phase.

void ConnectionManagerImpl::doDeferredStreamDestroy(ActiveStream& stream) {
  ……
  stream.completeRequest();
  stream.filter_manager_.onStreamComplete();

  stream.filter_manager_.log();  //  access_log and http_filter_log handler will be called here

  stream.filter_manager_.destroyFilters();
……
}

void log() {
……
    for (const auto& log_handler : access_log_handlers_) {   // access_log handler will be called first
      log_handler->log(request_headers, response_headers, response_trailers, stream_info_);
    }
……
  }

Expect

The access_log handler may be better to runs after all log handler of http filter.

Contributor guide