Flaky python unit test test_publish_compact_and_consume

[merlimat]

Expected behavior

Seen failure at : https://builds.apache.org/job/pulsar_precommit_cpp/2951/console

======================================================================
FAIL: test_publish_compact_and_consume (__main__.PulsarTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "pulsar_test.py", line 557, in test_publish_compact_and_consume
    self.assertEqual(msg0.data(), b'hello-1')
AssertionError: 'hello-0' != 'hello-1'

----------------------------------------------------------------------

2018-08-06 22:34:41.901 INFO  HandlerBase:53 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-producer-name] Getting connection from pool
2018-08-06 22:34:42.058 INFO  ProducerImpl:154 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-producer-name] Created producer on broker [127.0.0.1:55834 -> 127.0.0.1:8885] 
2018-08-06 22:34:42.060 INFO  HandlerBase:53 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub1, 0] Getting connection from pool
2018-08-06 22:34:42.133 INFO  ConsumerImpl:168 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub1, 0] Created consumer on broker [127.0.0.1:55834 -> 127.0.0.1:8885] 
2018-08-06 22:34:42.134 INFO  ConsumerImpl:761 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub1, 0] Closed consumer 0
2018-08-06 22:34:42.135 INFO  HandlerBase:53 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub2, 1] Getting connection from pool
2018-08-06 22:34:42.207 INFO  ConsumerImpl:168 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub2, 1] Created consumer on broker [127.0.0.1:55834 -> 127.0.0.1:8885] 
2018-08-06 22:34:42.265 INFO  ProducerImpl:466 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-producer-name] Closed producer
Compact still running
{"status":"RUNNING","lastError":""}
Compact still running
{"status":"RUNNING","lastError":""}
Compact Complete now
{"status":"SUCCESS","lastError":""}
2018-08-06 22:34:42.817 INFO  HandlerBase:53 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub1, 2] Getting connection from pool
2018-08-06 22:34:42.818 INFO  ConsumerImpl:168 | [persistent://sample/standalone/ns1/my-python-test_publish_compact_and_consume, my-sub1, 2] Created consumer on broker [127.0.0.1:55834 -> 127.0.0.1:8885] 

[merlimat]

Still happening in https://builds.apache.org/job/pulsar_precommit_cpp/5783/console

[merlimat]

Tried to run 100s of times in a loop within a Docker container on mac laptop and was not able to reproduce so far..

[ivankelly]

For the record I only managed one natural repro of this (with stress-ng --aggressive --class scheduler --all 5). It appears to be a very narrow race. It can be widened by changing the thenAccept to thenAcceptAsync at

pulsar/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/persistent/CompactorSubscription.java

Line 99 in 13ea25a

future.thenAccept((v) -> compactedTopic.newCompactedLedger(position, compactedLedgerId));

, and then putting a sleep in the callback.