Add iteration ID field to log events

[imiric]

This adds an iteration_id field to all log events that uniquely identifies a k6 iteration, and thus a single browser start/stop cycle. I'm finding it relatively useful when testing issues like grafana/k6#4417 that only happen when stress testing the entire tests package, and not a single test in isolation, since I can filter log events for a specific iteration.

It's only added to events when XK6_BROWSER_LOG is set to debug or trace.

Related to grafana/k6#4441

[imiric]

I'm not happy with this global, but I don't think we need to pass it somewhere from BrowserType, and it would be slightly awkward, so I don't mind it much. EDIT: Seems like I'll have to get rid of it, judging by the CI data race 😓

Though I'm currently running into an issue on this branch after a few minutes of stress testing that ends with:

panic: GoError: launching browser: inotify_init() failed: Too many open files (24)

... which is strange, since a) my ulimit -n is set to 50000, and b) I don't see how the changes here could cause it, unless this line does it somehow. Initially I had this inside WithTraceID(), and thought that might be the issue, but I moved it to a global, and still see the error. I haven't run into it on main, so I'm skeptical it's something here. Correction: I have now also seen this on main, so it's not related to these changes.

Any thoughts?

[imiric]

OK, I moved it to NewBrowserType() in f01e97e.

Still, please (stress) test this and let me know if you run into any issues.

[inancgumus]

Cool! I like this idea. I'll review it tomorrow.

By the way, IMO, trace_id does not convey the meaning that each trace is for an iteration. Should we call it iteration or something more descriptive? 🤔

Asking out of curiosity, what is the reason we don't just increment a counter for each iteration like 1, 2, N?

[imiric]

By the way, IMO, trace_id does not convey the meaning that each trace is for an iteration. Should we call it iteration or something more descriptive?

Good point. I suppose we could, though I wanted to leave this open for other use cases besides tracking iterations. Though if we were to add another tracing ID then it should definitely be called something more unique. So, sure, I'll rename it to iteration_id instead.

Asking out of curiosity, what is the reason we don't just increment a counter for each iteration like 1, 2, N?

I briefly considered exposing the scenario.iterationInTest value, but besides it being problematic to access (I'm not sure if extensions are able to, without some goja hacks... @mstoykov ?), it's not unique across scenarios, nor across distributed test runs. So while sequential IDs could possibly work for local execution, random hex IDs are safer against collision for distributed test runs.

[ankur22]

Nice! This would've been very useful when debugging the issues i've worked on recently 🙂

Maybe worth renaming it to iterationID, since traceID is generally the term used in microservices to trace a request through a system... actually, i guess it's being used in the same way, so traceID might be ok. I wonder if there's a way to feed the logs through Tempo 🤔 😄

[imiric]

@ankur22 Yeah, I renamed it to iteration_id after Inanc mentioned it, though "trace ID" is a fairly generic term and depends on the context of what you want to trace. :) Essentially, any log field that's unique and can be used to aggregate a bunch of events can be thought of as a trace ID.

I do think we'll want to expand this if we want to fully implement grafana/k6#4441, so that we can trace unique components and actions. That's why I was somewhat reluctant to rename everything here to iteration_id, since we probably don't want to add N args to log.New() for each traced field, but maybe pass it a struct or context with a few of these trace IDs. In any case, that's something to think about later. :)

[inancgumus]

LGTM. I have some non-blocking suggestions. Feel free to apply them or not 👍