Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OpenTelemetry Log message attributes are mixed across different messages #7311

Closed
cyrille-leclerc opened this issue Feb 16, 2022 · 3 comments · Fixed by #7358
Closed

OpenTelemetry Log message attributes are mixed across different messages #7311

cyrille-leclerc opened this issue Feb 16, 2022 · 3 comments · Fixed by #7358
Assignees
@axw
Labels
bug OpenTelemetry v8.0.0 v8.1.0 v8.2.0
Milestone
8.1

Comments

@cyrille-leclerc
Copy link
Contributor

cyrille-leclerc commented Feb 16, 2022 •
edited

APM Server version (apm-server version):

8.0

Description of the problem including expected versus actual behavior:

Otel Log Message attributes are be mixed between different incoming message

Steps to reproduce:

Create an app that generate otel log messages with:

  • body: "Log Message x"
  • attribute[myStringAttribute]: "Value x"
  • attribute[myNumericAttribute]: x
    where x is the variable.

The documents in Elasticsearch will mix attributes and labels.

Provide logs (if relevant):

lcDNBH8BOxCOyX1nBMIu	message:'Log Message 0', 	myStringAttribute: 'Value 4', myNumericAttribute: 4
lsDNBH8BOxCOyX1nBMIu	message:'Log Message 1', 	myStringAttribute: 'Value 4', myNumericAttribute: 4
l8DNBH8BOxCOyX1nBMIu	message:'Log Message 2', 	myStringAttribute: 'Value 4', myNumericAttribute: 4
mMDNBH8BOxCOyX1nBMIu	message:'Log Message 3', 	myStringAttribute: 'Value 4', myNumericAttribute: 4
mcDNBH8BOxCOyX1nBMIu	message:'Log Message 4', 	myStringAttribute: 'Value 4', myNumericAttribute: 4
msDNBH8BOxCOyX1nBMIu	message:'Log Message 5', 	myStringAttribute: 'Value 7', myNumericAttribute: 7
m8DNBH8BOxCOyX1nBMIu	message:'Log Message 6', 	myStringAttribute: 'Value 7', myNumericAttribute: 7
nMDNBH8BOxCOyX1nBMIu	message:'Log Message 7', 	myStringAttribute: 'Value 7', myNumericAttribute: 7
ncDNBH8BOxCOyX1nBMIu	message:'Log Message 8', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
nsDNBH8BOxCOyX1nBMIu	message:'Log Message 9', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
n8DNBH8BOxCOyX1nBMIu	message:'Log Message 10', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
oMDNBH8BOxCOyX1nBMIu	message:'Log Message 11', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
ocDNBH8BOxCOyX1nBMIu	message:'Log Message 12', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
osDNBH8BOxCOyX1nBMIu	message:'Log Message 13', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
o8DNBH8BOxCOyX1nBMIu	message:'Log Message 14', 	myStringAttribute: 'Value 14', myNumericAttribute: 14
...

Test case

See https://github.com/cyrille-leclerc/elastic-otel-log-bug

/*
 * Copyright The Original Author or Authors
 * SPDX-License-Identifier: Apache-2.0
 */

package io.jenkins.plugins.opentelemetry.job.log;

import co.elastic.clients.elasticsearch.ElasticsearchClient;
import co.elastic.clients.elasticsearch._types.FieldValue;
import co.elastic.clients.elasticsearch._types.SortOrder;
import co.elastic.clients.elasticsearch.core.SearchRequest;
import co.elastic.clients.elasticsearch.core.SearchResponse;
import co.elastic.clients.elasticsearch.core.search.Hit;
import co.elastic.clients.json.jackson.JacksonJsonpMapper;
import co.elastic.clients.transport.rest_client.RestClientTransport;
import com.fasterxml.jackson.databind.node.ObjectNode;
import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.common.Attributes;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.Tracer;
import io.opentelemetry.context.Context;
import io.opentelemetry.context.Scope;
import io.opentelemetry.sdk.OpenTelemetrySdk;
import io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk;
import io.opentelemetry.sdk.logs.LogEmitter;
import org.apache.http.HttpHost;
import org.apache.http.auth.AuthScope;
import org.apache.http.auth.UsernamePasswordCredentials;
import org.apache.http.impl.client.BasicCredentialsProvider;
import org.elasticsearch.client.RestClient;
import org.junit.Assert;
import org.junit.Test;

