From fb2e7d5f2c105f83159a592a2d072a91de63709f Mon Sep 17 00:00:00 2001
From: Dmitrii Iakunin <zeil@nebius.com>
Date: Mon, 3 Feb 2025 21:02:53 +0100
Subject: [PATCH] vdev: log waiting of the first GET_FEATURES request

Signed-off-by: Dmitrii Iakunin <zeil@nebius.com>
---
 vdev.c | 31 ++++++++++++++++++++++++-------
 1 file changed, 24 insertions(+), 7 deletions(-)

diff --git a/vdev.c b/vdev.c
index bec46e3..cbdb7b0 100644
--- a/vdev.c
+++ b/vdev.c
@@ -578,7 +578,10 @@ static void arm_msg_handling_timer(struct vhd_vdev *vdev, int secs)
     timerfd_settime(vdev->timerfd, 0, &itimer, NULL);
 }
 
-/* Every so many seconds report if the message is still being handled */
+/* Report every so many seconds if we haven't received GET_FEATURES request */
+#define MSG_GET_FEATURES_WAITING_LOG_INTERVAL 30
+
+/* Report every so many seconds if the message is still being handled */
 #define MSG_HANDLING_LOG_INTERVAL 30
 
 #ifdef VHD_DEBUG
@@ -591,9 +594,15 @@ static void arm_msg_handling_timer(struct vhd_vdev *vdev, int secs)
 #define MSG_ELAPSED_NSEC_LOG_THRESHOLD (500 * NSEC_PER_MSEC)
 #endif
 
+
 static void vdev_handle_start(struct vhd_vdev *vdev, uint32_t req,
                               bool ack_pending)
 {
+    /* we need to detach timer_handler only before very first GET_FEATURES request */
+    if (vdev->supported_features == 0) {
+        vhd_detach_io_handler(vdev->timer_handler);
+    }
+
     /* do not accept further messages until this one is fully handled */
     vhd_detach_io_handler(vdev->conn_handler);
 
@@ -1978,9 +1987,13 @@ static int timer_read(void *opaque)
 
     elapsed_time(vdev, &elapsed);
 
-    VHD_OBJ_WARN(vdev, "long processing %s (%u): elapsed %jd.%03lds",
-                 vhost_req_name(vdev->req), vdev->req,
-                 (intmax_t)elapsed.tv_sec, elapsed.tv_nsec / NSEC_PER_MSEC);
+    if (vdev->supported_features) {
+        VHD_OBJ_WARN(vdev, "long processing %s (%u): elapsed %jd.%03lds",
+                     vhost_req_name(vdev->req), vdev->req,
+                     (intmax_t)elapsed.tv_sec, elapsed.tv_nsec / NSEC_PER_MSEC);
+    } else {
+        VHD_OBJ_WARN(vdev, "Still waiting for GET_FEATURES request...");
+    }
 
     return 0;
 }
@@ -2018,8 +2031,6 @@ static int server_read(void *opaque)
     if (!timer_handler) {
         goto close_timer;
     }
-    /* it only needs to be attached during message handling */
-    vhd_detach_io_handler(timer_handler);
 
     vhd_detach_io_handler(vdev->listen_handler);
 
@@ -2027,9 +2038,15 @@ static int server_read(void *opaque)
     vdev->conn_handler = conn_handler;
     vdev->timerfd = timerfd;
     vdev->timer_handler = timer_handler;
-    vdev->negotiated_features = 0;
+    vdev->supported_protocol_features = 0;
     vdev->negotiated_protocol_features = 0;
+    /* supported_features is being set on handling first GET_FEATURES request */
+    vdev->supported_features = 0;
+    vdev->negotiated_features = 0;
     VHD_OBJ_INFO(vdev, "Connection established, sock = %d", connfd);
+
+    arm_msg_handling_timer(vdev, MSG_GET_FEATURES_WAITING_LOG_INTERVAL);
+
     return 0;
 
 close_timer: