Data race due to concurrent map access #1066

ka3de · 2023-10-13T07:59:04Z

Brief summary

The following test script reproduces a data race for concurrent access on a map:

import { check, sleep } from 'k6';
import { browser } from 'k6/experimental/browser';


export const options = {
  thresholds: {
    'browser_web_vital_inp': ['p(75) < 80'],
  },
  scenarios: {
    ui: {
      executor: 'ramping-vus',
      stages: [
        { duration: '10s', target: 5 },
        { duration: '20s', target: 5 },
        { duration: '10s', target: 0 },
      ],
      options: {
        browser: {
            type: 'chromium',
        },
      },
    },
  },
}


export default async function() {
  const context = browser.newContext();
  const page = context.newPage();

  try {
    await page.goto('https://test.k6.io/', { waitUntil: 'networkidle' });

    await Promise.all([
      page.waitForNavigation(),
      page.locator('a[href="/browser.php"]').click(),
    ]);
    page.locator('#text1').type('lorem ipsum');

    sleep(1);

    page.locator('#counter-button').click();

    sleep(0.5);
    
    await Promise.all([
      page.waitForNavigation(),
      page.locator('a[href="/"]').click(),
    ]);
    check(page, {
      'header': p => p.locator('h1').textContent() == 'test.k6.io',
    });


  } finally {
    page.close();
  }
}

Which produces the following [truncated] output:

output

panic_contents="fatal error: concurrent map iteration and map write
goroutine 7 [running]:
go.k6.io/k6/log.(*lokiHook).Listen(0xc000695ee0, {0x19d8eb8, 0xc00009a550})
go.k6.io/k6/log/loki.go:234 +0x71b
go.k6.io/k6/cmd.(*rootCommand).setLoggerHook.func1()
go.k6.io/k6/cmd/root.go:293 +0x2d
created by go.k6.io/k6/cmd.(*rootCommand).setLoggerHook in goroutine 1
go.k6.io/k6/cmd/root.go:292 +0xc9

goroutine 1 [chan receive]:
go.k6.io/k6/execution.(*Scheduler).Run(0xc000a7b110, {0x19d8eb8, 0xc00009a5a0}, {0x19d8e80, 0xc0006a7800}, 0xc001eff620)
go.k6.io/k6/execution/scheduler.go:472 +0xc6e
go.k6.io/k6/cmd.(*cmdRun).run(0xc000068320, 0xc000246f00, {0xc000004900?, 0x1, 0x30})
go.k6.io/k6/cmd/run.go:352 +0x1531
github.com/spf13/cobra.(*Command).execute(0xc000246f00, {0xc000004600, 0x30, 0x30})
github.com/spf13/[email protected]/command.go:856 +0x694
github.com/spf13/cobra.(*Command).ExecuteC(0xc0001bec80)
github.com/spf13/[email protected]/command.go:974 +0x38d
github.com/spf13/cobra.(*Command).Execute(...)
github.com/spf13/[email protected]/command.go:902
go.k6.io/k6/cmd.(*rootCommand).execute(0xc00009f290)
go.k6.io/k6/cmd/root.go:104 +0x125
go.k6.io/k6/cmd.Execute()
go.k6.io/k6/cmd/root.go:137 +0x2f
main.main()
go.k6.io/k6/main.go:8 +0xf

goroutine 8 [select]:
io.(*pipe).read(0xc000089380, {0xc00071a000, 0x10000, 0x42505c?})
io/pipe.go:57 +0xa5
io.(*PipeReader).Read(0x7f762f358378?, {0xc00071a000?, 0xc00071a000?, 0x0?})
io/pipe.go:136 +0x1b
bufio.(*Scanner).Scan(0xc00072ef28)
bufio/scan.go:214 +0x81b
github.com/sirupsen/logrus.(*Entry).writerScanner(0x0?, 0xc0000683d0, 0xc000051a80)
github.com/sirupsen/[email protected]/writer.go:86 +0x125
created by github.com/sirupsen/logrus.(*Entry).WriterLevel in goroutine 1
github.com/sirupsen/[email protected]/writer.go:57 +0x385

goroutine 9 [chan receive]:
go.k6.io/k6/cmd.(*rootCommand).setupLoggers.func2()
go.k6.io/k6/cmd/root.go:282 +0x3d
created by go.k6.io/k6/cmd.(*rootCommand).setupLoggers in goroutine 1
go.k6.io/k6/cmd/root.go:281 +0x645

