[K8S-543] rebalance status loop exits early and reports rebalance as incomplete - Couchbase database

XML

Word

Printable

Details

Type: Bug
Status: Closed
Priority: Critical
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.0.0
Component/s: operator
Labels:
None

Description

TestResizeClusterWithBucket

If a rebalance is attempted and the first attempt fails, it will be retried again. Once the rebalance successfully completes, only a rebalance incomplete event is seen. It would make more sense to report rebalance complete in the scenario and only report rebalance incomplete in scenarios where all retries have been exhausted. Otherwise, tests will fail like this:

Expected events to be:

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0000 added to cluster

    		Type: Normal | Reason: BucketCreated | Message: A new bucket `default` was created

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0001 added to cluster

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0002 added to cluster

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-mjwqv-0002 removed from the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-mjwqv-0001 removed from the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		but got:

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0000 added to cluster

    		Type: Normal | Reason: BucketCreated | Message: A new bucket `default` was created

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0001 added to cluster

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: NewMemberAdded | Message: New member test-couchbase-mjwqv-0002 added to cluster

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-mjwqv-0002 removed from the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceIncomplete | Message: A rebalance is incomplete

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-mjwqv-0001 removed from the cluster

This looks like rebalanced failed, but the cluster status before the events are checked is "balanced", ""healthy", and "ready".

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

cbinfo-default-test-couchbase-mjwqv-0000-20180815T170012-0700.zip
6.54 MB
16/Aug/18 10:11 PM
cbopinfo-20180815T170012-0700.tar.gz
29 kB
16/Aug/18 10:11 PM

Gerrit Reviews

- Issue Only
- Show All Reviews
- Show Open Reviews
- Show All Issues
- Show Open Issues

No reviews matched the request. Check your Options in the drop-down menu of this sections header.

Activity

Ascending order - Click to sort in descending order

Mike Wiederhold [X] (Inactive) added a comment - 16/Aug/18 10:11 PM

From looking at the logs this issue is caused by the rebalance status loop exiting early due to an error being returned by the server. In this case the logs show the following message while the rebalance status loop is running:

2018/08/15 23:59:06 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 400 Bad Request\r\nServer: MochiWeb/1.0 (Any of you quaids got a smint?)\r\nDate: Wed, 15 Aug 2018 23:59:06 GMT\r\nContent-Length: 0\r\n\r\n"; err=<nil>

The loop exits and then when we check to see if a rebalance is still needed ns_server report that it does because the rebalance is still in process.

time="2018-08-15T23:59:10Z" level=error msg="failed to reconcile: Failed to rebalance: cluster reports rebalance incomplete" cluster-name=test-couchbase-mjwqv module=cluster

The problem is that we need to do better error checking in the rebalance status loop. If the call to check the status fails we need to check another node. Even if all nodes fail we should still retry for a certain amount of time (maybe 60 seconds) before giving up. Below is a link the code that needs to be improved.

https://github.com/couchbase/gocbmgr/blob/master/api.go#L132

It should also be noted that it's possible that we may not be able to check the status for 60 seconds and in that case we should skip raising an event or raise an event for rebalance status unknown.

Mike Wiederhold [X] (Inactive) added a comment - 16/Aug/18 10:11 PM From looking at the logs this issue is caused by the rebalance status loop exiting early due to an error being returned by the server. In this case the logs show the following message while the rebalance status loop is running: 2018 / 08 / 15 23 : 59 : 06 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 400 Bad Request\r\nServer: MochiWeb/1.0 (Any of you quaids got a smint?)\r\nDate: Wed, 15 Aug 2018 23:59:06 GMT\r\nContent-Length: 0\r\n\r\n" ; err=<nil> The loop exits and then when we check to see if a rebalance is still needed ns_server report that it does because the rebalance is still in process. time= "2018-08-15T23:59:10Z" level=error msg= "failed to reconcile: Failed to rebalance: cluster reports rebalance incomplete" cluster-name=test-couchbase-mjwqv module=cluster The problem is that we need to do better error checking in the rebalance status loop. If the call to check the status fails we need to check another node. Even if all nodes fail we should still retry for a certain amount of time (maybe 60 seconds) before giving up. Below is a link the code that needs to be improved. https://github.com/couchbase/gocbmgr/blob/master/api.go#L132 It should also be noted that it's possible that we may not be able to check the status for 60 seconds and in that case we should skip raising an event or raise an event for rebalance status unknown.

