[fix][client] Fix RawReader hasMessageAvailable returns true when no messages #21032

Technoboy- · 2023-08-19T07:59:13Z

Motivation

When runs testHasMessageAvailableWithBatch, there is a race condition between test-thread and pulsar-client-internal-thread

time	`test-thread`	`pulsar-client-internal-4082-1`
1	reader.hasMessageAvailableAsync() = true
2	reader.readNextAsync() and print below msg from `3:0:-1:0` to `3:0:-1:9`
3	update `lastDequeuedMessageId: 3:0:-1:9`
4	reader.hasMessageAvailableAsync() = true
5	reader.readNextAsync() and print below msg from `3:1:-1:0` to `3:1:-1:9`
6	continue reader.hasMessageAvailableAsync() = true because `lastDequeuedMessageId: 3:0:-1:9`
7		update `lastDequeuedMessageId: 3:1:-1:9`
8	blocked

So we should update lastDequeuedMessageId before future.complete:

pulsar/pulsar-broker/src/main/java/org/apache/pulsar/client/impl/RawReaderImpl.java

Lines 154 to 161 in d06cda6

    
           if (!future.complete(messageAndCnx.msg)) { 
        
               messageAndCnx.msg.close(); 
        
               closeAsync(); 
        
           } 
        
           MessageIdData messageId = messageAndCnx.msg.getMessageIdData(); 
        
           lastDequeuedMessageId = new BatchMessageIdImpl(messageId.getLedgerId(), messageId.getEntryId(), 
        
               messageId.getPartition(), numMsg - 1);

Add related codes and logs:

2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderImpl$RawConsumerImpl@161] - update lastDequeuedMessageId: {}, lastDequeuedMessageId
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0], keys2 : [key0]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1], keys2 : [key0, key1]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2], keys2 : [key0, key1, key2]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3], keys2 : [key0, key1, key2, key3]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4], keys2 : [key0, key1, key2, key3, key4]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5], keys2 : [key0, key1, key2, key3, key4, key5]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6], keys2 : [key0, key1, key2, key3, key4, key5, key6]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8]
2023-08-19T12:20:59,710 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9]
2023-08-19T12:20:59,711 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:ConsumerImpl@2322] - hasMoreMessages,  lastMessageIdInBroker: 3:1:-1:9, lastDequeuedMessageId: 3:0:-1:9
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4, 3:1:-1:5], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14, key15]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4, 3:1:-1:5, 3:1:-1:6], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14, key15, key16]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4, 3:1:-1:5, 3:1:-1:6, 3:1:-1:7], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14, key15, key16, key17]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4, 3:1:-1:5, 3:1:-1:6, 3:1:-1:7, 3:1:-1:8], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14, key15, key16, key17, key18]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:RawReaderTest@162] - ids : [3:0:-1:0, 3:0:-1:1, 3:0:-1:2, 3:0:-1:3, 3:0:-1:4, 3:0:-1:5, 3:0:-1:6, 3:0:-1:7, 3:0:-1:8, 3:0:-1:9, 3:1:-1:0, 3:1:-1:1, 3:1:-1:2, 3:1:-1:3, 3:1:-1:4, 3:1:-1:5, 3:1:-1:6, 3:1:-1:7, 3:1:-1:8, 3:1:-1:9], keys2 : [key0, key1, key2, key3, key4, key5, key6, key7, key8, key9, key10, key11, key12, key13, key14, key15, key16, key17, key18, key19]
2023-08-19T12:20:59,714 - INFO  - [TestNG-method=testHasMessageAvailableWithBatch-1:ConsumerImpl@2322] - hasMoreMessages,  lastMessageIdInBroker: 3:1:-1:9, lastDequeuedMessageId: 3:0:-1:9
2023-08-19T12:20:59,714 - INFO  - [pulsar-client-internal-4082-1:RawReaderImpl$RawConsumerImpl@161] - update lastDequeuedMessageId: {}, lastDequeuedMessageId

This also fix #20998

Documentation

doc
doc-required
doc-not-needed
doc-complete

codecov-commenter · 2023-08-19T13:00:44Z

Codecov Report

Merging #21032 (f490be5) into master (0cb1c78) will increase coverage by 39.54%.
Report is 5 commits behind head on master.
The diff coverage is 100.00%.

@@              Coverage Diff              @@
##             master   #21032       +/-   ##
=============================================
+ Coverage     33.56%   73.11%   +39.54%     
- Complexity    12198    32262    +20064     
=============================================
  Files          1621     1875      +254     
  Lines        126970   139505    +12535     
  Branches      13857    15344     +1487     
=============================================
+ Hits          42618   101999    +59381     
+ Misses        78748    29436    -49312     
- Partials       5604     8070     +2466