goroutine 2099 [IO wait]:
internal/poll.runtime_pollWait(0x7f762f662c78, 0x72)
runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc002b72000?, 0xc0000ca000?, 0x0)
tinternal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc002b72000, {0xc0000ca000, 0x1000, 0x1000})
internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc002b72000, {0xc0000ca000?, 0x2000?, 0x9?})
net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc000122588, {0xc0000ca000?, 0xc002b72000?, 0xc000839a28?})
net/net.go:179 +0x45
bufio.(*Reader).fill(0xc001600d20)
bufio/bufio.go:113 +0x103
bufio.(*Reader).Peek(0xc001600d20, 0x2)
bufio/bufio.go:151 +0x53
github.com/gorilla/websocket.(*Conn).read(0xc000feb1e0, 0x3?)
github.com/gorilla/[email protected]/conn.go:371 +0x26
github.com/gorilla/websocket.(*Conn).advanceFrame(0xc000feb1e0)
github.com/gorilla/[email protected]/conn.go:809 +0x6d
github.com/gorilla/websocket.(*Conn).NextReader(0xc000feb1e0)
github.com/gorilla/[email protected]/conn.go:1009 +0xb0
github.com/gorilla/websocket.(*Conn).ReadMessage(0xc000839ea8?)
github.com/gorilla/[email protected]/conn.go:1093 +0x13
github.com/grafana/xk6-browser/common.(*Connection).recvLoop(0xc001eea780)
github.com/grafana/[email protected]/common/connection.go:305 +0xb7
created by github.com/grafana/xk6-browser/common.NewConnection in goroutine 54
github.com/grafana/[email protected]/common/connection.go:176 +0x3d6

goroutine 11 [chan receive]:
go.k6.io/k6/log.(*lokiHook).Listen.func2()
go.k6.io/k6/log/loki.go:167 +0x11b
created by go.k6.io/k6/log.(*lokiHook).Listen in goroutine 7
go.k6.io/k6/log/loki.go:164 +0x319

goroutine 12 [chan receive]:github.com/grafana/xk6-browser/browser.(*browserRegistry).handleExitEvent(0x9d97?, 0x9d9a?, 0x9d9b?)
github.com/grafana/[email protected]/browser/registry.go:293 +0x45
created by github.com/grafana/xk6-browser/browser.newBrowserRegistry in goroutine 1
github.com/grafana/[email protected]/browser/registry.go:225 +0x285

goroutine 13 [chan receive]:
github.com/grafana/xk6-browser/browser.(*browserRegistry).handleIterEvents(0xc002162e00, 0x0?, 0xc002693380)
github.com/grafana/[email protected]/browser/registry.go:238 +0x65
created by github.com/grafana/xk6-browser/browser.newBrowserRegistry in goroutine 1
github.com/grafana/[email protected]/browser/registry.go:226 +0x2e5

goroutine 21 [select]:
google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc000958e10, 0x1)
google.golang.org/[email protected]/internal/transport/controlbuf.go:418 +0x113
google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc000cd2ee0)
google.golang.org/[email protected]/internal/transport/controlbuf.go:552 +0x86
google.golang.org/grpc/internal/transport.newHTTP2Client.func6()
google.golang.org/[email protected]/internal/transport/http2_client.go:451 +0x85
created by google.golang.org/grpc/internal/transport.newHTTP2Client in goroutine 36
google.golang.org/[email protected]/internal/transport/http2_client.go:449 +0x2450

goroutine 73 [select]:
go.k6.io/k6/lib/executor.waiter.func1(0x1bf08eb00)
go" process_error="exit status 2" session_id=nvEYIQcXDFQbeNMw55P04IFwhZ5bEa6T stderr_contents="Logger format: RAW
fatal error: concurrent map iteration and map write

goroutine 7 [running]:
go.k6.io/k6/log.(*lokiHook).Listen(0xc000695ee0, {0x19d8eb8, 0xc00009a550})
go.k6.io/k6/log/loki.go:234 +0x71b
go.k6.io/k6/cmd.(*rootCommand).setLoggerHook.func1()
go.k6.io/k6/cmd/root.go:293 +0x2d
created by go.k6.io/k6/cmd.(*rootCommand).setLoggerHook in goroutine 1
go.k6.io/k6/cmd/root.go:292 +0xc9

