Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Thresholds with tags not capturing metric values for some API calls, returning zero instead #3518

Closed
luissalgadofreire opened this issue Dec 24, 2023 · 8 comments
Assignees
Labels

Comments

@luissalgadofreire
Copy link

luissalgadofreire commented Dec 24, 2023

Brief summary

While testing a CRUD API, thresholds with tags are used to get the metrics per tag. However, some calls, namely Delete and Purge, which are the only ones that don't return a body in the response (and therefore their response.json() is null) return 0 instead of the actual values. Using custom groups worked. Using thresholds with tags didn't.

k6 version

v0.48.0

OS

macOS Sonoma (14.1.2)

Docker version and image (if applicable)

No response

Steps to reproduce the problem

Use the following configuration to test the performance of a CRUD API.

// main.js
import { callEndpoints, deleteTestData } from './script.js';
import { textSummary } from 'https://jslib.k6.io/k6-summary/0.0.2/index.js';

globalThis.PAUSE_MIN = __ENV.PAUSE_MIN || 1;
globalThis.PAUSE_MAX = __ENV.PAUSE_MAX || 5;

// TODO: fix thresholds for tags Delete and Purge returning 0 (both have response.json() == null)
export const options = {
    vus: 1,
    duration: '1m',
    thresholds: {
        'http_req_failed': ["rate<0.01"],
        'http_req_failed{name:Create}': ["rate<0.01"],
        'http_req_failed{name:Get}': ["rate<0.01"],
        'http_req_failed{name:List}': ["rate<0.01"],
        'http_req_failed{name:Delete}': ["rate<0.01"],
        'http_req_failed{name:Purge}': ["rate<0.01"],
        'http_req_duration': ["p(95)<50"],
        'http_req_duration{name:Create}': ["p(95)<50"],
        'http_req_duration{name:Get}': ["p(95)<50"],
        'http_req_duration{name:List}': ["p(95)<50"],
        'http_req_duration{name:Delete}': ["p(95)<50"],
        'http_req_duration{name:Purge}': ["p(95)<50"],
    },
};

export default function () {
    callEndpoints();
}

export function handleSummary(data) {
    return {
        'summary.json': JSON.stringify(data), //the default data object
        'stdout': textSummary(data) // the default text summary
    };
}
// scripts.js
import http from 'k6/http';
import { check, group, sleep } from 'k6';
import { Trend } from 'k6/metrics';
import { uuidv4 } from 'https://jslib.k6.io/k6-utils/1.4.0/index.js';
import { randomIntBetween } from '../../../common/utils.js';

const baseUrl = 'https://localhost:40443/v1/persons';

const params = {
    headers: {
        "content-type": "application/json-patch+json",
        "accept": "application/json, text/javascript, */*; q=0.01",
        "accept-encoding": "gzip, deflate",
        "accept-language": "en-US,en;q=0.9",
        "connection": "keep-alive",
    }
};

export function callEndpoints() {
    let id = uuidv4();
  
    const paramsWithTag = (tag) => (Object.assign({}, params, { tags: { name: tag } }));
    
    group('Create', () => {
        const url = baseUrl;
        const payload = JSON.stringify({
          Id: id,
          Name: 'Alfa',
          Description: 'Description for Alfa'
        });
        const response = http.post(baseUrl, payload, paramsWithTag('Create'));
        check(response, {"Create response status code is 201": (r) => r.status == 201});
        sleep(randomIntBetween(globalThis.PAUSE_MIN, globalThis.PAUSE_MAX));
    });
    
    group('Get', () => {
        const url = `${baseUrl}/${id}`;
        const response = http.get(url, paramsWithTag('Get'));
        check(response, {"Get response status code is 200": (r) => r.status == 200});
        sleep(randomIntBetween(globalThis.PAUSE_MIN, globalThis.PAUSE_MAX));
    });
    
    group('List', () => {
        const path = 'keyset?Filter=not%20%28Name%20eq%20%27Kenny%27%29'
        const url = `${baseUrl}/${path}`;
        const response = http.get(url, paramsWithTag('List'));
        check(response, {"List response status code is 200": (r) => r.status == 200});
        sleep(randomIntBetween(globalThis.PAUSE_MIN, globalThis.PAUSE_MAX));
    });
    
    group('Delete', () => {
        const url = `${baseUrl}/${id}`;
        const response = http.del(url, paramsWithTag('Delete'));
        check(response, {"Delete response status code is 204": (r) => r.status == 204});
        sleep(randomIntBetween(globalThis.PAUSE_MIN, globalThis.PAUSE_MAX));
    });
    
    group('Purge', () => {
        const url = `${baseUrl}/${id}/purge`;
        const response = http.del(url, paramsWithTag('Purge'));
        check(response, {"Purge response status code is 204": (r) => r.status == 204});
        sleep(randomIntBetween(globalThis.PAUSE_MIN, globalThis.PAUSE_MAX));
    });
}

