Tag/label browser module logs with browser as the origin

ankur22 commented 1 year ago

When working with both the existing k6 modules and browser module, logs currently can't be easily discerned from each other. We want to make this easier by tagging/labelling the logs so that we can easily separate the logs from the different origins. What needs to be clarified is whether we can tag our logs with a new tag with logrus or whether we need to do anything with loki. Once that has been clarified it needs to be tested end to end to ensure everyone that needs to query browser module logs can do so.

ka3de commented 1 year ago

Taking a brief look at this, k6 has a Loki implementation of a Logrus hook which is initialized and set based on configuration defined by cmdline flags. So the logs are pushed to Loki through this hook via HTTP POST requests to the configured endpoint.

If we focus on the labels, which are set when building the Loki message from the Logrus Entry here, my understanding is that the fields that are set in the Logrus entry are compared with the configured allowed labels, if the field is allowed then it is set as a Loki label, which means that it will be indexed by Loki.

Based on this, if my understanding is correct, possibly the required changes in k6 browser to fulfill this issue would be:

Define a label that would indicate the origin of the logs, in order to distinguish logs generated from k6-core and k6 browser.
Modify our log methods implemented in our Log wrapper around logrus.FieldLogger in order to always include the field corresponding to the "origin/source/..." label defined in point 1.
Launch k6 with the appropiate cmdline flags that would configure the k6 Logrus hook "whitelist" the "origin/source/..." label so it is indexed by Loki when pushing the logs (If allowedLabels flag is not set, I believe all logrus entry fields are sent as labels).

inancgumus commented 1 year ago

ka3de commented 1 year ago

I have verified that the explanation from https://github.com/grafana/xk6-browser/issues/934#issuecomment-1600575890 is correct and for what I understand we just need to add a label in our logger implementation here. E.g.:

