How to quickly debug requests from k6 test scenarios

Using the k6 tool to run performance tests, it is very difficult to report incorrect results. Although errors can be displayed in the console, their reading and analysis must be aggregated in a file and then easily displayed. What if more than 500 errors are detected during soak tests? Their analysis from the console can be complicated. This is a confusing and complicated topic that should be explained.

Aggregating results to a file

In our K6 tests, we try to use as few external extensions as possible. For aggregation, we use a simple error display mechanism in the output. With a request and a check function result defined, we create a helper function for them called checkResult that checks if the check function returned true. Otherwise, it displays the entire request in the console.

function checkResult(res, status) {
  if (!status) {
    console.error(res)
  }
}

export default function () {
  const res = http.get('https//k6.io/api/v2/status.json')
  const status = check(
    res,
    {
      "response code is 201": (res) => res.status == 201
    }
  )
  checkResult(res, status)
}

Then the output left to redirect to a file in json format. We do this by defining the -log-output and -log-format parameters in the console.

k6 run --log-output=file=output.json --log-format=json script.js

In this way, all erroneous requests will be saved in the output.json file. The example result looks as follows:

{"level":"error","msg":"{\"remote_ip\":\"\",\"remote_port\":0,\"url\":\"https//k6.io/api/v2/status.json\",\"status\":0,\"status_text\":\"\",\"proto\":\"\",\"headers\":{},\"cookies\":{},\"body\":null,\"timings\":{\"duration\":0,\"blocked\":0,\"looking_up\":0,\"connecting\":0,\"tls_handshaking\":0,\"sending\":0,\"waiting\":0,\"receiving\":0},\"tls_version\":\"\",\"tls_cipher_suite\":\"\",\"ocsp\":{\"produced_at\":0,\"this_update\":0,\"next_update\":0,\"revoked_at\":0,\"revocation_reason\":\"\",\"status\":\"\"},\"error\":\"unsupported protocol scheme \\\"\\\"\",\"error_code\":1000,\"request\":{\"method\":\"GET\",\"url\":\"https//k6.io/api/v2/status.json\",\"headers\":{\"User-Agent\":[\"k6/0.38.3 (https://k6.io/)\"]},\"body\":\"\",\"cookies\":{}}}","source":"console","time":"2022-08-16T21:08:22+02:00"}

Reading erroneous requests

There are two types of errors inside the file – those aggregated by us and those aggregated by default by k6.

Reading the default errors

By default errors we mean those that would be displayed regardless of the console.error defined by us. They differ from those defined by us in that the requests are less clear and inaccurate.

Displaying all errors and their times

To display all error messages, the type of error and their times, we will use the command:

jq '. | select(.error) | .msg,.error,.time' output.json

Example:

"Request Failed"
"Get \"undefined/data/jobs-positions.json\": unsupported protocol scheme \"\""
"2022-08-16T21:13:57+02:00"

"Request Failed"
"Get \"undefined/static/tt-pro-bold-webfont-7842c22fb63b8a859ccff64910254df7.woff2\": unsupported protocol scheme \"\""
"2022-08-16T21:13:57+02:00"

Reading of errors aggregated by us

Reading all errors

jq '. | select(.level=="error" and .source=="console") | .msg | fromjson' output.json

Reading the number of all errors

jq -s '[.[] | select(.level=="error" and .source=="console")] | length' output.json

Reading an error with a given index

jq -s '[.[] | select(.level=="error" and .source=="console")][2]' output.json

Read errors from index 1 to 4

jq -s '[.[] | select(.level=="error" and .source=="console")] | .[1:4]' output.json

Reading the last 2 errors

jq -s '[.[] | select(.level=="error" and .source=="console")] | .[-2:]' output.json

Reading the first 3 errors

jq -s '[.[] | select(.level=="error" and .source=="console")] | .[:3]' output.json