[Maven Extension] Maven daemon build fails on second run

[delanym]

Reproduce as in #160 but use mvnd instead of mvn
https://github.com/apache/maven-mvnd/releases/tag/0.7.1

mvnd validate -Dotel.traces.exporter=otlp -Dotel.exporter.otlp.endpoint=http://10.1.1.1:4317 -Dmaven.ext.class.path=/tmp/opentelemetry-maven-extension-1.10.0-SNAPSHOT.jar -T3

The first run is successful, but the second fails with:

[INFO] Processing build on daemon e432b3dc
[INFO] Scanning for projects...
[ERROR] Internal error: java.lang.IllegalStateException: Root span already defined RecordEventsReadableSpan{traceId=ab428d41352f1a99385654f781e68ffc, spanId=fe206e623f88a74d, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=Build: org.apache.maven:maven:4.0.0-alpha-1-SNAPSHOT, kind=SERVER, attributes=AttributesMap{data={maven.project.version=4.0.0-alpha-1-SNAPSHOT, maven.project.groupId=org.apache.maven, maven.project.artifactId=maven}, capacity=128, totalAddedValues=3}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1641289758683000000, endEpochNanos=1641289762712689563} -> [Help 1]
org.apache.maven.InternalErrorException: Internal error: java.lang.IllegalStateException: Root span already defined RecordEventsReadableSpan{traceId=ab428d41352f1a99385654f781e68ffc, spanId=fe206e623f88a74d, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=Build: org.apache.maven:maven:4.0.0-alpha-1-SNAPSHOT, kind=SERVER, attributes=AttributesMap{data={maven.project.version=4.0.0-alpha-1-SNAPSHOT, maven.project.groupId=org.apache.maven, maven.project.artifactId=maven}, capacity=128, totalAddedValues=3}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1641289758683000000, endEpochNanos=1641289762712689563}
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:120)
        at org.apache.maven.cli.DaemonMavenCli.execute(DaemonMavenCli.java:825)
        at org.apache.maven.cli.DaemonMavenCli.doMain(DaemonMavenCli.java:244)
        at org.apache.maven.cli.DaemonMavenCli.main(DaemonMavenCli.java:222)
        at org.mvndaemon.mvnd.daemon.Server.handle(Server.java:573)
        at org.mvndaemon.mvnd.daemon.Server.client(Server.java:262)
        at org.mvndaemon.mvnd.daemon.Server.accept(Server.java:230)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Root span already defined RecordEventsReadableSpan{traceId=ab428d41352f1a99385654f781e68ffc, spanId=fe206e623f88a74d, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=Build: org.apache.maven:maven:4.0.0-alpha-1-SNAPSHOT, kind=SERVER, attributes=AttributesMap{data={maven.project.version=4.0.0-alpha-1-SNAPSHOT, maven.project.groupId=org.apache.maven, maven.project.artifactId=maven}, capacity=128, totalAddedValues=3}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1641289758683000000, endEpochNanos=1641289762712689563}
        at io.opentelemetry.maven.SpanRegistry.setRootSpan(SpanRegistry.java:39)
        at io.opentelemetry.maven.OtelExecutionListener.sessionStarted(OtelExecutionListener.java:139)
        at io.opentelemetry.maven.ChainedExecutionListener.sessionStarted(ChainedExecutionListener.java:36)
        at org.apache.maven.lifecycle.internal.DefaultExecutionEventCatapult.fire(DefaultExecutionEventCatapult.java:61)
        at org.apache.maven.lifecycle.internal.DefaultExecutionEventCatapult.fire(DefaultExecutionEventCatapult.java:42)
        at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:74)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
        at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
        at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
        ... 7 common frames omitted

Kill the daemon with mvnd --stop and try again and it works.

[gnodet]

mvnd caches the plugin realms, so the SpanRegistry is reused across maven sessions.
It may work if you annotate your bean with @SessionScoped or if you fix your component logic.
Another possibility is to force mvnd to discard the realm for the plugin using the mvnd plugin eviction pattern: https://github.com/apache/maven-mvnd/blob/09cb99fd48d7b8b0de09ffb8656b77a1648b4e95/common/src/main/java/org/mvndaemon/mvnd/common/Environment.java#L253-L265

