fix: start post_processor span before the factory call

flexmark-core-test/pom.xml

@@ -38,5 +38,10 @@
             <artifactId>jmh-generator-annprocess</artifactId>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>io.opentelemetry</groupId>
+            <artifactId>opentelemetry-sdk-testing</artifactId>
+            <scope>test</scope>
+        </dependency>
     </dependencies>
 </project>

flexmark-core-test/src/test/java/com/vladsch/flexmark/core/test/util/parser/PostProcessorManagerSpanTest.java

@@ -0,0 +1,118 @@
+package com.vladsch.flexmark.core.test.util.parser;
+
+import com.vladsch.flexmark.ast.Text;
+import com.vladsch.flexmark.parser.Parser;
+import com.vladsch.flexmark.parser.block.DocumentPostProcessor;
+import com.vladsch.flexmark.parser.block.DocumentPostProcessorFactory;
+import com.vladsch.flexmark.parser.block.NodePostProcessor;
+import com.vladsch.flexmark.parser.block.NodePostProcessorFactory;
+import com.vladsch.flexmark.util.ast.Document;
+import com.vladsch.flexmark.util.ast.Node;
+import com.vladsch.flexmark.util.ast.NodeTracker;
+import io.opentelemetry.api.GlobalOpenTelemetry;
+import io.opentelemetry.api.common.AttributeKey;
+import io.opentelemetry.api.trace.Span;
+import io.opentelemetry.sdk.testing.junit4.OpenTelemetryRule;
+import io.opentelemetry.sdk.trace.data.SpanData;
+import org.jetbrains.annotations.NotNull;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+
+import java.util.List;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertTrue;
+
+/**
+ * Verifies that the per-processor span wraps {@code PostProcessorFactory.apply(...)}, so time spent
+ * constructing a post processor is attributed to that processor's span.
+ */
+final public class PostProcessorManagerSpanTest {
+    private static final AttributeKey<String> CLASS_ATTRIBUTE = AttributeKey.stringKey("markdown.post_processor.class");
+
+    @Rule
+    public final OpenTelemetryRule openTelemetry = OpenTelemetryRule.create();
+
+    @Before
+    public void installAsGlobal() {
+        // PostProcessorManager obtains its tracer from GlobalOpenTelemetry, which the rule does not register.
+        GlobalOpenTelemetry.resetForTest();
+        GlobalOpenTelemetry.set(openTelemetry.getOpenTelemetry());
+    }
+
+    @After
+    public void resetGlobal() {
+        GlobalOpenTelemetry.resetForTest();
+    }
+
+    @Test
+    public void nodePostProcessorFactoryIsAppliedInsideItsSpan() {
+        RecordingNodePostProcessorFactory factory = new RecordingNodePostProcessorFactory();
+        Parser.builder().postProcessorFactory(factory).build().parse("some text");
+
+        assertFactoryAppliedInsideSpan(factory.spanCurrentDuringApply, RecordingNodePostProcessor.class);
+    }
+
+    @Test
+    public void documentPostProcessorFactoryIsAppliedInsideItsSpan() {
+        RecordingDocumentPostProcessorFactory factory = new RecordingDocumentPostProcessorFactory();
+        Parser.builder().postProcessorFactory(factory).build().parse("some text");
+
+        assertFactoryAppliedInsideSpan(factory.spanCurrentDuringApply, RecordingDocumentPostProcessor.class);
+    }
+
+    private void assertFactoryAppliedInsideSpan(Span spanCurrentDuringApply, Class<?> expectedProcessorClass) {
+        assertNotNull("factory was not applied", spanCurrentDuringApply);
+        List<SpanData> spans = openTelemetry.getSpans();
+        assertEquals(1, spans.size());
+        SpanData span = spans.get(0);
+        assertEquals("markdown.parse.post_processor", span.getName());
+        assertEquals("factory was applied outside the post_processor span", span.getSpanId(), spanCurrentDuringApply.getSpanContext().getSpanId());
+        assertEquals(expectedProcessorClass.getName(), span.getAttributes().get(CLASS_ATTRIBUTE));
+        assertTrue(span.hasEnded());
+    }
+
+    static class RecordingNodePostProcessorFactory extends NodePostProcessorFactory {
+        Span spanCurrentDuringApply;
+
+        RecordingNodePostProcessorFactory() {
+            super(false);
+            addNodes(Text.class);
+        }
+
+        @NotNull
+        @Override
+        public NodePostProcessor apply(@NotNull Document document) {
+            spanCurrentDuringApply = Span.current();
+            return new RecordingNodePostProcessor();
+        }
+    }
+
+    static class RecordingNodePostProcessor extends NodePostProcessor {
+        @Override
+        public void process(@NotNull NodeTracker state, @NotNull Node node) {
+        }
+    }
+
+    static class RecordingDocumentPostProcessorFactory extends DocumentPostProcessorFactory {
+        Span spanCurrentDuringApply;
+
+        @NotNull
+        @Override
+        public DocumentPostProcessor apply(@NotNull Document document) {
+            spanCurrentDuringApply = Span.current();
+            return new RecordingDocumentPostProcessor();
+        }
+    }
+
+    static class RecordingDocumentPostProcessor extends DocumentPostProcessor {
+        @NotNull
+        @Override
+        public Document processDocument(@NotNull Document document) {
+            return document;
+        }
+    }
+}

