Allow specifying log level per component

[imiric]

A long time ago, in ~a galaxy~ #131, we introduced the undocumented XK6_BROWSER_LOG environment variable, used to control the log level globally. At the time, this was only useful for developers, but since then we've received numerous feedback that our log output is too noisy and that users would like to control it in some way.

We've been suggesting that env var to some users, but it's clear that even that wasn't enough.

Part of the problem is the noisiness of our log output, which we're addressing in #304, so this issue is to implement a way of specifying the log level per "component".

Proposed Solution

There's a discussion here about possible approaches.

I think we agree that we should continue to use an environment variable to configure this, so we don't need any JS options or CLI flags (which we currently couldn't implement as a k6 extension either).

But there are a few open questions there we should agree on:

1. What should the environment variable be named? Inanc suggested using DEBUG as Playwright does, or K6B. Ivan prefers keeping it as XK6_BROWSER_LOG.

2. What are "components" exactly? They surely wouldn't map to specific Go structs. So can they be "categories", as we currently pass to all log events? We even have a categoryFilter regex, though it's currently not in use. I'm concerned that regex might considerably slow down our log output, and introduce a non-negligible CPU penalty, so consider removing this.

   It makes sense to have cdp as that's a current category, and maybe browser or console, as in "JS console".

   Which others? We preferably shouldn't have more than a handful of these, so we probably shouldn't separate them in internal categories like page or frame. Maybe use internal for all these "common" categories?

3. Should we have sub-components like Playwright's DEBUG has? E.g. command, response, etc. I think we don't need this level of granularity yet.

In any case, we should predefine a list of all components we want to have. All logged events should be part of a category. So maybe consider making that first Logger parameter an enum.

[inancgumus]

From a practical angle, I'd love to see what a component does and what CDP messages it sends and receives. For example, I can filter by the Page component and the click action and see something like:

Page.click("...")
    -> NewFrameClickOptions.Parse (...parameters here...)
    -> ElementHandle.click(...parameters here...)
         -> Mouse.click (...parameters here (position, etc.)...)
              -> ...
              -> CDP:Send <json here>
              <- CDP:Recv <json here>
              -> ...
    -> Frame.navigated (it's actually FrameManager.frameNavigate, but..)
         -> ... execution context changed to: 3

Even though I didn't enable other components, I can see them in one place since all these actions happen because of a click and go under the click. Otherwise, filtering the individual ones wouldn't help me much. This example is just the tip of the iceberg and maybe not be that easy to tackle. However, it can help us to figure out bugs and fix them.

It's hard to see CDP messages buried in logs. And, flat log lines don't help much when trying to diagnose problems. It would also help if we could colorize these (especially the CDP messages).

Note: For most users, it'd be better to omit CDP messages by default and enable them when needed. We and maybe advanced users would find enabling CDP messages and attaching them to individual steps useful.

[imiric]

@inancgumus I think that's a good idea, but you're describing log tracing, which is a separate issue from this one.

Besides, I see two potential issues with that:

• It would definitely leak internal Go APIs, which, as you say for CDP, would only be useful for xk6-browser devs.

  This feature should be aimed primarily at users, so we might want to lump all internal logs under the internal component/category. WDYT? Do we need more granularity there, and if so, how should it be split? At a struct level, as you mention for Page? Maybe those should be sub-components of internal, so internal.Page, internal.Frame, etc.?

• If our current logs are too noisy, seeing the call stack per log event would be unbearably so without extensive filtering (this issue).

  Unless you simply want to have a way to correlate deeply nested calls with higher level ones, in which case we could skip the indenting and assign a UUID at a high level and propagate it via Logger instances to deeper layers, and always output it, so you can correlate it manually, or via an external tool. I.e. log tracing.

  It's not realistic to want neatly arranged logs like that, as there will be many more events happening concurrently, so they would be interspersed with other messages anyway. Just consider the time between a CDP send and receive...

So, yeah, feel free to create a separate issue so we can discuss that proposal, but it's not something we should tackle in this issue.

[inancgumus]

This feature should be aimed primarily at users, so we might want to lump all internal logs under the internal component/category. WDYT?

That makes sense 👍 As you said, we can have main components under the internal category and be under the struct level. Or, we can bundle them by major areas such as: Browser (bundle w/BrowserProcess), Page (bundle w/Frame, FrameSession, and FrameManager), ElementHandle. I'm not sure about this last idea, though.

I created another issue #422.