search

grafana / xk6-browser

k6 extension that adds support for browser automation and end-to-end web testing via the Chrome Devtools Protocol
https://grafana.com/docs/k6/latest/javascript-api/k6-experimental/browser/
GNU Affero General Public License v3.0
337 stars 42 forks source link

Data race in Logger #162

Open inancgumus opened 2 years ago

inancgumus commented 2 years ago

Discovered by #141. I'm not sure this is related to logging.

7646   │ --- FAIL: TestPageInputSpecialCharacters (3.28s)
7647   │ 468: running [Created by common.NewBaseEventEmitter @ event_emitter.go:120] Race write @ 0xc00240ee70
7648   │     runtime map_faststr.go:202                        mapassign_faststr()
7649   │     common  event_emitter.go:179                      (*BaseEventEmitter).emit.func3()
7650   │     common  event_emitter.go:148                      (*BaseEventEmitter).sync.func1()
7651   │     common  event_emitter.go:135                      (*BaseEventEmitter).syncAll()
7652   │     common  event_emitter.go:120                      NewBaseEventEmitter·dwrap·22()
7653   │ 34: running [Created by testing.(*T).Run @ testing.go:1306] Race read @ 0xc00240ee70
7654   │     reflect map.go:1360                               maplen()
7655   │     reflect value.go:1496                             Value.Len()
7656   │     fmtsort sort.go:59                                Sort()
7657   │     fmt     print.go:769                              (*pp).printValue()
7658   │     fmt     print.go:806                              (*pp).printValue()
7659   │     fmt     print.go:806                              (*pp).printValue()
7660   │     fmt     print.go:876                              (*pp).printValue()
7661   │     fmt     print.go:712                              (*pp).printArg()
7662   │     fmt     print.go:1026                             (*pp).doPrintf()
7663   │     fmt     print.go:219                              Sprintf()
7664   │     logrus  entry.go:338                              (*Entry).Logf()
7665   │     common  logger.go:117                             (*Logger).Logf()
7666   │     common  logger.go:68                              (*Logger).Debugf()
7667   │     common  browser.go:328                            (*Browser).newPageInContext()
7668   │     common  browser_context.go:220                    (*BrowserContext).NewPage()
7669   │     common  browser.go:401                            (*Browser).NewPage()
7670   │     tests   element_handle_waitforselector_test.go:34 TestElementHandleWaitForSelector()
7671   │     testing testing.go:1259                           tRunner()
7672   │     testing testing.go:1306                           (*T).Run·dwrap·21()
7673   │ 468: running [Created by common.NewBaseEventEmitter @ event_emitter.go:120] Race write @ 0xc002028248
7674   │     common  event_emitter.go:180                      (*BaseEventEmitter).emit.func3()
7675   │     common  event_emitter.go:148                      (*BaseEventEmitter).sync.func1()
7676   │     common  event_emitter.go:135                      (*BaseEventEmitter).syncAll()
7677   │     common  event_emitter.go:120                      NewBaseEventEmitter·dwrap·22()
7678   │ 34: running [Created by testing.(*T).Run @ testing.go:1306] Race read @ 0xc002028248
7679   │     reflect mbarrier.go:178                           typedmemmove()
7680   │     reflect value.go:123                              packEface()
7681   │     reflect value.go:1381                             valueInterface()
7682   │     reflect value.go:1351                             Value.Interface()
7683   │     fmt     print.go:722                              (*pp).printValue()
7684   │     fmt     print.go:876                              (*pp).printValue()
7685   │     fmt     print.go:712                              (*pp).printArg()
7686   │     fmt     print.go:1026                             (*pp).doPrintf()
7687   │     fmt     print.go:219                              Sprintf()
7688   │     logrus  entry.go:338                              (*Entry).Logf()
7689   │     common  logger.go:117                             (*Logger).Logf()
7690   │     common  logger.go:68                              (*Logger).Debugf()
7691   │     common  browser.go:328                            (*Browser).newPageInContext()
7692   │     common  browser_context.go:220                    (*BrowserContext).NewPage()
7693   │     common  browser.go:401                            (*Browser).NewPage()
7694   │     tests   element_handle_waitforselector_test.go:34 TestElementHandleWaitForSelector()
7695   │     testing testing.go:1259                           tRunner()
7696   │     testing testing.go:1306                           (*T).Run·dwrap·21()
inancgumus commented 2 years ago