goroutine 1 [chan receive]:
go.k6.io/k6/execution.(*Scheduler).Run(0xc000a7b110, {0x19d8eb8, 0xc00009a5a0}, {0x19d8e80, 0xc0006a7800}, 0xc001eff620)
go.k6.io/k6/execution/scheduler.go:472 +0xc6e
go.k6.io/k6/cmd.(*cmdRun).run(0xc000068320, 0xc000246f00, {0xc000004900?, 0x1, 0x30})
go.k6.io/k6/cmd/run.go:352 +0x1531
github.com/spf13/cobra.(*Command).execute(0xc000246f00, {0xc000004600, 0x30, 0x30})
github.com/spf13/[email protected]/command.go:856 +0x694
github.com/spf13/cobra.(*Command).ExecuteC(0xc0001bec80)
github.com/spf13/[email protected]/command.go:974 +0x38d
github.com/spf13/cobra.(*Command).Execute(...)
github.com/spf13/[email protected]/command.go:902
go.k6.io/k6/cmd.(*rootCommand).execute(0xc00009f290)
go.k6.io/k6/cmd/root.go:104 +0x125
go.k6.io/k6/cmd.Execute()
go.k6.io/k6/cmd/root.go:137 +0x2f
main.main()
go.k6.io/k6/main.go:8 +0xf

goroutine 8 [select]:
io.(*pipe).read(0xc000089380, {0xc00071a000, 0x10000, 0x42505c?})
io/pipe.go:57 +0xa5
io.(*PipeReader).Read(0x7f762f358378?, {0xc00071a000?, 0xc00071a000?, 0x0?})
io/pipe.go:136 +0x1b
bufio.(*Scanner).Scan(0xc00072ef28)
bufio/scan.go:214 +0x81b
github.com/sirupsen/logrus.(*Entry).writerScanner(0x0?, 0xc0000683d0, 0xc000051a80)
github.com/sirupsen/[email protected]/writer.go:86 +0x125
created by github.com/sirupsen/logrus.(*Entry).WriterLevel in goroutine 1
github.com/sirupsen/[email protected]/writer.go:57 +0x385

goroutine 9 [chan receive]:
go.k6.io/k6/cmd.(*rootCommand).setupLoggers.func2()
go.k6.io/k6/cmd/root.go:282 +0x3d
created by go.k6.io/k6/cmd.(*rootCommand).setupLoggers in goroutine 1
go.k6.io/k6/cmd/root.go:281 +0x645

goroutine 2099 [IO wait]:
internal/p
... omitting 163922 bytes ...
[email protected]/common/frame.go:1991 +0x116
created by github.com/grafana/xk6-browser/common.call in goroutine 2876
github.com/grafana/[email protected]/common/helpers.go:102 +0x15c

goroutine 2898 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6

goroutine 2901 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6

goroutine 2904 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6

goroutine 2907 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6

goroutine 2910 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6

goroutine 2913 [select]:
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
github.com/grafana/[email protected]/common/context.go:61 +0x7c
created by github.com/grafana/xk6-browser/common.contextWithDoneChan in goroutine 2877
github.com/grafana/[email protected]/common/context.go:59 +0xb6
" stderr_error="k6 process was unexpectedly aborted" test_run_id=2001281

LoadTestRun: 2001281

This happened in another test run. ID: 2037840

output

fatal error: concurrent map iteration and map write

goroutine 7 [running]:
go.k6.io/k6/log.(*lokiHook).Listen(0xc0006616c0, {0x19d4958, 0xc000100c30})
go.k6.io/k6/log/loki.go:234 +0x71b
go.k6.io/k6/cmd.(*rootCommand).setLoggerHook.func1()
go.k6.io/k6/cmd/root.go:293 +0x2d
created by go.k6.io/k6/cmd.(*rootCommand).setLoggerHook in goroutine 1
go.k6.io/k6/cmd/root.go:292 +0xc9

