APM Tracing Bridge - Span.log.error() Problem

[KeithW]

HI

I have some custom spans that trace given business operations. These spans may have child spans with the same process.

According to https://www.elastic.co/guide/en/apm/agent/java/current/opentracing-bridge.html#logs, I should be able to log an error for a span like this:

    Exception e = ...
    span.log(
        Map.of(
            "event", "error",
            "error.object", e
        )
    )

Unfortunately I can't get this working for any type of span (parent or child). I can see spans in the APM dashboard (if they are .finished()), however if I log errors against them I don't see any errors.

I do see other errors for rest calls that get automatically added by the attach agent, so in general errors are working. In the API console GET apm-7.6.2-error/_ilm/explain returns ok. Errors just don't seem to be working for our custom spans.

Versions:
APM Server version: apm-server:7.6.2
APM Agent Version (Java): co.elastic.apm:apm-agent-attach@1.16.0
APM Bridge Version (Java): co.elastic.apm:apm-opentracing@1.16.0

Couple of questions:

1. any ideas on the above?
2. if a span errors, should we also call finish()?

Appreciate any help

Regards

Keith

[Eyal_Koren]

Hi and welcome to our forum!

@KeithW

if a span errors, should we also call finish()?

Yes, a span is reported only if it is finished. An error is sent as a separate event.

@KeithW

any ideas on the above?

Try to debug and see if the span you are calling the log on is a valid one and not a noop. Also, set the agent's log_level to DEBUG and see if you find anything interesting. If you set it to TRACE, the agent will also log all events it sends to the APM server.
I hope this helps you figuring this out.

[KeithW]

Thanks for reply the welcome

The span is of type co.elastic.apm.opentracing.ApmSpan, so not a noop.

To narrow this down, I created a test span, started, logged an error, then finished it.

io.opentracing.Span span = this.elasticApmTracer
    .buildSpan("Test-Error-Span")
    .start();
span.log(
    ImmutableMap.of(
        "event", "BOOM-Exception",
        "error.object", new Exception("BOOM")
    )
);
span.finish();

I bumped the log level as you suggested (nice tip). I didn't notice any smoking guns. There were a few flush calls which contained the test trace:

DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 53)
TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer ...

The json that got flushed had the trace, but no error details:

{
  "transaction": {
    "timestamp": 1592390077519004,
    "name": "Test-Error-Span",
    "id": "a1de5eeb641f807f",
    "trace_id": "4d9ac1981d005b6cf2a80d1724145c6c",
    "type": "unknown",
    "duration": 4.298,
    "context": {
      "tags": {}
    },
    "span_count": {
      "dropped": 0,
      "started": 0
    },
    "sampled": true
  }
}

... in a later flush  

{
  "metricset": {
    "timestamp": 1592390103155000,
    "transaction": {
      "name": "Test-Error-Span",
      "type": "unknown"
    },
    "span": {
      "type": "app",
      "subtype": null
    },
    "tags": {},
    "samples": {
      "span.self_time.count": {
        "value": 1
      },
      "span.self_time.sum.us": {
        "value": 4298
      }
    }
  }
}


  "metricset": {
    "timestamp": 1592390103155000,
    "transaction": {
      "name": "Test-Error-Span",
      "type": "unknown"
    },
    "tags": {},
    "samples": {
      "transaction.duration.count": {
        "value": 1
      },
      "transaction.duration.sum.us": {
        "value": 4298
      },
      "transaction.breakdown.count": {
        "value": 1
      }
    }
  }
}

I didn't see any text that was logged against the span (i.e. 'BOOM-Exception', or just 'BOOM');

The underlying co.elastic.apm.opentracing.ApmSpan seems to just have a noop for all logging calls:

    public ApmSpan log(String event) {
        this.log(Collections.singletonMap("event", event));
        return this;
    }

    public ApmSpan log(Map<String, ?> fields) {
        return this.log(-1L, fields);
    }

    public ApmSpan log(long timestampMicroseconds, String event) {
        this.log(timestampMicroseconds, Collections.singletonMap("event", event));
        return this;
    }

    public ApmSpan log(long timestampMicroseconds, Map<String, ?> fields) {
        return this;
    }

Not sure how that'd log anything unless there is some runtime weaving going on by the agent.
(Edit: looks like the source does elude to some injection going on: https://github.com/elastic/apm-agent-java/blob/master/apm-opentracing/src/main/java/co/elastic/apm/opentracing/ApmSpan.java)

Not sure what I'm doing wrong here?

Thanks for any help

[Eyal_Koren]

You need to use error as the value of the event key:

span.log(
    ImmutableMap.of(
        "event", "error",
        "error.object", new Exception("BOOM")
    )
);

This is what tells the agent to send an error event

[KeithW]

I just figured this out, looking at https://github.com/elastic/apm-agent-java/blob/master/apm-agent-plugins/apm-opentracing-plugin/src/main/java/co/elastic/apm/agent/opentracing/impl/ApmSpanInstrumentation.java#L137, the value of error must be error. I seemed to have it as a message.

[KeithW]

Thanks for the reply, i just figured it out. My bad. We'll was a fun investigation

Thanks for the help.