Data Race in bus package

[vknabel]

Occasionally integration tests fail due to a data race in the bus package.

See https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710

Details

?   	github.com/metal-stack/metal-lib	[no test files]
ok  	github.com/metal-stack/metal-lib/auditing	6.918s	coverage: 41.9% of statements
ok  	github.com/metal-stack/metal-lib/auth	0.115s	coverage: 36.9% of statements
?   	github.com/metal-stack/metal-lib/bus/testenv	[no test files]
[nsqd] 2023/07/31 12:19:20.691870 INFO: nsqd v1.2.1 (built w/go1.20.6)
[nsqd] 2023/07/31 12:19:20.692049 INFO: ID: 193
[nsqd] 2023/07/31 12:19:20.694740 INFO: TCP: listening on 127.0.0.1:44150
[nsqd] 2023/07/31 12:19:20.694875 INFO: HTTP: listening on 127.0.0.1:44151
[nsqd] 2023/07/31 12:19:21.628689 INFO: TOPIC(topic42): created
[nsqd] 2023/07/31 12:19:21.628735 INFO: 200 POST /topic/create?topic=topic42 (127.0.0.1:49860) 162.397µs
[nsqd] 2023/07/31 12:19:21.628891 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:21.630276 INFO: TCP: new client(127.0.0.1:36536)
[nsqd] 2023/07/31 12:19:21.630524 INFO: CLIENT(127.0.0.1:36536): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:21.630921 INFO: [127.0.0.1:36536] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:21.634297 INFO: TCP: new client(127.0.0.1:36548)
[nsqd] 2023/07/31 12:19:21.634462 INFO: CLIENT(127.0.0.1:36548): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:21.634784 INFO: [127.0.0.1:36548] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:21.635368 INFO: TOPIC(topic42): new channel(node42)
[nsqd] 2023/07/31 12:19:21.635487 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
received &{mymsg 42}
==================
WARNING: DATA RACE
Read at 0x00c00024e383 by goroutine 71:
  testing.(*common).logDepth()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:992 +0xc4
  testing.(*common).log()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:985 +0xa4
  testing.(*common).Logf()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1036 +0x6a
  testing.(*T).Logf()
      <autogenerated>:1 +0x75
  go.uber.org/zap/zaptest.testingWriter.Write()
      /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c
  go.uber.org/zap/zaptest.(*testingWriter).Write()
      <autogenerated>:1 +0x7e
  go.uber.org/zap/zapcore.(*ioCore).Write()
      /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce
  go.uber.org/zap.(*Logger).Debug()
      /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:212 +0x6d
  github.com/metal-stack/metal-lib/bus.bridgeNsqLogToCoreLog()
      /home/runner/work/metal-lib/metal-lib/bus/eventbus.go:407 +0x1ef
  github.com/metal-stack/metal-lib/bus.(*ConsumerRegistration).Output()
      /home/runner/work/metal-lib/metal-lib/bus/eventbus.go:157 +0xa4
  github.com/nsqio/go-nsq.(*Consumer).log()
      /home/runner/go/pkg/mod/github.com/nsqio/go-nsq@v1.1.0/consumer.go:1202 +0x261
  github.com/nsqio/go-nsq.(*Consumer).handlerLoop()
      /home/runner/go/pkg/mod/github.com/nsqio/go-nsq@v1.1.0/consumer.go:1133 +0x6d
  github.com/nsqio/go-nsq.(*Consumer).AddConcurrentHandlers.func1()
      /home/runner/go/pkg/mod/github.com/nsqio/go-nsq@v1.1.0/consumer.go:1128 +0x58

Previous write at 0x00c00024e383 by goroutine 69:
  testing.tRunner.func1()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1563 +0x82d
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.20.6/x64/src/runtime/panic.go:476 +0x32
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47

Goroutine 71 (running) created at:
  github.com/nsqio/go-nsq.(*Consumer).AddConcurrentHandlers()
      /home/runner/go/pkg/mod/github.com/nsqio/go-nsq@v1.1.0/consumer.go:1128 +0x7b
  github.com/metal-stack/metal-lib/bus.(*ConsumerRegistration).Consume()
      /home/runner/work/metal-lib/metal-lib/bus/eventbus.go:278 +0x576
  github.com/metal-stack/metal-lib/bus.TestNewConsumerWithTimeout()
      /home/runner/work/metal-lib/metal-lib/bus/eventbus_test.go:258 +0x392
  testing.tRunner()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47

Goroutine 69 (running) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x805
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2036 +0x8d
  testing.tRunner()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216
  testing.runTests()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2034 +0x87c
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1906 +0xb44
  github.com/metal-stack/metal-lib/bus.TestMain()
      /home/runner/work/metal-lib/metal-lib/bus/bus_test.go:56 +0x33
  main.main()
      _testmain.go:130 +0x33d
