Java apm-agent http status codes not correctly identified

Elastic Observability APM
1

Hi there Elastic community

I was testing the APM Java Agent to know what we can do with it. This is my test environment:

  • java spring app with one end point to receive requests.
  • apache tomcat to run the app.
  • elastic-apm-agent-0.7.0 deployed with tomcat
  • apm-server-6.2.2 running
  • elasticsearch-6.2.2 and kibana running

The app is tested with the following request:
APMTest/data/getQuotient.do?dividend=10&divisor=5
APMTest/data/getQuotient.do?dividend=10&divisor=0
APMTest/data/getQuotient.do?dividend=10&divisors=0

After starting all components and started to make requests, I turned to the dashboards to see what was being recorded. All fine with the requests, as they started to appear on the transactions dashboard, showing both the average response time and requests per minute metrics. What caught my attention was that I was expecting to get at least a third of the request with some kind of error status, given that exceptions were expected to occur because of missing parameters at least.

All requests were recorded as having 200 status code, although the exceptions were being recorded as well in the body. So the exceptions were in fact being sent to elastic, just not being correctly identified with the actual 500 Internal server error status code.

What I was wondering is if this is some kind of bug or there is something wrong with my testing scenario.

These are the respective traces:

Request made with CURL:

curl -I -XGET 180.174.36.53:8084/APMTest/data/getQuotient.do?dividend=10&divisors=0
**HTTP/1.1 500 Internal Server Error**
Server: Apache-Coyote/1.1
Content-Type: text/html;charset=utf-8
Content-Language: en
Content-Length: 4153
Date: Wed, 19 Sep 2018 15:54:27 GMT

elastic-apm.log
2018-09-19 10:54:27.963 [apm-reporter] TRACE co.elastic.apm.report.serialize.DslJsonSerializer - {"service":{"name":"tomcat-application","agent":{"name":"java","version":"0.7.0"},"language":{"name":"Java","version":"1.8.0_151"},"runtime":{"name":"Java","version":"1.8.0_151"},"version":null},"process":{"pid":7996,"title":"C:\\Program Files\\Java\\jdk1.8.0_151\\jre\\bin\\java.exe"},"system":{"architecture":"x86","hostname":"Windows 7","platform":"SMQROSCC110212S"},"errors":[{"timestamp":"2018-09-19T15:54:27.948Z","transaction":{"id":"ddb82e5f-cc19-54c8-33e8-417b0c8454c0"},"context":{"request":{"method":"GET","headers":{"user-agent":"curl/7.29.0","host":"180.174.36.53:8084","accept":"*/*"},"url":{"full":"http://180.174.36.53:8084/APMTest/data/getQuotient.do?dividend=10","hostname":"180.174.36.53","port":"8084","pathname":"/APMTest/data/getQuotient.do","search":"dividend=10","protocol":"http"},"socket":{"encrypted":false,"remote_address":"180.174.61.144"},"http_version":"1.1"},"response":{"finished":true,"headers_sent":false,**"status_code":200**},"tags":{}},"exception":{"message":"Request processing failed; nested exception is...

apm kibana index document

"_source": {
    "@timestamp": "2018-09-19T15:54:27.948Z",
    "context": {
      "request": {
        "headers": {
          "host": "180.174.36.53:8084",
          "user-agent": "curl/7.29.0",
          "accept": "*/*"
        },
        "method": "GET",
        "http_version": "1.1",
        "socket": {
          "encrypted": false,
          "remote_address": "180.174.61.144"
        },
        "url": {
          "hostname": "180.174.36.53",
          "search": "dividend=10",
          "protocol": "http",
          "port": "8084",
          "full": "http://180.174.36.53:8084/APMTest/data/getQuotient.do?dividend=10",
          "pathname": "/APMTest/data/getQuotient.do"
        }
      },
      "process": {
        "pid": 7996,
        "title": "C:\\Program Files\\Java\\jdk1.8.0_151\\jre\\bin\\java.exe"
      },
      "system": {
        "hostname": "Windows 7",
        "platform": "SMQROSCC110212S",
        "architecture": "x86"
      },
      "response": {
        **"status_code": 200**,
        "finished": true,
        "headers_sent": false
      },

Sorry for the fine details, but I thought that this information may be required for troubleshooting.

In short: Are other kind of status codes, like 4XX or 5XX correctly identified by apm java agent?

Thanks in advance for your help

2

Hi and thanks for the detailed report!

This indicates that the response has not been committed at the time Elastic APM has captured the transaction. That means that the status code is probably set to 500 after the agent reads it. How is the error thrown and how do you do the error handling?

3

Hi Felix!

The request getQuotient.do?dividend=10&divisors=0 is made to a servlet that expects 2 parameters, dividend and divisor. I am sending "divisors" parameter instead, which makes the expected "divisor" parameter to be null. This throws a runtime java.lang.NullPointerException, which bubbles up. No special handling is being made. Should I need to handle this exception for the APM module to capture it at the right time?

Here is the code on the server side:

@RequestMapping(value = "/data/getQuotient")
    protected ModelAndView getQuotient(HttpServletRequest hsr, HttpServletResponse hsr1) throws Exception {
        ModelAndView model = new ModelAndView("index");
        String dividendString = hsr.getParameter("dividend");
        String divisorString  = hsr.getParameter("divisor");
        double dividend = Double.parseDouble(dividendString);
        double divisor  = Double.parseDouble(divisorString);
        double result   = dividend/divisor;
        model.addObject("message", "result: " + result);
        return model;
    }

Regards.

4

I was able to reproduce it locally and created an issue: https://github.com/elastic/apm-agent-java/issues/225

5

Thanks Felix

On my part, I found the following workaround:

    @RequestMapping(value = "/data/getQuotient")
    protected ModelAndView getQuotient(HttpServletRequest hsr, HttpServletResponse response) throws Exception{
        ModelAndView model = new ModelAndView("index");
        try{
            String dividendString = hsr.getParameter("dividend");
            String divisorString  = hsr.getParameter("divisor");
            double dividend = Double.parseDouble(dividendString);
            double divisor  = Double.parseDouble(divisorString);
            double result   = dividend/divisor;
            model.addObject("message", "result: " + result);
            return model;
        }
        catch(Exception e)
        {
            response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage());
            throw e;
        }
    }

I don't know if this is the right way to handle this exceptions to get them intercepted, according to the original design of the agent.

I am posting it here anyway should it be of any help to you or someone else having the same problem.

Regards

6

Ideally, the agent should pick up the status automatically, without the need of code changes. It's a bug that this is currently not working.

7

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