recovery: reduce spam in logs

Before this patch "Finish bucket recovery step ..." logs were printed at
the end of recovery even if no buckets were successfully recovered. It led
to unnecessary log records. This patch fixes the issue by adding an
additional check for the number of recovered buckets.

Closes #212

NO_DOC=bugfix

Author: mrForza

test/storage-luatest/storage_1_1_1_test.lua

@@ -41,6 +41,7 @@ local cfg_template = {
     },
     bucket_count = 15,
     replication_timeout = 0.1,
+    rebalancer_mode = 'auto',
 }
 local global_cfg
 
@@ -101,3 +102,91 @@ test_group.test_manual_bucket_send_doubled_buckets = function(g)
         ilt.assert_equals(box.space._bucket:get(bid), nil)
     end, {bid})
 end
+
+local rebalancer_recovery_group = t.group('rebalancer-recovery-logging')
+
+local function get_first_storage_bucket_id(storage)
+    return storage:exec(function()
+        return box.space._bucket:select()[1].id
+    end)
+end
+
+local function move_bucket(src_storage, dest_storage, bucket_id)
+    src_storage:exec(function(bucket_id, replicaset_id)
+        ivshard.storage.bucket_send(bucket_id, replicaset_id)
+    end, {bucket_id, dest_storage:replicaset_uuid()})
+
+    dest_storage:exec(function(bucket_id)
+        t.helpers.retrying({timeout = 10}, function()
+            t.assert(box.space._bucket:select(bucket_id))
+        end)
+    end, {bucket_id})
+end
+
+rebalancer_recovery_group.before_all(function(g)
+    global_cfg = vtest.config_new(cfg_template)
+    vtest.cluster_new(g, global_cfg)
+    g.router = vtest.router_new(g, 'router', global_cfg)
+    vtest.cluster_bootstrap(g, global_cfg)
+    vtest.cluster_wait_vclock_all(g)
+
+    local first_buckets = vtest.cluster_exec_each_master(g, function()
+        rawset(_G, 'create_test_space', function()
+            box.schema.create_space('test_space')
+            box.space.test_space:format({
+                {name = 'pk', type = 'unsigned'},
+                {name = 'bucket_id', type = 'unsigned'},
+            })
+            box.space.test_space:create_index('primary', {parts = {'pk'}})
+            box.space.test_space:create_index(
+                'bucket_id', {parts = {'bucket_id'}, unique = false})
+        end)
+        return _G.get_first_bucket()
+    end)
+    for _, bucket_id in pairs(first_buckets) do
+        g.router:exec(function(storage_bucket)
+            ivshard.router.call(storage_bucket, 'write', 'create_test_space')
+        end, {bucket_id})
+    end
+    g.buckets_not_active_log = 'Some buckets are not active'
+    g.buckets_not_active_pattern = "%d+-%d+-%d+ %d+:%d+:%d+.%d+ .* " ..
+                                   g.buckets_not_active_log
+    g.rebalancer_wait_interval = 0.01
+end)
+
+rebalancer_recovery_group.after_all(function(g)
+    g.cluster:drop()
+end)
+
+--
+-- Improve logging of rebalancer and recovery (gh-212).
+--
+rebalancer_recovery_group.test_no_logs_while_unsuccess_recovery = function(g)
+    g.replica_2_a:exec(function()
+        ivshard.storage.internal.errinj.ERRINJ_RECEIVE_PARTIALLY = true
+        rawset(_G, 'old_call', ivshard.storage._call)
+        ivshard.storage._call = function(service_name, ...)
+            if service_name == 'recovery_bucket_stat' then
+                return error('TimedOut')
+            end
+            return _G.old_call(service_name, ...)
+        end
+    end)
+    local hanged_bucket_id = get_first_storage_bucket_id(g.replica_1_a)
+    move_bucket(g.replica_1_a, g.replica_2_a, hanged_bucket_id)
+    t.helpers.retrying({}, function()
+        t.assert(g.replica_1_a:grep_log('Error during recovery of bucket 1'))
+    end)
+    t.assert_not(g.replica_1_a:grep_log('Finish bucket recovery step, 0'))
+    g.replica_2_a:exec(function()
+        ivshard.storage.internal.errinj.ERRINJ_RECEIVE_PARTIALLY = false
+        ivshard.storage._call = _G.old_call
+        ivshard.storage.recovery_wakeup()
+    end)
+    g.replica_1_a:exec(function(bucket_id)
+        t.helpers.retrying({}, function()
+            t.assert_equals(box.space._bucket:select(bucket_id)[1].status,
+                            'active')
+        end)
+    end, {hanged_bucket_id})
+end

vshard/storage/init.lua

@@ -1003,7 +1003,7 @@ local function recovery_step_by_type(type)
         is_step_empty = false
 ::continue::
     end
-    if not is_step_empty then
+    if not is_step_empty and recovered > 0 then
         log.info('Finish bucket recovery step, %d %s buckets are recovered '..
                  'among %d', recovered, type, total)
     end