Audit Logging on the IO Thread Appears to Cause Instability

[original-brownbear]

While investigating some test slowness/instability today I found that we are running audit logging (including flushing logs to disk) on the transport/IO-thread (the one(s) where the network .select calls happen).
This caused the select loop(s) to get blocked for an extended period of time every now and then leading to periods where the network IO was frozen. This is especially visible when running large bulk requests (in the test in question a bulk request of size 10k) (#39575).

I would argue that this is a bug and blocking disk IO shouldn't be happening on the network IO thread as it can lead to unpredictable latency. One side effect of this, could be (we observed this once) that the introduced latency blocks the IO thread for long enough to make SSL handshakes fail.
It seems this was indirectly raised in #34321 but not investigated.

Stacktrace from Yourkit:
Stacks.txt

cc @DaveCTurner @dimitris-athanasiou

[elasticmachine]

Pinging @elastic/es-security

[albertzaharovits]

Good find @original-brownbear !

We haven't taken any precautions about the thread doing the audit write. But we have looked into making sure it is blocking so as to be assured IO errors bubble up if the audit trail cannot be appended.

It seems this was indirectly raised in #34321 but not investigated.

This issue was raised by Yogesh to investigate if the log4j settings for the audit log flush events after every write. This was the default setting and hence the issue was closed.

This is especially visible when running large bulk requests (in the test in question a bulk request of size 10k)

#36245 (7.0 onward, I think) changed auditing for bulk requests, so that every operation comprising the bulk is audited independently, making this problem observable.

As a remediation, I think we should switch from the network thread as soon as possible, just after completing the request and headers read, but I'm guessing there are technical motivations behind the current implementation (keeping authentication and authz on the network thread)...

[original-brownbear]

As a remediation, I think we should switch from the network thread as soon as possible, just after completing the request and headers read, but I'm guessing there are technical motivations behind the current implementation (keeping authentication and authz on the network thread)...

Yea this is just without alternative imo if you want to write+flush to disk here imo. The motivation to keep things on the network thread is probably just to avoid the context switch and performance penalty that comes with that, but as soon as you start doing things like flushing to disk or any other blocking thing you just have to go to some other thread-pool.

[jaymode]

I'm guessing there are technical motivations behind the current implementation (keeping authentication and authz on the network thread)...

I think it was oversight to be honest. Early on in 5.0 we moved everything to a different thread before authc/authz but that was due to the fact that everything was blocking and causing other issues. We can absolutely move this to a different thread. The question becomes which threadpool do we use and should we have limits?

[original-brownbear]

@jaymode

We can absolutely move this to a different thread. The question becomes which threadpool do we use and should we have limits?

Maybe just the generic thread pool is fine here? It seems limits are probably not necessarily needed since we get the limiting of the write pool in this scenario indirectly anyway?

[tvernum]

The only concern I have is that in a typical deployment, most requests will have successful authentication using cached credentials, and won't be auditing on authentication_success.

If we simply switch to a different thread before authentication, it in effect means that every rest request will incur an unnecessary thread switch (which to the best of my knowledge, we try avoid in the general case).

I don't have a specific alternative, but I'd like us to make sure we're considering what that context switch costs and how we can minimise it.