[PATCH ha-manager v2 04/14] fix #8059: manager: auto rebalance: do not retry failed rebalance motions right away

[Michael Ryom <Michael@RyomHerold.dk>]

The automatic load balancer only refrains from issuing new motions while
a migrate/relocate is queued or running. It never records the outcome of
a motion it issued. If the motion fails (e.g. because the guest has a
local CD-ROM image attached), the resource returns to 'started' on its
source node, and the very same motion is selected again as soon as the
imbalance has exceeded the threshold for the hold duration again. In
practice, this resulted in an endless loop of failing migrations about
every 40 seconds with the default hold duration.

Record the result of each resource motion issued by load_balance() when
the LRM reports it in next_state_migrate_relocate(). This also covers
the dependent resources of a resource bundle, which are moved together
with the bundle's leader, so a failure is recorded for the resource that
actually failed and is not lost if the bundle's leader changes.

Failed motions are handled per rebalancing attempt. An attempt starts
when the imbalance has exceeded the threshold for the hold duration and
is concluded when a rebalance motion succeeds, when there is no
rebalance motion left to try, or when the imbalance drops below the
threshold again:

- a failed motion is not tried again in the same rebalancing attempt,
  so the next best motion is tried instead;

- in the following attempt, it is considered again, since the cause of
  the failure might have been temporary;

- if it fails again, it is skipped in exponentially more of the
  following attempts (2, 4, 8, ..., at most 32), as the cause is likely
  not temporary.

Counting attempts instead of time avoids that two failing motions of the
same resource to different nodes take turns, because the time-based
backoff of one of them has just expired when the other one fails, before
the next best motion is ever tried.

Like sustained_imbalance_round, this state is not persisted across a
CRM failover.

The expected logs of the test cases added in the previous patch change
accordingly:

- test-crs-dynamic-auto-rebalance5: after the relocations of fa:109 to
  node2 and node3 failed, vm:102 is migrated instead; when the imbalance
  is still too high afterwards, fa:109 is tried once more in the next
  attempt, fails again, and vm:103 is migrated instead.

- test-crs-dynamic-auto-rebalance6: the only possible motion is retried
  less and less often (at 80, 220, 480, 860 and 1480 seconds) instead of
  every 80 seconds.

Signed-off-by: Michael Ryom <Michael@RyomHerold.dk>
---
 src/PVE/HA/Manager.pm                         | 130 ++++++++++++++++++
 .../log.expect                                |  67 +++++----
 .../log.expect                                |  90 ++++--------
 3 files changed, 191 insertions(+), 96 deletions(-)

diff --git a/src/PVE/HA/Manager.pm b/src/PVE/HA/Manager.pm
index e05f0a4..18ad12f 100644
--- a/src/PVE/HA/Manager.pm
+++ b/src/PVE/HA/Manager.pm
@@ -72,6 +72,26 @@ sub new {
         # this is not persisted for a CRM failover as in the mean time
         # the usage statistics might have change quite a bit already
         sustained_imbalance_round => 0,
+        # outcome tracking of the resource motions issued by load_balance()
+        #
+        # like sustained_imbalance_round, this is not persisted for a CRM
+        # failover
+        auto_rebalance_state => {
+            # number of rebalancing attempts so far; an attempt starts when the
+            # imbalance has exceeded the threshold for the hold duration and is
+            # concluded when a rebalance motion succeeds, when there is no
+            # rebalance motion left to try or when the imbalance drops below
+            # the threshold again
+            attempt => 0,
+            attempt_ongoing => 0,
+            # $sid => { target => $node, task => $task } for issued motions,
+            # which have not finished yet
+            issued => {},
+            # "$sid:$target" => { count => $count, attempt => $attempt } for
+            # rebalance motions which failed $count times in a row, the last
+            # time in rebalancing attempt $attempt
+            failures => {},
+        },
         group_migration_round => 3, # wait a little bit
     }, $class;
 
@@ -187,6 +207,76 @@ sub get_active_stationary_movable_resource_bundles {
     return $resource_bundles;
 }
 