I came across a data race in the logger and test browser.

Enabling parallel might have caused the issue? #389 

==================
WARNING: DATA RACE
Write at 0x00c0000fa000 by goroutine 1305:
  github.com/sirupsen/logrus.(*Logger).SetOutput()
      /Users/inanc/go/pkg/mod/github.com/sirupsen/logrus@v1.8.1/logger.go:388 +0x90
  github.com/grafana/xk6-browser/tests.attachLogCache()
      /Users/inanc/grafana/xk6-browser/tests/logrus_hook.go:74 +0x140
  github.com/grafana/xk6-browser/tests.newTestBrowser()
      /Users/inanc/grafana/xk6-browser/tests/test_browser.go:122 +0x4f8
  github.com/grafana/xk6-browser/tests.TestURLSkipRequest()
      /Users/inanc/grafana/xk6-browser/tests/network_manager_test.go:41 +0x64
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1486 +0x44

Previous read at 0x00c0000fa000 by goroutine 983:
  github.com/grafana/xk6-browser/log.(*Logger).ConsoleLogFormatterSerializer()
      /Users/inanc/grafana/xk6-browser/log/logger.go:169 +0x270
  github.com/grafana/xk6-browser/common.NewFrameSession()
      /Users/inanc/grafana/xk6-browser/common/frame_session.go:112 +0x384
  github.com/grafana/xk6-browser/common.NewPage()
      /Users/inanc/grafana/xk6-browser/common/page.go:139 +0x874
  github.com/grafana/xk6-browser/common.(*Browser).onAttachedToTarget()
      /Users/inanc/grafana/xk6-browser/common/browser.go:287 +0x80c
  github.com/grafana/xk6-browser/common.(*Browser).initEvents.func1()
      /Users/inanc/grafana/xk6-browser/common/browser.go:194 +0x2fc

Goroutine 1305 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1486 +0x560
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1839 +0x94
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1439 +0x18c
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1837 +0x6c8
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1719 +0x878
  main.main()
      _testmain.go:175 +0x2fc

Goroutine 983 (running) created at:
  github.com/grafana/xk6-browser/common.(*Browser).initEvents()
      /Users/inanc/grafana/xk6-browser/common/browser.go:179 +0x2c8
  github.com/grafana/xk6-browser/common.(*Browser).connect()
      /Users/inanc/grafana/xk6-browser/common/browser.go:140 +0x584
  github.com/grafana/xk6-browser/common.NewBrowser()
      /Users/inanc/grafana/xk6-browser/common/browser.go:99 +0x5c
  github.com/grafana/xk6-browser/chromium.(*BrowserType).Launch()
      /Users/inanc/grafana/xk6-browser/chromium/browser_type.go:156 +0x704
  github.com/grafana/xk6-browser/tests.newTestBrowser()
      /Users/inanc/grafana/xk6-browser/tests/test_browser.go:127 +0x59c
  github.com/grafana/xk6-browser/tests.TestLocatorTap()
      /Users/inanc/grafana/xk6-browser/tests/locator_test.go:394 +0x64
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1486 +0x44
==================
--- FAIL: TestLocatorInnerText (1.56s)
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorTextContent (1.59s)
    --- FAIL: TestLocatorTextContent/ok (0.29s)
        testing.go:1312: race detected during execution of test
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorFocus (1.60s)
    --- FAIL: TestLocatorFocus/strict (0.05s)
        testing.go:1312: race detected during execution of test
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorHover (1.72s)
    --- FAIL: TestLocatorHover/ok (0.56s)
        testing.go:1312: race detected during execution of test
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorClick (1.72s)
    --- FAIL: TestLocatorClick/ok (0.51s)
        testing.go:1312: race detected during execution of test
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorSelectOption (0.83s)
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorPress (0.97s)
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorTap (0.96s)
    testing.go:1312: race detected during execution of test
--- FAIL: TestURLSkipRequest (0.84s)
    testing.go:1312: race detected during execution of test
--- FAIL: TestLocatorElementState (2.45s)
    --- FAIL: TestLocatorElementState/readOnly (1.57s)
        testing.go:1312: race detected during execution of test
    testing.go:1312: race detected during execution of test
FAIL
FAIL    github.com/grafana/xk6-browser/tests    33.731s
FAIL