Expected behaviour

The configuration should return the below, with Delete and Purge calls returning the proper values instead of 0.

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: main.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 1m30s max duration (incl. graceful stop):
           * default: 1 looping VUs for 1m0s (gracefulStop: 30s)

     █ Create

       ✓ Create response status code is 201

     █ Get

       ✓ Get response status code is 200

     █ List

       ✓ List response status code is 200

     █ Delete

       ✓ Delete response status code is 204

     █ Purge

       ✓ Purge response status code is 204

     █ teardown

     checks.........................: 100.00% ✓ 20       ✗ 0  
     data_received..................: 13 kB   211 B/s
     data_sent......................: 9.6 kB  160 B/s
     group_duration.................: avg=3.01s   min=1s      med=2.51s   max=5.02s   p(90)=5s      p(95)=5.01s  
     http_req_blocked...............: avg=1.32ms  min=3µs     med=4µs     max=15.12ms p(90)=7µs     p(95)=12.69ms
     http_req_connecting............: avg=24.57µs min=0s      med=0s      max=362µs   p(90)=0s      p(95)=154µs  
   ✓ http_req_duration..............: avg=10.38ms min=3.53ms  med=7.64ms  max=20.5ms  p(90)=18.27ms p(95)=18.46ms
       { expected_response:true }...: avg=10.38ms min=3.53ms  med=7.64ms  max=20.5ms  p(90)=18.27ms p(95)=18.46ms
     ✓ { name:Create }..............: avg=7.32ms  min=4.24ms  med=5.12ms  max=14.81ms p(90)=12ms    p(95)=13.41ms
     ✓ { name:Delete }..............: avg=7.32ms  min=4.24ms  med=5.12ms  max=14.81ms p(90)=12ms    p(95)=13.41ms
     ✓ { name:Get }.................: avg=15.52ms min=11.42ms med=16.56ms max=17.55ms p(90)=17.33ms p(95)=17.44ms
     ✓ { name:List }................: avg=4.57ms  min=3.66ms  med=4.58ms  max=5.45ms  p(90)=5.35ms  p(95)=5.4ms  
     ✓ { name:Purge }...............: avg=7.32ms  min=4.24ms  med=5.12ms  max=14.81ms p(90)=12ms    p(95)=13.41ms
   ✓ http_req_failed................: 0.00%   ✓ 0        ✗ 21 
     ✓ { name:Create }..............: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:Delete }..............: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:Get }.................: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:List }................: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:Purge }...............: 0.00%   ✓ 0        ✗ 4  
     http_req_receiving.............: avg=98.38µs min=33µs    med=66µs    max=416µs   p(90)=148µs   p(95)=262µs  
     http_req_sending...............: avg=41.61µs min=17µs    med=31µs    max=187µs   p(90)=50µs    p(95)=111µs  
     http_req_tls_handshaking.......: avg=1.28ms  min=0s      med=0s      max=14.68ms p(90)=0s      p(95)=12.27ms
     http_req_waiting...............: avg=10.24ms min=3.07ms  med=7.56ms  max=20.39ms p(90)=18.2ms  p(95)=18.39ms
     http_reqs......................: 21      0.348468/s
     iteration_duration.............: avg=12.05s  min=18.89ms med=14.07s  max=17.05s  p(90)=17.05s  p(95)=17.05s 
     iterations.....................: 4       0.066375/s
     vus............................: 1       min=1      max=1

running (1m00.3s), 0/1 VUs, 4 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  1m0s

Actual behaviour

