Spring Security 6.0.2 ObservationFilterChainDecorator produce wrong instrument names

[andrebask]

Describe the bug

Open Telemetry Java Agent version 1.21 don't like the Instrument names produced by Spring Security 6.0 (from Class ObservationFilterChainDecorator)

Here is the WARNING Log (It appears to be a warning but is logged with log lever error by Spring):

WARN io.opentelemetry.ApiUsageLogging - Instrument name "spring.security.filterchains.WebAsyncManagerIntegrationFilter.after" is invalid, returning noop instrument. Instrument names must consist of 63 or fewer characters including alphanumeric, _, ., -, and start with a letter. Returning noop instrument.

The instrument name is produced by Spring Security there :

spring-security/web/src/main/java/org/springframework/security/web/ObservationFilterChainDecorator.java

Line 185 in 7ef659a

parent.before().event(Observation.Event.of(this.name + ".before", "before " + this.name));

A fix for spaces in the name (#12490) has been released, however, the warning is still displayed, probably due to the length of the identifier.

To Reproduce
Using a simple Spring Boot 3.0.3 project with Kotlin 1.7, JDK 17, Spring Boot 3.0.3, Spring Security 6.0.2 and Maven. Using Open Telemetry java Agent v 1.21. The application is running in a docker container, but you can reproduce the problem with a java -jar springboot.jar -javaagent:opentelemetry-javaagent-all.jar

Docker File :

ARG OPENJDK_IMAGE=openjdk:17-slim-bullseye
ARG USER=app
ARG WORKDIR=/app
ARG OPENTELEMETRY_VERSION=1.21.0
ARG OPENTELEMETRY_REPO="https://github.com/open-telemetry/opentelemetry-java-instrumentation"
ARG OPENTELEMETRY_JAR_PATH="/releases/download/v${OPENTELEMETRY_VERSION}/opentelemetry-javaagent.jar"
ARG OPENTELEMETRY_JAR=opentelemetry-javaagent-all.jar

# Build
FROM busybox:stable AS builder

ARG USER
ARG WORKDIR
ARG OPENTELEMETRY_REPO
ARG OPENTELEMETRY_JAR_PATH
ARG OPENTELEMETRY_JAR

RUN addgroup ${USER} \
    && adduser -D -H -G ${USER} ${USER}

WORKDIR ${WORKDIR}

RUN wget -O ${OPENTELEMETRY_JAR} ${OPENTELEMETRY_REPO}${OPENTELEMETRY_JAR_PATH}

# Main
FROM ${OPENJDK_IMAGE}

ARG USER
ARG WORKDIR
ARG OPENTELEMETRY_JAR

COPY --from=builder /etc/group /etc/group
COPY --from=builder /etc/passwd /etc/passwd

USER ${USER}:${USER}
WORKDIR ${WORKDIR}

ENV JAVA_TOOL_OPTIONS=-javaagent:${OPENTELEMETRY_JAR}
COPY --from=builder ${WORKDIR} .

Expected behaviour

The expected behaviour is that Open Telemetry Java Agent doesn't create WARNING logs about Spring Security instrument names.

[FrankSpitulski]

@jzheaux this fix does not seem to have actually made it into 6.0.3 as the release notes say. https://github.com/spring-projects/spring-security/blob/6.0.3/web/src/main/java/org/springframework/security/web/ObservationFilterChainDecorator.java

[mlux86]

@jzheaux Josh, as the change apparently didn't make it into 6.0.3, are you planning to integrate it into the next release?

[rcollette]

It did make it in, it's the Polish Event Name commit on Jan 6th however it is not dealing with long names like

[otel.javaagent 2023-04-28 02:14:38:190 +0000] [http-nio-5000-exec-1] WARN io.opentelemetry.sdk.metrics.internal.InstrumentNameValidator - Instrument name "spring.security.filterchains.WebAsyncManagerIntegrationFilter.after" is invalid, returning noop instrument. Instrument names must consist of 63 or fewer characters including alphanumeric, _, ., -, and start with a letter. Returning noop instrument.

This is more like an incompatibility between the metric names defined by Spring and the OTEL limitations. This is likely one of those things that will go to finger pointing till the end of time since an RFC spec is not providing guidance.

[FrankSpitulski]

@rcollette I’ve linked the 6.0.3 file that should have the Polish Event Name commit on top of it but those changes are missing.

[rcollette]

@FrankSpitulski - Look at line 184 of ObservationFilterChainDecorator... it has the changes from Polish Event Name.

Plus, note the tags

[FrankSpitulski]

My bad, you’re correct that the Polish Event Names commit made it in afterwards. It is odd to see the fix removed just after it was committed.

per the Bug Fixes section in this release https://github.com/spring-projects/spring-security/releases/tag/6.0.3 I would expect the that closing the issue would mean that it was resolved successfully. It is not clear why the opentelemetry compatible changes were backed out.

[mlux86]

So it looks like it was finally fixed in 6.1.0 😎
At least I don't observe the problem anymore once I pinned spring-security to that version.

[odoihc]

Hi, the warning is still present with 6.1.0, please let's fix it if possible @jzheaux

[otel.javaagent 2023-06-06 09:21:36:206 +0200] [http-nio-8082-exec-1] WARN io.opentelemetry.sdk.metrics.SdkMeter - Instrument name "spring.security.filterchains.WebAsyncManagerIntegrationFilter.before" is invalid, returning noop instrument. Instrument names must consist of 63 or fewer characters including alphanumeric, _, ., -, and start with a letter.
java.lang.AssertionError
	at io.opentelemetry.sdk.metrics.SdkMeter.checkValidInstrumentName(SdkMeter.java:161)
	at io.opentelemetry.sdk.metrics.SdkMeter.counterBuilder(SdkMeter.java:85)
	at io.opentelemetry.javaagent.shaded.instrumentation.micrometer.v1_5.OpenTelemetryCounter.<init>(OpenTelemetryCounter.java:36)
	at io.opentelemetry.javaagent.shaded.instrumentation.micrometer.v1_5.OpenTelemetryMeterRegistry.newCounter(OpenTelemetryMeterRegistry.java:76)

[andrebask]

You see,see

…

On Thu, 8 Jun 2023, 4:38 pm odoihc, ***@***.***> wrote: Hi, the warning is still present with 6.1.0, please let's fix it if possible @jzheaux <https://github.com/jzheaux> [otel.javaagent 2023-06-06 09:21:36:206 +0200] [http-nio-8082-exec-1] WARN io.opentelemetry.sdk.metrics.SdkMeter - Instrument name "spring.security.filterchains.WebAsyncManagerIntegrationFilter.before" is invalid, returning noop instrument. Instrument names must consist of 63 or fewer characters including alphanumeric, _, ., -, and start with a letter. java.lang.AssertionError at io.opentelemetry.sdk.metrics.SdkMeter.checkValidInstrumentName(SdkMeter.java:161) at io.opentelemetry.sdk.metrics.SdkMeter.counterBuilder(SdkMeter.java:85) at io.opentelemetry.javaagent.shaded.instrumentation.micrometer.v1_5.OpenTelemetryCounter.<init>(OpenTelemetryCounter.java:36) at io.opentelemetry.javaagent.shaded.instrumentation.micrometer.v1_5.OpenTelemetryMeterRegistry.newCounter(OpenTelemetryMeterRegistry.java:76) — Reply to this email directly, view it on GitHub <#12811 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACUBA5D3YEGS3LBE57NTCTXKHWW5ANCNFSM6AAAAAAVL3UNKI> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[tomilchik]

Not sure of the eventual outcome of this ^^^.
But: same behavior observed with SS 6.0.2 + OTEL 1.28.0.
I don't think this is Spring Security bug. Metric names are valid, except they exceed 63 chars (since they are constructed using actual filter names).
This looks to be OTEL Agent bug; limit of 63 chars on anything is too restrictive.

[rcollette]

It's not an OTEL agent bug. 63 Characters is the limit defined by the OTEL specification.

https://opentelemetry.io/docs/specs/otel/metrics/api/

[aegliv]

For everyone else stumbling over this issue, it seemsbe be adressed by OTEL itself, see: open-telemetry/opentelemetry-java#5697