Call for feedback: I've implemented an AsyncHttpAppender

[mlangc]

I've spent a considerable part of my Christmas holidays putting together an AsyncHttpAppender that I want to release in
the more-log4j2 library that I'm maintaining.

My personal use-case is pushing logs to the Dynatrace Ingest API without relying on proprietary Java agents or OpenTelemetry, but the appender is generic and can be integrated with other log monitoring solutions like Datadog and Grafana.

In theory, pushing logs to these APIs is also possible with the regular HttpAppender, however its performance is not acceptable even for toy projects, since logging a few lines per second ties up an entire thread due to the synchronous nature of the HttpAppender.

Thanks to compression and batching, the AsyncHttpAppender can handle log throughputs that are multiple orders of magnitude higher than what you can achieve with the regular HttpAppender. The implementation features different strategies to deal with overload situations, and retries with exponential backoff.

I would like to release this new appender as part of more-log4j2-2.0.0 in the near future, but before doing so, I want to
collect and address any feedback you may have. You can use the snapshot release that I've pushed to Maven Central, if you want some hands-on experience without checking out the project locally.

[ppkarwasz]

Hi @mlangc,

Sorry for the delayed response, and thanks for sharing your work: it’s great to see experimentation around this area.

[the regular HttpAppender] its performance is not acceptable even for toy projects

I haven’t benchmarked it myself, but that assessment wouldn’t surprise me. HttpAppender is one of those components that was added without a strong, established user base driving its design or evolution, so its limitations aren’t particularly shocking.

Your appender looks quite interesting, especially the batching support, which directly tackles the main drawback of HTTP: per-request overhead. Am I correct in assuming that this relies on server-side APIs that can accept multiple log events per request? Or do the backends you target simply treat logs as a raw character stream?

Regarding the asynchronous aspect: have you already experimented with the asynchronous facilities that are part of Log4j Core itself (see Asynchronous loggers)? They aim to solve the same problem: minimizing latency on the logging call path.
AsyncLogger does this by using the LMAX Disruptor to hand off log events to a dedicated worker thread, where all blocking operations occur.

When asynchronous loggers are in use, additional asynchronous behavior inside appenders can sometimes become more of a liability than a benefit:

• it introduces an extra async boundary,
• and in rare cases it can even lead to deadlocks (see Appender may caused deadlock on AsyncLoggerDisruptor #2893), especially if the appender implementation performs logging internally.

Improvement proposal

It might be worth exploring the following approach:

• Remove the asynchronous execution from the HTTP appender itself and rely on AsyncLogger for offloading work.
• You could likely simplify the batching logic by leveraging LogEvent#isEndOfBatch().
  This flag is set when the Disruptor drains its queue, effectively marking the end of a contiguous batch of events: a natural trigger point for issuing an HTTP request.

Overall, this looks like a promising direction, and I’m curious to see how it evolves.

In the past, we have discussed generalizing HttpManager (the engine behind HttpAppender) so that alternative implementations could be discovered via ServiceLoader. This is still an option we could revisit: it would allow HttpAppender to transparently benefit from enhanced implementations whenever your artifact is present on the classpath, without requiring configuration changes from users.

[mlangc]

Sorry for the delayed response, and thanks for sharing your work: it’s great to see experimentation around this area.

Thanks a lot for your feedback!

Am I correct in assuming that this relies on server-side APIs that can accept multiple log events per request?

Yes, that's correct, all log ingestion APIs that I looked into support batching. The AsyncHttpAppender creates batches out of buffered and serialized log events using batchPrefix, batchSuffix and batchSeparator options.

have you already experimented with the asynchronous facilities that are part of Log4j Core itself

Yes, this was one of the first things I did, however the fundamental problem is that pushing logs against an HTTP API one-by-one is inefficient and slow by design. Asynchronous loggers can hide the slowness, but only for very low average log throughputs. Without batching, even one log event per second can add significant overhead.

asynchronous loggers are in use, additional asynchronous behavior inside appenders can sometimes become more of a liability than a benefit

I did my best to make the implementation efficient and robust. The AsyncHttpAppender uses a single lock that is only held shortly, and all asynchronous operations, including HTTP IO with retries, are performed on a single, dedicated thread. I did a lot of testing to make sure that the appender behaves properly, especially under adverse conditions like high concurrency, unreliable backends and extreme loads, but sure, bugs cannot be ruled out.

Last but not least, doing synchronous network IO potentially traversing multiple time zones in the logging thread is quite problematic as well. If retries are involved, it might take seconds till a message is finally delivered. During this time, the affected application threads are blocked from doing anything useful. In extreme cases, the entire application might be blocked from making progress.

It introduces an extra async boundary

Yes, however only per batch, and not per log line. Normally the log event is rendered, and appended to the current batch synchronously.

especially if the appender implementation performs logging internally

I'm only using the StatusLogger internally - however there is an advanced batch completion listener option, that could lead to logs being generated from within the appender. This is mentioned explicitly in the documentation.

Remove the asynchronous execution from the HTTP appender itself and rely on AsyncLogger for offloading work.
You could likely simplify the batching logic by leveraging LogEvent#isEndOfBatch().

So you mean that we could still batch log events, potentially by inspecting LogEvent#isEndOfBatch, but send batches synchronously? This is something I can definitely explore, though I would see that as a potential enhancement of the regular HttpAppender.

Regarding using LogEvent#isEndOfBatch: I need to have a deeper understanding about the involved mechanics, but I wonder if the batches resulting from this approach would be appropriate for an HTTP backend with regards to size and the frequency in which they would be delivered.

In the past, we have discussed generalizing HttpManager

I like the idea. Ideally this advanced HttpManager could then also offer an asynchronous API. This way users could benefit from java.net.http.HttpClient if they are on newer Java versions just by adding an additional dependency if I understand the part with the ServiceLoader correctly.

I'm happy to explore/experiment in this direction and share my findings for discussion if you are interested.