goroutine 1 [chan receive, 52 minutes]:
go.k6.io/k6/execution.(*Scheduler).Run(0xc003bacbd0, {0x19d4958, 0xc000100c80}, {0x19d4920, 0xc0000284e0}, 0xc001569b60)
go.k6.io/k6/execution/scheduler.go:472 +0xc6e
go.k6.io/k6/cmd.(*cmdRun).run(0xc000068330, 0xc0001bf180, {0xc000139880?, 0x1, 0x36})
go.k6.io/k6/cmd/run.go:352 +0x1531
github.com/spf13/cobra.(*Command).execute(0xc0001bf180, {0xc000138380, 0x36, 0x38})
github.com/spf13/[email protected]/command.go:856 +0x694
github.com/spf13/cobra.(*Command).ExecuteC(0xc0002bcc80)
github.com/spf13/[email protected]/command.go:974 +0x38d
github.com/spf13/cobra.(*Command).Execute(...)
github.com/spf13/[email protected]/command.go:902
go.k6.io/k6/cmd.(*rootCommand).execute(0xc00009d7a0)
go.k6.io/k6/cmd/root.go:104 +0x125
go.k6.io/k6/cmd.Execute()
go.k6.io/k6/cmd/root.go:137 +0x2f
main.main()
go.k6.io/k6/main.go:8 +0xf

goroutine 8 [select, 52 minutes]:
io.(*pipe).read(0xc0000892c0, {0xc0005c0000, 0x10000, 0x5?})
io/pipe.go:57 +0xa5
io.(*PipeReader).Read(0x7f31ef4e9dd8?, {0xc0005c0000?, 0xc000060e20?, 0x0?})
io/pipe.go:136 +0x1b
bufio.(*Scanner).Scan(0xc000060f28)
bufio/scan.go:214 +0x81b
github.com/sirupsen/logrus.(*Entry).writerScanner(0x0?, 0xc0000683e0, 0xc000051240)
github.com/sirupsen/[email protected]/writer.go:86 +0x125
created by github.com/sirupsen/logrus.(*Entry).WriterLevel in goroutine 1
github.com/sirupsen/[email protected]/writer.go:57 +0x385

goroutine 9 [chan receive, 52 minutes]:
go.k6.io/k6/cmd.(*rootCommand).setupLoggers.func2()
go.k6.io/k6/cmd/root.go:282 +0x3d
created by go.k6.io/k6/cmd.(*rootCommand).setupLoggers in goroutine 1
go.k6.io/k6/cmd/root.go:281 +0x645

goroutine 23 [IO wait]:
internal/poll.runtime_pollWait(0x7f31ef70df58, 0x72)
runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc00556ef80?, 0xc0005b5000?, 0x0)
internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc00556ef80, {0xc0005b5000, 0x1800, 0x1800})
internal/poll/fd_unix.go:164 +0x27a
net.(*netFD).Read(0xc00556ef80, {0xc0005b5000?, 0xc0005b5005?, 0x22?})
net/fd_posix.go:55 +0x25
net.(*conn).Read(0xc001042000, {0xc0005b5000?, 0x155?, 0xc000c408b8?})
net/net.go:179 +0x45
crypto/tls.(*atLeastReader).Read(0xc0010b6768, {0xc0005b5000?, 0xc0010b6768?, 0x0?})
crypto/tls/conn.go:805 +0x3b
bytes.(*Buffer).ReadFrom(0xc000c409a8, {0x19c3f60, 0xc0010b6768})
bytes/buffer.go:211 +0x98
crypto/tls.(*Conn).readFromUntil(0xc000c40700, {0x19c3b80?, 0xc001042000}, 0x1800?)
crypto/tls/conn.go:827 +0xde
crypto/tls.(*Conn).readRecordOrCCS(0xc000c40700, 0x0)
crypto/tls/conn.go:625 +0x250
crypto/tls.(*Conn).readRecord(...)
crypto/tls/conn.go:587
crypto/tls.(*Conn).Read(0xc000c40700, {0xc005662000, 0x8000, 0x0?})
crypto/tls/conn.go:1369 +0x158
bufio.(*Reader).Read(0xc0021e3c80, {0xc005631e00, 0x9, 0x7f32362965b8?})
bufio/bufio.go:244 +0x197
io.ReadAtLeast({0x19c2980, 0xc0021e3c80}, {0xc005631e00, 0x9, 0x9}, 0x9)
io/io.go:335 +0x90
io.ReadFull(...)
io/io.go:354
golang.org/x/net/http2.readFrameHeader({0xc005631e00, 0x9, 0x27657e0?}, {0x19c2980?, 0xc0021e3c80?})
golang.org/x/[email protected]/http2/frame.go:237 +0x65
golang.org/x/net/http2.(*Framer).ReadFrame(0xc005631dc0)
golang.org/x/[email protected]/http2/frame.go:498 +0x85
google.golang.org/grpc/internal/transport.(*http2Client).reader(0xc002d46240, 0xc00018e680?)
google.golang.org/[email protected]/internal/transport/http2_client.go:1594 +0x245
created by google.golang.org/grpc/internal/transport.newHTTP2Client in goroutine 36
google.golang.org/[email protected]/internal/transport/http2_client.go:397 +0x1e93

