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 `(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,22 @@ 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/storage/init.lua

@@ -2800,7 +2800,7 @@ local function rebalancer_download_states()
             replicaset, 'vshard.storage.rebalancer_request_state', {},
             {timeout = consts.REBALANCER_GET_STATE_TIMEOUT})
         if state == nil then
-            return
+            return nil, replicaset.id
         end
         local bucket_count = state.bucket_active_count +
                              state.bucket_pinned_count
@@ -2815,7 +2815,7 @@ local function rebalancer_download_states()
     end
     local sum = total_bucket_active_count + total_bucket_locked_count
     if sum == M.total_bucket_count then
-        return replicasets, total_bucket_active_count
+        return total_bucket_active_count, replicasets
     else
         log.info('Total active bucket count is not equal to total. '..
                  'Possibly a boostrap is not finished yet. Expected %d, but '..
@@ -2839,18 +2839,19 @@ local function rebalancer_service_f(service)
         end
         service:set_activity('downloading states')
         lfiber.testcancel()
-        local status, replicasets, total_bucket_active_count =
+        local status, total_bucket_active_count, replicasets =
             pcall(rebalancer_download_states)
         if M.module_version ~= module_version then
             return
         end
-        if not status or replicasets == nil then
+        if not status or total_bucket_active_count == nil then
             if not status then
                 log.error(service:set_status_error(
                     'Error during downloading rebalancer states: %s',
                     replicasets))
             end
-            log.info('Some buckets are not active, retry rebalancing later')
+            log.info('Some buckets in replicaset %s are not active, retry ' ..
+                     'rebalancing later', replicasets)
             service:set_activity('idling')
             lfiber.testcancel()
             lfiber.sleep(consts.REBALANCER_WORK_INTERVAL)