import java.io.InputStream;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Properties;
import java.util.Random;

public class OpenTelemetryLogToElasticsearchIT {
    private final static Random RANDOM = new Random();

    @Test
    public void test() throws Exception {
        InputStream envAsStream = Thread.currentThread().getContextClassLoader().getResourceAsStream(".env");
        Assert.assertNotNull(".env file not found in classpath", envAsStream);
        Properties env = new Properties();
        env.load(envAsStream);
        Map<String, String> configuration = new HashMap<>();
        env.forEach((k, v) -> configuration.put(k.toString(), v.toString()));
        configuration.put("otel.traces.exporter", "otlp");
        configuration.put("otel.metrics.exporter", "otlp");
        configuration.put("otel.logs.exporter", "otlp");

        final int LOG_MESSAGE_COUNT = 100;
        String traceId;
        // PRODUCE OPEN TELEMETRY LOG MESSAGES
        {
            AutoConfiguredOpenTelemetrySdk autoConfiguredOpenTelemetrySdk = AutoConfiguredOpenTelemetrySdk.builder()
                .addPropertiesSupplier(() -> configuration).build();
            try {
                OpenTelemetrySdk sdk = autoConfiguredOpenTelemetrySdk.getOpenTelemetrySdk();
                Tracer tracer = sdk.getTracer("test");
                LogEmitter logEmitter = sdk.getSdkLogEmitterProvider().get("test");
                Span span = tracer.spanBuilder("my-test-pipeline").startSpan();
                try (Scope scope = span.makeCurrent()) {
                    for (int i = 0; i < LOG_MESSAGE_COUNT; i++) {
                        logEmitter
                            .logBuilder()
                            .setContext(Context.current())
                            .setBody("Log Message " + i)
                            .setAttributes(
                                Attributes.of(
                                    AttributeKey.stringKey("myStringAttribute"), "Value " + i,
                                    AttributeKey.longKey("myNumericAttribute"), (long) i))
                            .emit();
                        Thread.sleep(RANDOM.nextInt(100));
                    }
                } finally {
                    span.end();
                }
                traceId = span.getSpanContext().getTraceId();
            } finally {
                autoConfiguredOpenTelemetrySdk.getOpenTelemetrySdk().getSdkLogEmitterProvider().close();
                autoConfiguredOpenTelemetrySdk.getOpenTelemetrySdk().getSdkTracerProvider().close();
            }
        }

        Thread.sleep(3_000);
        // VERIFY LOG MESSAGES IN ELASTICSEARCH
        {
            String elasticsearchUrl = configuration.get("elasticsearch.url");
            String elasticsearchUsername = configuration.get("elasticsearch.username");
            String elasticsearchPassword = configuration.get("elasticsearch.password");

            BasicCredentialsProvider credentialsProvider = new BasicCredentialsProvider();
            credentialsProvider.setCredentials(AuthScope.ANY, new UsernamePasswordCredentials(elasticsearchUsername, elasticsearchPassword));

            RestClient restClient = RestClient.builder(HttpHost.create(elasticsearchUrl))
                .setHttpClientConfigCallback(httpClientBuilder -> httpClientBuilder.setDefaultCredentialsProvider(credentialsProvider))
                .build();
            RestClientTransport elasticsearchTransport = new RestClientTransport(restClient, new JacksonJsonpMapper());
            ElasticsearchClient elasticsearchClient = new ElasticsearchClient(elasticsearchTransport);

            SearchRequest searchRequest = new SearchRequest.Builder()
                .index("logs-apm.app-*")
                .size(500)
                .sort(s -> s.field(f -> f.field("@timestamp").order(SortOrder.Asc)))
                .query(q -> q.match(m -> m.field("trace.id").query(FieldValue.of(traceId))))
                .build();
            SearchResponse<ObjectNode> searchResponse = elasticsearchClient.search(searchRequest, ObjectNode.class);
            List<Hit<ObjectNode>> hits = searchResponse.hits().hits();
            if (hits.size() != LOG_MESSAGE_COUNT) {
                System.err.println("Invalid number of log messages: actual: " + hits.size() + ", expected: " + LOG_MESSAGE_COUNT);
            }

            for (Hit<ObjectNode> hit : hits) {

                ObjectNode source = hit.source();
                ObjectNode labels = (ObjectNode) source.findValue("labels");
                ObjectNode numericLabels = (ObjectNode) source.findValue("numeric_labels");

                try {
                    String message = source.findValue("message").asText();
                    String myStringAttribute = labels.findValue("myStringAttribute").asText();
                    long myNumericAttribute = numericLabels.findValue("myNumericAttribute").longValue();
                    System.out.println(hit.id() + "\tmessage:'" + message + "', \tmyStringAttribute: '" + myStringAttribute + "', myNumericAttribute: " + myNumericAttribute);
                } catch (Exception e) {
                    System.err.println("Error parsing " + source);
                }
            }
        }
    }
}