==================
[nsqd] 2023/07/31 12:19:21.89[175](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:176)0 INFO: TOPIC(helloworld): created
[nsqd] 2023/07/31 12:19:21.891891 INFO: 200 POST /topic/create?topic=helloworld (127.0.0.1:49860) 220.897µs
[nsqd] 2023/07/31 12:19:21.891845 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:21.893173 INFO: TCP: new client(127.0.0.1:36560)
[nsqd] 2023/07/31 12:19:21.893452 INFO: CLIENT(127.0.0.1:36560): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:21.893680 INFO: [127.0.0.1:36560] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:21.894382 INFO: TOPIC(helloworld): new channel(function)
[nsqd] 2023/07/31 12:19:21.894462 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.145583 INFO: TOPIC(uniquehelloworld-249ffd30-bc82-4a98-bc36-2110091f63ad): created
[nsqd] 2023/07/31 12:19:22.145621 INFO: 200 POST /topic/create?topic=uniquehelloworld-249ffd30-bc82-4a98-bc36-2110091f63ad (127.0.0.1:49860) 160.598µs
[nsqd] 2023/07/31 12:19:22.145820 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.147092 INFO: TCP: new client(127.0.0.1:36572)
[nsqd] 2023/07/31 12:19:22.147318 INFO: CLIENT(127.0.0.1:36572): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.147546 INFO: [127.0.0.1:36572] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.148443 INFO: TOPIC(uniquehelloworld-249ffd30-bc82-4a98-bc36-2110091f63ad#ephemeral): created
[nsqd] 2023/07/31 12:19:22.148742 INFO: TOPIC(uniquehelloworld-249ffd30-bc82-4a98-bc36-2110091f63ad#ephemeral): new channel(function#ephemeral)
[nsqd] 2023/07/31 12:19:22.399818 INFO: TOPIC(distributed-hello): created
[nsqd] 2023/07/31 12:19:22.399860 INFO: 200 POST /topic/create?topic=distributed-hello (127.0.0.1:49860) 133.299µs
[nsqd] 2023/07/31 12:19:22.400016 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.402553 INFO: TCP: new client(127.0.0.1:36574)
[nsqd] 2023/07/31 12:19:22.402578 INFO: CLIENT(127.0.0.1:36574): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.402786 INFO: [127.0.0.1:36574] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.403184 INFO: TOPIC(distributed-hello): new channel(function)
[nsqd] 2023/07/31 12:19:22.403272 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.4[182](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:183)41 INFO: 200 POST /topic/create?topic=distributed-hello (127.0.0.1:49876) 17µs
[nsqd] 2023/07/31 12:19:22.4[189](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:190)68 INFO: TCP: new client(127.0.0.1:36576)
[nsqd] 2023/07/31 12:19:22.4[191](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:192)28 INFO: CLIENT(127.0.0.1:36576): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.419683 INFO: [127.0.0.1:36576] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.432879 INFO: PROTOCOL(V2): [127.0.0.1:36576] exiting ioloop
[nsqd] 2023/07/31 12:19:22.432961 INFO: PROTOCOL(V2): [127.0.0.1:36576] exiting messagePump
[nsqd] 2023/07/31 12:19:22.654029 INFO: TOPIC(hello-result-b873b51a-4940-488e-b77c-d3ee1c08c4e5): created
[nsqd] 2023/07/31 12:19:22.654066 INFO: 200 POST /topic/create?topic=hello-result-b873b51a-4940-488e-b77c-d3ee1c08c4e5 (127.0.0.1:49860) 131.898µs
[nsqd] 2023/07/31 12:19:22.654665 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.656510 INFO: TCP: new client(127.0.0.1:36586)
[nsqd] 2023/07/31 12:19:22.656886 INFO: CLIENT(127.0.0.1:36586): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.657115 INFO: [127.0.0.1:36586] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.657754 INFO: TOPIC(hello-service): created
[nsqd] 2023/07/31 12:19:22.657787 INFO: 200 POST /topic/create?topic=hello-service (127.0.0.1:49860) 110.698µs
[nsqd] 2023/07/31 12:19:22.657973 INFO: TOPIC(hello-result-b873b51a-4940-488e-b77c-d3ee1c08c4e5#ephemeral): created
[nsqd] 2023/07/31 12:19:22.658039 INFO: TOPIC(hello-result-b873b51a-4940-488e-b77c-d3ee1c08c4e5#ephemeral): new channel(function#ephemeral)
[nsqd] 2023/07/31 12:19:22.658141 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.682633 INFO: 200 POST /topic/create?topic=hello-service (127.0.0.1:49884) 20.1µs
[nsqd] 2023/07/31 12:19:22.683930 INFO: TCP: new client(127.0.0.1:36590)
[nsqd] 2023/07/31 12:19:22.684104 INFO: CLIENT(127.0.0.1:36590): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.684715 INFO: [127.0.0.1:36590] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.685245 INFO: TOPIC(hello-service): new channel(function)
[nsqd] 2023/07/31 12:19:22.685331 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.935944 INFO: 200 POST /topic/create?topic=hello-result-b873b51a-4940-488e-b77c-d3ee1c08c4e5 (127.0.0.1:49884) 27.399µs
[nsqd] 2023/07/31 12:19:22.936748 INFO: TCP: new client(127.0.0.1:36600)
[nsqd] 2023/07/31 12:19:22.936914 INFO: CLIENT(127.0.0.1:36600): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.937376 INFO: [127.0.0.1:36600] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.941000 INFO: TOPIC(helloworld-retry): created
[nsqd] 2023/07/31 12:19:22.941032 INFO: 200 POST /topic/create?topic=helloworld-retry (127.0.0.1:49860) 2.825261ms
[nsqd] 2023/07/31 12:19:22.942767 INFO: TCP: new client(127.0.0.1:36612)
[nsqd] 2023/07/31 12:19:22.943036 INFO: CLIENT(127.0.0.1:36612): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:22.943266 INFO: [127.0.0.1:36612] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:22.943838 INFO: TOPIC(helloworld-retry): new channel(function)
[nsqd] 2023/07/31 12:19:22.943887 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.947037 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:22.951992 INFO: PROTOCOL(V2): [127.0.0.1:36600] exiting ioloop
[nsqd] 2023/07/31 12:19:22.952059 INFO: PROTOCOL(V2): [127.0.0.1:36590] exiting ioloop
[nsqd] 2023/07/31 12:19:22.952213 INFO: PROTOCOL(V2): [127.0.0.1:36590] exiting messagePump
[nsqd] 2023/07/31 12:19:22.952254 INFO: PROTOCOL(V2): [127.0.0.1:36600] exiting messagePump
[nsqd] 2023/07/31 12:19:28.[195](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:196)975 INFO: TOPIC(hellostruct): created
[nsqd] 2023/07/31 12:19:28.[196](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:197)012 INFO: 200 POST /topic/create?topic=hellostruct (127.0.0.1:49860) 135.199µs
[nsqd] 2023/07/31 12:19:28.196079 INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
[nsqd] 2023/07/31 12:19:28.[197](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:198)473 INFO: TCP: new client(127.0.0.1:57906)
[nsqd] 2023/07/31 12:19:28.197505 INFO: CLIENT(127.0.0.1:57906): desired protocol magic '  V2'
[nsqd] 2023/07/31 12:19:28.197813 INFO: [127.0.0.1:57906] IDENTIFY: {ClientID:fv-az446-369 Hostname:fv-az446-369 HeartbeatInterval:5000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.1.0 MsgTimeout:0}
[nsqd] 2023/07/31 12:19:28.[198](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:199)293 INFO: TOPIC(hellostruct): new channel(function)
[nsqd] [202](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:203)3/07/31 12:19:28.198[311](https://github.com/metal-stack/metal-lib/actions/runs/5714559648/job/15482128710#step:4:312) INFO: NSQ: persisting topic/channel metadata to /tmp/nsqd.dat
FAIL
	github.com/metal-stack/metal-lib/bus	coverage: 67.5% of statements
FAIL	github.com/metal-stack/metal-lib/bus	7.874s
ok  	github.com/metal-stack/metal-lib/httperrors	0.032s	coverage: 24.1% of statements
ok  	github.com/metal-stack/metal-lib/jwt/grp	0.032s	coverage: 88.4% of statements
ok  	github.com/metal-stack/metal-lib/jwt/jwt	0.719s	coverage: 19.4% of statements
ok  	github.com/metal-stack/metal-lib/jwt/sec	1.575s	coverage: 91.2% of statements
ok  	github.com/metal-stack/metal-lib/pkg/cache	3.478s	coverage: 66.1% of statements
ok  	github.com/metal-stack/metal-lib/pkg/genericcli	0.068s	coverage: 28.3% of statements
?   	github.com/metal-stack/metal-lib/pkg/genericcli/printers/proto_test	[no test files]
ok  	github.com/metal-stack/metal-lib/pkg/genericcli/printers	0.064s	coverage: 86.3% of statements
ok  	github.com/metal-stack/metal-lib/pkg/k8s	0.032s	coverage: 100.0% of statements
?   	github.com/metal-stack/metal-lib/pkg/net	[no test files]
ok  	github.com/metal-stack/metal-lib/pkg/multisort	0.052s	coverage: 79.1% of statements
ok  	github.com/metal-stack/metal-lib/pkg/pointer	0.029s	coverage: 56.5% of statements
ok  	github.com/metal-stack/metal-lib/pkg/sign	0.197s	coverage: 60.7% of statements
?   	github.com/metal-stack/metal-lib/pkg/ssh	[no test files]
?   	github.com/metal-stack/metal-lib/pkg/testcommon	[no test files]
ok  	github.com/metal-stack/metal-lib/pkg/tag	0.031s	coverage: 91.7% of statements
?   	github.com/metal-stack/metal-lib/pkg/vpn	[no test files]
ok  	github.com/metal-stack/metal-lib/rest	0.054s	coverage: 72.3% of statements
FAIL
make: *** [Makefile:19: test-integration] Error 1

[majst01]

Its the bus package

[vknabel]

Right, it's in bus. I mixed it up with our dbus in our gardener PR. 😅