Mike Wiederhold [X] (Inactive) added a comment - 19/Aug/18 10:03 PM

In order to get more information on this issue I've added a change to add debug logging to gocbmgr. Once this change gets merged we should be able to re-run the tests and then put a proper fix in for this issue.

http://review.couchbase.org/#/c/98485/

Mike Wiederhold [X] (Inactive) added a comment - 19/Aug/18 10:03 PM In order to get more information on this issue I've added a change to add debug logging to gocbmgr. Once this change gets merged we should be able to re-run the tests and then put a proper fix in for this issue. http://review.couchbase.org/#/c/98485/

Korrigan Clark added a comment - 23/Aug/18 9:14 AM

In the latest run we still see "rebalance is incomplete" event. This by itself is not an issue, the issue is that there is no terminating "rebalance completed" event for this particular rebalance. This it is impossible to wait for rebalance completion as it is never reported.

Search the console logs for "rebalance is incomplete": http://qa.sc.couchbase.com/view/Cloud/job/trigger-kubernetes-P0/461/consoleFull

Artifacts can be found here: http://qa.sc.couchbase.com/view/Cloud/job/trigger-kubernetes-P0/461/

Korrigan Clark added a comment - 23/Aug/18 9:14 AM In the latest run we still see "rebalance is incomplete" event. This by itself is not an issue, the issue is that there is no terminating "rebalance completed" event for this particular rebalance. This it is impossible to wait for rebalance completion as it is never reported. Search the console logs for "rebalance is incomplete": http://qa.sc.couchbase.com/view/Cloud/job/trigger-kubernetes-P0/461/consoleFull Artifacts can be found here: http://qa.sc.couchbase.com/view/Cloud/job/trigger-kubernetes-P0/461/

Korrigan Clark added a comment - 23/Aug/18 9:16 AM

Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceIncomplete | Message: A rebalance is incomplete

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-dg27k-0000 removed from the cluster

    		Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-dg27k-0001 removed from the cluster

    		Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster

    		Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed

From these events you can see 2 rebalances are started but only the last one if reported as complete

Korrigan Clark added a comment - 23/Aug/18 9:16 AM Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster Type: Normal | Reason: RebalanceIncomplete | Message: A rebalance is incomplete Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-dg27k- 0000 removed from the cluster Type: Normal | Reason: MemberRemoved | Message: Existing member test-couchbase-dg27k- 0001 removed from the cluster Type: Normal | Reason: RebalanceStarted | Message: A rebalance has been started to balance data across the cluster Type: Normal | Reason: RebalanceCompleted | Message: A rebalance has completed From these events you can see 2 rebalances are started but only the last one if reported as complete

Mike Wiederhold [X] (Inactive) added a comment - 23/Aug/18 11:17 AM

The behavior reported is expected. The rebalance did fail and as a result we exited out of the reconcile loop. Once the reconcile loop runs again nodes 0001 and 0000 and no longer part of the cluster because they were failed over and they get removed. We then see that the cluster is still not balances and start the rebalance again.

Mike Wiederhold [X] (Inactive) added a comment - 23/Aug/18 11:17 AM The behavior reported is expected. The rebalance did fail and as a result we exited out of the reconcile loop. Once the reconcile loop runs again nodes 0001 and 0000 and no longer part of the cluster because they were failed over and they get removed. We then see that the cluster is still not balances and start the rebalance again.

People

Assignee:: Mike Wiederhold [X] (Inactive)

Reporter:: Korrigan Clark

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 16/Aug/18 2:53 PM

Updated:: 23/Aug/18 1:11 PM

Resolved:: 23/Aug/18 11:17 AM

Gerrit Reviews

There are no open Gerrit changes

Show There are 4 closed Gerrit changes

Hide There are 4 closed Gerrit changes

K8S-543: Add debug level log messages for HTTP requests/responses: Gerrit Review:

K8S-543: Check to see if the rebalance status is stale or timed out: Gerrit Review:

K8S-543: Remove stale status check when checking the rebalance status: Gerrit Review:

K8S-543: Update gocbmgr to pick up rebalance status fixes: Gerrit Review:

PagerDuty

Couchbase Kubernetes

Details

Description

Attachments

Attachments

Gerrit Reviews

Activity

People

Dates

Gerrit Reviews

PagerDuty