Send logs to OTel collector with logback (using OpenTelemetryAppender)

[ziomill]

Hello,

We are developing some Java-based microservice with Spring Boot and we would adopt the OpenTelemetry as the Observability standard.

• All workloads use Logback as the Logging library
• The Log format is JSON
• The Log pattern has been based on the OpenTelemetry proposed specification (https://opentelemetry.io/docs/reference/specification/logs/data-model/#log-and-event-record-definition)
• All workloads are instrumented with the OpenTelemetry java instrumentation library.
• All workloads prints log to the console by using the Logback Console Appender in conjunction with the net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder (that enable the JSON format)
• We have configured the instrumentation library to send logs, traces and metrics to the Otel collector service:

# Starts microservice, with OpenTelemetry instrumentation
ENTRYPOINT ["sh","-c","java -javaagent:opentelemetry-javaagent.jar \
                            -Dotel.service.name=users-api \
                            -Dotel.logs.exporter=otlp \
                            -Dotel.traces.exporter=otlp \
                            -Dotel.metrics.exporter=otlp \
                            -Dotel.exporter.otlp.protocol=grpc \
                            -Dotel.exporter.otlp.endpoint=http://host.docker.internal:4317 \
                            -Xmx1024m -jar users-api.jar"]

Just for debugging, I configured the OTel collector with a File exporter:

....
....
exporters:
  file:
    path: my_otel_export.json
...
...

What I noticed is that the logs arrived on the Otel Collector, aren't in the same original format. Many fields are missing:

On Otel Collector side:

{
   "resourceLogs":[
      {
         "resource":{
            "attributes":[
               {
                  "key":"container.id",
                  "value":{
                     "stringValue":"0293de120ff3bfc4881fd152c4e042802d085738896312ceec4c4f3c108b25ed"
                  }
               },
               {
                  "key":"host.arch",
                  "value":{
                     "stringValue":"amd64"
                  }
               },
               {
                  "key":"host.name",
                  "value":{
                     "stringValue":"0293de120ff3"
                  }
               },
               {
                  "key":"os.description",
                  "value":{
                     "stringValue":"Linux 5.4.72-microsoft-standard-WSL2"
                  }
               },
               {
                  "key":"os.type",
                  "value":{
                     "stringValue":"linux"
                  }
               },
               {
                  "key":"process.command_line",
                  "value":{
                     "stringValue":"/usr/lib/jvm/java-16-amazon-corretto:bin:java -javaagent:opentelemetry-javaagent.jar -Dotel.service.name=users-api -Dotel.logs.exporter=otlp -Dotel.traces.exporter=otlp -Dotel.metrics.exporter=otlp -Dotel.exporter.otlp.protocol=grpc -Dotel.exporter.otlp.endpoint=http://host.docker.internal:4317 -Xmx1024m"
                  }
               },
               {
                  "key":"process.executable.path",
                  "value":{
                     "stringValue":"/usr/lib/jvm/java-16-amazon-corretto:bin:java"
                  }
               },
               {
                  "key":"process.pid",
                  "value":{
                     "intValue":"1"
                  }
               },
               {
                  "key":"process.runtime.description",
                  "value":{
                     "stringValue":"Amazon.com Inc. OpenJDK 64-Bit Server VM 16.0.2+7"
                  }
               },
               {
                  "key":"process.runtime.name",
                  "value":{
                     "stringValue":"OpenJDK Runtime Environment"
                  }
               },
               {
                  "key":"process.runtime.version",
                  "value":{
                     "stringValue":"16.0.2+7"
                  }
               },
               {
                  "key":"service.name",
                  "value":{
                     "stringValue":"users-api"
                  }
               },
               {
                  "key":"telemetry.auto.version",
                  "value":{
                     "stringValue":"1.11.0"
                  }
               },
               {
                  "key":"telemetry.sdk.language",
                  "value":{
                     "stringValue":"java"
                  }
               },
               {
                  "key":"telemetry.sdk.name",
                  "value":{
                     "stringValue":"opentelemetry"
                  }
               },
               {
                  "key":"telemetry.sdk.version",
                  "value":{
                     "stringValue":"1.11.0"
                  }
               }
            ]
         },
         "instrumentationLibraryLogs":[
            {
               "instrumentationLibrary":{
                  "name":"it.millsoft.users.api.business.UsersServicesImpl"
               },
               "logs":[
                  {
                     "timeUnixNano":"1646321267232000000",
                     "severityNumber":"SEVERITY_NUMBER_INFO",
                     "severityText":"INFO",
                     "body":{
                        "stringValue":"{} users has been found"
                     },
                     "flags":1,
                     "traceId":"fe9ec863c187fe62f2e674412a601165",
                     "spanId":"f857539a74f125d6"
                  }
               ]
            }
         ],
         "schemaUrl":"https://opentelemetry.io/schemas/1.8.0"
      }
   ]
}

Original Log:

{
   "Timestamp":"2022-03-03T15:38:54.486Z",
   "TraceId":"5797a1986da1958e76b802c74d38c38a",
   "SpanId":"faf09b273428d181",
   "SeverityText":"INFO",
   "Body":"1 users has been found",
   "Resource":{
      "container-name":"myContainer",
	  "container-namespace":"myContainerNamespace"
   },
   "Attributes":{
      "tag":"applicative_log",
      "thread":"http-nio-10000-exec-3",
      "class":"it.millsoft.users.api.business.UsersServicesImpl"
   }
}

Thank you

[jkwatson]

I'm going to move this over to the instrumentation repository where the logback appender currently lives.

[ziomill]

Hello @trask

I tried updating the java instrumentation lib to the last 1.12.0 version, but I'm still experiencing the issue.

Just to make things easier, I put up a simple PoC to reproduce the problem:
opentelemetry-poc.zip

Step to reproduce:

1. Unzip the attached file.
2. Build the code and launch the Docker compose, executing the compose___build_and_deploy.bat from the PoC root folder
3. Generate some applicative logs calling one of the users-api microservice's API:

CURL Add User:

curl --request POST   --url http://localhost:10000/users-api/user   --header 'Content-Type: application/json'   --data '{ "name": "Jhon","surname": "Doe","email": "[email protected]"}' -i

CURL Get Users:

curl --request GET \
       --url http://localhost:10000/users-api/users -i

You should see applicative logs on the users-api container console:

{
   "Timestamp":"2022-03-14T11:10:16.205Z",
   "TraceId":"133c5a41e861b9eaed7feffceaff33f3",
   "SpanId":"29a7dbca13290a59",
   "SeverityText":"INFO",
   "Body":"2 users has been found",
   "Resource":{
      "container-namespace":"usersapi.mock.container.namespace",
      "container-name":"usersapi.mock.container",
      "container-version":"1.0"
   },
   "Attributes":{
      "tag":"applicative_log",
      "thread":"http-nio-10000-exec-3",
      "class":"it.millsoft.users.api.business.UsersServicesImpl"
   }
}

Comparing applicative logs with exported ones you will see that all custom fields are ignored.

Applicative logs are exported by the OTel collector into the JSON file placed in:
{$POC_ROOT}/otel-collector/my_otel_export.json

The applicative logback.xml file is placed in:
{$POC_ROOT}/users-api/src/main/resources/logback.xml

Thank you for your help!

[trask]

hi @ziomill, I took a look at your repro, thx!

the "OpenTelemetry way" to capture your Resource fields is using OpenTelemetry Resources, in particular it looks like your Resource fields may map well to the container resource attributes https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/resource/semantic_conventions/container.md#container

so far, the javaagent only captures container.id I believe, see source at https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk-extensions/resources/src/main/java/io/opentelemetry/sdk/extension/resources/ContainerResource.java

you can also add your own resource attributes at startup using OTEL_RESOURCE_ATTRIBUTES

if you enable otel.instrumentation.logback-appender.experimental-log-attributes, you will get thread.name (see

opentelemetry-java-instrumentation/instrumentation/logback/logback-appender-1.0/library/src/main/java/io/opentelemetry/instrumentation/logback/appender/v1_0/internal/LoggingEventMapper.java

Lines 117 to 121 in 0139a8d

	if (captureExperimentalAttributes) {
	Thread currentThread = Thread.currentThread();
	attributes.put(SemanticAttributes.THREAD_NAME, currentThread.getName());
	attributes.put(SemanticAttributes.THREAD_ID, currentThread.getId());
	}

)

and logger name is already captured in instrumentationLibrary -> name

I think that just leaves the tag of applicative_log, which could also be a resource attribute since it doesn't change for the life of the process.

let me know if this all makes sense

[ziomill]

Hi @trask

First of all, thank you for the explanation. I will take a look at your suggested configurations.

Anyway, keeping in mind that Logs specification is already unstable, what I have understood following OpenTelemetry docs is that the format of a Log record must map the one shown in the Log specification:

Field Name	Description
Timestamp	Time when the event occurred.
ObservedTimestamp	Time when the event was observed.
TraceId	Request trace id.
SpanId	Request span id.
TraceFlags	W3C trace flag.
SeverityText	The severity text (also known as log level).
SeverityNumber	Numerical value of the severity.
Body	The body of the log record.
Resource	Describes the source of the log.
InstrumentationScope	Describes the scope that emitted the log.
Attributes	Additional information about the event.

So, adapting natively my applicative logs format (by configuring the logback,xml) in order to adhere to the specification, I would have expected that "Opentelemetry" instrumentation would have sent log records to the collector "as they are". Instead, it seems that only the "body" field is sent, ignoring everything else in the original record and attaching to it some default "instrumented" data.

I have to admit that I'm a little confused about this point :-)

[trask]

the javaagent instruments the logback Logger interface and captures the logs regardless of what appender or encoder you are using, while your example relies on functionality only available in net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder to map your logs to structured data

(supporting logstash could be useful, see also open-telemetry/opentelemetry-specification#2234 (comment))

[ziomill]

the javaagent instruments the logback Logger interface and captures the logs regardless of what appender or encoder you are using, while your example relies on functionality only available in net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder to map your logs to structured data

(supporting logstash could be useful, see also open-telemetry/opentelemetry-specification#2234 (comment))

Ok, now it makes sense to me.
So, at the time, isn't possible to implement my use case by using encoders with extended capabilities (like the json format capability).

Thank you @trask

[trajano]

Am I guessing correctly that because we're using the LogstashEncoder that based on #5496 (reply in thread) is the reason why we're not getting logs being sent to OTEL Collector?

Unfortunately, I just tested my hypothesis by switching back to the default CONSOLE log and it still does not show any logs in OTEL Collector debugger configured

receivers:
  otlp:
    protocols:
      grpc:
      http:
service:
  pipelines:
    logs:
      receivers: [otlp]
      exporters: [debug]

[trask]

hi @trajano, is this the same as #9819?

[trajano]

yes I was planning to drop that but I forgot to hit the close button as I was writing out what needs to be done. But there was an answer by @laurit which I could test later which was to set an environment variable as it wasn't active by default, but I didn't see that mentioned anywhere before.