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 entries. 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,125 @@ 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
+
+--
+-- The string should be strictly in format: YEAR-MONTH-DAY HOUR:MIN:SEC.MS
+--
+local function convert_string_to_datetime(str)
+    local date, time = string.match(str, "(%d+-%d+-%d+) (%d+:%d+:%d+.%d+)")
+    t.assert(date)
+    local year, month, day = string.match(date, "^(%d+)-(%d+)-(%d+)")
+    t.assert(year, "Unable to parse 'date' field of string")
+    local hour, min, sec, ms = string.match(time, "(%d+):(%d+):(%d+).(%d+)$")
+    t.assert(hour, "Unable to parse 'time' field of string")
+
+    return require("datetime").new{
+        year = tonumber(year), month = tonumber(month), day = tonumber(day),
+        hour = tonumber(hour), min = tonumber(min), sec = tonumber(sec),
+        nsec = tonumber(ms)}
+end
+
+local function test_only_one_record_appears_in_logs(server, record, wait_time)
+    local first_log_record = nil
+    t.helpers.retrying({}, function()
+        first_log_record = server:grep_log(record)
+        t.assert(first_log_record)
+    end)
+    local first_log_time = convert_string_to_datetime(first_log_record)
+    -- We need to wait a bit in order to catch how much as possible
+    -- spam in server's logs.
+    require("fiber").sleep(wait_time)
+    local last_log_record = server:grep_log(record)
+    t.assert(last_log_record)
+    local last_log_time = convert_string_to_datetime(last_log_record)
+    t.assert_equals(first_log_time, last_log_time,
+                    "There are two identical records in logs")
+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)
+
+    for _, storage in pairs({g.replica_1_a, g.replica_2_a, g.replica_3_a}) do
+        storage:exec(function()
+            rawset(_G, 'create_test_space', function()
+                box.schema.create_space('test_space')
+                box.space.test_space:format({
+                    {name = 'pk', type = 'uuid'},
+                    {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)
+        end)
+        g.router:exec(function(bucket_id)
+            ivshard.router.call(bucket_id, 'write', 'create_test_space')
+        end, {get_first_storage_bucket_id(storage)})
+    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