envoyproxy / envoyproxy/envoy

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

Open
#14,767 13 comments 2 reactions 0 assignees View on GitHub
area/access_log help wanted
Dominant language
C++
Stars
28.9k
Forks
5.6k
Avg merge
1d 20h
Merged PRs (30d)
428

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](https://github.com/envoyproxy/envoy/blob/main/source/common/http/conn_manager_impl.cc#L593).

```
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](https://github.com/envoyproxy/envoy/blob/main/source/common/http/conn_manager_impl.cc#L999).
```
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](https://github.com/envoyproxy/envoy/blob/main/source/common/http/filter_manager.cc#L470), 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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.