goroutine 20 [chan receive]:
go.k6.io/k6/log.(*lokiHook).Listen.func2()
go.k6.io/k6/log/loki.go:167 +0x11b
created by go.k6.io/k6/log.(*lokiHook).Listen in goroutine 7
go.k6.io/k6/log/loki.go:164 +0x319

goroutine 11 [chan receive, 52 minutes]:
github.com/grafana/xk6-browser/browser.(*browserRegistry).handleExitEvent(0x0?, 0x0?, 0x0?)
github.com/grafana/[email protected]/browser/registry.go:293 +0x45
created by github.com/grafana/xk6-browser/browser.newBrowserRegistry in goroutine 1
github.com/grafana/[email protected]/browser/registry.go:225 +0x285

goroutine 12 [chan receive, 52 minutes]:
github.com/grafana/xk6-browser/browser.(*browserRegistry).handleIterEvents(0xc001627a00, 0x0?, 0xc0039036b0)
github.com/grafana/[email protected]/browser/registry.go:238 +0x65
created by github.com/grafana/xk6-browser/browser.newBrowserRegistry in goroutine 1
github.com/grafana/[email protected]/browser/registry.go:226 +0x2e5

goroutine 30 [IO wait]:
internal/poll.runtime_pollWait(0x7f31ef70dd68, 0x72)
runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc0047ec300?, 0xc0018a6000?, 0x0)
internal

xk6-browser version

v0.46.0

OS

Linux

Chrome version

119.0.6035.3

Docker version and image (if applicable)

No response

Steps to reproduce the problem

Run the test script (might require multiple executions to reproduce the data race).

Expected behaviour

The test finishes correctly.

Actual behaviour

Test panics due to a data race.

Tasks

Give feedback

ankur22 · 2023-12-15T12:59:02Z

Found another one: 2167394

ankur22 · 2024-01-30T15:54:29Z

And another: 2272052

ankur22 · 2024-02-13T13:55:58Z

We've seen a few occurrences of this now, and the thing that they have in common are:

At the moment I suspect it's either us not working with logrus and hooks in a concurrent safe way, or it's logrus.

ankur22 · 2024-02-13T16:26:03Z

When running the test script in this issue with -race and --log-output loki:

XK6_RACE_DETECTOR=1 xk6 run test.js --log-output loki

It would result in the following error:

Stack trace and error

==================
WARNING: DATA RACE 2/5 VUs, 0 complete and 0 interrupted iterations
Read at 0x00c00229bb30 by goroutine 17:-------] 2/5 VUs  04.6s/40.0s
  go.k6.io/k6/log.(*lokiHook).Listen()
      go.k6.io/[email protected]/log/loki.go:234 +0x730
  go.k6.io/k6/cmd.(*rootCommand).setLoggerHook.func1()
      go.k6.io/[email protected]/cmd/root.go:287 +0x60

Previous write at 0x00c00229bb30 by goroutine 109:
  runtime.mapassign_faststr()
      runtime/map_faststr.go:203 +0x40c
  github.com/grafana/xk6-browser/log.(*consoleLogFormatter).Format()
      github.com/grafana/[email protected]/log/logger.go:188 +0x130
  github.com/sirupsen/logrus.(*Entry).write()
      github.com/sirupsen/[email protected]/entry.go:289 +0xe0
  github.com/sirupsen/logrus.(*Entry).log()
      github.com/sirupsen/[email protected]/entry.go:252 +0x730
  github.com/sirupsen/logrus.(*Entry).Log()
      github.com/sirupsen/[email protected]/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      github.com/sirupsen/[email protected]/entry.go:321 +0x44
  github.com/grafana/xk6-browser/common.(*FrameSession).onConsoleAPICalled()
      github.com/grafana/[email protected]/common/frame_session.go:639 +0x3bc
  github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
      github.com/grafana/[email protected]/common/frame_session.go:272 +0x598

