Skip to content

Commit 220e271

Browse files
brunobatbrunobat
committed
Add GCP complient tracing data to JSON logging
1 parent c0a01a9 commit 220e271

File tree

11 files changed

+595
-17
lines changed

11 files changed

+595
-17
lines changed

‎docs/src/main/asciidoc/logging.adoc‎

Lines changed: 18 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -363,6 +363,8 @@ Although the root logger's handlers are usually configured directly via `quarkus
363363

364364
== Logging format
365365

366+
=== Human-readable text
367+
366368
{project-name} uses a pattern-based logging formatter that generates human-readable text logs by default, but you can also configure the format for each log handler by using a dedicated property.
367369

368370
For the console handler, the property is `quarkus.log.console.format`.
@@ -399,14 +401,8 @@ The logging format string supports the following symbols:
399401
|%x|Nested Diagnostics context values|Renders all the values from Nested Diagnostics Context in format `{value1.value2}`.
400402
|===
401403

402-
403-
[id="alt-console-format"]
404-
=== Alternative console logging formats
405-
406-
Changing the console log format is useful, for example, when the console output of the Quarkus application is captured by a service that processes and stores the log information for later analysis.
407-
408404
[id="json-logging"]
409-
==== JSON logging format
405+
=== JSON logging format
410406

411407
The `quarkus-logging-json` extension might be employed to add support for the JSON logging format and its related configuration.
412408

@@ -441,7 +437,21 @@ This can be achieved using different profiles, as shown in the following configu
441437
%test.quarkus.log.console.json.enabled=false
442438
----
443439

444-
===== Configuration
440+
+
441+
. Choose the JSON logging format by setting the config property:
442+
[source, properties]
443+
----
444+
quarkus.log.console.json.log-format
445+
----
446+
This case will set the format for the console. The config values are:
447+
448+
* *default*: Will generate structured logging based on the `key,values` present in the log record. MDC and NDC data will be also included nested in `mdc` and `ndc` fields.
449+
* *ecs*: https://www.elastic.co/docs/reference/ecs/ecs-field-reference[Elastic Common Fields]. Some default fields names are modified and some otheres are added to better comply with ECS. Namely: `@timestamp`,`log.logger`, `log.level`, `process.pid`, `process.name`, `process.thread.name`, `process.thread.id`, `host.hostname`, `event.sequence`, `error.message`, `error.stack_trace`, `ecs.version`, `data_stream.type`, `service.name`, `service.version` and `service.environment`.
450+
* *gcp*: https://cloud.google.com/logging/docs/structured-logging#structured_logging_special_fields[Google Cloud]. Follows the `Default` format and when the xref:opentelemetry-tracing.adoc[OpenTelemetry] is used, tracing data present in the `mdc` field is flattened and copied to `spanId`, `traceSampled` and `trace`, but this last one with a prefix. GCP requires the `trace` to follow this semantic: `"projects/<my-trace-project>/traces/12345"`. Where `<my-trace-project>` has the same value as the `quarkus.application.name` config property.
451+
+
452+
453+
454+
==== Configuration
445455

446456
Configure the JSON logging extension using supported properties to customize its behavior.
447457

‎extensions/logging-json/deployment/pom.xml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,11 @@
5252
<artifactId>quarkus-jackson-deployment</artifactId>
5353
<scope>test</scope>
5454
</dependency>
55+
<dependency>
56+
<groupId>io.quarkus</groupId>
57+
<artifactId>quarkus-vertx-deployment</artifactId>
58+
<scope>test</scope>
59+
</dependency>
5560
</dependencies>
5661

5762
<build>