The configuration returns the below, with Delete and Purge calls being basically ignored and returning 0 instead. The one thing where they differ from the other calls is that they return no body, so response.json() is null and trying to call it will throw an error. I suspect thresholds with tags may be calling response.json() somewhere in the source code and ends up not returning the proper metric.

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: main.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 1m30s max duration (incl. graceful stop):
           * default: 1 looping VUs for 1m0s (gracefulStop: 30s)

     █ Create

       ✓ Create response status code is 201

     █ Get

       ✓ Get response status code is 200

     █ List

       ✓ List response status code is 200

     █ Delete

       ✓ Delete response status code is 204

     █ Purge

       ✓ Purge response status code is 204

     █ teardown

     checks.........................: 100.00% ✓ 20       ✗ 0  
     data_received..................: 13 kB   211 B/s
     data_sent......................: 9.6 kB  160 B/s
     group_duration.................: avg=3.01s   min=1s      med=2.51s   max=5.02s   p(90)=5s      p(95)=5.01s  
     http_req_blocked...............: avg=1.32ms  min=3µs     med=4µs     max=15.12ms p(90)=7µs     p(95)=12.69ms
     http_req_connecting............: avg=24.57µs min=0s      med=0s      max=362µs   p(90)=0s      p(95)=154µs  
   ✓ http_req_duration..............: avg=10.38ms min=3.53ms  med=7.64ms  max=20.5ms  p(90)=18.27ms p(95)=18.46ms
       { expected_response:true }...: avg=10.38ms min=3.53ms  med=7.64ms  max=20.5ms  p(90)=18.27ms p(95)=18.46ms
     ✓ { name:Create }..............: avg=7.32ms  min=4.24ms  med=5.12ms  max=14.81ms p(90)=12ms    p(95)=13.41ms
     ✓ { name:Delete }..............: avg=0s      min=0s      med=0s      max=0s      p(90)=0s      p(95)=0s     
     ✓ { name:Get }.................: avg=15.52ms min=11.42ms med=16.56ms max=17.55ms p(90)=17.33ms p(95)=17.44ms
     ✓ { name:List }................: avg=4.57ms  min=3.66ms  med=4.58ms  max=5.45ms  p(90)=5.35ms  p(95)=5.4ms  
     ✓ { name:Purge }...............: avg=0s      min=0s      med=0s      max=0s      p(90)=0s      p(95)=0s     
   ✓ http_req_failed................: 0.00%   ✓ 0        ✗ 21 
     ✓ { name:Create }..............: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:Delete }..............: 0.00%   ✓ 0        ✗ 0  
     ✓ { name:Get }.................: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:List }................: 0.00%   ✓ 0        ✗ 4  
     ✓ { name:Purge }...............: 0.00%   ✓ 0        ✗ 0  
     http_req_receiving.............: avg=98.38µs min=33µs    med=66µs    max=416µs   p(90)=148µs   p(95)=262µs  
     http_req_sending...............: avg=41.61µs min=17µs    med=31µs    max=187µs   p(90)=50µs    p(95)=111µs  
     http_req_tls_handshaking.......: avg=1.28ms  min=0s      med=0s      max=14.68ms p(90)=0s      p(95)=12.27ms
     http_req_waiting...............: avg=10.24ms min=3.07ms  med=7.56ms  max=20.39ms p(90)=18.2ms  p(95)=18.39ms
     http_reqs......................: 21      0.348468/s
     iteration_duration.............: avg=12.05s  min=18.89ms med=14.07s  max=17.05s  p(90)=17.05s  p(95)=17.05s 
     iterations.....................: 4       0.066375/s
     vus............................: 1       min=1      max=1

running (1m00.3s), 0/1 VUs, 4 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  1m0s
@luissalgadofreire luissalgadofreire changed the title Thresholds with tags not capturing metric values, returning zero instead Thresholds with tags not capturing metric values for some API calls, returning zero instead Dec 24, 2023
@oleiade
Copy link
Member

oleiade commented Jan 15, 2024

Hi @luissalgadofreire 👋🏻

Thanks for reporting this 🙇🏻

I can confirm I am able to reproduce the behavior you're observing in a simplified script that isolates it:

import { check, group } from 'k6';
import http from 'k6/http';

export const options = {
	iterations: 10,
	thresholds: {
		'http_req_duration{name: Get}': ["p(95)<1000"],
		'http_req_duration{name: Delete}': ["p(95)<1000"],
		'http_req_duration{name: Purge}': ["p(95)<1000"],
	}
}

export default function () {
	group('Get', () => {
		const response = http.get('http://httpbin.org/get', { tags: { name: 'Get' } });
		check(response, {
			"Get response status code is 200": (r) => r.status === 200
		});
	});

	group('Delete', () => {
		const response = http.del('http://httpbin.org/status/204', { tags: { name: 'Delete' } });
		check(response, {
			"Purge response status code is 204": (r) => r.status === 204
		});
	});

	group('Purge', () => {
		const response = http.del('http://httpbin.org/status/204', { tags: { name: 'Purge' } });
		check(response, {
			"Purge response status code is 204": (r) => r.status === 204
		});
	});
}

