Plugin: WARN: End has already been called

Elastic Observability APM
1

Hi,

I have developed a small instrumentation plugin for the Java APM agent.

The advice class follows the pattern suggested in the documentation:

public static class AdviceClass
{
  @Advice.OnMethodEnter(suppress = Throwable.class, inline = false)
  public static Object onBeforeExecute()
  {
    Span active = ElasticApm.currentSpan();
    // ...
    Span span = active.startExitSpan(type, subtype, action);
    span.setName("SPANNAME");

    return span.activate();
  }

  @Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
  public static void onAfterExecute(@Advice.Enter Object obj, @Advice.Thrown Throwable t)
  {
    if (!(obj instanceof Scope))
      return;

    Span span = ElasticApm.currentSpan();
    try (Scope scope = (Scope) obj)
    {
      if (t != null)
      {
        span.setOutcome(Outcome.FAILURE);
        span.captureException(t);
      }
    }
    finally
    {
      span.end();
    }
 }

Everything seems to work fine - I can see the Spans in the APM dashboard.

However, I keep getting a warning messages:

WARN co.elastic.apm.agent.impl.transaction.AbstractSpan - End has already been called: 'SPANNAME'

What is wrong with my code?

2

If you use debug log level, you would see all starts and ends of each span printed with the trace context and the object identity hash code, so you can follow it. If you use trace level, it would print stack traces as well.
Try to execute as little invocations of the instrumentation as possible (ideally only one) because this would be quite verbose.
I hope this helps.

1 Like
3

I wasn't really able to pinpoint want went wrong exactly, but after changing my plugin to the following, the warning has disappeared:

  @Advice.OnMethodEnter(suppress = Throwable.class, inline = false)
  public static Object onBeforeExecute()
  {
    //...

    Scope scope = span.activate();
    // Note: Pair.of (from apache commons would work too - however, the following doesn't have any external dependencies):
    return new AbstractMap.SimpleImmutableEntry<>(span, scope);
  }

  @Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
  public static void onAfterExecute(@Advice.Enter Object obj, @Advice.Thrown Throwable t)
  {
    Entry<Span, Scope> pair = (Entry<Span, Scope>) obj;

    Span span = entry.getKey();
    try (Scope scope = entry.getValue())
    {
      //...
    }
    finally
    {
      span.end();
    }
 }

Apparently, closing the current span in a plugin seems to be a bad idea.

4

Does

@Advice.OnMethodExit(suppress = Throwable.class, onThrowable = Throwable.class, inline = false)
  public static void onAfterExecute(@Advice.Enter Object obj, @Advice.Thrown Throwable t)
  {
    if (!(obj instanceof Scope))
      return;

    Span span = ElasticApm.currentSpan();
    try
    {
      if (t != null)
      {
        span.setOutcome(Outcome.FAILURE);
        span.captureException(t);
      }
      span.end();
    }
    finally
    {
      ((Scope) obj).close();
    }
 }

work?

5

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.