Log provider offers and measured reasons for confirmed stream migrations

src/stream/stream_optimizer.c

@@ -114,7 +114,15 @@ static void probes_poll(struct stream_optimizer *o, struct STREAM_HANDLE *h, uin
                 s->failures++; s->retry_ms = now + backoff(s->failures);
                 stream_receive_close(s->probe); s->probe = NULL; continue;
             }
-        } else { s->offers[s->probe_sub].info = info; s->failures = 0; s->retry_ms = 0; }
+        } else {
+            s->offers[s->probe_sub].info = info; s->failures = 0; s->retry_ms = 0;
+            DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, "stream optimizer offer peer=%llx sub=%u range=%llu..%llu hops=%u rtt=%u/%d chain=%u/%d slots=%u accepting=%d lag=%llu stopped=%d age=%llu/%d queue=%llu",
+                (unsigned long long)s->node, s->probe_sub, (unsigned long long)info.first_available,
+                (unsigned long long)info.last_available, info.path.count, info.rtt_ms, info.rtt_valid,
+                info.path_rtt_ms, info.path_rtt_valid, info.free_slots, info.accepting,
+                (unsigned long long)info.supplier_metrics.lag_ms, info.supplier_metrics.stopped,
+                (unsigned long long)info.progress_age_ms, info.progress_valid, (unsigned long long)info.supplier_queue_bytes);
+        }
         unsigned next = s->probe_sub + 1;
         if (next == o->descriptor.n) { stream_receive_close(s->probe); s->probe = NULL; continue; }
         if (info.state == STREAM_RECEIVE_CLOSED) {
@@ -359,6 +367,11 @@ void stream_optimizer_tick(struct stream_optimizer *o, struct STREAM_HANDLE *h,
         }
         if (pick->better_node != s->node) { pick->better_node = s->node; pick->better_ms = now; }
         if (now - pick->better_ms < o->settings.migration_confirm_ms) continue;
+        DEBUG_DEBUG(DEBUG_CATEGORY_STREAM, "stream optimizer improvement sub=%u old=%llx new=%llx old_problems=%.3f new_problems=%.3f old_rtt=%llu new_rtt=%llu old_usage=%u new_usage=%u confirmed_ms=%llu",
+            sub, (unsigned long long)info.peer, (unsigned long long)s->node, problems(&info.metrics, info.metrics_valid),
+            problems(&s->offers[sub].info.supplier_metrics, s->offers[sub].info.supplier_metrics_valid),
+            (unsigned long long)total_rtt(&info), (unsigned long long)total_rtt(&s->offers[sub].info),
+            usage(o, info.peer, sub), usage(o, s->node, sub), (unsigned long long)(now - pick->better_ms));
         if (stream_receive_open(h, s->node, (uint8_t)sub, seq, &pick->replacement) == STREAM_OK) {
             pick->replacement_ms = now; migrating = 1;
             DEBUG_INFO(DEBUG_CATEGORY_STREAM, "stream optimizer overlap sub=%u old=%llx new=%llx index=%llu",