output format for errors changes to structured log when running k6 as a subprocess

[pablochacin]

Brief summary

When running k6 as a subprocess (from a go program) and capturing the stdout and stderr in a buffer, the format of error messages changes to a structured log format.

k6 version

v0.50.0

OS

windows

Docker version and image (if applicable)

No response

Steps to reproduce the problem

1. Create an empty file named script.js

2. Run the following go program:

package main

import (
	"bytes"
	"fmt"
	"os/exec"
)

func main() {

	cmd := exec.Command("k6", "run", "script.js")
	outBuff := bytes.NewBuffer(nil)
	cmd.Stdout = outBuff
	cmd.Stderr = outBuff

	cmd.Run()

	fmt.Println(outBuff.String())
}

Expected behaviour

The same output that is generated when running the script.js file with k6 in the console:

> k6 run script.js

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

ERRO[0000] could not initialize 'script.js': could not load JS test 'file:///home/pablo/go/src/github.com/grafana/grafana-api-tests/script.js': no exported functions in script 

Actual behaviour

The output has a structured log format:

> go run main.go 

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

time="2024-05-16T11:43:43+02:00" level=error msg="could not initialize 'script.js': could not load JS test 'file:///home/pablo/go/src/github.com/grafana/grafana-api-tests/script.js': no exported functions in script"

[joanlopez]

Hi @pablochacin,

Looking at the k6 codebase, that's the expected behavior, because it explicitly sets one output format or the other depending whether k6 is executed in a terminal or not.

I don't have enough historical context to fully assert if that's intentionally (or not), and whether we want to actually change that behavior, thus consider it a bug, or just the expected behavior. Especially considering that, if this behavior have been like this for years, it would represent a breaking change (what if anyone is doing what you're trying but relying on the current behavior?)

That said, the only recommendation that comes to my mind is to "fake" that behavior, so isatty checks believes it is being executed in a terminal. For instance, you can use something like github.com/creack/pty, as follows:

cmd := exec.Command("k6", "run", "script.js")

// Start the command with a pseudo-terminal
ptmx, _ := pty.Start(cmd)

// Copy the output to the buffer
outBuff := bytes.NewBuffer(nil)
_, _ = io.Copy(outBuff, ptmx)
	
fmt.Println(outBuff.String())

Note that this snippet is just to give you an idea, so I'm intentionally skipping error handling and all that. However, I have to admit if that would have any other implication in your case, therefore a feasible workaround.

Thanks! 🙇🏻

[joanlopez]

I'm wondering, if there's any other way to bypass that, or if the change we could make is to leave the default behavior as-is but add a mechanism to bypass/force that behavior by configuration cc/ @mstoykov

[mstoykov]

This seems to be more of a logrus thing. Where if it detects TTY it will change how it outputs. And apparently having colours or not changes more than just ... colors.

See https://github.com/sirupsen/logrus/issues/1194 as well as search the docs for TextFormatter (sorry can't link directly any particular place).

Given that this has been like this for a while and https://github.com/grafana/k6/issues/2958 I don't feel like we should try to "fix" this. Also I am not certain what the fix will be.

I would also expect anything running k6 as a subprocess to prefer the --log-format=json then the text formatter.

[pablochacin]

I would also expect anything running k6 as a subprocess to prefer the --log-format=json then the text formatted.

That depends on the use case. In our case, we are capturing the output and displaying it if we find some error, and the log format obscures this output, as shown in the example

Given that this has been like this for a while and https://github.com/grafana/k6/issues/2958 I don't feel like we should try to "fix" this.

Given that #2958 has been open for quite a while, I expect we find some fix for this issue in the meantime.

Also I am not certain what the fix will be.

From Logrus documentation:

Note: to force colored output when there is no TTY, set the ForceColors field to true