Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Flaky test: Data Race detected in CI test #879

Closed
zzzming opened this issue Oct 31, 2022 · 3 comments
Closed

Flaky test: Data Race detected in CI test #879

zzzming opened this issue Oct 31, 2022 · 3 comments

Comments

@zzzming
Copy link
Contributor

zzzming commented Oct 31, 2022

CI's make test occasionally fails because of data race detected

Based on the stack, the problem seems to be connection is closed while consumer still tries to Ack()

=== RUN   TestLargeMessage
time="2022-10-31T01:58:18Z" level=info msg="Connecting to broker" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:58:18Z" level=info msg="TCP connection established" local_addr="127.0.0.1:51432" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:58:18Z" level=info msg="Connection is ready" local_addr="127.0.0.1:51432" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:58:18Z" level=info msg="Connected producer" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:58:18Z" level=info msg="Created producer" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:58:18Z" level=info msg="Connected producer" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:58:18Z" level=info msg="Created producer" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:58:18Z" level=info msg="Connected consumer" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:58:18Z" level=info msg="Created consumer" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=warning msg="Connection was closed" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=warning msg="Connection was closed" cnx="127.0.0.1:51432 -> 127.0.0.1:6650" producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Reconnecting to broker in 116.571508ms" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="runEventsLoop will reconnect in producer" producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Reconnecting to broker in 100.75366ms" producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="runEventsLoop will reconnect in producer" producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Reconnecting to broker in 108.423144ms" producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Connecting to broker" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:59:18Z" level=info msg="TCP connection established" local_addr="127.0.0.1:51434" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:59:18Z" level=info msg="Connection is ready" local_addr="127.0.0.1:51434" remote_addr="pulsar://localhost:6650"
time="2022-10-31T01:59:18Z" level=info msg="Connected producer" cnx="127.0.0.1:51434 -> 127.0.0.1:6650" epoch=1 producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Reconnected producer to broker" cnx="127.0.0.1:51434 -> 127.0.0.1:6650" producerID=2 producer_name=standalone-0-173 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Connected producer" cnx="127.0.0.1:51434 -> 127.0.0.1:6650" epoch=1 producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:18Z" level=info msg="Reconnected producer to broker" cnx="127.0.0.1:51434 -> 127.0.0.1:6650" producerID=1 producer_name=standalone-0-172 topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:22Z" level=info msg="Removing chunk message-id356:50:0" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:22Z" level=info msg="Removing chunk message-id356:51:0" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:22Z" level=error msg="Connection was closed when request ack cmd" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
time="2022-10-31T01:59:22Z" level=error msg="Connection was closed when request ack cmd" consumerID=1 name=sbiay subscription=chunk-subscriber topic="persistent://public/default/my-topic-577261200"
==================
WARNING: DATA RACE
Read at 0x00c0006ac170 by goroutine 558:
  github.com/apache/pulsar-client-go/pulsar.(*partitionConsumer).AckID()
      /pulsar-client-go/pulsar/consumer_partition.go:450 +0x94b
  github.com/apache/pulsar-client-go/pulsar.(*chunkedMsgCtx).discard()
      /pulsar-client-go/pulsar/consumer_partition.go:1697 +0x42f
  github.com/apache/pulsar-client-go/pulsar.(*chunkedMsgCtxMap).discardChunkMessage()
      /pulsar-client-go/pulsar/consumer_partition.go:1790 +0x1ce
  github.com/apache/pulsar-client-go/pulsar.(*chunkedMsgCtxMap).discardChunkIfExpire()
      /pulsar-client-go/pulsar/consumer_partition.go:1806 +0x8c
  github.com/apache/pulsar-client-go/pulsar.(*chunkedMsgCtxMap).addIfAbsent.func2()
      /pulsar-client-go/pulsar/consumer_partition.go:1729 +0x68

Previous write at 0x00c0006ac170 by goroutine 358:
  github.com/apache/pulsar-client-go/pulsar.(*partitionConsumer).internalAck()
      /pulsar-client-go/pulsar/consumer_partition.go:683 +0xa44
  github.com/apache/pulsar-client-go/pulsar.(*partitionConsumer).runEventsLoop()
      /pulsar-client-go/pulsar/consumer_partition.go:1213 +0x43b
  github.com/apache/pulsar-client-go/pulsar.newPartitionConsumer.func2()
      /pulsar-client-go/pulsar/consumer_partition.go:300 +0x39

Goroutine 558 (running) created at:
  github.com/apache/pulsar-client-go/pulsar.(*chunkedMsgCtxMap).addIfAbsent()
      /pulsar-client-go/pulsar/consumer_partition.go:1729 +0x6dc
  github.com/apache/pulsar-client-go/pulsar.(*partitionConsumer).processMessageChunk()
      /pulsar-client-go/pulsar/consumer_partition.go:914 +0x534
  github.com/apache/pulsar-client-go/pulsar.(*partitionConsumer).MessageReceived()
      /pulsar-client-go/pulsar/consumer_partition.go:756 +0x8c4
  github.com/apache/pulsar-client-go/pulsar/internal.(*connection).handleMessage()
      /pulsar-client-go/pulsar/internal/connection.go:724 +0x1b8
  github.com/apache/pulsar-client-go/pulsar/internal.(*connection).internalReceivedCommand()
      /pulsar-client-go/pulsar/internal/connection.go:567 +0x36e
  github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run()
      /pulsar-client-go/pulsar/internal/connection.go:416 +0x70c
  github.com/apache/pulsar-client-go/pulsar/internal.(*connection).start.func1()
      /pulsar-client-go/pulsar/internal/connection.go:227 +0xa4

Goroutine 358 (running) created at:
  github.com/apache/pulsar-client-go/pulsar.newPartitionConsumer()
      /pulsar-client-go/pulsar/consumer_partition.go:300 +0x1945
  github.com/apache/pulsar-client-go/pulsar.(*consumer).internalTopicSubscribeToPartitions.func1()
      /pulsar-client-go/pulsar/consumer_impl.go:380 +0xb38
  github.com/apache/pulsar-client-go/pulsar.(*consumer).internalTopicSubscribeToPartitions.func4()
      /pulsar-client-go/pulsar/consumer_impl.go:386 +0x66
@zzzming zzzming changed the title Data Race detected in CI test Flaky test: Data Race detected in CI test Oct 31, 2022
@Gleiphir2769
Copy link
Contributor

Hi, I think I have found the problem. I will fix it.

@Gleiphir2769 Gleiphir2769 mentioned this issue Nov 2, 2022
Merged
1 task
@nodece
Copy link
Member

nodece commented Nov 4, 2022

I think we should return this error, do you have any other way to fix this?

@nodece
Copy link
Member

nodece commented Nov 29, 2022

Closed by #881

@nodece nodece closed this as completed Nov 29, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nodece @zzzming @Gleiphir2769