OpenTelemetry Collector Logging Exporter showing the source data are valid, not mixed

Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:14.293867 +0000 UTC
Severity:
ShortName:
Body: Log Message 48
Attributes:
     -> myNumericAttribute: INT(48)
     -> myStringAttribute: STRING(Value 48)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #3
Timestamp: 2022-02-17 09:07:14.313705 +0000 UTC
Severity:
ShortName:
Body: Log Message 49
Attributes:
     -> myNumericAttribute: INT(49)
     -> myStringAttribute: STRING(Value 49)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #4
Timestamp: 2022-02-17 09:07:14.360093 +0000 UTC
Severity:
ShortName:
Body: Log Message 50
Attributes:
     -> myNumericAttribute: INT(50)
     -> myStringAttribute: STRING(Value 50)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:14.801+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:14.45247 +0000 UTC
Severity:
ShortName:
Body: Log Message 51
Attributes:
     -> myNumericAttribute: INT(51)
     -> myStringAttribute: STRING(Value 51)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:14.49793 +0000 UTC
Severity:
ShortName:
Body: Log Message 52
Attributes:
     -> myNumericAttribute: INT(52)
     -> myStringAttribute: STRING(Value 52)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:14.534954 +0000 UTC
Severity:
ShortName:
Body: Log Message 53
Attributes:
     -> myNumericAttribute: INT(53)
     -> myStringAttribute: STRING(Value 53)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #3
Timestamp: 2022-02-17 09:07:14.564734 +0000 UTC
Severity:
ShortName:
Body: Log Message 54
Attributes:
     -> myNumericAttribute: INT(54)
     -> myStringAttribute: STRING(Value 54)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #4
Timestamp: 2022-02-17 09:07:14.597444 +0000 UTC
Severity:
ShortName:
Body: Log Message 55
Attributes:
     -> myNumericAttribute: INT(55)
     -> myStringAttribute: STRING(Value 55)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:15.002+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:14.659473 +0000 UTC
Severity:
ShortName:
Body: Log Message 56
Attributes:
     -> myNumericAttribute: INT(56)
     -> myStringAttribute: STRING(Value 56)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:14.714034 +0000 UTC
Severity:
ShortName:
Body: Log Message 57
Attributes:
     -> myNumericAttribute: INT(57)
     -> myStringAttribute: STRING(Value 57)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:14.799326 +0000 UTC
Severity:
ShortName:
Body: Log Message 58
Attributes:
     -> myNumericAttribute: INT(58)
     -> myStringAttribute: STRING(Value 58)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:15.203+0100	INFO	loggingexporter/logging_exporter.go:69	LogsExporter	{"#logs": 6}