Goroutine 17 (running) created at:
  go.k6.io/k6/cmd.(*rootCommand).setLoggerHook()
      go.k6.io/[email protected]/cmd/root.go:286 +0x130
  go.k6.io/k6/cmd.(*rootCommand).setupLoggers()
      go.k6.io/[email protected]/cmd/root.go:265 +0x920
  go.k6.io/k6/cmd.(*rootCommand).persistentPreRunE()
      go.k6.io/[email protected]/cmd/root.go:78 +0x40
  go.k6.io/k6/cmd.(*rootCommand).persistentPreRunE-fm()
      <autogenerated>:1 +0x54
  github.com/spf13/cobra.(*Command).execute()
      github.com/spf13/[email protected]/command.go:835 +0x6b4
  github.com/spf13/cobra.(*Command).ExecuteC()
      github.com/spf13/[email protected]/command.go:974 +0x45c
  github.com/spf13/cobra.(*Command).Execute()
      github.com/spf13/[email protected]/command.go:902 +0x158
  go.k6.io/k6/cmd.(*rootCommand).execute()
      go.k6.io/[email protected]/cmd/root.go:108 +0x144
  go.k6.io/k6/cmd.Execute()
      go.k6.io/[email protected]/cmd/root.go:130 +0x38
  main.main()
      k6/main.go:12 +0x20

Goroutine 109 (running) created at:
  github.com/grafana/xk6-browser/common.(*FrameSession).initEvents()
      github.com/grafana/[email protected]/common/frame_session.go:223 +0x280
  github.com/grafana/xk6-browser/common.NewFrameSession()
      github.com/grafana/[email protected]/common/frame_session.go:132 +0x994
  github.com/grafana/xk6-browser/common.NewPage()
      github.com/grafana/[email protected]/common/page.go:299 +0x8b0
  github.com/grafana/xk6-browser/common.(*Browser).onAttachedToTarget()
      github.com/grafana/[email protected]/common/browser.go:253 +0x3d0
  github.com/grafana/xk6-browser/common.(*Browser).initEvents.func1()
      github.com/grafana/[email protected]/common/browser.go:192 +0x2f4
==================
==================
WARNING: DATA RACE
Read at 0x00c001fd6038 by goroutine 17:
  go.k6.io/k6/log.(*lokiHook).Listen()
      go.k6.io/[email protected]/log/loki.go:242 +0x86c
  go.k6.io/k6/cmd.(*rootCommand).setLoggerHook.func1()
      go.k6.io/[email protected]/cmd/root.go:287 +0x60

Previous write at 0x00c001fd6038 by goroutine 109:
  github.com/grafana/xk6-browser/log.(*consoleLogFormatter).Format()
      github.com/grafana/[email protected]/log/logger.go:187 +0xcc
  github.com/sirupsen/logrus.(*Entry).write()
      github.com/sirupsen/[email protected]/entry.go:289 +0xe0
  github.com/sirupsen/logrus.(*Entry).log()
      github.com/sirupsen/[email protected]/entry.go:252 +0x730
  github.com/sirupsen/logrus.(*Entry).Log()
      github.com/sirupsen/[email protected]/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      github.com/sirupsen/[email protected]/entry.go:321 +0x44
  github.com/grafana/xk6-browser/common.(*FrameSession).onConsoleAPICalled()
      github.com/grafana/[email protected]/common/frame_session.go:639 +0x3bc
  github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
      github.com/grafana/[email protected]/common/frame_session.go:272 +0x598

Goroutine 17 (running) created at:
  go.k6.io/k6/cmd.(*rootCommand).setLoggerHook()
      go.k6.io/[email protected]/cmd/root.go:286 +0x130
  go.k6.io/k6/cmd.(*rootCommand).setupLoggers()
      go.k6.io/[email protected]/cmd/root.go:265 +0x920
  go.k6.io/k6/cmd.(*rootCommand).persistentPreRunE()
      go.k6.io/[email protected]/cmd/root.go:78 +0x40
  go.k6.io/k6/cmd.(*rootCommand).persistentPreRunE-fm()
      <autogenerated>:1 +0x54
  github.com/spf13/cobra.(*Command).execute()
      github.com/spf13/[email protected]/command.go:835 +0x6b4
  github.com/spf13/cobra.(*Command).ExecuteC()
      github.com/spf13/[email protected]/command.go:974 +0x45c
  github.com/spf13/cobra.(*Command).Execute()
      github.com/spf13/[email protected]/command.go:902 +0x158
  go.k6.io/k6/cmd.(*rootCommand).execute()
      go.k6.io/[email protected]/cmd/root.go:108 +0x144
  go.k6.io/k6/cmd.Execute()
      go.k6.io/[email protected]/cmd/root.go:130 +0x38
  main.main()
      k6/main.go:12 +0x20