diff --git a/log/logger.go b/log/logger.go
index 374e26c..78012ae 100644
--- a/log/logger.go
+++ b/log/logger.go
@@ -101,6 +101,7 @@ func (l *Logger) Logf(level logrus.Level, category string, msg string, args ...a
                "category":  category,
                "elapsed":   fmt.Sprintf("%d ms", elapsed),
                "goroutine": goRoutineID(),
+               "module":    "browser",
        }
        if l.iterID != "" && l.GetLevel() > logrus.InfoLevel {
                fields["iteration_id"] = l.iterID

You can test this by running Loki locally with the following setup:

./
  - loki-config.yaml
  - promtail-local-config.yaml
  - docker-compose.yaml

Where:

loki-config.yaml

```yaml --- server: http_listen_port: 3100 memberlist: join_members: - loki:7946 schema_config: configs: - from: 2021-08-01 store: boltdb-shipper object_store: s3 schema: v11 index: prefix: index_ period: 24h common: path_prefix: /loki replication_factor: 1 storage: s3: endpoint: minio:9000 insecure: true bucketnames: loki-data access_key_id: loki secret_access_key: supersecret s3forcepathstyle: true ring: kvstore: store: memberlist ruler: storage: s3: bucketnames: loki-ruler ```

promtail-local-config.yaml

```yaml --- server: http_listen_port: 9080 grpc_listen_port: 0 positions: filename: /tmp/positions.yaml clients: - url: http://gateway:3100/loki/api/v1/push tenant_id: tenant1 scrape_configs: - job_name: flog_scrape docker_sd_configs: - host: unix:///var/run/docker.sock refresh_interval: 5s relabel_configs: - source_labels: ['__meta_docker_container_name'] regex: '/(.*)' target_label: 'container' ```

docker-compose.yaml

```yaml --- version: "3" networks: loki: services: read: image: grafana/loki:2.8.2 command: "-config.file=/etc/loki/config.yaml -target=read" ports: - 3101:3100 - 7946 - 9095 volumes: - ./loki-config.yaml:/etc/loki/config.yaml depends_on: - minio healthcheck: test: [ "CMD-SHELL", "wget --no-verbose --tries=1 --spider http://localhost:3100/ready || exit 1" ] interval: 10s timeout: 5s retries: 5 networks: &loki-dns loki: aliases: - loki write: image: grafana/loki:2.8.2 command: "-config.file=/etc/loki/config.yaml -target=write" ports: - 3102:3100 - 7946 - 9095 volumes: - ./loki-config.yaml:/etc/loki/config.yaml healthcheck: test: [ "CMD-SHELL", "wget --no-verbose --tries=1 --spider http://localhost:3100/ready || exit 1" ] interval: 10s timeout: 5s retries: 5 depends_on: - minio networks: <<: *loki-dns promtail: image: grafana/promtail:2.8.2 volumes: - ./promtail-local-config.yaml:/etc/promtail/config.yaml:ro - /var/run/docker.sock:/var/run/docker.sock command: -config.file=/etc/promtail/config.yaml depends_on: - gateway networks: - loki minio: image: minio/minio entrypoint: - sh - -euc - | mkdir -p /data/loki-data && \ mkdir -p /data/loki-ruler && \ minio server /data environment: - MINIO_ROOT_USER=loki - MINIO_ROOT_PASSWORD=supersecret - MINIO_PROMETHEUS_AUTH_TYPE=public - MINIO_UPDATE=off ports: - 9000 volumes: - ./.data/minio:/data healthcheck: test: [ "CMD", "curl", "-f", "http://localhost:9000/minio/health/live" ] interval: 15s timeout: 20s retries: 5 networks: - loki grafana: image: grafana/grafana:latest environment: - GF_PATHS_PROVISIONING=/etc/grafana/provisioning - GF_AUTH_ANONYMOUS_ENABLED=true - GF_AUTH_ANONYMOUS_ORG_ROLE=Admin depends_on: - gateway entrypoint: - sh - -euc - | mkdir -p /etc/grafana/provisioning/datasources cat < /etc/grafana/provisioning/datasources/ds.yaml apiVersion: 1 datasources: - name: Loki type: loki access: proxy url: http://gateway:3100 jsonData: httpHeaderName1: "X-Scope-OrgID" secureJsonData: httpHeaderValue1: "tenant1" EOF /run.sh ports: - "3000:3000" healthcheck: test: [ "CMD-SHELL", "wget --no-verbose --tries=1 --spider http://localhost:3000/api/health || exit 1" ] interval: 10s timeout: 5s retries: 5 networks: - loki gateway: image: nginx:latest depends_on: - read - write entrypoint: - sh - -euc - | cat < /etc/nginx/nginx.conf user nginx; worker_processes 5; ## Default: 1 events { worker_connections 1000; } http { resolver 127.0.0.11; server { listen 3100; location = / { return 200 'OK'; auth_basic off; } location = /api/prom/push { proxy_pass http://write:3100\$$request_uri; } location = /api/prom/tail { proxy_pass http://read:3100\$$request_uri; proxy_set_header Upgrade \$$http_upgrade; proxy_set_header Connection "upgrade"; } location ~ /api/prom/.* { proxy_pass http://read:3100\$$request_uri; } location = /loki/api/v1/push { proxy_pass http://write:3100\$$request_uri; proxy_set_header X-Scope-OrgID tenant1; } location = /loki/api/v1/tail { proxy_pass http://read:3100\$$request_uri; proxy_set_header Upgrade \$$http_upgrade; proxy_set_header Connection "upgrade"; } location ~ /loki/api/.* { proxy_pass http://read:3100\$$request_uri; } } } EOF /docker-entrypoint.sh nginx -g "daemon off;" ports: - "3100:3100" healthcheck: test: ["CMD", "service", "nginx", "status"] interval: 10s timeout: 5s retries: 5 networks: - loki flog: image: mingrammer/flog command: -f json -d 1s -l networks: - loki ```

Such as:

docker-compose up

And executing a k6 browser test (with debug enabled so we get more logs) such as:

K6_VERSION=master xk6 build --with github.com/grafana/xk6-browser="/path/to/xk6-browser/repo/with/logger/diff"
K6_BROWSER_DEBUG=true ./k6 run --log-output=loki=http://localhost:3100/loki/api/v1/push,label.testlabel=browser /path/to/test/script.js

Then we should be able to access Grafana instance configured with the Loki datasource at http://localhost:3000, access the Explore tab and find the k6 browser logs for the test filtering by labels module=browser (set in src code) or testlabel=browser (set in cmdline args).

@Carlos or @DefCon-007 I believe this request came from the backend team. Can you confirm that this is the desired result? Also, I'm not sure if there is a "labeling schema" already in place for other extensions. Any considerations about this or the specific label naming for k6 browser @mstoykov ?

DefCon-007 commented 1 year ago

From what I understood, it will require adding a new label (module) for the logs on the k6 browser side, a small optional suggestion from my side would be to maybe use extension as a label so that in the future we can distinguish logs from all the extensions very easily.

mstoykov commented 1 year ago

note: I haven't read the whole thread in depth, but did some quick searching through it and scan reeding

Also, I'm not sure if there is a "labeling schema" already in place for other extensions. Any considerations about this or the specific label naming for k6 browser @mstoykov ?

There isn't any labeling schema AFAIK. We decided not to have tons of labels as at least loki ~v1.x had problems with high cardinality, and we didn't want to get this overwhelmed.

The relevant currently enabled labels in the cloud are:

allowedLabels=[lz,level,test_run_id,instance_id,source]

As you can see there is a label called source that seems pretty okay to be used, the current (known to me values) are:

"stacktrace" - for when an exception bubbles up and interrupts iteration
"console" - when a user logs to the console with console.log and co.
"http-debug" - for logs from --http-debug
"grafana-k6-cloud" - for logs from the cloud API

There are also two cases where browser already uses it:
https://github.com/grafana/xk6-browser/blob/44fce67d847b401a5a79260c709918ae52744430/common/frame_session.go#L758 https://github.com/grafana/xk6-browser/blob/44fce67d847b401a5a79260c709918ae52744430/common/frame_session.go#L585

There really is no problem for there to be a new label "extension" or "module" - but I would expect in most cases this won't be used as much and source seems to cover most of the cases already :shrug:

And you will need to go edit every release on staging and production for the label to stick. While you won't need to that for source.

grafana / xk6-browser

Tag/label browser module logs with browser as the origin #934