Make console.log() available in the init context

[na--]

As seen in this issue, console.log() could be quite useful in the init context for debugging purposes.

The main user-facing problem with this it the fact that code in the init context is executed multiple times. Off the top of my head, it's executed once in the beginning of a k6 run to get the exported script options, once for setup(), once for the initialization in each VU, and once in teardown(). So if we enable this by default, it's going to be quite noisy...

There are 2 somewhat major things from an implementation perspective that are potentially problematic. First, the logger for each runtime (i.e. VU) is currently in the lib.State struct, which isn't available in the init context. In fact, its presence of absence are often how we verify whether a particular piece of k6 Go code is executed in the VU or init context respectively...

The second issue stems from the fact that we likely can't enable this logging by default due to its noisiness. This likely means that we have to hide it behind a flag. Unfortunately, it can't be a JS option only, since those are retrieved after the init context is executed once. But it seems like something minor that doesn't deserve its own CLI/environment variable flag...

So, here's an initial proposal that needs to be further evaluated for feasibility:

• By default, trying console.log() in the init context will return an error. But it won't be the current ReferenceError: console is not defined, rather it will be something like Using console.log() in the init context only works when verbose mode is enabled. You can do that with the --verbose/-v CLI flags or the K6_VERBOSE environment variable.
• If users turn on verbose mode, console methods in the init context will start to work. Each message will likely be emitted multiple times, once per init context execution, unless there's an error somewhere in the code that aborts the script execution.
• Ideally, users should be able to differentiate between the messages from different init context executions. This could be accomplished by adding a source field in each log message. And it's also somewhat tied to this issue about having VU numbers in the init context.

But yeah, more evaluation definitely needed, since this seemingly simple feature has a lot of complications if we want to get it right...

[kkeranen]

Description of this issue helped me in finding out a problem I have been struggling with for hours: #969

[mstoykov]

For me the whole noisiness is not an issue ... if you want to log something in the init context I suppose you are debugging something. Making you jump through hoops and one of them being making the whole output even more noisy by enabling verbose is seems unreasonable.

On the second(first) issue of Logger being in lib.State, console.log doesn't use it . Maybe it should but I see no point atm as everything just copies the runner's Logger which is the standard , but by default the console also uses the standard.

So technically adding:

rt.Set("console", common.Bind(rt, newConsole(), init.ctxPtr))

somewhere in here fixes it ...
In the case the console is not redirected to file :(. In that case I need the whole options which are not calculated at this time... The bad thing is that I don't even have the not full options at that time I only have access to the env through lib.RuntimeOptions. The redirect can't be set through the options in the script so I only need the cli flags as well but I will need some way to transport them from something in cmd/run.go to Bundle >.<.

At this point I wonder if the Bundle.Options shouldn't be the options as calculated upto this point and we again hit #883

[na--]

making the whole output even more noisy by enabling verbose is seems unreasonable.

You're absolutely right, sorry for disagreeing earlier! I didn't consider the extra noisiness -v would bring to a debugging situation... It might be useful in some situations, but definitely not in all of them. And telling users to enable a flag just so they can use the console is not exactly ideal from an UX perspective either... Both combined definitely outweigh any UX issues stemming from multiple identical messages on the console.

And if we can fix the configuration challenges you describe (:sob:), have proper loggers per-VU, and actually implement #889 and attach (via log.WithFields()) the VU ID to each log message, any user confusion from multiple identical messages will likely disappear.

But yeah, I don't have a good solution for the redirection to file at this point, sorry. The massive refactoring I'm currently doing will somewhat improve the passing of a logger from cmd/run.go down the engine->executor->VU pipeline, but that won't help very much with the file logging, it will just clean up the code so that a global singleton-like logger isn't used...

I propose that we either wait until we fix some of the configuration for this, or we just implement this in a hacky way where the first init context execution always logs to stdout, regardless if a file was specified. I don't like either of those options, but I don't see many alternatives...

[maxekman]

Any update on when this can be fixed? It would sometimes be very helpful to log info during development of init scripts (for auth for example).

[maxekman]

Even more problematic with not having console.log support in init is that some dependencies may use it, which makes it a total blocker for using those in init phases.

[na--]

@maxekman, you are right. We have an open PR that fixes this (#982), but we haven't merged it yet, because it's incompatible with the --console-output flag 😞 With the simple fix in #982, if that flag is enabled, console.log() statements in the init context won't respect it and would just be emitted to stdout.

Unfortunately, to properly fix this would require significant refactoring. So it's likely we'll soon merge the fix as it is, even even with that known bug, and we'll come back at some point in the future to properly fix everything...

[maxekman]

It would be very welcome to get that merged! In my current situation I can't even import a lib for VUs (auth0-js) as it depends on console.

[maxekman]

As a workaround for anyone blocked by imports requiring the console I managed to define the missing console using console-browserify inside the generated UMD file: var console = require("./console-browserify.js"). A bit tedious to edit the generated files, but at least it allows k6 to run for now. 🙂

[na--]

@maxekman, you should now be able to use the master docker image tag to have console in the init context, or you can build your own k6 binary from the current master source.