Leading to the following output, where indeed the metrics linked to the requests using the del method, and tagged with Delete and Purge are left to zero.

     █ Get

       ✓ Get response status code is 200

     █ Delete

       ✓ Purge response status code is 204

     █ Purge

       ✓ Purge response status code is 204

     checks.........................: 100.00% ✓ 30       ✗ 0
     data_received..................: 9.3 kB  1.3 kB/s
     data_sent......................: 4.5 kB  624 B/s
     group_duration.................: avg=240.72ms min=170.25ms med=172.07ms max=714.54ms p(90)=551.7ms  p(95)=567.21ms
     http_req_blocked...............: avg=6.61ms   min=3µs      med=8µs      max=198.31ms p(90)=10.2µs   p(95)=15.29µs
     http_req_connecting............: avg=5.69ms   min=0s       med=0s       max=170.98ms p(90)=0s       p(95)=0s
     http_req_duration..............: avg=233.77ms min=169.98ms med=171.62ms max=714.08ms p(90)=551.41ms p(95)=566.91ms
       { expected_response:true }...: avg=233.77ms min=169.98ms med=171.62ms max=714.08ms p(90)=551.41ms p(95)=566.91ms
     ✓ { name: Delete }.............: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     ✓ { name: Get }................: avg=184.69ms min=170.83ms med=171.89ms max=295.35ms p(90)=188.42ms p(95)=241.88ms
     ✓ { name: Purge }..............: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     http_req_failed................: 0.00%   ✓ 0        ✗ 30
     http_req_receiving.............: avg=204.83µs min=40µs     med=103µs    max=3.12ms   p(90)=211.4µs  p(95)=238.5µs
     http_req_sending...............: avg=40.4µs   min=20µs     med=36.5µs   max=170µs    p(90)=52.6µs   p(95)=60.2µs
     http_req_tls_handshaking.......: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     http_req_waiting...............: avg=233.53ms min=169.88ms med=171.42ms max=713.8ms  p(90)=551.26ms p(95)=566.81ms
     http_reqs......................: 30      4.153035/s
     iteration_duration.............: avg=722.28ms min=514.06ms med=578.88ms max=1.27s    p(90)=1.08s    p(95)=1.17s
     iterations.....................: 10      1.384345/s
     vus............................: 1       min=1      max=1
     vus_max........................: 1       min=1      max=1
     ```

I'm gonna look into it and try to isolate the root cause further.

@oleiade
Copy link
Member

oleiade commented Jan 15, 2024

I've found out that only the http.del method seems to be affected. By switching to any other method, the handleSummary displays correct measurements.

Directing the k6 output to a JSON file, shows that some actual data points are actually recorded, even when using the http.del method though:

{
	"metric": "http_req_duration",
	"type": "Point",
	"data": {
	"time": "2024-01-15T14:44:45.914034+01:00",
		"value": 119.493,
		"tags": {
		"expected_response": "true",
			"group": "::Purge",
			"method": "DELETE",
			"name": "http://httpbin.org/status/204",
			"proto": "HTTP/1.1",
			"scenario": "default",
			"status": "204",
			"url": "http://httpbin.org/status/204"
	}
}

Which seems to hint that the issue might be at the handleSummary level instead?

@oleiade oleiade removed the triage label Jan 15, 2024
@luissalgadofreire
Copy link
Author

luissalgadofreire commented Jan 15, 2024

Hi, @oleiade.

Your example indeed shows that HTTP requests that do not return a body (hence the 204 - No Content HTTP status code) end up zeroed in the summary output.

It could be that the problem resides in handleSummary(), I can't really tell. I removed the explicit call to handleSummary() and the behavior is the same but, then again, that is expected as I was calling the default function.

My only hint, however, is 1) the absence of a body in the response or 2) the HTTP method (DELETE) or 3) the HTTP status code (204) somehow triggering this behaviour somewhere in k6...

@oleiade
Copy link
Member

oleiade commented Jan 15, 2024

I'm not convinced that this bug happens because of the absence of a body. With a quick and dirty Python-based HTTP server returning 200 on DELETE, with a JSON body, I get the same result.

server script:

#!/usr/bin/env python3

from http.server import BaseHTTPRequestHandler, HTTPServer
import json


class SimpleHTTPRequestHandler(BaseHTTPRequestHandler):
    def do_DELETE(self):
        # Respond with 204 No Content status
        # self.send_response(204)
        self.send_response(200)

        # Send headers
        self.send_header("Content-type", "application/json")
        self.end_headers()

        # Send a basic JSON response
        response = json.dumps({"message": "Delete request processed"})
        self.wfile.write(response.encode())


def run(server_class=HTTPServer, handler_class=SimpleHTTPRequestHandler, port=8000):
    server_address = ("", port)
    httpd = server_class(server_address, handler_class)
    print(f"Starting httpd server on port {port}")
    httpd.serve_forever()


if __name__ == "__main__":
    run()

Replaced script line:

		const response = http.del('http://localhost:8000', { tags: { name: 'Delete' } });

And same result:

✓ { name: Delete }.............: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s

@luissalgadofreire
Copy link
Author

luissalgadofreire commented Jan 15, 2024 via email

@oleiade
Copy link
Member

oleiade commented Jan 15, 2024

Hey @luissalgadofreire,

So, it turns out the issue is probably much simpler than I had anticipated, and would have had a link to the body, but, the request's.

I always forget about it, but the http.del method takes a body arg, could you try replacing your http.del calls with the following: const response = http.del(url, null, paramsWithTag('Delete')); and let me know if that addresses the issue for you?

@luissalgadofreire
Copy link
Author

Hi again, @oleiade.

Yup, that seems to solve it:

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  ()  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: main.js
     output: -

  scenarios: (100.00%) 1 scenario, 100 max VUs, 1m30s max duration (incl. graceful stop):
           * rps_50: 10.00 iterations/s for 1m0s (maxVUs: 50-100, gracefulStop: 30s)


      Create

        Create response status code is 201

      Get

        Get response status code is 200

      List

        List response status code is 200

      Delete

        Delete response status code is 204

      Purge

        Purge response status code is 204

      teardown

     checks.........................: 100.00%  3000      0   
     data_received..................: 5.5 MB  86 kB/s
     data_sent......................: 1.1 MB  17 kB/s
     group_duration.................: avg=507.3ms  min=3.05ms  med=47.76ms max=1.81s    p(90)=1.01s   p(95)=1.02s  
     http_req_blocked...............: avg=258.6µs  min=1µs     med=3µs     max=37.83ms  p(90)=5µs     p(95)=6µs    
     http_req_connecting............: avg=4.53µs   min=0s      med=0s      max=1.92ms   p(90)=0s      p(95)=0s     
    http_req_duration..............: avg=15.36ms  min=2.87ms  med=6.48ms  max=875.98ms p(90)=21.5ms  p(95)=25.49ms
       { expected_response:true }...: avg=15.36ms  min=2.87ms  med=6.48ms  max=875.98ms p(90)=21.5ms  p(95)=25.49ms
      { name:Create }..............: avg=12.17ms  min=2.87ms  med=4.41ms  max=875.98ms p(90)=6.01ms  p(95)=7.61ms 
      { name:Delete }..............: avg=21.53ms  min=12.58ms med=17.78ms max=152.44ms p(90)=25.35ms p(95)=33.84ms
      { name:Get }.................: avg=26.97ms  min=10.65ms med=18.27ms max=695.72ms p(90)=26.4ms  p(95)=37.14ms
      { name:List }................: avg=9.94ms   min=3.22ms  med=4.97ms  max=516.25ms p(90)=7.85ms  p(95)=9.26ms 
      { name:Purge }...............: avg=6.17ms   min=3.73ms  med=5.45ms  max=52.48ms  p(90)=8.09ms  p(95)=10.34ms
    http_req_failed................: 0.00%    0         3001
      { name:Create }..............: 0.00%    0         600 
      { name:Delete }..............: 0.00%    0         600 
      { name:Get }.................: 0.00%    0         600 
      { name:List }................: 0.00%    0         600 
      { name:Purge }...............: 0.00%    0         600 
     http_req_receiving.............: avg=216.3µs  min=15µs    med=65µs    max=9.61ms   p(90)=411µs   p(95)=723µs  
     http_req_sending...............: avg=23.38µs  min=9µs     med=21µs    max=169µs    p(90)=34µs    p(95)=39µs   
     http_req_tls_handshaking.......: avg=249.36µs min=0s      med=0s      max=37.29ms  p(90)=0s      p(95)=0s     
     http_req_waiting...............: avg=15.12ms  min=2.79ms  med=6.25ms  max=866.64ms p(90)=21.23ms p(95)=25.28ms
     http_reqs......................: 3001    46.53064/s
     iteration_duration.............: avg=2.53s    min=31.38ms med=2.28s   max=5.27s    p(90)=4.05s   p(95)=4.06s  
     iterations.....................: 600     9.303027/s
     vus............................: 1       min=1      max=32
     vus_max........................: 50      min=50     max=50


running (1m04.5s), 000/050 VUs, 600 complete and 0 interrupted iterations
rps_50  [======================================] 000/050 VUs  1m0s  10.00 iters/s

It is a little tricky, though;).

Thanks, nevertheless, it does work perfectly now, with that correction.

@oleiade
Copy link
Member

oleiade commented Jan 16, 2024

It is a little tricky, though;).

The team agrees, and we are in the process of providing a new HTTP module which will surely improve on this #2461.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants