KAFKA-8620: fix NPE due to race condition during shutdown while rebalancing by abbccdda · Pull Request #7021 · apache/kafka

abbccdda · 2019-07-01T22:19:12Z

We have detected a race condition under system test failure. The problem was that the task manager internal active tasks should be guarded against state changes on the stream thread. Could definitely consider other fixes but this is currently the make-sense one.

Committer Checklist (excluded from commit message)

Verify design and implementation
Verify test coverage and CI build status
Verify documentation (including upgrade notes)

abbccdda · 2019-07-08T18:28:19Z

@mjsax @guozhangwang @ableegoldman @cadonna @bbejeck @vvcephei Call for review

mjsax · 2019-07-09T00:57:20Z

                return null;
            } else if (state == State.PARTITIONS_REVOKED && newState == State.PARTITIONS_REVOKED) {
+                log.debug("Invalid transition from PARTITIONS_REVOKED to PARTITIONS_REVOKED: " +
+                              "self transition is not allowed");


Thinking about this, I am wondering if we should just change the FSM to allow this transition and simplify the code here? \cc @guozhangwang

I thought about this when tightening the FSM before but the unit tests reminds me of one thing: our current contract is that we only transit to PARTITIONS_REVOKED when calling onPartitionsRevoked, which is called only once at the beginning of the rebalance today, so keeping it strict is better just in case we have incorrect partial rebalance procedure.

With KIP-429 this may be violated so we need to revisit our FSM once Streams adopt cooperative protocols. cc @ableegoldman who's working on this.

mjsax · 2019-07-09T01:02:11Z

-                    return;
-                }
-                if (streamThread.assignmentErrorCode.get() == StreamsPartitionAssignor.Error.NONE.code()) {
+                    log.error("State transition from {} to PARTITIONS_ASSIGNED failed. " +


Why is this an ERROR? If we receive a SHUTDOWN signal, it's just an "eager exit" to not create tasks IMHO. We might want to log a DEBUG though.

Would also update the message:

log.debug("Skipping task creation in rebalance because we are already in shutdown phase.");

Sounds good to me.

mjsax · 2019-07-09T01:37:24Z

        setState(State.PENDING_SHUTDOWN);

-        log.info("Shutting down");
+        log.info("Shutting down with cleanRun {}", cleanRun);


Not sure if we need this? If the shutdown is not clean, we logged an ERROR before in StreamThread#run()

I would not use variable names in log messages.

I could avoid using variable name in the log, but still feel needed to log the flag here, as we can't control future changes to set cleanRun flag.

mjsax · 2019-07-09T01:38:52Z

+
+        // assign single partition
+        assignedPartitions.add(t1p1);
+        assignedPartitions.add(t1p2);


Why do we need two partitions?

mjsax · 2019-07-09T01:43:05Z

+        beginOffsets.put(t1p2, 0L);
+        mockConsumer.updateBeginningOffsets(beginOffsets);
+
+        final Thread callbackThread = new Thread(() -> {


Why do we need a Thread here?

We need a separate thread to trigger callbacks, otherwise the state won't proceed. Maybe there is a better way to do that?

Can you elaborate? What do you mean by

otherwise the state won't proceed

cadonna

@abbccdda, Thank you for the PR.

cadonna · 2019-07-09T09:11:49Z

-                if (streamThread.assignmentErrorCode.get() == StreamsPartitionAssignor.Error.NONE.code()) {
+                    log.error("State transition from {} to PARTITIONS_ASSIGNED failed. " +
+                                  "Will skip the task initialization", streamThread.state());
+                } else if (streamThread.assignmentErrorCode.get() != StreamsPartitionAssignor.Error.NONE.code()) {


Isn't this a rather brittle fix? How does this code guarantee that after streamThread.assignmentErrorCode.get() != StreamsPartitionAssignor.Error.NONE.code() is false, the result of streamThread.assignmentErrorCode.get() does not change again before the tasks are created?

in PartitionsAssigned we should have already passed the assignment error placement, so I won't expect another flip for its value during this round rebalance.

Makes sense

cadonna · 2019-07-09T09:18:56Z

        setState(State.PENDING_SHUTDOWN);

-        log.info("Shutting down");
+        log.info("Shutting down with cleanRun {}", cleanRun);


I would not use variable names in log messages.

vvcephei

LGTM. Just one minor suggestion.

…consumer

cadonna

LGTM
@mjsax, What is so bad about using a mock for the task manager?

cadonna · 2019-07-09T21:25:21Z

-                if (streamThread.assignmentErrorCode.get() == StreamsPartitionAssignor.Error.NONE.code()) {
+                    log.error("State transition from {} to PARTITIONS_ASSIGNED failed. " +
+                                  "Will skip the task initialization", streamThread.state());
+                } else if (streamThread.assignmentErrorCode.get() != StreamsPartitionAssignor.Error.NONE.code()) {


Makes sense

cadonna · 2019-07-10T09:31:40Z

    }

+    @Test
+    public void shouldNotAccessTaskManagerWhenPendingShutdownInRunOnce() {


I would give this test a more meaningful name, e.g. shouldNotThrowWhenPendingShutdownInRunOnce.

cadonna · 2019-07-10T09:37:19Z

+    }
+
+    @Test
+    public void shouldHaveNoErrorAccessTaskManagerInRunOnceNoShutdown() {


Same as above, e.g. shouldNotThrowWithoutPendingShutdownInRunOnce

cadonna · 2019-07-10T09:42:08Z

-                    return;
-                }
-                if (streamThread.assignmentErrorCode.get() == StreamsPartitionAssignor.Error.NONE.code()) {
+                    log.debug("Skipping task creation in rebalance because we are already in {} state.",


Shouldn't the indentation be as follows?

log.debug( "Skipping task creation in rebalance because we are already in {} state.", streamThread.state() );

cadonna · 2019-07-10T09:45:20Z

+                              streamThread.state());
+                } else if (streamThread.assignmentErrorCode.get() != StreamsPartitionAssignor.Error.NONE.code()) {
+                    log.debug("Encountered assignment error during partition assignment: {}. " +
+                                  "Will skip the task initialization", streamThread.assignmentErrorCode);


Shouldn't the indentation be as follows?

log.debug( "Encountered assignment error during partition assignment: {}. Will skip the task initialization", streamThread.assignmentErrorCode );

The first parameter is one or two characters too long, though.

cadonna · 2019-07-10T10:10:27Z

Retest this, please

abbccdda · 2019-07-10T15:28:56Z

@cadonna Thank you for the review, addressed!

mjsax · 2019-07-10T16:19:14Z

@cadonna The bug is, that if we don't create tasks on the TaskManager and when we later try to receive tasks from it, we hit an NPE. Hence, the TaskManager is on the test code path -- mocking it seems to make the test weak IMHO.

abbccdda · 2019-07-10T19:09:04Z

Retest this please

cadonna · 2019-07-10T19:46:14Z

@mjsax I do not agree. The TaskManager is on the test code path, but it does not need to be tested. A unit test should test the class under test which is StreamThread in this case and avoid as much as possible testing other classes. With a TaskManager mock, you could easily verify if the calls to the TaskManager that would result in a NullPointerException are done or not. In addition, with a TaskManager mock the tests would also better document what the productive code is supposed to do because you have to specify it explicitly on the mock.

mjsax · 2019-07-10T20:57:59Z

@cadonna Maybe. Do you want that we switch back to a mock? If yes, please let @abbccdda know. If not, please let me know so the PR can be merged. Your call.

abbccdda · 2019-07-10T22:42:30Z

Retest this please

abbccdda · 2019-07-10T23:55:34Z

@cadonna @mjsax My take is that the purpose of mocking taskManager is to create a conditional behavior path: if you set an active task, you could retrieve it later; if you don't, you will get NPE, while the setup of real taskManger is too much compared with a mock. Actually in our case, the mock examples in other tests doesn't quite fit to implement this mentioned conditional logic, and the task manager setup is not bad either. So we should be fine just creating a new client in this case.

ijuma · 2019-07-11T03:07:53Z

Reopening to trigger Jenkins build.

cadonna · 2019-07-11T10:32:35Z

@abbccdda: What you describe is also a valid use case of a mock, but it only achieves the isolation of the class under test. It does not document well the expected behaviour of productive code. Furthermore, IMO conditional behaviour in a mock should be avoided if possible, because it introduces code that needs maintenance and could be wrong. A mock should be as simple as possible. Admittedly, in this case the code would probably not be that complex, but if it could be avoided, I would avoid it.

@mjsax @abbccdda: I do not want to block this fix further. The test seems to be correct. My concern is about clean and maintainable code. Up to you to follow my reasoning or not.

bbejeck · 2019-07-11T13:59:09Z

retest this please

bbejeck · 2019-07-11T14:45:02Z

retest this please

bbejeck · 2019-07-11T15:49:00Z

retest this please

abbccdda · 2019-07-11T19:02:38Z

Checked log and the single test failure was in RebalanceSourceConnectorsIntegrationTest in Connect, not related

bbejeck · 2019-07-11T19:51:47Z

retest this please

abbccdda · 2019-07-12T01:44:42Z

retest this please

abbccdda · 2019-07-12T08:10:36Z

retest this please

bbejeck · 2019-07-12T14:51:02Z

failures unrelated
retest this please

abbccdda · 2019-07-12T18:14:06Z

All flaky tests:
ExampleConnectIntegrationTest > testSourceConnector

abbccdda · 2019-07-12T18:14:44Z

retest this please

abbccdda · 2019-07-13T03:16:27Z

@mjsax @bbejeck I have witnessed 4 times 2/3 green builds, and all failures are flaky tests including this time: ExampleConnectIntegrationTest.testSourceConnector
I personally don't think there is any further meaning to trigger another jenkins build, but you will make the call.

…ancing (#7021) Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io>

guozhangwang · 2019-07-15T22:10:30Z

                return null;
            } else if (state == State.PARTITIONS_REVOKED && newState == State.PARTITIONS_REVOKED) {
+                log.debug("Invalid transition from PARTITIONS_REVOKED to PARTITIONS_REVOKED: " +
+                              "self transition is not allowed");


I thought about this when tightening the FSM before but the unit tests reminds me of one thing: our current contract is that we only transit to PARTITIONS_REVOKED when calling onPartitionsRevoked, which is called only once at the beginning of the rebalance today, so keeping it strict is better just in case we have incorrect partial rebalance procedure.

With KIP-429 this may be violated so we need to revisit our FSM once Streams adopt cooperative protocols. cc @ableegoldman who's working on this.

guozhangwang · 2019-07-15T22:12:03Z

-                        "will abort the current process and re-throw at the end of rebalance: {}",
-                    t
-                );
+                        "will abort the current process and re-throw at the end of rebalance", t);


Nice catch.

…ancing (#7021) Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io>

mjsax · 2019-07-15T23:13:35Z

Merged to trunk and cherry-picked to 2.3, 2.2, and 2.1 branches.

* apache-github/2.3: MINOR: Update documentation for enabling optimizations (apache#7099) MINOR: Remove stale streams producer retry default docs. (apache#6844) KAFKA-8635; Skip client poll in Sender loop when no request is sent (apache#7085) KAFKA-8615: Change to track partition time breaks TimestampExtractor (apache#7054) KAFKA-8670; Fix exception for kafka-topics.sh --describe without --topic mentioned (apache#7094) KAFKA-8602: Separate PR for 2.3 branch (apache#7092) KAFKA-8530; Check for topic authorization errors in OffsetFetch response (apache#6928) KAFKA-8662; Fix producer metadata error handling and consumer manual assignment (apache#7086) KAFKA-8637: WriteBatch objects leak off-heap memory (apache#7050) KAFKA-8620: fix NPE due to race condition during shutdown while rebalancing (apache#7021) HOT FIX: close RocksDB objects in correct order (apache#7076) KAFKA-7157: Fix handling of nulls in TimestampConverter (apache#7070) KAFKA-6605: Fix NPE in Flatten when optional Struct is null (apache#5705) Fixes apache#8198 KStreams testing docs use non-existent method pipe (apache#6678) KAFKA-5998: fix checkpointableOffsets handling (apache#7030) KAFKA-8653; Default rebalance timeout to session timeout for JoinGroup v0 (apache#7072) KAFKA-8591; WorkerConfigTransformer NPE on connector configuration reloading (apache#6991) MINOR: add upgrade text (apache#7013) Bump version to 2.3.1-SNAPSHOT

…during shutdown while rebalancing (apache#7021) TICKET = KAFKA-8620 LI_DESCRIPTION = EXIT_CRITERIA = HASH [0f0093c] ORIGINAL_DESCRIPTION = Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io> (cherry picked from commit 0f0093c)

mjsax added the streams label Jul 2, 2019

fix the state after poll request

c6a5997

abbccdda force-pushed the system_test_fix branch from 1cb82e5 to c6a5997 Compare July 3, 2019 02:44

abbccdda added 2 commits July 3, 2019 11:49

add unit test

1337616

trying to find a way to pass assignment in

d5b7b5c

abbccdda force-pushed the system_test_fix branch from 95c29b0 to 09e0cc5 Compare July 7, 2019 20:45

abbccdda force-pushed the system_test_fix branch from 09e0cc5 to 3ce0a54 Compare July 8, 2019 23:41

minor fix

b2326b4

abbccdda force-pushed the system_test_fix branch from 3ce0a54 to b2326b4 Compare July 8, 2019 23:42

mjsax changed the title ~~KAFKA-8620: fix stream task concurrent access issue~~ KAFKA-8620: fix NPE due to race condition during shutdown while rebalancing Jul 9, 2019

mjsax reviewed Jul 9, 2019

View reviewed changes

cadonna reviewed Jul 9, 2019

View reviewed changes

address comments

58b7ce3

abbccdda force-pushed the system_test_fix branch from 5c40cc2 to 4a9ce55 Compare July 9, 2019 19:40

success reproduce

9c13d42

abbccdda force-pushed the system_test_fix branch from 4a9ce55 to 9c13d42 Compare July 9, 2019 20:00

vvcephei approved these changes Jul 9, 2019

View reviewed changes

Comment thread streams/src/main/java/org/apache/kafka/streams/processor/internals/StreamThread.java Outdated

address minor suggestion

f1b1002

mjsax reviewed Jul 9, 2019

View reviewed changes

abbccdda added 2 commits July 9, 2019 15:15

avoid info exposure of internal implementation

eb490a9

address comments by initializing real task manager and one-time mock …

a99606b

…consumer

abbccdda force-pushed the system_test_fix branch from a09a388 to a99606b Compare July 10, 2019 02:33

cadonna reviewed Jul 10, 2019

View reviewed changes

cadonna approved these changes Jul 10, 2019

View reviewed changes

address Bruno's comment

5c6ec62

mjsax approved these changes Jul 10, 2019

View reviewed changes

ijuma closed this Jul 11, 2019

ijuma reopened this Jul 11, 2019

mjsax merged commit 3e48bdb into apache:trunk Jul 15, 2019

mjsax pushed a commit that referenced this pull request Jul 15, 2019

KAFKA-8620: fix NPE due to race condition during shutdown while rebal…

0f0093c

…ancing (#7021) Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io>

mjsax pushed a commit that referenced this pull request Jul 15, 2019

KAFKA-8620: fix NPE due to race condition during shutdown while rebal…

71f6f57

…ancing (#7021) Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io>

guozhangwang approved these changes Jul 15, 2019

View reviewed changes

mjsax pushed a commit that referenced this pull request Jul 15, 2019

KAFKA-8620: fix NPE due to race condition during shutdown while rebal…

8fb9eb8

…ancing (#7021) Reviewers: Matthias J. Sax <matthias@confluent.io>, Bruno Cadonna <bruno@confluent.io>, John Roesler <john@confluent.io>

Uh oh!

Conversation

abbccdda commented Jul 1, 2019

Committer Checklist (excluded from commit message)

Uh oh!

abbccdda commented Jul 8, 2019

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

cadonna left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vvcephei left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

cadonna left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cadonna commented Jul 10, 2019

Uh oh!

abbccdda commented Jul 10, 2019

Uh oh!

mjsax commented Jul 10, 2019

Uh oh!

abbccdda commented Jul 10, 2019

Uh oh!

cadonna commented Jul 10, 2019

Uh oh!

mjsax commented Jul 10, 2019

Uh oh!

abbccdda commented Jul 10, 2019

cadonna commented Jul 11, 2019 •

edited

Loading