2022-02-17T10:07:15.204+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:14.891916 +0000 UTC
Severity:
ShortName:
Body: Log Message 59
Attributes:
     -> myNumericAttribute: INT(59)
     -> myStringAttribute: STRING(Value 59)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:14.974425 +0000 UTC
Severity:
ShortName:
Body: Log Message 60
Attributes:
     -> myNumericAttribute: INT(60)
     -> myStringAttribute: STRING(Value 60)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:14.978196 +0000 UTC
Severity:
ShortName:
Body: Log Message 61
Attributes:
     -> myNumericAttribute: INT(61)
     -> myStringAttribute: STRING(Value 61)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #3
Timestamp: 2022-02-17 09:07:15.001706 +0000 UTC
Severity:
ShortName:
Body: Log Message 62
Attributes:
     -> myNumericAttribute: INT(62)
     -> myStringAttribute: STRING(Value 62)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #4
Timestamp: 2022-02-17 09:07:15.016403 +0000 UTC
Severity:
ShortName:
Body: Log Message 63
Attributes:
     -> myNumericAttribute: INT(63)
     -> myStringAttribute: STRING(Value 63)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #5
Timestamp: 2022-02-17 09:07:15.032158 +0000 UTC
Severity:
ShortName:
Body: Log Message 64
Attributes:
     -> myNumericAttribute: INT(64)
     -> myStringAttribute: STRING(Value 64)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:15.404+0100	INFO	loggingexporter/logging_exporter.go:69	LogsExporter	{"#logs": 5}
2022-02-17T10:07:15.404+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:15.116334 +0000 UTC
Severity:
ShortName:
Body: Log Message 65
Attributes:
     -> myNumericAttribute: INT(65)
     -> myStringAttribute: STRING(Value 65)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:15.219392 +0000 UTC
Severity:
ShortName:
Body: Log Message 66
Attributes:
     -> myNumericAttribute: INT(66)
     -> myStringAttribute: STRING(Value 66)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:15.237461 +0000 UTC
Severity:
ShortName:
Body: Log Message 67
Attributes:
     -> myNumericAttribute: INT(67)
     -> myStringAttribute: STRING(Value 67)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #3
Timestamp: 2022-02-17 09:07:15.251361 +0000 UTC
Severity:
ShortName:
Body: Log Message 68
Attributes:
     -> myNumericAttribute: INT(68)
     -> myStringAttribute: STRING(Value 68)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #4
Timestamp: 2022-02-17 09:07:15.263786 +0000 UTC
Severity:
ShortName:
Body: Log Message 69
Attributes:
     -> myNumericAttribute: INT(69)
     -> myStringAttribute: STRING(Value 69)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:15.605+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:15.300449 +0000 UTC
Severity:
ShortName:
Body: Log Message 70
Attributes:
     -> myNumericAttribute: INT(70)
     -> myStringAttribute: STRING(Value 70)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:15.397436 +0000 UTC
Severity:
ShortName:
Body: Log Message 71
Attributes:
     -> myNumericAttribute: INT(71)
     -> myStringAttribute: STRING(Value 71)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:15.465347 +0000 UTC
Severity:
ShortName:
Body: Log Message 72
Attributes:
     -> myNumericAttribute: INT(72)
     -> myStringAttribute: STRING(Value 72)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1

2022-02-17T10:07:15.807+0100	DEBUG	loggingexporter/logging_exporter.go:79	ResourceLog #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.8.0
Resource labels:
     -> host.arch: STRING(x86_64)
     -> host.name: STRING(MacBook-Pro.localdomain)
     -> os.description: STRING(Mac OS X 11.2)
     -> os.type: STRING(darwin)
     -> process.command_line: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java -ea -Dhudson.udp=-1 -Djava.io.tmpdir=/Users/cyrilleleclerc/git/jenkins/jenkins-opentelemetry/target/tmp -Djava.awt.headless=true -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Xms768M -Xmx768M -XX:+HeapDumpOnOutOfMemoryError -XX:+TieredCompilation -XX:TieredStopAtLevel=1 -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=52282:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8)
     -> process.executable.path: STRING(/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home:bin:java)
     -> process.pid: INT(4594)
     -> process.runtime.description: STRING(AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.11+9)
     -> process.runtime.name: STRING(OpenJDK Runtime Environment)
     -> process.runtime.version: STRING(11.0.11+9)
     -> service.name: STRING(jenkins)
     -> service.namespace: STRING(jenkins)
     -> telemetry.sdk.language: STRING(java)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.11.0)
