rebalancer: add replicaset.id in "Some buckets are not active" log

Before this patch the function `rebalancer_download_states` didn't
return information about replicaset from which the states could not
be downloaded. As a result, the log "Some buckets are not active
..." lacks of valuable information about unhealthy replicaset.

Now, we return `(BUCKETS_NOT_IN_PROPER_STATE error with replicaset.
id, nil)` instead of `nil` in case when rebalancer can't download
state from this replicaset. Also we add replicaset.id in "Some
buckets are not active ..." log.

Also we change `rebalancer/rebalancer.test.lua` test which expected
the old "Some buckets are not active" log without replicaset.id.

Closes #212

NO_DOC=bugfix

Author: mrForza

test/rebalancer/rebalancer.result

@@ -318,7 +318,13 @@ _bucket:update({150}, {{'=', 2, vshard.consts.BUCKET.RECEIVING}})
 ---
 - [150, 'receiving']
 ...
-wait_rebalancer_state("Some buckets are not active", test_run)
+formatted_replicaset_uuid = string.gsub(util.replicasets[1], '%-', '%%-')
+---
+...
+log_msg = string.format('Some buckets in replicaset %s are not active', formatted_replicaset_uuid)
+---
+...
+wait_rebalancer_state(log_msg, test_run)
 ---
 ...
 _bucket:update({150}, {{'=', 2, vshard.consts.BUCKET.ACTIVE}})

test/rebalancer/rebalancer.test.lua

@@ -156,7 +156,9 @@ util.map_bucket_protection(test_run, {REPLICASET_1}, false)
 test_run:switch('box_1_a')
 vshard.storage.rebalancer_enable()
 _bucket:update({150}, {{'=', 2, vshard.consts.BUCKET.RECEIVING}})
-wait_rebalancer_state("Some buckets are not active", test_run)
+formatted_replicaset_uuid = string.gsub(util.replicasets[1], '%-', '%%-')
+log_msg = string.format('Some buckets in replicaset %s are not active', formatted_replicaset_uuid)
+wait_rebalancer_state(log_msg, test_run)
 _bucket:update({150}, {{'=', 2, vshard.consts.BUCKET.ACTIVE}})
 vshard.storage.sync()
 

test/storage-luatest/storage_1_1_1_test.lua

@@ -220,3 +220,20 @@ rebalancer_recovery_group.test_rebalancer_routes_logging = function(g)
         g.replica_1_a:grep_log('The cluster is balanced ok.')
     end)
 end
+
+rebalancer_recovery_group.test_no_log_spam_when_buckets_no_active = function(g)
+    local moved_bucket = vtest.storage_first_bucket(g.replica_2_a)
+    start_bucket_move(g.replica_1_a, g.replica_2_a, moved_bucket)
+    wait_for_bucket_is_transferred(g.replica_1_a, g.replica_2_a, moved_bucket)
+    vtest.storage_stop(g.replica_2_a)
+    local buckets_not_active = string.format('Some buckets in replicaset ' ..
+                                             '%s are not active',
+                                             g.replica_2_a:replicaset_uuid())
+    t.helpers.retrying({timeout = 60}, function()
+        g.replica_1_a:exec(function() ivshard.storage.rebalancer_wakeup() end)
+        t.assert(g.replica_1_a:grep_log(buckets_not_active))
+    end)
+    vtest.storage_start(g.replica_2_a, global_cfg)
+    start_bucket_move(g.replica_2_a, g.replica_1_a, moved_bucket)
+    wait_for_bucket_is_transferred(g.replica_2_a, g.replica_1_a, moved_bucket)
+end

vshard/error.lua

@@ -207,6 +207,11 @@ local error_message_template = {
         msg = 'Mismatch server name: expected "%s", but got "%s"',
         args = {'expected_name', 'actual_name'},
     },
+    [42] = {
+        name = 'BUCKETS_NOT_IN_PROPER_STATE',
+        msg = 'Replicaset %s doesn\'t have all buckets in proper state',
+        args = {'replicaset_id'}
+    }
 }
 
 --

vshard/storage/init.lua

@@ -2800,7 +2800,8 @@ local function rebalancer_download_states()
             replicaset, 'vshard.storage.rebalancer_request_state', {},
             {timeout = consts.REBALANCER_GET_STATE_TIMEOUT})
         if state == nil then
-            return
+            return lerror.vshard(lerror.code.BUCKETS_NOT_IN_PROPER_STATE,
+                                 replicaset.id), nil
         end
         local bucket_count = state.bucket_active_count +
                              state.bucket_pinned_count
@@ -2844,13 +2845,15 @@ local function rebalancer_service_f(service)
         if M.module_version ~= module_version then
             return
         end
-        if not status or replicasets == nil then
-            if not status then
+        if not status or total_bucket_active_count == nil then
+            local err = status and total_bucket_active_count or replicasets
+            if err then
                 log.error(service:set_status_error(
                     'Error during downloading rebalancer states: %s',
-                    replicasets))
+                    err.replicaset_id))
             end
-            log.info('Some buckets are not active, retry rebalancing later')
+            log.info('Some buckets in replicaset %s are not active, retry ' ..
+                     'rebalancing later', err and err.replicaset_id)
             service:set_activity('idling')
             lfiber.testcancel()
             lfiber.sleep(consts.REBALANCER_WORK_INTERVAL)