‎extensions/logging-json/deployment/src/test/java/io/quarkus/logging/json/ConsoleJsonFormatterGCPConfigTest.java‎

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,84 @@
1+
package io.quarkus.logging.json;
2+
3+
import static org.assertj.core.api.Assertions.assertThat;
4+
5+
import java.time.ZoneId;
6+
import java.time.format.DateTimeFormatter;
7+
import java.util.Arrays;
8+
import java.util.logging.Formatter;
9+
import java.util.logging.Handler;
10+
import java.util.logging.Level;
11+
import java.util.logging.LogManager;
12+
import java.util.logging.Logger;
13+
14+
import org.jboss.logmanager.formatters.StructuredFormatter;
15+
import org.jboss.logmanager.handlers.ConsoleHandler;
16+
import org.jboss.shrinkwrap.api.asset.StringAsset;
17+
import org.junit.jupiter.api.Test;
18+
import org.junit.jupiter.api.extension.RegisterExtension;
19+
20+
import io.quarkus.bootstrap.logging.InitialConfigurator;
21+
import io.quarkus.bootstrap.logging.QuarkusDelayedHandler;
22+
import io.quarkus.logging.json.runtime.JsonFormatter;
23+
import io.quarkus.test.QuarkusUnitTest;
24+
import io.quarkus.vertx.core.runtime.VertxMDC;
25+
26+
public class ConsoleJsonFormatterGCPConfigTest {
27+
28+
@RegisterExtension
29+
static final QuarkusUnitTest config = new QuarkusUnitTest()
30+
.withApplicationRoot((jar) -> jar
31+
.addAsResource(new StringAsset("""
32+
quarkus.log.level=INFO
33+
quarkus.log.console.enabled=true
34+
quarkus.log.console.level=WARNING
35+
quarkus.log.console.format=%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c{3.}] (%t) %s%e%n
36+
quarkus.log.console.json.enabled=true
37+
quarkus.log.console.json.log-format=gcp
38+
"""), "application.properties"));
39+
40+
@Test
41+
public void jsonFormatterDefaultConfigurationTest() {
42+
VertxMDC instance = VertxMDC.INSTANCE;
43+
instance.put("traceId", "aaaaaaaaaaaaaaaaaaaaaaaa");
44+
instance.put("spanId", "bbbbbbbbbbbbbb");
45+
instance.put("sampled", "true");
46+
47+
JsonFormatter jsonFormatter = getJsonFormatter();
48+
assertThat(jsonFormatter.isPrettyPrint()).isFalse();
49+
assertThat(jsonFormatter.getDateTimeFormatter().toString())
50+
.isEqualTo(DateTimeFormatter.ISO_OFFSET_DATE_TIME.withZone(ZoneId.systemDefault()).toString());
51+
assertThat(jsonFormatter.getDateTimeFormatter().getZone()).isEqualTo(ZoneId.systemDefault());
52+
assertThat(jsonFormatter.getExceptionOutputType()).isEqualTo(StructuredFormatter.ExceptionOutputType.DETAILED);
53+
assertThat(jsonFormatter.getRecordDelimiter()).isEqualTo("\n");
54+
assertThat(jsonFormatter.isPrintDetails()).isFalse();
55+
assertThat(jsonFormatter.getExcludedKeys()).isEmpty();
56+
assertThat(jsonFormatter.getAdditionalFields().entrySet()).isNotEmpty();
57+
assertThat(jsonFormatter.getAdditionalFields().get("trace")).isNotNull();
58+
assertThat(jsonFormatter.getAdditionalFields().get("spanId")).isNotNull();
59+
assertThat(jsonFormatter.getAdditionalFields().get("traceSampled")).isNotNull();
60+
61+
instance.remove("traceId");
62+
instance.remove("spanId");
63+
instance.remove("sampled");
64+
}
65+
66+
public static JsonFormatter getJsonFormatter() {
67+
LogManager logManager = LogManager.getLogManager();
68+
assertThat(logManager).isInstanceOf(org.jboss.logmanager.LogManager.class);
69+
70+
QuarkusDelayedHandler delayedHandler = InitialConfigurator.DELAYED_HANDLER;
71+
assertThat(Logger.getLogger("").getHandlers()).contains(delayedHandler);
72+
assertThat(delayedHandler.getLevel()).isEqualTo(Level.ALL);
73+
74+
Handler handler = Arrays.stream(delayedHandler.getHandlers())
75+
.filter(h -> (h instanceof ConsoleHandler))
76+
.findFirst().orElse(null);
77+
assertThat(handler).isNotNull();
78+
assertThat(handler.getLevel()).isEqualTo(Level.WARNING);
79+
80+
Formatter formatter = handler.getFormatter();
81+
assertThat(formatter).isInstanceOf(JsonFormatter.class);
82+
return (JsonFormatter) formatter;
83+
}
84+
}

‎extensions/logging-json/deployment/src/test/java/io/quarkus/logging/json/FileJsonFormatterGCPConfigTest.java‎