flexmark/src/main/java/com/vladsch/flexmark/parser/internal/PostProcessorManager.java

@@ -76,9 +76,10 @@ public Document postProcess(Document document) {
             boolean hadGlobal = false;
             for (PostProcessorFactory dependent : stage.dependents) {
                 if (dependent.affectsGlobalScope()) {
-                    PostProcessor postProcessor = dependent.apply(document);
-                    Span span = startPostProcessorSpan(postProcessor);
+                    Span span = startPostProcessorSpan();
                     try (Scope ignored = span.makeCurrent()) {
+                        PostProcessor postProcessor = dependent.apply(document);
+                        span.setAttribute(POST_PROCESSOR_CLASS_ATTRIBUTE, postProcessor.getClass().getName());
                         document = postProcessor.processDocument(document);
                     } catch (Throwable t) {
                         span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
@@ -98,17 +99,18 @@ public Document postProcess(Document document) {
                     }
 
                     Map<Class<?>, Set<Class<?>>> dependentNodeTypes = dependent.getNodeTypes();
-                    PostProcessor postProcessor = dependent.apply(document);
-                    BitSet exclusionSet = new BitSet();
-                    if (dependentNodeTypes != null) {
-                        for (Set<Class<?>> excluded : dependentNodeTypes.values()) {
-                            BitSet mapped = classifyingNodeTracker.getExclusionSet().indexBitSet(excluded);
-                            exclusionSet.or(mapped);
-                        }
+                    Span span = startPostProcessorSpan();
+                    try (Scope ignored = span.makeCurrent()) {
+                        PostProcessor postProcessor = dependent.apply(document);
+                        span.setAttribute(POST_PROCESSOR_CLASS_ATTRIBUTE, postProcessor.getClass().getName());
+                        BitSet exclusionSet = new BitSet();
+                        if (dependentNodeTypes != null) {
+                            for (Set<Class<?>> excluded : dependentNodeTypes.values()) {
+                                BitSet mapped = classifyingNodeTracker.getExclusionSet().indexBitSet(excluded);
+                                exclusionSet.or(mapped);
+                            }
 
-                        ReversibleIterable<Node> nodes = classifyingNodeTracker.getCategoryItems(Node.class, dependentNodeTypes.keySet());
-                        Span span = startPostProcessorSpan(postProcessor);
-                        try (Scope ignored = span.makeCurrent()) {
+                            ReversibleIterable<Node> nodes = classifyingNodeTracker.getCategoryItems(Node.class, dependentNodeTypes.keySet());
                             for (Node node : nodes) {
                                 if (node.getParent() == null) continue; // was already removed
                                 // now we need to get the bitset for the excluded ancestors of the node, then intersect it with the actual ancestors of this factory
@@ -132,12 +134,12 @@ public Document postProcess(Document document) {
                                 }
                                 postProcessor.process(classifyingNodeTracker, node);
                             }
-                        } catch (Throwable t) {
-                            span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
-                            throw t;
-                        } finally {
-                            span.end();
                         }
+                    } catch (Throwable t) {
+                        span.setStatus(StatusCode.ERROR, t.getClass().getSimpleName() + ": " + t.getMessage());
+                        throw t;
+                    } finally {
+                        span.end();
                     }
                 }
             }
@@ -146,11 +148,16 @@ public Document postProcess(Document document) {
         return document;
     }
 
-    private static Span startPostProcessorSpan(PostProcessor postProcessor) {
+    private static final String POST_PROCESSOR_CLASS_ATTRIBUTE = "markdown.post_processor.class";
+
+    // Started before PostProcessorFactory.apply(...) so that work done while constructing the processor
+    // (which may be expensive, e.g. loading data to build matching patterns) is attributed to this span
+    // instead of showing up only as unexplained time in the enclosing post_process span. The processor
+    // class is therefore added as an attribute by the caller once the instance exists.
+    private static Span startPostProcessorSpan() {
         // no-op span unless a Java agent (or the application) has wired GlobalOpenTelemetry
         return GlobalOpenTelemetry.getTracer("com.vladsch.flexmark")
                 .spanBuilder("markdown.parse.post_processor")
-                .setAttribute("markdown.post_processor.class", postProcessor.getClass().getName())
                 .startSpan();
     }
 

pom.xml

@@ -546,6 +546,13 @@
                 <artifactId>opentelemetry-instrumentation-annotations</artifactId>
                 <version>2.16.0</version>
             </dependency>
+            <!-- Test-only: in-memory span exporter for asserting on spans. Keep in step with the
+                 opentelemetry-api version pulled in transitively by the annotations artifact. -->
+            <dependency>
+                <groupId>io.opentelemetry</groupId>
+                <artifactId>opentelemetry-sdk-testing</artifactId>
+                <version>1.50.0</version>
+            </dependency>
 
             <!-- Common test dependencies -->
             <dependency>