Skip to content

Commit 5d23dca

Browse files
csviricsviri
authored
feat: contextual information about processing for loging using MDC (#642)
1 parent 530a7ee commit 5d23dca

File tree

7 files changed

+126
-39
lines changed

7 files changed

+126
-39
lines changed

Diff for: ‎docs/documentation/features.md

+17
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,23 @@ permalink: /docs/features
3333

3434
## Monitoring with Micrometer
3535

36+
## Contextual Info for Logging with MDC
37+
38+
Logging is enhanced with additional contextual information using [MDC](http://www.slf4j.org/manual.html#mdc).
39+
This following attributes are available in most parts of reconciliation logic and during the execution of the controller:
40+
41+
| MDC Key | Value added from Custom Resource |
42+
| :--- | :--- |
43+
| `resource.apiVersion` | `.apiVersion` |
44+
| `resource.kind` | `.kind` |
45+
| `resource.name` | `.metadata.name` |
46+
| `resource.namespace` | `.metadata.namespace` |
47+
| `resource.resourceVersion` | `.metadata.resourceVersion` |
48+
| `resource.generation` | `.metadata.generation` |
49+
| `resource.uid` | `.metadata.uid` |
50+
51+
For more information about MDC see this [link](https://www.baeldung.com/mdc-in-log4j-2-logback).
52+
3653

3754

3855

Diff for: ‎operator-framework-core/pom.xml

+12
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,18 @@
6262
<groupId>org.slf4j</groupId>
6363
<artifactId>slf4j-api</artifactId>
6464
</dependency>
65+
<dependency>
66+
<groupId>org.apache.logging.log4j</groupId>
67+
<artifactId>log4j-slf4j-impl</artifactId>
68+
<scope>test</scope>
69+
</dependency>
70+
<dependency>
71+
<groupId>org.apache.logging.log4j</groupId>
72+
<artifactId>log4j-core</artifactId>
73+
<version>${log4j.version}</version>
74+
<type>test-jar</type>
75+
<scope>test</scope>
76+
</dependency>
6577

6678
<dependency>
6779
<groupId>org.junit.jupiter</groupId>

Diff for: ‎operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/DefaultEventHandler.java

+34-27
Original file line numberDiff line numberDiff line change
@@ -103,6 +103,7 @@ public void handleEvent(Event event) {
103103
return;
104104
}
105105
final var resourceID = event.getRelatedCustomResourceID();
106+
MDCUtils.addCustomResourceIDInfo(resourceID);
106107
metrics.receivedEvent(event);
107108

108109
handleEventMarking(event);
@@ -111,40 +112,44 @@ public void handleEvent(Event event) {
111112
} else {
112113
cleanupForDeletedEvent(resourceID);
113114
}
114-
115115
} finally {
116116
lock.unlock();
117+
MDCUtils.removeCustomResourceIDInfo();
117118
}
118119
}
119120

120121
private void submitReconciliationExecution(CustomResourceID customResourceUid) {
121-
boolean controllerUnderExecution = isControllerUnderExecution(customResourceUid);
122-
Optional<R> latestCustomResource =
123-
resourceCache.getCustomResource(customResourceUid);
124-
125-
if (!controllerUnderExecution
126-
&& latestCustomResource.isPresent()) {
127-
setUnderExecutionProcessing(customResourceUid);
128-
final var retryInfo = retryInfo(customResourceUid);
129-
ExecutionScope<R> executionScope =
130-
new ExecutionScope<>(
131-
latestCustomResource.get(),
132-
retryInfo);
133-
eventMarker.unMarkEventReceived(customResourceUid);
134-
metrics.reconcileCustomResource(customResourceUid, retryInfo);
135-
log.debug("Executing events for custom resource. Scope: {}", executionScope);
136-
executor.execute(new ControllerExecution(executionScope));
137-
} else {
138-
log.debug(
139-
"Skipping executing controller for resource id: {}."
140-
+ " Controller in execution: {}. Latest CustomResource present: {}",
141-
customResourceUid,
142-
controllerUnderExecution,
143-
latestCustomResource.isPresent());
144-
if (latestCustomResource.isEmpty()) {
145-
log.warn("no custom resource found in cache for CustomResourceID: {}",
146-
customResourceUid);
122+
try {
123+
boolean controllerUnderExecution = isControllerUnderExecution(customResourceUid);
124+
Optional<R> latestCustomResource =
125+
resourceCache.getCustomResource(customResourceUid);
126+
latestCustomResource.ifPresent(MDCUtils::addCustomResourceInfo);
127+
if (!controllerUnderExecution
128+
&& latestCustomResource.isPresent()) {
129+
setUnderExecutionProcessing(customResourceUid);
130+
final var retryInfo = retryInfo(customResourceUid);
131+
ExecutionScope<R> executionScope =
132+
new ExecutionScope<>(
133+
latestCustomResource.get(),
134+
retryInfo);
135+
eventMarker.unMarkEventReceived(customResourceUid);
136+
metrics.reconcileCustomResource(customResourceUid, retryInfo);
137+
log.debug("Executing events for custom resource. Scope: {}", executionScope);
138+
executor.execute(new ControllerExecution(executionScope));
139+
} else {
140+
log.debug(
141+
"Skipping executing controller for resource id: {}."
142+
+ " Controller in execution: {}. Latest CustomResource present: {}",
143+
customResourceUid,
144+
controllerUnderExecution,
145+
latestCustomResource.isPresent());
146+
if (latestCustomResource.isEmpty()) {
147+
log.warn("no custom resource found in cache for CustomResourceID: {}",
148+
customResourceUid);
149+
}
147150
}
151+
} finally {
152+
MDCUtils.removeCustomResourceInfo();
148153
}
149154
}
150155

@@ -351,13 +356,15 @@ public void run() {
351356
final var thread = Thread.currentThread();
352357
final var name = thread.getName();
353358
try {
359+
MDCUtils.addCustomResourceInfo(executionScope.getCustomResource());
354360
thread.setName("EventHandler-" + controllerName);
355361
PostExecutionControl<R> postExecutionControl =
356362
eventDispatcher.handleExecution(executionScope);
357363
eventProcessingFinished(executionScope, postExecutionControl);
358364
} finally {
359365
// restore original name
360366
thread.setName(name);
367+
MDCUtils.removeCustomResourceInfo();
361368
}
362369
}
363370

Diff for: ‎operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/MDCUtils.java

+47
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
package io.javaoperatorsdk.operator.processing;
2+
3+
import org.slf4j.MDC;
4+
5+
import io.fabric8.kubernetes.client.CustomResource;
6+
import io.javaoperatorsdk.operator.processing.event.CustomResourceID;
7+
8+
public class MDCUtils {
9+
10+
private static final String NAME = "resource.name";
11+
private static final String NAMESPACE = "resource.namespace";
12+
private static final String API_VERSION = "resource.apiVersion";
13+
private static final String KIND = "resource.kind";
14+
private static final String RESOURCE_VERSION = "resource.resourceVersion";
15+
private static final String GENERATION = "resource.generation";
16+
private static final String UID = "resource.uid";
17+
18+
public static void addCustomResourceIDInfo(CustomResourceID customResourceID) {
19+
MDC.put(NAME, customResourceID.getName());
20+
MDC.put(NAMESPACE, customResourceID.getNamespace().orElse("no namespace"));
21+
}
22+
23+
public static void removeCustomResourceIDInfo() {
24+
MDC.remove(NAME);
25+
MDC.remove(NAMESPACE);
26+
}
27+
28+
public static void addCustomResourceInfo(CustomResource<?, ?> customResource) {
29+
MDC.put(API_VERSION, customResource.getApiVersion());
30+
MDC.put(KIND, customResource.getKind());
31+
MDC.put(NAME, customResource.getMetadata().getName());
32+
MDC.put(NAMESPACE, customResource.getMetadata().getNamespace());
33+
MDC.put(RESOURCE_VERSION, customResource.getMetadata().getResourceVersion());
34+
MDC.put(GENERATION, customResource.getMetadata().getGeneration().toString());
35+
MDC.put(UID, customResource.getMetadata().getUid());
36+
}
37+
38+
public static void removeCustomResourceInfo() {
39+
MDC.remove(API_VERSION);
40+
MDC.remove(KIND);
41+
MDC.remove(NAME);
42+
MDC.remove(NAMESPACE);
43+
MDC.remove(RESOURCE_VERSION);
44+
MDC.remove(GENERATION);
45+
MDC.remove(UID);
46+
}
47+
}

Diff for: ‎operator-framework-core/src/main/java/io/javaoperatorsdk/operator/processing/event/internal/CustomResourceEventSource.java

+15-10
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
import io.javaoperatorsdk.operator.api.config.Cloner;
1616
import io.javaoperatorsdk.operator.api.config.ControllerConfiguration;
1717
import io.javaoperatorsdk.operator.processing.ConfiguredController;
18+
import io.javaoperatorsdk.operator.processing.MDCUtils;
1819
import io.javaoperatorsdk.operator.processing.ResourceCache;
1920
import io.javaoperatorsdk.operator.processing.event.AbstractEventSource;
2021
import io.javaoperatorsdk.operator.processing.event.CustomResourceID;
@@ -116,17 +117,21 @@ public void stop() {
116117
}
117118

118119
public void eventReceived(ResourceAction action, T customResource, T oldResource) {
119-
log.debug(
120-
"Event received for resource: {}", getName(customResource));
121-
122-
if (filter.acceptChange(controller.getConfiguration(), oldResource, customResource)) {
123-
eventHandler.handleEvent(
124-
new CustomResourceEvent(action, CustomResourceID.fromResource(customResource)));
125-
} else {
120+
try {
126121
log.debug(
127-
"Skipping event handling resource {} with version: {}",
128-
getUID(customResource),
129-
getVersion(customResource));
122+
"Event received for resource: {}", getName(customResource));
123+
MDCUtils.addCustomResourceInfo(customResource);
124+
if (filter.acceptChange(controller.getConfiguration(), oldResource, customResource)) {
125+
eventHandler.handleEvent(
126+
new CustomResourceEvent(action, CustomResourceID.fromResource(customResource)));
127+
} else {
128+
log.debug(
129+
"Skipping event handling resource {} with version: {}",
130+
getUID(customResource),
131+
getVersion(customResource));
132+
}
133+
} finally {
134+
MDCUtils.removeCustomResourceInfo();
130135
}
131136
}
132137

Diff for: ‎operator-framework-core/src/test/java/io/javaoperatorsdk/operator/TestUtils.java

-1
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,6 @@ public static TestCustomResource testCustomResource(CustomResourceID id) {
3737
.withNamespace(id.getNamespace().orElse(null))
3838
.build());
3939
resource.getMetadata().setAnnotations(new HashMap<>());
40-
resource.setKind("CustomService");
4140
resource.setSpec(new TestCustomResourceSpec());
4241
resource.getSpec().setConfigMapName("test-config-map");
4342
resource.getSpec().setKey("test-key");

Diff for: ‎operator-framework-core/src/test/resources/log4j2.xml

+1-1
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@
22
<Configuration status="WARN">
33
<Appenders>
44
<Console name="Console" target="SYSTEM_OUT">
5-
<PatternLayout pattern="%d %threadId %-30c{1.} [%-5level] %msg%n%throwable"/>
5+
<PatternLayout pattern="%d %threadId %-30c{1.} [%-5level] resource.name=%X{resource.name} %msg%n%throwable "/>
66
</Console>
77
</Appenders>
88
<Loggers>

0 commit comments

Comments
 (0)