Flag	Coverage Δ
inttests	`24.24% <100.00%> (+<0.01%)`	⬆️
systests	`25.15% <100.00%> (?)`
unittests	`72.40% <100.00%> (+40.30%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files Changed	Coverage Δ
...a/org/apache/pulsar/client/impl/RawReaderImpl.java	`83.65% <100.00%> (+0.96%)`	⬆️

... and 1518 files with indirect coverage changes

pulsar-broker/src/test/java/org/apache/pulsar/client/impl/MultiTopicsReaderTest.java

pulsar-broker/src/test/java/org/apache/pulsar/client/impl/NegativeAcksTest.java

zymap · 2023-08-21T00:49:38Z

pulsar-broker/src/test/java/org/apache/pulsar/client/impl/RawReaderTest.java

        Set<String> keys = publishMessages(topic, numKeys, true);
        RawReader reader = RawReader.create(pulsarClient, topic, subscription).get();
        int messageCount = 0;
        while (true) {
            boolean hasMsg = reader.hasMessageAvailableAsync().get();
-            if (hasMsg && (messageCount == numKeys)) {


Why remove the original checks? It changes the original testing purpose, no?

It may be blocked at the readNextAsync without any information until the test timeout.

…messages (#21032)

shibd · 2023-10-22T02:56:40Z

@Technoboy- Can you help create a PR to cherry-pick this change to branch-2.11?

…messages (#21032)

Technoboy- added 12 commits August 17, 2023 09:03

fix

9d65a87

address comment

13fafe1

add log

84beb1f

add log

6b2d1b9

remove timeout

75ece25

fix test

d31bed6

fix test

33681e6

add log

b64ee22

update

71403af

fix checkstyle

06f9c56

fix checkstyle

28ad518

add log

2618d2c

github-actions bot added the doc-not-needed Your PR changes do not impact docs label Aug 19, 2023

Technoboy- closed this Aug 19, 2023

Technoboy- reopened this Aug 19, 2023

Technoboy- force-pushed the fix-test-3 branch from 731fafd to 2618d2c Compare August 19, 2023 11:47

Technoboy- closed this Aug 19, 2023

Technoboy- reopened this Aug 19, 2023

Technoboy- added the ready-to-test label Aug 19, 2023

add more log

cc30961

Technoboy- self-assigned this Aug 19, 2023

Technoboy- added this to the 3.2.0 milestone Aug 19, 2023

Technoboy- changed the title ~~[fix][test] Fix flaky test RawReaderTest~~ [fix][test] Fix RawReader hasMessageAvailable returns true when no messages Aug 19, 2023

Technoboy- changed the title ~~[fix][test] Fix RawReader hasMessageAvailable returns true when no messages~~ [fix][client] Fix RawReader hasMessageAvailable returns true when no messages Aug 19, 2023

rollback for all the log

f490be5

Technoboy- added area/client release/2.9.5 release/3.0.2 release/2.11.3 labels Aug 19, 2023

Technoboy- added release/2.10.6 release/3.1.1 labels Aug 19, 2023

mattisonchao approved these changes Aug 19, 2023

View reviewed changes

Demogorgon314 approved these changes Aug 20, 2023

View reviewed changes

BewareMyPower reviewed Aug 20, 2023

View reviewed changes

pulsar-broker/src/test/java/org/apache/pulsar/client/impl/MultiTopicsReaderTest.java Show resolved Hide resolved

pulsar-broker/src/test/java/org/apache/pulsar/client/impl/NegativeAcksTest.java Show resolved Hide resolved

BewareMyPower approved these changes Aug 20, 2023

View reviewed changes

Technoboy- merged commit 00ca6aa into apache:master Aug 20, 2023
59 checks passed

zymap reviewed Aug 21, 2023

View reviewed changes

codelipenghui added the type/bug The PR fixed a bug or issue reported a bug label Aug 21, 2023

Technoboy- added a commit that referenced this pull request Aug 21, 2023

[fix][client] Fix RawReader hasMessageAvailable returns true when no …

399e711

…messages (#21032)

Technoboy- added cherry-picked/branch-3.0 cherry-picked/branch-3.1 labels Aug 21, 2023

Technoboy- added a commit that referenced this pull request Aug 21, 2023

[fix][client] Fix RawReader hasMessageAvailable returns true when no …

d568606

…messages (#21032)

Technoboy- mentioned this pull request Aug 21, 2023

Flaky-test: MultiTopicsReaderTest.testReaderWithTimeLong #21002

Closed

2 tasks

shibd added cherry-picked/branch-2.11 and removed cherry-picked/branch-2.11 labels Oct 22, 2023

Technoboy- added a commit that referenced this pull request Oct 24, 2023

[fix][client] Fix RawReader hasMessageAvailable returns true when no …

c8abba8

…messages (#21032)

Technoboy- added the cherry-picked/branch-2.11 label Oct 24, 2023

lhotari added release/2.10.7 and removed release/2.10.6 labels Mar 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[fix][client] Fix RawReader hasMessageAvailable returns true when no messages #21032

[fix][client] Fix RawReader hasMessageAvailable returns true when no messages #21032

Technoboy- commented Aug 19, 2023 •

edited by Demogorgon314

Loading

codecov-commenter commented Aug 19, 2023 •

edited

Loading

zymap Aug 21, 2023 •

edited

Loading

zymap Aug 21, 2023 •

edited

Loading

shibd commented Oct 22, 2023

	if (!future.complete(messageAndCnx.msg)) {
	messageAndCnx.msg.close();
	closeAsync();
	}
	MessageIdData messageId = messageAndCnx.msg.getMessageIdData();
	lastDequeuedMessageId = new BatchMessageIdImpl(messageId.getLedgerId(), messageId.getEntryId(),
	messageId.getPartition(), numMsg - 1);

[fix][client] Fix RawReader hasMessageAvailable returns true when no messages #21032

[fix][client] Fix RawReader hasMessageAvailable returns true when no messages #21032

Conversation

Technoboy- commented Aug 19, 2023 • edited by Demogorgon314 Loading

Motivation

Documentation

codecov-commenter commented Aug 19, 2023 • edited Loading

Codecov Report

zymap Aug 21, 2023 • edited Loading

Choose a reason for hiding this comment

zymap Aug 21, 2023 • edited Loading

Choose a reason for hiding this comment

shibd commented Oct 22, 2023

Technoboy- commented Aug 19, 2023 •

edited by Demogorgon314

Loading

codecov-commenter commented Aug 19, 2023 •

edited

Loading

zymap Aug 21, 2023 •

edited

Loading

zymap Aug 21, 2023 •

edited

Loading