InstrumentationLibraryLogs #0
InstrumentationLibraryMetrics SchemaURL:
InstrumentationLibrary test
LogRecord #0
Timestamp: 2022-02-17 09:07:15.508525 +0000 UTC
Severity:
ShortName:
Body: Log Message 73
Attributes:
     -> myNumericAttribute: INT(73)
     -> myStringAttribute: STRING(Value 73)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #1
Timestamp: 2022-02-17 09:07:15.556769 +0000 UTC
Severity:
ShortName:
Body: Log Message 74
Attributes:
     -> myNumericAttribute: INT(74)
     -> myStringAttribute: STRING(Value 74)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #2
Timestamp: 2022-02-17 09:07:15.619443 +0000 UTC
Severity:
ShortName:
Body: Log Message 75
Attributes:
     -> myNumericAttribute: INT(75)
     -> myStringAttribute: STRING(Value 75)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #3
Timestamp: 2022-02-17 09:07:15.619487 +0000 UTC
Severity:
ShortName:
Body: Log Message 76
Attributes:
     -> myNumericAttribute: INT(76)
     -> myStringAttribute: STRING(Value 76)
Trace ID: e15fad2bfee87e5e052177e35ea3d8e1
Span ID: e5929edc4fc84188
Flags: 1
LogRecord #4
Timestamp: 2022-02-17 09:07:15.642132 +0000 UTC
Severity:
ShortName:
Body: Log Message 77
Attributes:
     -> myNumericAttribute: INT(77)
     -> myStringAttribute: STRING(Value 77)
@cyrille-leclerc
Copy link
Contributor Author

Note that I couldn't test on 8.1 latest as I get an exception "502 (Bad Gateway)" when I try to connect an Otel Collector to Elastic APM Server 8.1 on Elastic Cloud

@axw
Copy link
Member

axw commented Feb 17, 2022

@cyrille-leclerc let's first rule out the SDK as the source of the problem. We can do that by checking the OTLP payload.

Can you please test this again with apm-server's debug logging for the "otel" logging module enabled? You can do this by running apm-server with -d otel.

@cyrille-leclerc cyrille-leclerc changed the title [OpenTelemetry] Log message attributes are mixed across different messages OpenTelemetry Log message attributes are mixed across different messages Feb 17, 2022
@axw
Copy link
Member

axw commented Feb 17, 2022

Thanks @cyrille-leclerc, I can reproduce this on main with https://github.com/cyrille-leclerc/elastic-otel-log-bug.

The issue is that we initialise a map for labels for all of the events:

apm-server/processor/otel/logs.go

Line 74 in 4b3419c

translateResourceMetadata(resource, &baseEvent)

... and we never copy those to event-specific label maps, like we do for traces:

apm-server/processor/otel/traces.go

Line 205 in 4b3419c

initEventLabels(&event)

I'll put up a fix for this early next week.

@axw axw self-assigned this Feb 21, 2022
@axw axw added the v8.0.0 label Feb 21, 2022
@axw axw mentioned this issue Feb 21, 2022
Merged
1 task
@axw axw added this to the 8.1 milestone Feb 21, 2022
@axw axw closed this as completed in #7358 Feb 21, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@axw axw

Labels
bug OpenTelemetry v8.0.0 v8.1.0 v8.2.0
Projects
None yet
Milestone
8.1
Development

Successfully merging a pull request may close this issue.

processor/otel: clone shared labels for log events axw/apm-server
2 participants
@cyrille-leclerc @axw