[janHildebrandt98]

What?

Add an opt-in cli flag / env var that switches log timestamps from second to nanosecond precision, for both --log-format=json and the default text format (when --no-color is set).

Core changes:

1. Introduced new env var K6_LOG_NS_TIMESTAMPS and cli switch --log-ns-timestamps
2. FallbackLogger and Logger on GlobalState respect that flag and log timestamps in nanoseconds if enabled
3. Adjusted ReportCaller() to no longer replace the entire formatter on the global logger thus overwriting all config applied to it. It will now simply mutate the existing. Also added a test ensuring functionality of ReportCaller() --> separate PR
4. Moved the block setting up the log format out of setupLoggers() into a separate function to comply with linted max func length

Decided against feature flag because feature flags are resolved after setupLoggers() already ran so they are not available when needed.

Checklist

• I have performed a self-review of my code.
• I have commented on my code, particularly in hard-to-understand areas.
• I have added tests for my changes.
• I have run linter and tests locally (make check) and all pass.

Checklist: Documentation (only for k6 maintainers and if relevant)

Please do not merge this PR until the following items are filled out.

• I have added the correct milestone and labels to the PR.

Related PR(s)/Issue(s)

Closes #6000

[mstoykov]

When I tested it - if you set this up , but do not set anything else it still shows second difference from the start of the exceution (instead of timestamps) - and to have actual timestamps here you have to est one more option.

Have you tested it ? It might be a bit strange that you set this flag and in the most usual case nothing changes

[janHildebrandt98]

Yes that is true. To get actual timestamps you either have to

1. switch to JSON format
2. set --no-color, then logrus will emit logfmt including timestamps (that is what SM is doing)

I thought about it and decided that it should be fairly obvious that you can only change timestamps if you actually receiving timestamps. But it could be worth a hint in the docs?
Don't see a way to fix it really. We would need to magically change other things depending on this flag which I think is also strange.

[mstoykov]

Okay lets have it in the docs - I think the cli help already is good neough. And not certain manyy people will ever hit this either wya

[janHildebrandt98]

adressed in grafana/k6-docs#2305

[joanlopez]

Even an empty value here will enable this feature. I guess this is what we want, because it looks consistent with other env vars like NO_COLOR or K6_PROFILING_ENABLED, but just wanted to double-check it with you folks. Is that the case? cc/ @mstoykov @janHildebrandt98

---

Question aside: Is that something we should perhaps try to "fix" for v3? Like, not enabling stuff if the value is not truthy, even if the env var is defined? Or is that some sort of a common pattern, or am I missing some historical context that makes this more reasonable that it sounds at first glance?

Thanks!

[janHildebrandt98]

Not sure on this. it is mixed right now. NO_COLOR and K6_PROFILING_ENABLED don't care about the value but K6_AUTO_EXTENSION_RESOLUTION actually parses and only evaluates to true if the value is truthy. We need to decide what we want here.
Short research from my side showed that there does not seem to be a consensus on how to handle this in other apps - both approaches exist

[janHildebrandt98]

honestly I think I would prefer actually parsing the value. It feels wrong to have K6_PROFILING_ENABLED=false enable profiling :D

[joanlopez]

Yes! I'd be even tempted to ship it as a bugfix. But, for instance, for NO_COLOR there's a comment stating this is the desired behavior. Not sure why, tho.

[joanlopez]

It seems to me thatl.ReportCaller() could be called concurrently, right? See the reasoning below 👇🏻

ReportCaller() runs on every call to makeLogger(), and makeLogger() is invoked from BrowserType.init(), which is called by Launch(), Connect(), and ConnectOverCDP(), so it could be called concurrently when calling newBrowserRegistry once per VU, or when connecting to remote browser instances.

If so, I think we should add mutual exclusion to prevent data races when assigning the formatter attributes below.

A targeted Go test to reproduce the data race could be:

func TestReportCallerRace(t *testing.T) {
	base := logrus.New()
	base.SetOutput(io.Discard)
	base.SetFormatter(&logrus.TextFormatter{})

	var wg sync.WaitGroup
	for i := 0; i < 8; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			l := New(base, "")
			_ = l.ReportCaller()
		}()
	}
	for i := 0; i < 8; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			l := New(base, "")
			for j := 0; j < 100; j++ {
				l.Infof("cat", "hello %d", j)
			}
		}()
	}
	wg.Wait()
}

Do I get it right that we should handle this? Or we're okay with that because the chances are low?

[janHildebrandt98]

solved since i removed the changes to ReportCaller

[joanlopez]

I think there's a raw formatter regression.

If I run the following on this branch:

K6_BROWSER_LOG_CALLER=true go run main.go run --log-format=raw - <<'EOF'
import { browser } from 'k6/browser';

export const options = {
  scenarios: {
    ui: {
      executor: 'shared-iterations',
      options: { browser: { type: 'chromium' } },
    },
  },
};

export default async function () {
  const page = await browser.newPage();
  await page.close();
}
EOF

I get error building browser on IterStart: initializing browser type: error setting up logger: unknown formatter type *cmd.RawFormatter at default (file:///-:12:16(0)).

While the same works fine in master.

Can you double check that, please? @janHildebrandt98 Thanks! 🙇🏻

[joanlopez]

I think at this point we haven't parsed CLI flags, so if the user chooses to use --log-ns-timestamp, this will make no effect.

Are we fine with this only working when the user relies on K6_LOG_NS_TIMESTAMPS (cc/ @mstoykov)? Or should we move this down the execution path up to a point where Cobra already did bind the flags?

[janHildebrandt98]

we should definitely move this. I missed that getFlags() only reads the env vars 🤦‍♂️ I will come up with something...

[joanlopez]

Yeah, it's not obvious from the method name.. 😅

[janHildebrandt98]

decided to ignore the fallback formatter. Since it will only emit when the actual log output has issues and we are also not applying any other formatting, I figured its better to stay consistent and not introduce any hacks to apply the formatting later.

[janHildebrandt98]

Decided to move the changes to ReportCaller() out of this PR as they were getting out of hand.. Issue: #6335 will be tackled in a separate PR.