+# Upper bound for the number of rebalancing attempts, in which a rebalance motion
+# that failed repeatedly is skipped.
+my $auto_rebalance_max_skipped_attempts = 32;
+
+# Returns the number of rebalancing attempts following the last failure, in
+# which a rebalance motion that failed $count times in a row is skipped.
+my sub skipped_rebalance_attempts {
+    my ($count) = @_;
+
+    return 0 if $count <= 1;
+
+    my $skipped_attempts = 2**($count - 1);
+
+    return $skipped_attempts < $auto_rebalance_max_skipped_attempts
+        ? $skipped_attempts
+        : $auto_rebalance_max_skipped_attempts;
+}
+
+# Returns whether the motion of $sid to $target is not to be considered in the
+# current rebalancing attempt, because it failed before.
+#
+# A failed motion is never retried in the same rebalancing attempt, so that the
+# next best motion is tried instead. If it fails again in a later attempt, it is
+# skipped for exponentially more of the following attempts, as it might not be
+# a temporary issue that caused the failure.
+my sub is_rebalance_motion_backed_off {
+    my ($self, $sid, $target) = @_;
+
+    my $state = $self->{auto_rebalance_state};
+    my $failure = $state->{failures}->{"$sid:$target"} or return 0;
+
+    my $skipped_attempts = skipped_rebalance_attempts($failure->{count});
+
+    return $state->{attempt} <= $failure->{attempt} + $skipped_attempts;
+}
+
+# Records the result of a resource motion, if it was issued by load_balance().
+sub record_rebalance_motion_result {
+    my ($self, $sid, $target, $success) = @_;
+
+    my $state = $self->{auto_rebalance_state};
+
+    my $issued = $state->{issued}->{$sid};
+    return if !$issued || $issued->{target} ne $target;
+
+    delete $state->{issued}->{$sid};
+
+    my $key = "$sid:$target";
+
+    if ($success) {
+        delete $state->{failures}->{$key};
+        $state->{attempt_ongoing} = 0;
+        return;
+    }
+
+    my $failure = $state->{failures}->{$key} //= { count => 0 };
+    $failure->{count}++;
+    $failure->{attempt} = $state->{attempt};
+
+    my $msg = "auto rebalance - $issued->{task} $sid to $target failed";
+    if ($failure->{count} == 1) {
+        $msg .= ", not trying it again in this rebalancing attempt";
+    } else {
+        my $skipped_attempts = skipped_rebalance_attempts($failure->{count});
+        $msg .= " $failure->{count} times in a row, not trying it again in this"
+            . " and the next $skipped_attempts rebalancing attempts";
+    }
+    $self->{haenv}->log('warning', $msg);
+}
+
 # Returns a hash of hashes, where each item contains the resource bundle's
 # leader, the list of HA resources in the resource bundle, and the list of
 # possible nodes to migrate to.