Lines changed: 125 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,125 @@
1+
package io.quarkus.logging.json;
2+
3+
import static io.quarkus.logging.json.FileJsonFormatterDefaultConfigTest.getJsonFormatter;
4+
import static org.assertj.core.api.Assertions.assertThat;
5+
6+
import java.time.ZoneId;
7+
import java.util.logging.Level;
8+
import java.util.logging.LogRecord;
9+
10+
import org.assertj.core.api.Assertions;
11+
import org.jboss.logmanager.formatters.StructuredFormatter;
12+
import org.jboss.shrinkwrap.api.asset.StringAsset;
13+
import org.junit.jupiter.api.Test;
14+
import org.junit.jupiter.api.extension.RegisterExtension;
15+
16+
import com.fasterxml.jackson.databind.JsonNode;
17+
import com.fasterxml.jackson.databind.ObjectMapper;
18+
19+
import io.quarkus.logging.json.runtime.JsonFormatter;
20+
import io.quarkus.logging.json.runtime.JsonLogConfig.AdditionalFieldConfig;
21+
import io.quarkus.test.QuarkusUnitTest;
22+
import io.quarkus.vertx.core.runtime.VertxMDC;
23+
24+
public class FileJsonFormatterGCPConfigTest {
25+
26+
@RegisterExtension
27+
static final QuarkusUnitTest config = new QuarkusUnitTest()
28+
.withApplicationRoot((jar) -> jar
29+
.addClasses(FileJsonFormatterDefaultConfigTest.class)
30+
.addAsResource(new StringAsset("""
31+
quarkus.log.level=INFO
32+
quarkus.log.file.enabled=true
33+
quarkus.log.file.level=WARNING
34+
quarkus.log.file.json.enabled=true
35+
quarkus.log.file.json.pretty-print=true
36+
quarkus.log.file.json.date-format=d MMM uuuu
37+
quarkus.log.file.json.record-delimiter=\\n;
38+
quarkus.log.file.json.zone-id=UTC+05:00
39+
quarkus.log.file.json.exception-output-type=DETAILED_AND_FORMATTED
40+
quarkus.log.file.json.print-details=true
41+
quarkus.log.file.json.key-overrides=level=HEY
42+
quarkus.log.file.json.excluded-keys=timestamp,sequence
43+
quarkus.log.file.json.additional-field.foo.value=42
44+
quarkus.log.file.json.additional-field.foo.type=int
45+
quarkus.log.file.json.additional-field.bar.value=baz
46+
quarkus.log.file.json.additional-field.bar.type=string
47+
quarkus.log.file.json.log-format=gcp
48+
"""), "application.properties"));
49+
50+
@Test
51+
public void jsonFormatterCustomConfigurationTest() {
52+
JsonFormatter jsonFormatter = getJsonFormatter();
53+
assertThat(jsonFormatter.isPrettyPrint()).isTrue();
54+
assertThat(jsonFormatter.getDateTimeFormatter().toString())
55+
.isEqualTo("Value(DayOfMonth)' 'Text(MonthOfYear,SHORT)' 'Value(Year,4,19,EXCEEDS_PAD)");
56+
assertThat(jsonFormatter.getDateTimeFormatter().getZone()).isEqualTo(ZoneId.of("UTC+05:00"));
57+
assertThat(jsonFormatter.getExceptionOutputType())
58+
.isEqualTo(StructuredFormatter.ExceptionOutputType.DETAILED_AND_FORMATTED);
59+
assertThat(jsonFormatter.getRecordDelimiter()).isEqualTo("\n;");
60+
assertThat(jsonFormatter.isPrintDetails()).isTrue();
61+
assertThat(jsonFormatter.getExcludedKeys()).containsExactlyInAnyOrder("timestamp", "sequence");
62+
assertThat(jsonFormatter.getAdditionalFields().size()).isEqualTo(5);
63+
assertThat(jsonFormatter.getAdditionalFields().containsKey("foo")).isTrue();
64+
assertThat(jsonFormatter.getAdditionalFields().get("foo").type()).isEqualTo(AdditionalFieldConfig.Type.INT);
65+
assertThat(jsonFormatter.getAdditionalFields().get("foo").value()).isEqualTo("42");
66+
assertThat(jsonFormatter.getAdditionalFields().containsKey("bar")).isTrue();
67+
assertThat(jsonFormatter.getAdditionalFields().get("bar").type()).isEqualTo(AdditionalFieldConfig.Type.STRING);
68+
assertThat(jsonFormatter.getAdditionalFields().get("bar").value()).isEqualTo("baz");
69+
assertThat(jsonFormatter.getAdditionalFields().containsKey("trace")).isTrue();
70+
assertThat(jsonFormatter.getAdditionalFields().get("trace").type()).isEqualTo(AdditionalFieldConfig.Type.STRING);
71+
assertThat(jsonFormatter.getAdditionalFields().containsKey("spanId")).isTrue();
72+
assertThat(jsonFormatter.getAdditionalFields().get("spanId").type()).isEqualTo(AdditionalFieldConfig.Type.STRING);
73+
assertThat(jsonFormatter.getAdditionalFields().containsKey("traceSampled")).isTrue();
74+
assertThat(jsonFormatter.getAdditionalFields().get("traceSampled").type()).isEqualTo(AdditionalFieldConfig.Type.STRING);
75+
}
76+
77+
@Test
78+
public void jsonFormatterOutputTest() throws Exception {
79+
VertxMDC instance = VertxMDC.INSTANCE;
80+
instance.put("traceId", "aaaaaaaaaaaaaaaaaaaaaaaa");
81+
instance.put("spanId", "bbbbbbbbbbbbbb");
82+
instance.put("sampled", "true");
83+
84+
JsonFormatter jsonFormatter = getJsonFormatter();
85+
String line = jsonFormatter.format(new LogRecord(Level.INFO, "Hello, World!"));
86+
87+
JsonNode node = new ObjectMapper().readTree(line);
88+
// "level" has been renamed to HEY
89+
Assertions.assertThat(node.has("level")).isFalse();
90+
Assertions.assertThat(node.has("HEY")).isTrue();
91+
Assertions.assertThat(node.get("HEY").asText()).isEqualTo("INFO");
92+
93+
// excluded fields
94+
Assertions.assertThat(node.has("timestamp")).isFalse();
95+
Assertions.assertThat(node.has("sequence")).isFalse();
96+
97+
// additional fields
98+
Assertions.assertThat(node.has("foo")).isTrue();
99+
Assertions.assertThat(node.get("foo").asInt()).isEqualTo(42);
100+
Assertions.assertThat(node.has("bar")).isTrue();
101+
Assertions.assertThat(node.get("bar").asText()).isEqualTo("baz");
102+
Assertions.assertThat(node.get("message").asText()).isEqualTo("Hello, World!");
103+
Assertions.assertThat(node.has("trace")).isTrue();
104+
Assertions.assertThat(node.get("trace").asText())
105+
.isEqualTo("projects/quarkus-logging-json-deployment/traces/aaaaaaaaaaaaaaaaaaaaaaaa");
106+
Assertions.assertThat(node.has("spanId")).isTrue();
107+
Assertions.assertThat(node.get("spanId").asText()).isEqualTo("bbbbbbbbbbbbbb");
108+
Assertions.assertThat(node.has("traceSampled")).isTrue();
109+
Assertions.assertThat(node.get("traceSampled").asText()).isEqualTo("true");
110+
111+
instance.remove("traceId");
112+
instance.remove("spanId");
113+
instance.remove("sampled");
114+
115+
String line2 = jsonFormatter.format(new LogRecord(Level.INFO, "Make sure MDC data is not cached!"));
116+
JsonNode node2 = new ObjectMapper().readTree(line2);
117+
Assertions.assertThat(node2.get("message").asText()).isEqualTo("Make sure MDC data is not cached!");
118+
Assertions.assertThat(node2.has("trace")).isTrue();
119+
Assertions.assertThat(node2.get("trace").asText()).isEqualTo("");
120+
Assertions.assertThat(node2.has("spanId")).isTrue();
121+
Assertions.assertThat(node2.get("spanId").asText()).isEqualTo("");
122+
Assertions.assertThat(node2.has("traceSampled")).isTrue();
123+
Assertions.assertThat(node2.get("traceSampled").asText()).isEqualTo("");
124+
}
125+
}

0 commit comments

Comments
 (0)