How do you trace logs?

Grafana k6 OSS Support
1

Hi! For example I specified cmdline as such:

k6 run -e BASE_URL="http://host:port" \
    --out statsd \
    --verbose \
    --vus $VUs \
    --duration $DURATION \
    --http-debug="full" \
    --summary-export=tests/reports/summary_VUs-${VUs}_duration-${DURATION}.json \
    --out json=tests/reports/report_VUs-${VUs}_duration-${DURATION}.json \
    --out csv=tests/reports/report_VUs-${VUs}_duration-${DURATION}.csv \
    tests/test.js 2>&1 | tee tests/reports/test-logs.$(date +"%F_--_%H.%M.%S").stdout-stderr.log

and in logs/stdout I see a lot of entries for a lot of users and it seems to quite hard to trace down every VU for every user in a testdata (which is provided through SharedArray), especially when in load testing profile there is specified quite high amount of VUs:
in logs it seems like everything just randomly mixed up or k6 spits out console.log entries in a low priority fashion?
So what is the best way to see requests-responses and console.log-entries per VU and fetched user from test data file (in another words: how to trace down all of that info in a correct way) ?

3

I think I’ve partially figured that out…
I just need to rely on this info in each request or response data:

" 0=P 1=O 10=a 11=m 12=e 13=e 14=- 15=m 16=s 17=i 18=s 19=d 2=S 20=n 3=T 4=- 5=i 6=n 7=i 8=t 9=G group="::03. POST /cursedMethod should return 200 OK and correct data" iter=0 project_name=CURSED_PROJECT request_id=1793f13d-e726-484f-5aac-3b5fc49fba7f scenario=MyCursedScenario scenario_name=MyCursedScenario source=http-debug vu=1

And trace for every request or response, e.g. this id:
request_id=1793f13d-e726-484f-5aac-3b5fc49fba7f

I guess, same logic goes to any console.log attempts:
One need to come up with his own ID or something similar and put it with a regular basis into console.log code.

This could become quite cumbersome to go through such logs, but at least this is something, I guess…
If there’s a better way, please let me know, it would be highly appreciated!

4

Just stucked again with the thing that I actually need both info from --http-debug=full and other debug info about current active user, VU, iteration and so on…
via option --http-debug=full I could use search in some editor (though it sometimes could be quite cumbersome and could cause performance issues with editor and OS itself, because those logs may become REALY BIG & LONG), but is there a way to get this request_id via script itself? Some internal function or method, may be (really don’t want to hand-craft myself HTTP-transaction logger, it would be great just to use things that may be available in k6 out of the box)?

5 
func (t httpDebugTransport) debugRequest(req *http.Request, requestID string) {
	dump, err := httputil.DumpRequestOut(req, t.httpDebugOption == "full")
	if err != nil {
		t.logger.Error(err)
	}
	t.logger.WithField("request_id", requestID).Infof("Request:\n%s\n",
		bytes.ReplaceAll(dump, []byte("\r\n"), []byte{'\n'}))
}

func (t httpDebugTransport) debugResponse(res *http.Response, requestID string) {
	if res != nil {
		dump, err := httputil.DumpResponse(res, t.httpDebugOption == "full")
		if err != nil {
			t.logger.Error(err)
		}
		t.logger.WithField("request_id", requestID).Infof("Response:\n%s\n",
			bytes.ReplaceAll(dump, []byte("\r\n"), []byte{'\n'}))
	}
}

(From here)
:sob::sob::sob:

6

Hi there!

--http-debug=full is not really a good fit when you need to do some advanced correlation. As you noticed, the output will be mixed with your script’s console logs, and will be difficult to parse. And that request_id is only generated for logging purposes, and you can’t access it from the script.

But what other information are you missing from the --http-debug=full output? Like you mentioned, you already get:

group= iter=0 request_id=ed71a22f-dfea-4e24-7b67-1a9694bc4c2c scenario=default source=http-debug vu=1

So to match the request with the response, you would filter by that request_id. If the log file is too large to open in an editor, you might want to do that with some CLI tools instead. For example:

grep -Po '(?<=msg=").*request_id=db882861.*' test.log | sed -e 's:\\n:\n:g' -e 's:\\":":g'

Assuming your test log is in structured format (one event per line), which it should be since you’re piping to tee, this would output the request and response for request_id that starts with db882861, and clean up the output to get somewhat readable payload data.

Though note that there are a few issues with --http-debug in general. Like if you’re dealing with binary data, you will only get a garbled mess.

If you need something more reliable, I would recommend the following:

  1. Add some metadata to your requests, like a new header or query string, that identifies the VU or anything else you need to correlate from your test.

  2. Capture the test traffic using Wireshark. There you can filter by the metadata you added, and easily correlate requests with responses (see the documentation).

Hope this helps,

Ivan

P.S.: You also might find the xk6-distributed-tracing extension interesting, though you don’t really need it for what you’re doing here.