Custom trend disappears from console output with handleSummary + textSummary

MattDodsonEnglish commented 1 year ago

Brief summary

In this script, one custom trend, wsw_time, disappears from the console output when I use the handleSummary with the textSummary from the jslib. Strangely, I think it didn't happen every time, either. Sorry I can't confirm that it's only occasionally reproducible, but I can attach a screenshot of a time it didn't appear.

import http from "k6/http";
import { textSummary } from "https://jslib.k6.io/k6-summary/0.0.2/index.js";
import { Trend } from "k6/metrics";

const myTrend = new Trend("wsw_time");
const theirTrend = new Trend("their_time");

export default function () {
  const getRes = http.get("http://httpbin.test.k6.io/");
  theirTrend.add(getRes.timings.duration);
  const resWSW = http.get("https://wellshapedwords.com/");
  myTrend.add(resWSW.timings.duration);
}

export function handleSummary(data) {
  return {
    stdout: textSummary(data, { indent: "→", enableColors: true }),
  };
}

Not that the other custom metric, their_time shows up fine in both cases.

k6 version

k6 v0.44.0 ((devel), go1.20.3, linux/amd64)

OS

Arch linux, installed through AUR

Docker version and image (if applicable)

No response

Steps to reproduce the problem

Run script attached

Expected behaviour

wsw_time summary appears in handleSummary terminal output.

Actual behaviour

wsw_time doesn't appear.

mstoykov commented 1 year ago

This is a bug ... of sorts.

The in k6 implementation does by default add a bunch of new lines. And I feel like that should just not be needed. As without them parts of the end summary got eaten up by other parts that are written over.

https://github.com/grafana/k6/blob/9fa50b2d1f259cdccff5cc7bc18a236d31c345ac/js/summary-wrapper.js#L66

I don't know if this was done due to some kind of deficiency that we intend on fixing or what.

cc @na-- any memories as you were the one that implemented this originally

As current workaround - copy the linked code.

na-- commented 1 year ago

I don't know if this was done due to some kind of deficiency that we intend on fixing or what.

No, the newlines definitely were not there to avoid overwriting by the progress bars, they were added to make the JS summary output identical to the old k6 Go code that produced the same summary.

The problem probably occurs because we use terminal control codes to control the terminal "cursor" (caret?) and essentially print the progressbars in the same place. I might have messed up something in https://github.com/grafana/k6/pull/2815 that caused the last progressbar printing to overwrite the last line of the end-of-test summary :thinking: Or this bug might have existed before even that.

In either case, we should probably finish with the progress bars before we handle the end-of-test summary, which should resolve this bug too :thinking:

grafana / k6