Logging MDC values get confused with overlapping reconciler calls

[nstuart]

Expected Behavior

Logging MDC values like resource.name and resource.namespace are correct for reconciled resources in question

Actual Behavior

When multiple reconciliations are happening at once, the MDC values seem to be "random" and could be set to any values for any of the reconciliations.

Notes

When enabling JSON logging and looking at the MDC values provided out of the box by the framework I noticed that the values were pretty jumbled when a lot of reconciliations were happening in parallel. I assume this is because the underlying Java Operator SDK is responsible for the values, as documented here, and it doesn't play well with the Quarkus threading approach.

If I add my own interceptor and clear the MDC and re-add those values, things appear to stick as expected, from my limited testing

I don't see a way to disable the JOSDK values, or that the Quarkus Operator will inject it's own (with the appropriate threading model for the MDC).

[metacosm]

Hi @nstuart, I don't think that the way Quarkus handles thread should impact things there… I suspect that the issue you're seeing would also happen if you were to use the Java Operator SDK directly without Quarkus.

That said, I'm not sure what could be causing the issue. Do you have a way to replicate the problem, perhaps, so that we could look into it?

/cc @xstefank

[nstuart]

@metacosm, I'll see if I can reproduce in local test setup of some sort. I saw this while looking at our logs in GCP with a dozen or so resources being reconciled at once and the MDC values were all over the place.

[metacosm]

@metacosm, I'll see if I can reproduce in local test setup of some sort. I saw this while looking at our logs in GCP with a dozen or so resources being reconciled at once and the MDC values were all over the place.

Would being able to disable MDC logging at the SDK level help?

[xstefank]

I would be surprised if this would work out of the box because Quarkus uses it's own MDC propagation based on Vert.x context. Since we don't control on which thread the reconciliation runs (JOSDK does) we really can't intercept MDC on our side now.

So we would need a way how supply threads to JOSDK I suppose.

[metacosm]

I would be surprised if this would work out of the box because Quarkus uses it's own MDC propagation based on Vert.x context. Since we don't control on which thread the reconciliation runs (JOSDK does) we really can't intercept MDC on our side now.

I wasn't aware of this. Thanks! I've never used MDC so I have to admit that I don't know much about it or how it's used in Quarkus.

So we would need a way how supply threads to JOSDK I suppose.

Hmm. I'm not sure how that would work… 🤔
Do you mean, provide a Quarkus-based executor to JOSDK? We can already customize part of the executors that JOSDK uses but we'd need to check that all of them can be replaced by Quarkus ones, if needed.

[nstuart]

@xstefank thanks, I think this is what my investigation went towards, I guess I'm ok with this "not working" since I know it happens and can manually update the MDC, it just kind of caught me off guard when I first enabled the logging to expose that information.

I still haven't had time to generate a small test case for this, but it sounds like it's kind of "expected behavior" for now. It would be nice, if somehow, the default MDC stuff was removed by quarkus at least and have this be documented so folks aren't seeing these incorrect values by default (rather see nothing than wrong values).