[cyrille-leclerc]

Thanks @delanym and @gnodet . Please see

• [Maven Extension] Fix lifecycle to support the Maven Daemon #169

[delanym]

@cyrille-leclerc the traces look unusual, but i'm quite new to this. Did you check them? There are spans for some module plugin executions appearing as their own root spans in Jaeger

[cyrille-leclerc]

@delanym can you please attach a screenshot and indicate how I can reproduce locally? Did you use https://github.com/apache/maven as a test? what was your command line?

[delanym]

Build with mvnd install .... Then make trivial change like below and build again. You should get a trace like pic

diff --git a/maven-compat/src/main/java/org/apache/maven/repository/VersionNotFoundException.java b/maven-compat/src/main/java/org/apache/maven/repository/VersionNotFoundException.java
index 77b1af127..b70eb2312 100644
--- a/maven-compat/src/main/java/org/apache/maven/repository/VersionNotFoundException.java
+++ b/maven-compat/src/main/java/org/apache/maven/repository/VersionNotFoundException.java
@@ -56,7 +56,7 @@ public VersionNotFoundException( String projectId, Dependency dependency, File p
 
     private static String formatLocationInPom( Dependency dependency )
     {
-        return "Dependency: " + ArtifactUtils.versionlessKey( dependency.getGroupId(), dependency.getArtifactId() );
+        return "dependency: " + ArtifactUtils.versionlessKey( dependency.getGroupId(), dependency.getArtifactId() );
     }
 
     public Dependency getDependency()

[cyrille-leclerc]

@delanym while the build is not finished, it's a known limitation that the root span is missing. Once the build is finished, the root span should be visible.
Could your screenshot have been taken while the build was not finished?

The reason of this missing root span while the build is not finished is that spans are exported by the OpenTelemetry SDK after they are finished and the root span finishes at the end of the build.

Here is the view I get in Jaeger of "mvnd validate" on https//github.com/apache/maven after the build has completed. This view looks correct to me.

[delanym]

Yes that was the case. It looks good then.

[delanym]

@cyrille-leclerc it seems on v1.10.0-alpha its no longer sending a trace

[cyrille-leclerc]

@delanym strange, it works on my environment with 1.1.10-alpha as you can see the mvnd -X logs: https://gist.github.com/cyrille-leclerc/9cad0babb808b52e6782c82fd13e8063

Could you have forgotten to export OTEL_TRACES_EXPORTER="otlp" in addition to export OTEL_EXPORTER_OTLP_ENDPOINT="..."?

[delanym]

I had to restart the daemon: mvnd --stop. I shouldn't have to do that though. Gnodet says here about persisting data across invocations. Does the extension do that? Or maybe the issue is with mvnd itself not updating properly from .mvn/extensions.xml

[cyrille-leclerc]

Do you have a problem of failure or a problem of configuration of the second build being ignored?

[delanym]

Problem of configuration. Mvnd doesn't pick up the new version of the extension.

[gnodet]

Problem of configuration. Mvnd doesn't pick up the new version of the extension.

@delanym Could you try with a mvnd snapshot (you'll have to build it locally...) ? If it isn't fixed by, could you raise an issue on mvnd explaining the exact steps to reproduce the issue ? Please also report the output of mvnd --version.

[cyrille-leclerc]

@delanym can you please verify this draft issue, I think I understand the cause of your problem:

• [Maven Extension] Extension doesn't refresh its config across multiple executions with mvnd #220

@gnodet it's likely to be a problem in the extension, I'm investigation with @delanym ^^

[delanym]

@cyrille-leclerc mvnd is correctly starting another daemon when the extension changes. I do notice that the first time it does this the extension gives a warning:
[WARN] [stderr] javassist.NotFoundException: start(..) is not found in java.lang.ProcessBuilder

I'll look at #220 in the morning

[cyrille-leclerc]

Thanks @delanym for verifying. I suspect javassist.NotFoundException is an mvnd problem rather than an otel maven extension problem.