Goroutine 109 (running) created at:
  github.com/grafana/xk6-browser/common.(*FrameSession).initEvents()
      github.com/grafana/[email protected]/common/frame_session.go:223 +0x280
  github.com/grafana/xk6-browser/common.NewFrameSession()
      github.com/grafana/[email protected]/common/frame_session.go:132 +0x994
  github.com/grafana/xk6-browser/common.NewPage()
      github.com/grafana/[email protected]/common/page.go:299 +0x8b0
  github.com/grafana/xk6-browser/common.(*Browser).onAttachedToTarget()
      github.com/grafana/[email protected]/common/browser.go:253 +0x3d0
  github.com/grafana/xk6-browser/common.(*Browser).initEvents.func1()
      github.com/grafana/[email protected]/common/browser.go:192 +0x2f4
==================

Although it might not seem the same as the original issue (it does show some similarities: logrus and loki) if we dig into it we will find that it does match the original issue.

The stack trace in this comment shows that this issue is within the logger.formatter which is deleting the entry.Data while in the loki hook the entry.Data is being read.

The loki hook works asynchronously, and the entry (the log message and the metadata) is sent to the hook first and then it is formatted and written to logger.out later. The loki hook implemented in k6 assumes that the entry will not be altered and so each entry is dealt asynchronously. The entry isn't thread safe. So we can't work with the logrus formatter while also working with a asynchronous hook. Not only that but the formatted data might not be updated in time when the log is formatted due to asynchronous condition of the loki-hook.

The two possible fixes are:

Edit the entry before logging it.
Do not edit it to format it.

Having explored the codebase, I feel that now there isn't as much value in keeping the formatter, which is only used in one part of our codebase when logging the console.log output from the website under test. A quick fix is probably to move the formatter out of the logger and just to do it in onConsoleAPICalled.

Thanks to @mstoykov for pointing this out.

ka3de added the bug Something isn't working label Oct 13, 2023

inancgumus added the next Might be eligible for the next planning (not guaranteed!) label Nov 1, 2023

ankur22 mentioned this issue Dec 5, 2023

Making k6/experimental/browser module part of k6 core #1117

Closed

inancgumus mentioned this issue Dec 14, 2023

Browser: Runtime stability #1138

Open

ankur22 assigned ankur22 and unassigned ankur22 Feb 13, 2024

ankur22 mentioned this issue Feb 13, 2024

Fix data race with logging #1215

Merged

3 tasks

ankur22 self-assigned this Feb 13, 2024

ankur22 mentioned this issue Feb 14, 2024

Add 1215 to release notes grafana/k6#3599

Merged

5 tasks

ankur22 closed this as completed Feb 26, 2024

inancgumus mentioned this issue Jun 7, 2024

Concurrent map iteration and write bugs #1375

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Data race due to concurrent map access #1066

Data race due to concurrent map access #1066

ka3de commented Oct 13, 2023 •

edited by ankur22

Loading

Tasks

ankur22 commented Dec 15, 2023

ankur22 commented Jan 30, 2024

ankur22 commented Feb 13, 2024

ankur22 commented Feb 13, 2024

Data race due to concurrent map access #1066

Data race due to concurrent map access #1066

Comments

ka3de commented Oct 13, 2023 • edited by ankur22 Loading

Brief summary

xk6-browser version

OS

Chrome version

Docker version and image (if applicable)

Steps to reproduce the problem

Expected behaviour

Actual behaviour

Tasks

ankur22 commented Dec 15, 2023

ankur22 commented Jan 30, 2024

ankur22 commented Feb 13, 2024

ankur22 commented Feb 13, 2024

ka3de commented Oct 13, 2023 •

edited by ankur22

Loading