504s are not being logged properly with checks

Grafana k6
1

I’m seeing some interesting behavior with the summary output and how it is logging data to present what it shows properly.

Below is a screenshot of the summary from one of my latest runs. I have two checks, then the default summary output from k6. I would also like to note that I am load testing a graphql endpoint.

Screenshot 2024-04-24 at 11.50.15 AM
Screenshot 2024-04-24 at 11.50.15 AM1034×419 63 KB

The code for the checks is as follows:

check(res, {
    'response code was 200': (res) => res.status == 200,
  });

// Need to check body of response for errors since this is a GQL endpoint
  check(body, {
    'body contains no errors': (body) => body.errors == undefined,
  });

What alerted me to the issue was that the response code was 200 check is reporting that all of the requests are 200, but the http_req_failed metric is reporting that 128 requests failed.

On top of this, when I run a load test I sometimes get these errors to pop-up intermittently:

ERRO[0767] GoError: cannot parse json due to an error at line 1, character 2 , error: invalid character 'r' looking for beginning of value
        at reflect.methodValueCall (native)
        at file:///Users/zakirefai/Work/load-testing/dist/price-quotes.products.coordinates.unauth.test.js:2:24999(3)
        at c (file:///Users/zakirefai/Work/load-testing/dist/price-quotes.products.coordinates.unauth.test.js:2:25121(54))  executor=ramping-vus scenario=load source=stacktrace

After some investigation into the granular output from the test I believe I have found the issue. Here is the output of the http_req_failed when it encounters a failed request.

{
    "metric": "http_req_failed",
    "type": "Point",
    "data": {
        "time": "2024-04-24T11:07:00.264696-04:00",
        "value": 1,
        "tags": {
            "error_code": "1504",
            "expected_response": "false",
            "group": "",
            "method": "POST",
            "name": "https://api.prescryptive.io/graphql",
            "proto": "HTTP/2.0",
            "scenario": "load",
            "status": "504",
            "tls_version": "tls1.3",
            "url": "https://api.prescryptive.io/graphql"
        }
    }
}

It tells me that a 504 error occurred during one of the requests. Now the checks should fire off and log that a 504 error occurred, but nowhere after a 504 failure does the check occur. I can see the checks logging in the granular output after a 200 response, but not after a 504. I believe this is where the JSON error ERRO[0767] from above comes into play. Maybe it is failing to perform the check against this request because it’s not able to parse the JSON somehow after a 504?

Please advise on what I should do. I’m not sure how to go about solving this.

2

I think there is no way r.json() can succeed if the response status > 399 and is not JSON content
hence it’s a basic error of the method
maybe log something like r.body or better r.status_text instead of r.json()

3

@zakirefai

I think this happens because you call res.json() before the res.status == 200 check, and if the status is not 200, the body is not parsable as json.
You should modify your script like this:

check(res, {
    'response code was 200': (res) => res.status == 200,
  });

if (res.status == 200) {
  const body = res.json();
// Need to check body of response for errors since this is a GQL endpoint
  check(body, {
    'body contains no errors': (body) => body.errors == undefined,
  });
}

I hope this helps

1 Like
4

Thanks! This small fix worked

1 Like