@@ -213,6 +303,14 @@ sub get_resource_migration_candidates {
 
         delete $target_nodes->{$current_leader_node};
 
+        for my $node (keys %$target_nodes) {
+            for my $sid ($resource_bundles->{$leader_sid}->@*) {
+                next if !is_rebalance_motion_backed_off($self, $sid, $node);
+                delete $target_nodes->{$node};
+                last;
+            }
+        }
+
         next if !%$target_nodes;
 
         push @compact_migration_candidates,
@@ -234,6 +332,15 @@ sub load_balance {
 
     return if !$auto_rebalance_opts->{enable};
     return if $crs->{scheduler} ne 'static' && $crs->{scheduler} ne 'dynamic';
+
+    my $state = $self->{auto_rebalance_state};
+
+    # forget issued motions which were dropped before they were carried out
+    for my $sid (keys $state->{issued}->%*) {
+        delete $state->{issued}->{$sid}
+            if !defined($self->{ss}->{$sid}) || !$self->is_resource_motion_queued_or_running($sid);
+    }
+
     return if $self->any_resource_motion_queued_or_running();
 
     my ($threshold, $method, $hold_duration, $margin) =
@@ -257,6 +364,7 @@ sub load_balance {
     # the <= relation prevents load balancing from triggering for $imbalance = 0.0
     if ($imbalance <= $threshold) {
         $self->{sustained_imbalance_round} = 0;
+        $state->{attempt_ongoing} = 0;
         return;
     } else {
         $self->{sustained_imbalance_round}++;
@@ -264,6 +372,14 @@ sub load_balance {
         $self->{sustained_imbalance_round} = 0;
     }
 
+    if (!$state->{attempt_ongoing}) {
+        $state->{attempt}++;
+        $state->{attempt_ongoing} = 1;
+    }
+
+    # concluded unless a rebalance motion is issued below
+    $state->{attempt_ongoing} = 0;
+
     my $candidates = $self->get_resource_migration_candidates();
 
     my $result;
@@ -295,6 +411,18 @@ sub load_balance {
     $haenv->log('info', "auto rebalance - $task $sid to $target ($imbalance_change_str)");
 
     $self->queue_resource_motion($cmd, $task, $sid, $target);
+
+    # queue_resource_motion() refuses to queue the motion if there are blocking
+    # resources on the target node
+    return if !$self->is_resource_motion_queued_or_running($sid);
+
+    $state->{attempt_ongoing} = 1;
+
+    # the whole resource bundle is moved together with its leader $sid
+    my ($candidate) = grep { $_->{leader} eq $sid } @$candidates;
+    for my $csid ($candidate ? $candidate->{resources}->@* : ($sid)) {
+        $state->{issued}->{$csid} = { target => $target, task => $task };
+    }
 }
 
 sub cleanup {
@@ -1269,6 +1397,7 @@ sub next_state_migrate_relocate {
         my $exit_code = $lrm_res->{exit_code};
         my $req_state = $cd->{state} eq 'started' ? 'started' : 'request_stop';
         if ($exit_code == SUCCESS) {
+            $self->record_rebalance_motion_result($sid, $sd->{target}, 1);
             &$change_service_state($self, $sid, $req_state, node => $sd->{target});
             return;
         } elsif ($exit_code == EWRONG_NODE) {
@@ -1285,6 +1414,7 @@ sub next_state_migrate_relocate {
             $change_service_state->($self, $sid, $req_state, node => $sd->{node});
         } else {
             $haenv->log('err', "service '$sid' - migration failed (exit code $exit_code)");
+            $self->record_rebalance_motion_result($sid, $sd->{target}, 0);
             &$change_service_state($self, $sid, $req_state, node => $sd->{node});
             return;
         }
diff --git a/src/test/test-crs-dynamic-auto-rebalance5/log.expect b/src/test/test-crs-dynamic-auto-rebalance5/log.expect
index a5dad5a..bc80ea1 100644
--- a/src/test/test-crs-dynamic-auto-rebalance5/log.expect
+++ b/src/test/test-crs-dynamic-auto-rebalance5/log.expect
@@ -42,47 +42,42 @@ err      81    node1/lrm: service fa:109 not moved (migration error)
 info     83    node2/lrm: got lock 'ha_agent_node2_lock'
 info     83    node2/lrm: status change wait_for_agent_lock => active
 err     100    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    100    node1/crm: auto rebalance - relocate fa:109 to node2 failed, not trying it again in this rebalancing attempt
 info    100    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    160    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    160    node1/crm: got crm command: relocate fa:109 node2
-info    160    node1/crm: relocate service 'fa:109' to node 'node2'
-info    160    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
+info    160    node1/crm: auto rebalance - relocate fa:109 to node3 (expected change for imbalance from 100.0% to 66.1%)
+info    160    node1/crm: got crm command: relocate fa:109 node3
+info    160    node1/crm: relocate service 'fa:109' to node 'node3'
+info    160    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node3)
 err     161    node1/lrm: service fa:109 not moved (migration error)
+info    165    node3/lrm: got lock 'ha_agent_node3_lock'
+info    165    node3/lrm: status change wait_for_agent_lock => active
 err     180    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    180    node1/crm: auto rebalance - relocate fa:109 to node3 failed, not trying it again in this rebalancing attempt
 info    180    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    240    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    240    node1/crm: got crm command: relocate fa:109 node2
-info    240    node1/crm: relocate service 'fa:109' to node 'node2'
-info    240    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     241    node1/lrm: service fa:109 not moved (migration error)
-err     260    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    260    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    320    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    320    node1/crm: got crm command: relocate fa:109 node2
-info    320    node1/crm: relocate service 'fa:109' to node 'node2'
-info    320    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
+info    240    node1/crm: auto rebalance - migrate vm:102 to node2 (expected change for imbalance from 100.0% to 66.1%)
+info    240    node1/crm: got crm command: migrate vm:102 node2
+info    240    node1/crm: migrate service 'vm:102' to node 'node2'
+info    240    node1/crm: service 'vm:102': state changed from 'started' to 'migrate'  (node = node1, target = node2)
+info    241    node1/lrm: service vm:102 - start migrate to node 'node2'
+info    241    node1/lrm: service vm:102 - end migrate to node 'node2'
+info    260    node1/crm: service 'vm:102': state changed from 'migrate' to 'started'  (node = node2)
+info    263    node2/lrm: starting service vm:102
+info    263    node2/lrm: service status vm:102 started
+info    320    node1/crm: auto rebalance - relocate fa:109 to node3 (expected change for imbalance from 66.1% to 25.0%)
+info    320    node1/crm: got crm command: relocate fa:109 node3
+info    320    node1/crm: relocate service 'fa:109' to node 'node3'
+info    320    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node3)
 err     321    node1/lrm: service fa:109 not moved (migration error)
 err     340    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    340    node1/crm: auto rebalance - relocate fa:109 to node3 failed 2 times in a row, not trying it again in this and the next 2 rebalancing attempts
 info    340    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    400    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    400    node1/crm: got crm command: relocate fa:109 node2
-info    400    node1/crm: relocate service 'fa:109' to node 'node2'
-info    400    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     401    node1/lrm: service fa:109 not moved (migration error)
-err     420    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    420    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    480    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    480    node1/crm: got crm command: relocate fa:109 node2
-info    480    node1/crm: relocate service 'fa:109' to node 'node2'
-info    480    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     481    node1/lrm: service fa:109 not moved (migration error)
-err     500    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    500    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    560    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 66.1%)
-info    560    node1/crm: got crm command: relocate fa:109 node2
-info    560    node1/crm: relocate service 'fa:109' to node 'node2'
-info    560    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     561    node1/lrm: service fa:109 not moved (migration error)
-err     580    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    580    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
+info    400    node1/crm: auto rebalance - migrate vm:103 to node3 (expected change for imbalance from 66.1% to 25.0%)
+info    400    node1/crm: got crm command: migrate vm:103 node3
+info    400    node1/crm: migrate service 'vm:103' to node 'node3'
+info    400    node1/crm: service 'vm:103': state changed from 'started' to 'migrate'  (node = node1, target = node3)
+info    401    node1/lrm: service vm:103 - start migrate to node 'node3'
+info    401    node1/lrm: service vm:103 - end migrate to node 'node3'
+info    420    node1/crm: service 'vm:103': state changed from 'migrate' to 'started'  (node = node3)
+info    425    node3/lrm: starting service vm:103
+info    425    node3/lrm: service status vm:103 started
 info    620     hardware: exit simulation - done
diff --git a/src/test/test-crs-dynamic-auto-rebalance6/log.expect b/src/test/test-crs-dynamic-auto-rebalance6/log.expect
index 9758af5..7401c45 100644
--- a/src/test/test-crs-dynamic-auto-rebalance6/log.expect
+++ b/src/test/test-crs-dynamic-auto-rebalance6/log.expect
@@ -29,72 +29,42 @@ err      81    node1/lrm: service fa:109 not moved (migration error)
 info     83    node2/lrm: got lock 'ha_agent_node2_lock'
 info     83    node2/lrm: status change wait_for_agent_lock => active
 err     100    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    100    node1/crm: auto rebalance - relocate fa:109 to node2 failed, not trying it again in this rebalancing attempt
 info    100    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    160    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    160    node1/crm: got crm command: relocate fa:109 node2
-info    160    node1/crm: relocate service 'fa:109' to node 'node2'
-info    160    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     161    node1/lrm: service fa:109 not moved (migration error)
-err     180    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    180    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    240    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    240    node1/crm: got crm command: relocate fa:109 node2
-info    240    node1/crm: relocate service 'fa:109' to node 'node2'
-info    240    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     241    node1/lrm: service fa:109 not moved (migration error)
-err     260    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    260    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    320    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    320    node1/crm: got crm command: relocate fa:109 node2
-info    320    node1/crm: relocate service 'fa:109' to node 'node2'
-info    320    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     321    node1/lrm: service fa:109 not moved (migration error)
-err     340    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    340    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    400    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    400    node1/crm: got crm command: relocate fa:109 node2
-info    400    node1/crm: relocate service 'fa:109' to node 'node2'
-info    400    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     401    node1/lrm: service fa:109 not moved (migration error)
-err     420    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    420    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
+info    220    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
+info    220    node1/crm: got crm command: relocate fa:109 node2
+info    220    node1/crm: relocate service 'fa:109' to node 'node2'
+info    220    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
+err     221    node1/lrm: service fa:109 not moved (migration error)
+err     240    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    240    node1/crm: auto rebalance - relocate fa:109 to node2 failed 2 times in a row, not trying it again in this and the next 2 rebalancing attempts
+info    240    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
 info    480    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
 info    480    node1/crm: got crm command: relocate fa:109 node2
 info    480    node1/crm: relocate service 'fa:109' to node 'node2'
 info    480    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
 err     481    node1/lrm: service fa:109 not moved (migration error)
 err     500    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    500    node1/crm: auto rebalance - relocate fa:109 to node2 failed 3 times in a row, not trying it again in this and the next 4 rebalancing attempts
 info    500    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    560    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    560    node1/crm: got crm command: relocate fa:109 node2
-info    560    node1/crm: relocate service 'fa:109' to node 'node2'
-info    560    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     561    node1/lrm: service fa:109 not moved (migration error)
-err     580    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    580    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    640    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    640    node1/crm: got crm command: relocate fa:109 node2
-info    640    node1/crm: relocate service 'fa:109' to node 'node2'
-info    640    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     641    node1/lrm: service fa:109 not moved (migration error)
-err     660    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    660    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    720    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    720    node1/crm: got crm command: relocate fa:109 node2
-info    720    node1/crm: relocate service 'fa:109' to node 'node2'
-info    720    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-err     721    node1/lrm: service fa:109 not moved (migration error)
-err     740    node1/crm: service 'fa:109' - migration failed (exit code 1)
-info    740    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
-info    800    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
-info    800    node1/crm: got crm command: relocate fa:109 node2
-info    800    node1/crm: relocate service 'fa:109' to node 'node2'
-info    800    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
-info    801    node1/lrm: service fa:109 - start relocate to node 'node2'
-info    801    node1/lrm: stopping service fa:109 (relocate)
-info    801    node1/lrm: service status fa:109 stopped
-info    801    node1/lrm: service fa:109 - end relocate to node 'node2'
-info    820    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node2)
-info    823    node2/lrm: starting service fa:109
-info    823    node2/lrm: service status fa:109 started
+info    860    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
+info    860    node1/crm: got crm command: relocate fa:109 node2
+info    860    node1/crm: relocate service 'fa:109' to node 'node2'
+info    860    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
+err     861    node1/lrm: service fa:109 not moved (migration error)
+err     880    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn    880    node1/crm: auto rebalance - relocate fa:109 to node2 failed 4 times in a row, not trying it again in this and the next 8 rebalancing attempts
+info    880    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
+info   1303    node2/lrm: node had no service configured for 60 rounds, going idle.
+info   1303    node2/lrm: status change active => wait_for_agent_lock
+info   1480    node1/crm: auto rebalance - relocate fa:109 to node2 (expected change for imbalance from 100.0% to 27.3%)
+info   1480    node1/crm: got crm command: relocate fa:109 node2
+info   1480    node1/crm: relocate service 'fa:109' to node 'node2'
+info   1480    node1/crm: service 'fa:109': state changed from 'started' to 'relocate'  (node = node1, target = node2)
+err    1481    node1/lrm: service fa:109 not moved (migration error)
+info   1483    node2/lrm: got lock 'ha_agent_node2_lock'
+info   1483    node2/lrm: status change wait_for_agent_lock => active
+err    1500    node1/crm: service 'fa:109' - migration failed (exit code 1)
+warn   1500    node1/crm: auto rebalance - relocate fa:109 to node2 failed 5 times in a row, not trying it again in this and the next 16 rebalancing attempts
+info   1500    node1/crm: service 'fa:109': state changed from 'relocate' to 'started'  (node = node1)
 info   1520     hardware: exit simulation - done
-- 
2.47.3