DPDK patches and discussions
 help / color / mirror / Atom feed
* [PATCH v3 0/9] vhost: improve logging
@ 2022-01-26  9:55 Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 1/9] vhost: improve IOTLB logs Maxime Coquelin
                   ` (9 more replies)
  0 siblings, 10 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This series aims at easing Vhost logs analysis, by
prepending the Vhost-user socket path to all logs and to
remove multi-line comments. Doing so, filtering Vhost-user
ports logs is much easier.

Changes in v3:
==============
- Fix various typos reported (Chenbo)
- Revert one multi-line comment removal (Chenbo)

Changes in v2:
==============
- Add missing socket paths (David)
- avoid identical logs in iotlb code (David)
- Use data log type when used in datapath (David)

Maxime Coquelin (9):
  vhost: improve IOTLB logs
  vhost: improve vDPA registration failure log
  vhost: improve Vhost layer logs
  vhost: improve Vhost-user layer logs
  vhost: improve socket layer logs
  vhost: improve Virtio-net layer logs
  vhost: remove multi-line logs
  vhost: differentiate IOTLB logs
  vhost: use proper logging type for data path

 lib/vhost/iotlb.c      |  30 +-
 lib/vhost/iotlb.h      |  10 +-
 lib/vhost/socket.c     | 148 ++++-----
 lib/vhost/vdpa.c       |   4 +-
 lib/vhost/vhost.c      | 108 ++++---
 lib/vhost/vhost_user.c | 678 ++++++++++++++++++++---------------------
 lib/vhost/vhost_user.h |   4 +-
 lib/vhost/virtio_net.c | 165 +++++-----
 8 files changed, 548 insertions(+), 599 deletions(-)

-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 1/9] vhost: improve IOTLB logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 2/9] vhost: improve vDPA registration failure log Maxime Coquelin
                   ` (8 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch adds IOTLB mempool name when logging debug
or error messages, and also prepends the socket path.
to all the logs.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/iotlb.c      | 26 +++++++++++++++-----------
 lib/vhost/iotlb.h      | 10 +++++-----
 lib/vhost/vhost.c      |  2 +-
 lib/vhost/vhost_user.c |  2 +-
 4 files changed, 22 insertions(+), 18 deletions(-)

diff --git a/lib/vhost/iotlb.c b/lib/vhost/iotlb.c
index 82bdb84526..afa86d7c2b 100644
--- a/lib/vhost/iotlb.c
+++ b/lib/vhost/iotlb.c
@@ -62,7 +62,7 @@ vhost_user_iotlb_pending_miss(struct vhost_virtqueue *vq, uint64_t iova,
 }
 
 void
-vhost_user_iotlb_pending_insert(struct vhost_virtqueue *vq,
+vhost_user_iotlb_pending_insert(struct virtio_net *dev, struct vhost_virtqueue *vq,
 				uint64_t iova, uint8_t perm)
 {
 	struct vhost_iotlb_entry *node;
@@ -70,14 +70,16 @@ vhost_user_iotlb_pending_insert(struct vhost_virtqueue *vq,
 
 	ret = rte_mempool_get(vq->iotlb_pool, (void **)&node);
 	if (ret) {
-		VHOST_LOG_CONFIG(DEBUG, "IOTLB pool empty, clear entries\n");
+		VHOST_LOG_CONFIG(DEBUG, "(%s) IOTLB pool %s empty, clear entries\n",
+				dev->ifname, vq->iotlb_pool->name);
 		if (!TAILQ_EMPTY(&vq->iotlb_pending_list))
 			vhost_user_iotlb_pending_remove_all(vq);
 		else
 			vhost_user_iotlb_cache_random_evict(vq);
 		ret = rte_mempool_get(vq->iotlb_pool, (void **)&node);
 		if (ret) {
-			VHOST_LOG_CONFIG(ERR, "IOTLB pool still empty, failure\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB pool %s still empty, failure\n",
+					dev->ifname, vq->iotlb_pool->name);
 			return;
 		}
 	}
@@ -156,22 +158,25 @@ vhost_user_iotlb_cache_random_evict(struct vhost_virtqueue *vq)
 }
 
 void
-vhost_user_iotlb_cache_insert(struct vhost_virtqueue *vq, uint64_t iova,
-				uint64_t uaddr, uint64_t size, uint8_t perm)
+vhost_user_iotlb_cache_insert(struct virtio_net *dev, struct vhost_virtqueue *vq,
+				uint64_t iova, uint64_t uaddr,
+				uint64_t size, uint8_t perm)
 {
 	struct vhost_iotlb_entry *node, *new_node;
 	int ret;
 
 	ret = rte_mempool_get(vq->iotlb_pool, (void **)&new_node);
 	if (ret) {
-		VHOST_LOG_CONFIG(DEBUG, "IOTLB pool empty, clear entries\n");
+		VHOST_LOG_CONFIG(DEBUG, "(%s) IOTLB pool %s empty, clear entries\n",
+				dev->ifname, vq->iotlb_pool->name);
 		if (!TAILQ_EMPTY(&vq->iotlb_list))
 			vhost_user_iotlb_cache_random_evict(vq);
 		else
 			vhost_user_iotlb_pending_remove_all(vq);
 		ret = rte_mempool_get(vq->iotlb_pool, (void **)&new_node);
 		if (ret) {
-			VHOST_LOG_CONFIG(ERR, "IOTLB pool still empty, failure\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB pool %s still empty, failure\n",
+					dev->ifname, vq->iotlb_pool->name);
 			return;
 		}
 	}
@@ -311,7 +316,7 @@ vhost_user_iotlb_init(struct virtio_net *dev, int vq_index)
 
 	snprintf(pool_name, sizeof(pool_name), "iotlb_%u_%d_%d",
 			getpid(), dev->vid, vq_index);
-	VHOST_LOG_CONFIG(DEBUG, "IOTLB cache name: %s\n", pool_name);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) IOTLB cache name: %s\n", dev->ifname, pool_name);
 
 	/* If already created, free it and recreate */
 	vq->iotlb_pool = rte_mempool_lookup(pool_name);
@@ -324,9 +329,8 @@ vhost_user_iotlb_init(struct virtio_net *dev, int vq_index)
 			RTE_MEMPOOL_F_NO_CACHE_ALIGN |
 			RTE_MEMPOOL_F_SP_PUT);
 	if (!vq->iotlb_pool) {
-		VHOST_LOG_CONFIG(ERR,
-				"Failed to create IOTLB cache pool (%s)\n",
-				pool_name);
+		VHOST_LOG_CONFIG(ERR, "(%s) Failed to create IOTLB cache pool %s\n",
+				dev->ifname, pool_name);
 		return -1;
 	}
 
diff --git a/lib/vhost/iotlb.h b/lib/vhost/iotlb.h
index b6e0757ad6..8d0ff7473b 100644
--- a/lib/vhost/iotlb.h
+++ b/lib/vhost/iotlb.h
@@ -33,17 +33,17 @@ vhost_user_iotlb_wr_unlock(struct vhost_virtqueue *vq)
 	rte_rwlock_write_unlock(&vq->iotlb_lock);
 }
 
-void vhost_user_iotlb_cache_insert(struct vhost_virtqueue *vq, uint64_t iova,
-					uint64_t uaddr, uint64_t size,
-					uint8_t perm);
+void vhost_user_iotlb_cache_insert(struct virtio_net *dev, struct vhost_virtqueue *vq,
+					uint64_t iova, uint64_t uaddr,
+					uint64_t size, uint8_t perm);
 void vhost_user_iotlb_cache_remove(struct vhost_virtqueue *vq,
 					uint64_t iova, uint64_t size);
 uint64_t vhost_user_iotlb_cache_find(struct vhost_virtqueue *vq, uint64_t iova,
 					uint64_t *size, uint8_t perm);
 bool vhost_user_iotlb_pending_miss(struct vhost_virtqueue *vq, uint64_t iova,
 						uint8_t perm);
-void vhost_user_iotlb_pending_insert(struct vhost_virtqueue *vq, uint64_t iova,
-						uint8_t perm);
+void vhost_user_iotlb_pending_insert(struct virtio_net *dev, struct vhost_virtqueue *vq,
+						uint64_t iova, uint8_t perm);
 void vhost_user_iotlb_pending_remove(struct vhost_virtqueue *vq, uint64_t iova,
 						uint64_t size, uint8_t perm);
 void vhost_user_iotlb_flush_all(struct vhost_virtqueue *vq);
diff --git a/lib/vhost/vhost.c b/lib/vhost/vhost.c
index 13a9bb9dd1..e52d7f7bb6 100644
--- a/lib/vhost/vhost.c
+++ b/lib/vhost/vhost.c
@@ -56,7 +56,7 @@ __vhost_iova_to_vva(struct virtio_net *dev, struct vhost_virtqueue *vq,
 		 */
 		vhost_user_iotlb_rd_unlock(vq);
 
-		vhost_user_iotlb_pending_insert(vq, iova, perm);
+		vhost_user_iotlb_pending_insert(dev, vq, iova, perm);
 		if (vhost_user_iotlb_miss(dev, iova, perm)) {
 			VHOST_LOG_CONFIG(ERR,
 				"IOTLB miss req failed for IOVA 0x%" PRIx64 "\n",
diff --git a/lib/vhost/vhost_user.c b/lib/vhost/vhost_user.c
index 5eb1dd6812..6aaac6a316 100644
--- a/lib/vhost/vhost_user.c
+++ b/lib/vhost/vhost_user.c
@@ -2563,7 +2563,7 @@ vhost_user_iotlb_msg(struct virtio_net **pdev, struct VhostUserMsg *msg,
 			if (!vq)
 				continue;
 
-			vhost_user_iotlb_cache_insert(vq, imsg->iova, vva,
+			vhost_user_iotlb_cache_insert(dev, vq, imsg->iova, vva,
 					len, imsg->perm);
 
 			if (is_vring_iotlb(dev, vq, imsg))
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 2/9] vhost: improve vDPA registration failure log
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 1/9] vhost: improve IOTLB logs Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 3/9] vhost: improve Vhost layer logs Maxime Coquelin
                   ` (7 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch adds name of the device failing vDPA registration.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/vdpa.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/vhost/vdpa.c b/lib/vhost/vdpa.c
index 09ad5d866e..6df2230a67 100644
--- a/lib/vhost/vdpa.c
+++ b/lib/vhost/vdpa.c
@@ -82,8 +82,8 @@ rte_vdpa_register_device(struct rte_device *rte_dev,
 			!ops->get_protocol_features || !ops->dev_conf ||
 			!ops->dev_close || !ops->set_vring_state ||
 			!ops->set_features) {
-		VHOST_LOG_CONFIG(ERR,
-				"Some mandatory vDPA ops aren't implemented\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) Some mandatory vDPA ops aren't implemented\n",
+				rte_dev->name);
 		return NULL;
 	}
 
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 3/9] vhost: improve Vhost layer logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 1/9] vhost: improve IOTLB logs Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 2/9] vhost: improve vDPA registration failure log Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 4/9] vhost: improve Vhost-user " Maxime Coquelin
                   ` (6 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch prepends Vhost logs with the Vhost-user socket
path when available to ease filtering logs for a given port.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/vhost.c | 104 +++++++++++++++++++++++-----------------------
 1 file changed, 51 insertions(+), 53 deletions(-)

diff --git a/lib/vhost/vhost.c b/lib/vhost/vhost.c
index e52d7f7bb6..3b05f17a50 100644
--- a/lib/vhost/vhost.c
+++ b/lib/vhost/vhost.c
@@ -58,9 +58,8 @@ __vhost_iova_to_vva(struct virtio_net *dev, struct vhost_virtqueue *vq,
 
 		vhost_user_iotlb_pending_insert(dev, vq, iova, perm);
 		if (vhost_user_iotlb_miss(dev, iova, perm)) {
-			VHOST_LOG_CONFIG(ERR,
-				"IOTLB miss req failed for IOVA 0x%" PRIx64 "\n",
-				iova);
+			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB miss req failed for IOVA 0x%" PRIx64 "\n",
+				dev->ifname, iova);
 			vhost_user_iotlb_pending_remove(vq, iova, 1, perm);
 		}
 
@@ -126,8 +125,8 @@ __vhost_log_write_iova(struct virtio_net *dev, struct vhost_virtqueue *vq,
 	hva = __vhost_iova_to_vva(dev, vq, iova, &map_len, VHOST_ACCESS_RW);
 	if (map_len != len) {
 		VHOST_LOG_DATA(ERR,
-			"Failed to write log for IOVA 0x%" PRIx64 ". No IOTLB entry found\n",
-			iova);
+			"(%s) failed to write log for IOVA 0x%" PRIx64 ". No IOTLB entry found\n",
+			dev->ifname, iova);
 		return;
 	}
 
@@ -243,8 +242,8 @@ __vhost_log_cache_write_iova(struct virtio_net *dev, struct vhost_virtqueue *vq,
 	hva = __vhost_iova_to_vva(dev, vq, iova, &map_len, VHOST_ACCESS_RW);
 	if (map_len != len) {
 		VHOST_LOG_DATA(ERR,
-			"Failed to write log for IOVA 0x%" PRIx64 ". No IOTLB entry found\n",
-			iova);
+			"(%s) failed to write log for IOVA 0x%" PRIx64 ". No IOTLB entry found\n",
+			dev->ifname, iova);
 		return;
 	}
 
@@ -422,9 +421,9 @@ translate_log_addr(struct virtio_net *dev, struct vhost_virtqueue *vq,
 		gpa = hva_to_gpa(dev, hva, exp_size);
 		if (!gpa) {
 			VHOST_LOG_CONFIG(ERR,
-				"VQ: Failed to find GPA for log_addr: 0x%"
+				"(%s) failed to find GPA for log_addr: 0x%"
 				PRIx64 " hva: 0x%" PRIx64 "\n",
-				log_addr, hva);
+				dev->ifname, log_addr, hva);
 			return 0;
 		}
 		return gpa;
@@ -551,16 +550,15 @@ init_vring_queue(struct virtio_net *dev, uint32_t vring_idx)
 	int numa_node = SOCKET_ID_ANY;
 
 	if (vring_idx >= VHOST_MAX_VRING) {
-		VHOST_LOG_CONFIG(ERR,
-				"Failed not init vring, out of bound (%d)\n",
-				vring_idx);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to init vring, out of bound (%d)\n",
+				dev->ifname, vring_idx);
 		return;
 	}
 
 	vq = dev->virtqueue[vring_idx];
 	if (!vq) {
-		VHOST_LOG_CONFIG(ERR, "Virtqueue not allocated (%d)\n",
-				vring_idx);
+		VHOST_LOG_CONFIG(ERR, "(%s) virtqueue not allocated (%d)\n",
+				dev->ifname, vring_idx);
 		return;
 	}
 
@@ -572,8 +570,8 @@ init_vring_queue(struct virtio_net *dev, uint32_t vring_idx)
 
 #ifdef RTE_LIBRTE_VHOST_NUMA
 	if (get_mempolicy(&numa_node, NULL, 0, vq, MPOL_F_NODE | MPOL_F_ADDR)) {
-		VHOST_LOG_CONFIG(ERR, "(%d) failed to query numa node: %s\n",
-			dev->vid, rte_strerror(errno));
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to query numa node: %s\n",
+			dev->ifname, rte_strerror(errno));
 		numa_node = SOCKET_ID_ANY;
 	}
 #endif
@@ -590,15 +588,15 @@ reset_vring_queue(struct virtio_net *dev, uint32_t vring_idx)
 
 	if (vring_idx >= VHOST_MAX_VRING) {
 		VHOST_LOG_CONFIG(ERR,
-				"Failed not init vring, out of bound (%d)\n",
-				vring_idx);
+				"(%s) failed to reset vring, out of bound (%d)\n",
+				dev->ifname, vring_idx);
 		return;
 	}
 
 	vq = dev->virtqueue[vring_idx];
 	if (!vq) {
-		VHOST_LOG_CONFIG(ERR, "Virtqueue not allocated (%d)\n",
-				vring_idx);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to reset vring, virtqueue not allocated (%d)\n",
+				dev->ifname, vring_idx);
 		return;
 	}
 
@@ -620,8 +618,8 @@ alloc_vring_queue(struct virtio_net *dev, uint32_t vring_idx)
 
 		vq = rte_zmalloc(NULL, sizeof(struct vhost_virtqueue), 0);
 		if (vq == NULL) {
-			VHOST_LOG_CONFIG(ERR,
-				"Failed to allocate memory for vring:%u.\n", i);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate memory for vring %u.\n",
+					dev->ifname, i);
 			return -1;
 		}
 
@@ -673,16 +671,14 @@ vhost_new_device(void)
 	}
 
 	if (i == MAX_VHOST_DEVICE) {
-		VHOST_LOG_CONFIG(ERR,
-			"Failed to find a free slot for new device.\n");
+		VHOST_LOG_CONFIG(ERR, "failed to find a free slot for new device.\n");
 		pthread_mutex_unlock(&vhost_dev_lock);
 		return -1;
 	}
 
 	dev = rte_zmalloc(NULL, sizeof(struct virtio_net), 0);
 	if (dev == NULL) {
-		VHOST_LOG_CONFIG(ERR,
-			"Failed to allocate memory for new dev.\n");
+		VHOST_LOG_CONFIG(ERR, "failed to allocate memory for new device.\n");
 		pthread_mutex_unlock(&vhost_dev_lock);
 		return -1;
 	}
@@ -834,9 +830,8 @@ rte_vhost_get_numa_node(int vid)
 	ret = get_mempolicy(&numa_node, NULL, 0, dev,
 			    MPOL_F_NODE | MPOL_F_ADDR);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"(%d) failed to query numa node: %s\n",
-			vid, rte_strerror(errno));
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to query numa node: %s\n",
+			dev->ifname, rte_strerror(errno));
 		return -1;
 	}
 
@@ -1470,8 +1465,8 @@ rte_vhost_rx_queue_count(int vid, uint16_t qid)
 		return 0;
 
 	if (unlikely(qid >= dev->nr_vring || (qid & 1) == 0)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, qid);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+			dev->ifname, __func__, qid);
 		return 0;
 	}
 
@@ -1636,23 +1631,23 @@ async_channel_register(int vid, uint16_t queue_id,
 
 	if (unlikely(vq->async)) {
 		VHOST_LOG_CONFIG(ERR,
-				"async register failed: already registered (vid %d, qid: %d)\n",
-				vid, queue_id);
+				"(%s) async register failed: already registered (qid: %d)\n",
+				dev->ifname, queue_id);
 		return -1;
 	}
 
 	async = rte_zmalloc_socket(NULL, sizeof(struct vhost_async), 0, node);
 	if (!async) {
-		VHOST_LOG_CONFIG(ERR, "failed to allocate async metadata (vid %d, qid: %d)\n",
-				vid, queue_id);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate async metadata (qid: %d)\n",
+				dev->ifname, queue_id);
 		return -1;
 	}
 
 	async->pkts_info = rte_malloc_socket(NULL, vq->size * sizeof(struct async_inflight_info),
 			RTE_CACHE_LINE_SIZE, node);
 	if (!async->pkts_info) {
-		VHOST_LOG_CONFIG(ERR, "failed to allocate async_pkts_info (vid %d, qid: %d)\n",
-				vid, queue_id);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate async_pkts_info (qid: %d)\n",
+				dev->ifname, queue_id);
 		goto out_free_async;
 	}
 
@@ -1661,8 +1656,8 @@ async_channel_register(int vid, uint16_t queue_id,
 				vq->size * sizeof(struct vring_used_elem_packed),
 				RTE_CACHE_LINE_SIZE, node);
 		if (!async->buffers_packed) {
-			VHOST_LOG_CONFIG(ERR, "failed to allocate async buffers (vid %d, qid: %d)\n",
-					vid, queue_id);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate async buffers (qid: %d)\n",
+					dev->ifname, queue_id);
 			goto out_free_inflight;
 		}
 	} else {
@@ -1670,8 +1665,8 @@ async_channel_register(int vid, uint16_t queue_id,
 				vq->size * sizeof(struct vring_used_elem),
 				RTE_CACHE_LINE_SIZE, node);
 		if (!async->descs_split) {
-			VHOST_LOG_CONFIG(ERR, "failed to allocate async descs (vid %d, qid: %d)\n",
-					vid, queue_id);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate async descs (qid: %d)\n",
+					dev->ifname, queue_id);
 			goto out_free_inflight;
 		}
 	}
@@ -1712,8 +1707,8 @@ rte_vhost_async_channel_register(int vid, uint16_t queue_id,
 
 	if (unlikely(!(config.features & RTE_VHOST_ASYNC_INORDER))) {
 		VHOST_LOG_CONFIG(ERR,
-			"async copy is not supported on non-inorder mode "
-			"(vid %d, qid: %d)\n", vid, queue_id);
+			"(%s) async copy is not supported on non-inorder mode (qid: %d)\n",
+			dev->ifname, queue_id);
 		return -1;
 	}
 
@@ -1749,8 +1744,8 @@ rte_vhost_async_channel_register_thread_unsafe(int vid, uint16_t queue_id,
 
 	if (unlikely(!(config.features & RTE_VHOST_ASYNC_INORDER))) {
 		VHOST_LOG_CONFIG(ERR,
-			"async copy is not supported on non-inorder mode "
-			"(vid %d, qid: %d)\n", vid, queue_id);
+			"(%s) async copy is not supported on non-inorder mode (qid: %d)\n",
+			dev->ifname, queue_id);
 		return -1;
 	}
 
@@ -1785,14 +1780,15 @@ rte_vhost_async_channel_unregister(int vid, uint16_t queue_id)
 		return ret;
 
 	if (!rte_spinlock_trylock(&vq->access_lock)) {
-		VHOST_LOG_CONFIG(ERR, "Failed to unregister async channel. "
-			"virt queue busy.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel, virtqueue busy.\n",
+				dev->ifname);
 		return -1;
 	}
 
 	if (vq->async->pkts_inflight_n) {
-		VHOST_LOG_CONFIG(ERR, "Failed to unregister async channel. "
-			"async inflight packets must be completed before unregistration.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel. "
+			"async inflight packets must be completed before unregistration.\n",
+			dev->ifname);
 		ret = -1;
 		goto out;
 	}
@@ -1825,8 +1821,9 @@ rte_vhost_async_channel_unregister_thread_unsafe(int vid, uint16_t queue_id)
 		return 0;
 
 	if (vq->async->pkts_inflight_n) {
-		VHOST_LOG_CONFIG(ERR, "Failed to unregister async channel. "
-			"async inflight packets must be completed before unregistration.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel. "
+			"async inflight packets must be completed before unregistration.\n",
+			dev->ifname);
 		return -1;
 	}
 
@@ -1857,8 +1854,9 @@ rte_vhost_async_get_inflight(int vid, uint16_t queue_id)
 		return ret;
 
 	if (!rte_spinlock_trylock(&vq->access_lock)) {
-		VHOST_LOG_CONFIG(DEBUG, "Failed to check in-flight packets. "
-			"virt queue busy.\n");
+		VHOST_LOG_CONFIG(DEBUG,
+			"(%s) failed to check in-flight packets. virtqueue busy.\n",
+			dev->ifname);
 		return ret;
 	}
 
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 4/9] vhost: improve Vhost-user layer logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (2 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 3/9] vhost: improve Vhost layer logs Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 5/9] vhost: improve socket " Maxime Coquelin
                   ` (5 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch adds the Vhost-user socket path to Vhost-user
layer logs in order to ease logs filtering.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/vhost_user.c | 573 ++++++++++++++++++++---------------------
 1 file changed, 275 insertions(+), 298 deletions(-)

diff --git a/lib/vhost/vhost_user.c b/lib/vhost/vhost_user.c
index 6aaac6a316..c95eef8f5d 100644
--- a/lib/vhost/vhost_user.c
+++ b/lib/vhost/vhost_user.c
@@ -94,7 +94,7 @@ static const char *vhost_message_str[VHOST_USER_MAX] = {
 };
 
 static int send_vhost_reply(int sockfd, struct VhostUserMsg *msg);
-static int read_vhost_message(int sockfd, struct VhostUserMsg *msg);
+static int read_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg);
 
 static void
 close_msg_fds(struct VhostUserMsg *msg)
@@ -117,14 +117,13 @@ close_msg_fds(struct VhostUserMsg *msg)
  * close all FDs and return an error if this is not the case.
  */
 static int
-validate_msg_fds(struct VhostUserMsg *msg, int expected_fds)
+validate_msg_fds(struct virtio_net *dev, struct VhostUserMsg *msg, int expected_fds)
 {
 	if (msg->fd_num == expected_fds)
 		return 0;
 
-	VHOST_LOG_CONFIG(ERR,
-		" Expect %d FDs for request %s, received %d\n",
-		expected_fds,
+	VHOST_LOG_CONFIG(ERR, "(%s) expect %d FDs for request %s, received %d\n",
+		dev->ifname, expected_fds,
 		vhost_message_str[msg->request.master],
 		msg->fd_num);
 
@@ -144,7 +143,7 @@ get_blk_size(int fd)
 }
 
 static int
-async_dma_map(struct rte_vhost_mem_region *region, bool do_map)
+async_dma_map(struct virtio_net *dev, struct rte_vhost_mem_region *region, bool do_map)
 {
 	uint64_t host_iova;
 	int ret = 0;
@@ -172,7 +171,7 @@ async_dma_map(struct rte_vhost_mem_region *region, bool do_map)
 			if (rte_errno == ENODEV || rte_errno == ENOTSUP)
 				return 0;
 
-			VHOST_LOG_CONFIG(ERR, "DMA engine map failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) DMA engine map failed\n", dev->ifname);
 			/* DMA mapping errors won't stop VHST_USER_SET_MEM_TABLE. */
 			return 0;
 		}
@@ -188,7 +187,7 @@ async_dma_map(struct rte_vhost_mem_region *region, bool do_map)
 			if (rte_errno == EINVAL)
 				return 0;
 
-			VHOST_LOG_CONFIG(ERR, "DMA engine unmap failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) DMA engine unmap failed\n", dev->ifname);
 			return ret;
 		}
 	}
@@ -209,7 +208,7 @@ free_mem_region(struct virtio_net *dev)
 		reg = &dev->mem->regions[i];
 		if (reg->host_user_addr) {
 			if (dev->async_copy && rte_vfio_is_enabled("vfio"))
-				async_dma_map(reg, false);
+				async_dma_map(dev, reg, false);
 
 			munmap(reg->mmap_addr, reg->mmap_size);
 			close(reg->fd);
@@ -287,11 +286,13 @@ vhost_user_notify_queue_state(struct virtio_net *dev, uint16_t index,
  * the device hasn't been initialised.
  */
 static int
-vhost_user_set_owner(struct virtio_net **pdev __rte_unused,
+vhost_user_set_owner(struct virtio_net **pdev,
 			struct VhostUserMsg *msg,
 			int main_fd __rte_unused)
 {
-	if (validate_msg_fds(msg, 0) != 0)
+	struct virtio_net *dev = *pdev;
+
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	return RTE_VHOST_MSG_RESULT_OK;
@@ -304,7 +305,7 @@ vhost_user_reset_owner(struct virtio_net **pdev,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	vhost_destroy_device_notify(dev);
@@ -324,7 +325,7 @@ vhost_user_get_features(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	struct virtio_net *dev = *pdev;
 	uint64_t features = 0;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	rte_vhost_driver_get_features(dev->ifname, &features);
@@ -346,7 +347,7 @@ vhost_user_get_queue_num(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	struct virtio_net *dev = *pdev;
 	uint32_t queue_num = 0;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	rte_vhost_driver_get_queue_num(dev->ifname, &queue_num);
@@ -370,14 +371,13 @@ vhost_user_set_features(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	uint64_t vhost_features = 0;
 	struct rte_vdpa_device *vdpa_dev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	rte_vhost_driver_get_features(dev->ifname, &vhost_features);
 	if (features & ~vhost_features) {
-		VHOST_LOG_CONFIG(ERR,
-			"(%d) received invalid negotiated features.\n",
-			dev->vid);
+		VHOST_LOG_CONFIG(ERR, "(%s) received invalid negotiated features.\n",
+			dev->ifname);
 		dev->flags |= VIRTIO_DEV_FEATURES_FAILED;
 		dev->status &= ~VIRTIO_DEVICE_STATUS_FEATURES_OK;
 
@@ -394,9 +394,8 @@ vhost_user_set_features(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		 * is enabled when the live-migration starts.
 		 */
 		if ((dev->features ^ features) & ~(1ULL << VHOST_F_LOG_ALL)) {
-			VHOST_LOG_CONFIG(ERR,
-				"(%d) features changed while device is running.\n",
-				dev->vid);
+			VHOST_LOG_CONFIG(ERR, "(%s) features changed while device is running.\n",
+				dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 
@@ -413,11 +412,10 @@ vhost_user_set_features(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	} else {
 		dev->vhost_hlen = sizeof(struct virtio_net_hdr);
 	}
-	VHOST_LOG_CONFIG(INFO,
-		"negotiated Virtio features: 0x%" PRIx64 "\n", dev->features);
-	VHOST_LOG_CONFIG(DEBUG,
-		"(%d) mergeable RX buffers %s, virtio 1 %s\n",
-		dev->vid,
+	VHOST_LOG_CONFIG(INFO, "(%s) negotiated Virtio features: 0x%" PRIx64 "\n",
+			dev->ifname, dev->features);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) mergeable RX buffers %s, virtio 1 %s\n",
+		dev->ifname,
 		(dev->features & (1 << VIRTIO_NET_F_MRG_RXBUF)) ? "on" : "off",
 		(dev->features & (1ULL << VIRTIO_F_VERSION_1)) ? "on" : "off");
 
@@ -461,11 +459,12 @@ vhost_user_set_vring_num(struct virtio_net **pdev,
 	struct virtio_net *dev = *pdev;
 	struct vhost_virtqueue *vq = dev->virtqueue[msg->payload.state.index];
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (msg->payload.state.num > 32768) {
-		VHOST_LOG_CONFIG(ERR, "invalid virtqueue size %u\n", msg->payload.state.num);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid virtqueue size %u\n",
+				dev->ifname, msg->payload.state.num);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -482,8 +481,8 @@ vhost_user_set_vring_num(struct virtio_net **pdev,
 	 */
 	if (!vq_is_packed(dev)) {
 		if (vq->size & (vq->size - 1)) {
-			VHOST_LOG_CONFIG(ERR,
-				"invalid virtqueue size %u\n", vq->size);
+			VHOST_LOG_CONFIG(ERR, "(%s) invalid virtqueue size %u\n",
+					dev->ifname, vq->size);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	}
@@ -497,7 +496,8 @@ vhost_user_set_vring_num(struct virtio_net **pdev,
 				RTE_CACHE_LINE_SIZE, vq->numa_node);
 		if (!vq->shadow_used_packed) {
 			VHOST_LOG_CONFIG(ERR,
-					"failed to allocate memory for shadow used ring.\n");
+				"(%s) failed to allocate memory for shadow used ring.\n",
+				dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 
@@ -511,7 +511,8 @@ vhost_user_set_vring_num(struct virtio_net **pdev,
 
 		if (!vq->shadow_used_split) {
 			VHOST_LOG_CONFIG(ERR,
-					"failed to allocate memory for vq internal data.\n");
+				"(%s) failed to allocate memory for vq internal data.\n",
+				dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	}
@@ -522,8 +523,8 @@ vhost_user_set_vring_num(struct virtio_net **pdev,
 				vq->size * sizeof(struct batch_copy_elem),
 				RTE_CACHE_LINE_SIZE, vq->numa_node);
 	if (!vq->batch_copy_elems) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to allocate memory for batching copy.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate memory for batching copy.\n",
+			dev->ifname);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -559,7 +560,8 @@ numa_realloc(struct virtio_net *dev, int index)
 
 	ret = get_mempolicy(&node, NULL, 0, vq->desc, MPOL_F_NODE | MPOL_F_ADDR);
 	if (ret) {
-		VHOST_LOG_CONFIG(ERR, "Unable to get virtqueue %d numa information.\n", index);
+		VHOST_LOG_CONFIG(ERR, "(%s) unable to get virtqueue %d numa information.\n",
+				dev->ifname, index);
 		return dev;
 	}
 
@@ -568,13 +570,14 @@ numa_realloc(struct virtio_net *dev, int index)
 
 	vq = rte_realloc_socket(vq, sizeof(*vq), 0, node);
 	if (!vq) {
-		VHOST_LOG_CONFIG(ERR, "Failed to realloc virtqueue %d on node %d\n",
-				index, node);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc virtqueue %d on node %d\n",
+				dev->ifname, index, node);
 		return dev;
 	}
 
 	if (vq != dev->virtqueue[index]) {
-		VHOST_LOG_CONFIG(INFO, "reallocated virtqueue on node %d\n", node);
+		VHOST_LOG_CONFIG(INFO, "(%s) reallocated virtqueue on node %d\n",
+				dev->ifname, node);
 		dev->virtqueue[index] = vq;
 		vhost_user_iotlb_init(dev, index);
 	}
@@ -585,7 +588,8 @@ numa_realloc(struct virtio_net *dev, int index)
 		sup = rte_realloc_socket(vq->shadow_used_packed, vq->size * sizeof(*sup),
 				RTE_CACHE_LINE_SIZE, node);
 		if (!sup) {
-			VHOST_LOG_CONFIG(ERR, "Failed to realloc shadow packed on node %d\n", node);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc shadow packed on node %d\n",
+					dev->ifname, node);
 			return dev;
 		}
 		vq->shadow_used_packed = sup;
@@ -595,7 +599,8 @@ numa_realloc(struct virtio_net *dev, int index)
 		sus = rte_realloc_socket(vq->shadow_used_split, vq->size * sizeof(*sus),
 				RTE_CACHE_LINE_SIZE, node);
 		if (!sus) {
-			VHOST_LOG_CONFIG(ERR, "Failed to realloc shadow split on node %d\n", node);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc shadow split on node %d\n",
+					dev->ifname, node);
 			return dev;
 		}
 		vq->shadow_used_split = sus;
@@ -604,7 +609,8 @@ numa_realloc(struct virtio_net *dev, int index)
 	bce = rte_realloc_socket(vq->batch_copy_elems, vq->size * sizeof(*bce),
 			RTE_CACHE_LINE_SIZE, node);
 	if (!bce) {
-		VHOST_LOG_CONFIG(ERR, "Failed to realloc batch copy elem on node %d\n", node);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc batch copy elem on node %d\n",
+				dev->ifname, node);
 		return dev;
 	}
 	vq->batch_copy_elems = bce;
@@ -614,7 +620,8 @@ numa_realloc(struct virtio_net *dev, int index)
 
 		lc = rte_realloc_socket(vq->log_cache, sizeof(*lc) * VHOST_LOG_CACHE_NR, 0, node);
 		if (!lc) {
-			VHOST_LOG_CONFIG(ERR, "Failed to realloc log cache on node %d\n", node);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc log cache on node %d\n",
+					dev->ifname, node);
 			return dev;
 		}
 		vq->log_cache = lc;
@@ -625,8 +632,8 @@ numa_realloc(struct virtio_net *dev, int index)
 
 		ri = rte_realloc_socket(vq->resubmit_inflight, sizeof(*ri), 0, node);
 		if (!ri) {
-			VHOST_LOG_CONFIG(ERR, "Failed to realloc resubmit inflight on node %d\n",
-					node);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc resubmit inflight on node %d\n",
+					dev->ifname, node);
 			return dev;
 		}
 		vq->resubmit_inflight = ri;
@@ -637,8 +644,8 @@ numa_realloc(struct virtio_net *dev, int index)
 			rd = rte_realloc_socket(ri->resubmit_list, sizeof(*rd) * ri->resubmit_num,
 					0, node);
 			if (!rd) {
-				VHOST_LOG_CONFIG(ERR, "Failed to realloc resubmit list on node %d\n",
-						node);
+				VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc resubmit list on node %d\n",
+						dev->ifname, node);
 				return dev;
 			}
 			ri->resubmit_list = rd;
@@ -654,7 +661,7 @@ numa_realloc(struct virtio_net *dev, int index)
 
 	ret = get_mempolicy(&dev_node, NULL, 0, dev, MPOL_F_NODE | MPOL_F_ADDR);
 	if (ret) {
-		VHOST_LOG_CONFIG(ERR, "Unable to get Virtio dev %d numa information.\n", dev->vid);
+		VHOST_LOG_CONFIG(ERR, "(%s) unable to get numa information.\n", dev->ifname);
 		return dev;
 	}
 
@@ -663,18 +670,20 @@ numa_realloc(struct virtio_net *dev, int index)
 
 	dev = rte_realloc_socket(old_dev, sizeof(*dev), 0, node);
 	if (!dev) {
-		VHOST_LOG_CONFIG(ERR, "Failed to realloc dev on node %d\n", node);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc dev on node %d\n",
+				dev->ifname, node);
 		return old_dev;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "reallocated device on node %d\n", node);
+	VHOST_LOG_CONFIG(INFO, "(%s) reallocated device on node %d\n", dev->ifname, node);
 	vhost_devices[dev->vid] = dev;
 
 	mem_size = sizeof(struct rte_vhost_memory) +
 		sizeof(struct rte_vhost_mem_region) * dev->mem->nregions;
 	mem = rte_realloc_socket(dev->mem, mem_size, 0, node);
 	if (!mem) {
-		VHOST_LOG_CONFIG(ERR, "Failed to realloc mem table on node %d\n", node);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc mem table on node %d\n",
+				dev->ifname, node);
 		return dev;
 	}
 	dev->mem = mem;
@@ -682,7 +691,8 @@ numa_realloc(struct virtio_net *dev, int index)
 	gp = rte_realloc_socket(dev->guest_pages, dev->max_guest_pages * sizeof(*gp),
 			RTE_CACHE_LINE_SIZE, node);
 	if (!gp) {
-		VHOST_LOG_CONFIG(ERR, "Failed to realloc guest pages on node %d\n", node);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to realloc guest pages on node %d\n",
+				dev->ifname, node);
 		return dev;
 	}
 	dev->guest_pages = gp;
@@ -774,9 +784,8 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 		vq->log_guest_addr =
 			log_addr_to_gpa(dev, vq);
 		if (vq->log_guest_addr == 0) {
-			VHOST_LOG_CONFIG(DEBUG,
-				"(%d) failed to map log_guest_addr.\n",
-				dev->vid);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) failed to map log_guest_addr.\n",
+				dev->ifname);
 			return dev;
 		}
 	}
@@ -788,9 +797,8 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 		if (vq->desc_packed == NULL ||
 				len != sizeof(struct vring_packed_desc) *
 				vq->size) {
-			VHOST_LOG_CONFIG(DEBUG,
-				"(%d) failed to map desc_packed ring.\n",
-				dev->vid);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) failed to map desc_packed ring.\n",
+				dev->ifname);
 			return dev;
 		}
 
@@ -804,9 +812,8 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 					vq, addr->avail_user_addr, &len);
 		if (vq->driver_event == NULL ||
 				len != sizeof(struct vring_packed_desc_event)) {
-			VHOST_LOG_CONFIG(DEBUG,
-				"(%d) failed to find driver area address.\n",
-				dev->vid);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) failed to find driver area address.\n",
+				dev->ifname);
 			return dev;
 		}
 
@@ -816,9 +823,8 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 					vq, addr->used_user_addr, &len);
 		if (vq->device_event == NULL ||
 				len != sizeof(struct vring_packed_desc_event)) {
-			VHOST_LOG_CONFIG(DEBUG,
-				"(%d) failed to find device area address.\n",
-				dev->vid);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) failed to find device area address.\n",
+				dev->ifname);
 			return dev;
 		}
 
@@ -834,9 +840,7 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 	vq->desc = (struct vring_desc *)(uintptr_t)ring_addr_to_vva(dev,
 			vq, addr->desc_user_addr, &len);
 	if (vq->desc == 0 || len != sizeof(struct vring_desc) * vq->size) {
-		VHOST_LOG_CONFIG(DEBUG,
-			"(%d) failed to map desc ring.\n",
-			dev->vid);
+		VHOST_LOG_CONFIG(DEBUG, "(%s) failed to map desc ring.\n", dev->ifname);
 		return dev;
 	}
 
@@ -851,9 +855,7 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 	vq->avail = (struct vring_avail *)(uintptr_t)ring_addr_to_vva(dev,
 			vq, addr->avail_user_addr, &len);
 	if (vq->avail == 0 || len != expected_len) {
-		VHOST_LOG_CONFIG(DEBUG,
-			"(%d) failed to map avail ring.\n",
-			dev->vid);
+		VHOST_LOG_CONFIG(DEBUG, "(%s) failed to map avail ring.\n", dev->ifname);
 		return dev;
 	}
 
@@ -865,16 +867,15 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 	vq->used = (struct vring_used *)(uintptr_t)ring_addr_to_vva(dev,
 			vq, addr->used_user_addr, &len);
 	if (vq->used == 0 || len != expected_len) {
-		VHOST_LOG_CONFIG(DEBUG,
-			"(%d) failed to map used ring.\n",
-			dev->vid);
+		VHOST_LOG_CONFIG(DEBUG, "(%s) failed to map used ring.\n", dev->ifname);
 		return dev;
 	}
 
 	if (vq->last_used_idx != vq->used->idx) {
 		VHOST_LOG_CONFIG(WARNING,
-			"last_used_idx (%u) and vq->used->idx (%u) mismatches; "
+			"(%s) last_used_idx (%u) and vq->used->idx (%u) mismatches; "
 			"some packets maybe resent for Tx and dropped for Rx\n",
+			dev->ifname,
 			vq->last_used_idx, vq->used->idx);
 		vq->last_used_idx  = vq->used->idx;
 		vq->last_avail_idx = vq->used->idx;
@@ -882,14 +883,11 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 
 	vq->access_ok = true;
 
-	VHOST_LOG_CONFIG(DEBUG, "(%d) mapped address desc: %p\n",
-			dev->vid, vq->desc);
-	VHOST_LOG_CONFIG(DEBUG, "(%d) mapped address avail: %p\n",
-			dev->vid, vq->avail);
-	VHOST_LOG_CONFIG(DEBUG, "(%d) mapped address used: %p\n",
-			dev->vid, vq->used);
-	VHOST_LOG_CONFIG(DEBUG, "(%d) log_guest_addr: %" PRIx64 "\n",
-			dev->vid, vq->log_guest_addr);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) mapped address desc: %p\n", dev->ifname, vq->desc);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) mapped address avail: %p\n", dev->ifname, vq->avail);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) mapped address used: %p\n", dev->ifname, vq->used);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) log_guest_addr: %" PRIx64 "\n",
+			dev->ifname, vq->log_guest_addr);
 
 	return dev;
 }
@@ -907,7 +905,7 @@ vhost_user_set_vring_addr(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	struct vhost_vring_addr *addr = &msg->payload.addr;
 	bool access_ok;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (dev->mem == NULL)
@@ -951,7 +949,7 @@ vhost_user_set_vring_base(struct virtio_net **pdev,
 	struct vhost_virtqueue *vq = dev->virtqueue[msg->payload.state.index];
 	uint64_t val = msg->payload.state.num;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (vq_is_packed(dev)) {
@@ -990,7 +988,7 @@ add_one_guest_page(struct virtio_net *dev, uint64_t guest_phys_addr,
 					dev->max_guest_pages * sizeof(*page),
 					RTE_CACHE_LINE_SIZE);
 		if (dev->guest_pages == NULL) {
-			VHOST_LOG_CONFIG(ERR, "cannot realloc guest_pages\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) cannot realloc guest_pages\n", dev->ifname);
 			rte_free(old_pages);
 			return -1;
 		}
@@ -1069,11 +1067,11 @@ dump_guest_pages(struct virtio_net *dev)
 		page = &dev->guest_pages[i];
 
 		VHOST_LOG_CONFIG(INFO,
-			"guest physical page region %u\n"
+			"(%s) guest physical page region %u\n"
 			"\t guest_phys_addr: %" PRIx64 "\n"
 			"\t host_phys_addr : %" PRIx64 "\n"
 			"\t size           : %" PRIx64 "\n",
-			i,
+			dev->ifname, i,
 			page->guest_phys_addr,
 			page->host_phys_addr,
 			page->size);
@@ -1124,8 +1122,9 @@ vhost_user_postcopy_region_register(struct virtio_net *dev,
 
 	if (ioctl(dev->postcopy_ufd, UFFDIO_REGISTER,
 				&reg_struct)) {
-		VHOST_LOG_CONFIG(ERR, "Failed to register ufd for region "
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to register ufd for region "
 				"%" PRIx64 " - %" PRIx64 " (ufd = %d) %s\n",
+				dev->ifname,
 				(uint64_t)reg_struct.range.start,
 				(uint64_t)reg_struct.range.start +
 				(uint64_t)reg_struct.range.len - 1,
@@ -1134,7 +1133,8 @@ vhost_user_postcopy_region_register(struct virtio_net *dev,
 		return -1;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "\t userfaultfd registered for range : %" PRIx64 " - %" PRIx64 "\n",
+	VHOST_LOG_CONFIG(INFO, "(%s)\t userfaultfd registered for range : %" PRIx64 " - %" PRIx64 "\n",
+			dev->ifname,
 			(uint64_t)reg_struct.range.start,
 			(uint64_t)reg_struct.range.start +
 			(uint64_t)reg_struct.range.len - 1);
@@ -1180,19 +1180,18 @@ vhost_user_postcopy_register(struct virtio_net *dev, int main_fd,
 	/* Wait for qemu to acknowledge it got the addresses
 	 * we've got to wait before we're allowed to generate faults.
 	 */
-	if (read_vhost_message(main_fd, &ack_msg) <= 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"Failed to read qemu ack on postcopy set-mem-table\n");
+	if (read_vhost_message(dev, main_fd, &ack_msg) <= 0) {
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to read qemu ack on postcopy set-mem-table\n",
+				dev->ifname);
 		return -1;
 	}
 
-	if (validate_msg_fds(&ack_msg, 0) != 0)
+	if (validate_msg_fds(dev, &ack_msg, 0) != 0)
 		return -1;
 
 	if (ack_msg.request.master != VHOST_USER_SET_MEM_TABLE) {
-		VHOST_LOG_CONFIG(ERR,
-				"Bad qemu ack on postcopy set-mem-table (%d)\n",
-				ack_msg.request.master);
+		VHOST_LOG_CONFIG(ERR, "(%s) bad qemu ack on postcopy set-mem-table (%d)\n",
+				dev->ifname, ack_msg.request.master);
 		return -1;
 	}
 
@@ -1219,10 +1218,9 @@ vhost_user_mmap_region(struct virtio_net *dev,
 
 	/* Check for memory_size + mmap_offset overflow */
 	if (mmap_offset >= -region->size) {
-		VHOST_LOG_CONFIG(ERR,
-				"mmap_offset (%#"PRIx64") and memory_size "
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap_offset (%#"PRIx64") and memory_size "
 				"(%#"PRIx64") overflow\n",
-				mmap_offset, region->size);
+				dev->ifname, mmap_offset, region->size);
 		return -1;
 	}
 
@@ -1236,8 +1234,8 @@ vhost_user_mmap_region(struct virtio_net *dev,
 	 */
 	alignment = get_blk_size(region->fd);
 	if (alignment == (uint64_t)-1) {
-		VHOST_LOG_CONFIG(ERR,
-				"couldn't get hugepage size through fstat\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) couldn't get hugepage size through fstat\n",
+				dev->ifname);
 		return -1;
 	}
 	mmap_size = RTE_ALIGN_CEIL(mmap_size, alignment);
@@ -1250,9 +1248,9 @@ vhost_user_mmap_region(struct virtio_net *dev,
 		 * mmap() kernel implementation would return an error, but
 		 * better catch it before and provide useful info in the logs.
 		 */
-		VHOST_LOG_CONFIG(ERR, "mmap size (0x%" PRIx64 ") "
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap size (0x%" PRIx64 ") "
 				"or alignment (0x%" PRIx64 ") is invalid\n",
-				region->size + mmap_offset, alignment);
+				dev->ifname, region->size + mmap_offset, alignment);
 		return -1;
 	}
 
@@ -1261,7 +1259,7 @@ vhost_user_mmap_region(struct virtio_net *dev,
 			MAP_SHARED | populate, region->fd, 0);
 
 	if (mmap_addr == MAP_FAILED) {
-		VHOST_LOG_CONFIG(ERR, "mmap failed (%s).\n", strerror(errno));
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap failed (%s).\n", dev->ifname, strerror(errno));
 		return -1;
 	}
 
@@ -1271,21 +1269,24 @@ vhost_user_mmap_region(struct virtio_net *dev,
 
 	if (dev->async_copy) {
 		if (add_guest_pages(dev, region, alignment) < 0) {
-			VHOST_LOG_CONFIG(ERR, "adding guest pages to region failed.\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) adding guest pages to region failed.\n",
+					dev->ifname);
 			return -1;
 		}
 
 		if (rte_vfio_is_enabled("vfio")) {
-			ret = async_dma_map(region, true);
+			ret = async_dma_map(dev, region, true);
 			if (ret) {
-				VHOST_LOG_CONFIG(ERR, "Configure IOMMU for DMA engine failed\n");
+				VHOST_LOG_CONFIG(ERR,
+					"(%s) configure IOMMU for DMA engine failed\n",
+					dev->ifname);
 				return -1;
 			}
 		}
 	}
 
 	VHOST_LOG_CONFIG(INFO,
-			"guest memory region size: 0x%" PRIx64 "\n"
+			"(%s) guest memory region size: 0x%" PRIx64 "\n"
 			"\t guest physical addr: 0x%" PRIx64 "\n"
 			"\t guest virtual  addr: 0x%" PRIx64 "\n"
 			"\t host  virtual  addr: 0x%" PRIx64 "\n"
@@ -1293,6 +1294,7 @@ vhost_user_mmap_region(struct virtio_net *dev,
 			"\t mmap size : 0x%" PRIx64 "\n"
 			"\t mmap align: 0x%" PRIx64 "\n"
 			"\t mmap off  : 0x%" PRIx64 "\n",
+			dev->ifname,
 			region->size,
 			region->guest_phys_addr,
 			region->guest_user_addr,
@@ -1317,18 +1319,17 @@ vhost_user_set_mem_table(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	uint32_t i;
 	bool async_notify = false;
 
-	if (validate_msg_fds(msg, memory->nregions) != 0)
+	if (validate_msg_fds(dev, msg, memory->nregions) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (memory->nregions > VHOST_MEMORY_MAX_NREGIONS) {
-		VHOST_LOG_CONFIG(ERR,
-			"too many memory regions (%u)\n", memory->nregions);
+		VHOST_LOG_CONFIG(ERR, "(%s) too many memory regions (%u)\n",
+				dev->ifname, memory->nregions);
 		goto close_msg_fds;
 	}
 
 	if (dev->mem && !vhost_memory_changed(memory, dev->mem)) {
-		VHOST_LOG_CONFIG(INFO,
-			"(%d) memory regions not changed\n", dev->vid);
+		VHOST_LOG_CONFIG(INFO, "(%s) memory regions not changed\n", dev->ifname);
 
 		close_msg_fds(msg);
 
@@ -1380,9 +1381,8 @@ vhost_user_set_mem_table(struct virtio_net **pdev, struct VhostUserMsg *msg,
 					numa_node);
 		if (dev->guest_pages == NULL) {
 			VHOST_LOG_CONFIG(ERR,
-				"(%d) failed to allocate memory "
-				"for dev->guest_pages\n",
-				dev->vid);
+				"(%s) failed to allocate memory for dev->guest_pages\n",
+				dev->ifname);
 			goto close_msg_fds;
 		}
 	}
@@ -1391,8 +1391,8 @@ vhost_user_set_mem_table(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		sizeof(struct rte_vhost_mem_region) * memory->nregions, 0, numa_node);
 	if (dev->mem == NULL) {
 		VHOST_LOG_CONFIG(ERR,
-			"(%d) failed to allocate memory for dev->mem\n",
-			dev->vid);
+			"(%s) failed to allocate memory for dev->mem\n",
+			dev->ifname);
 		goto free_guest_pages;
 	}
 
@@ -1413,7 +1413,7 @@ vhost_user_set_mem_table(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		mmap_offset = memory->regions[i].mmap_offset;
 
 		if (vhost_user_mmap_region(dev, reg, mmap_offset) < 0) {
-			VHOST_LOG_CONFIG(ERR, "Failed to mmap region %u\n", i);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to mmap region %u\n", dev->ifname, i);
 			goto free_mem_table;
 		}
 
@@ -1525,13 +1525,12 @@ virtio_is_ready(struct virtio_net *dev)
 	dev->flags |= VIRTIO_DEV_READY;
 
 	if (!(dev->flags & VIRTIO_DEV_RUNNING))
-		VHOST_LOG_CONFIG(INFO,
-			"virtio is now ready for processing.\n");
+		VHOST_LOG_CONFIG(INFO, "(%s) virtio is now ready for processing.\n", dev->ifname);
 	return 1;
 }
 
 static void *
-inflight_mem_alloc(const char *name, size_t size, int *fd)
+inflight_mem_alloc(struct virtio_net *dev, const char *name, size_t size, int *fd)
 {
 	void *ptr;
 	int mfd = -1;
@@ -1546,8 +1545,8 @@ inflight_mem_alloc(const char *name, size_t size, int *fd)
 	if (mfd == -1) {
 		mfd = mkstemp(fname);
 		if (mfd == -1) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to get inflight buffer fd\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to get inflight buffer fd\n",
+					dev->ifname);
 			return NULL;
 		}
 
@@ -1555,16 +1554,14 @@ inflight_mem_alloc(const char *name, size_t size, int *fd)
 	}
 
 	if (ftruncate(mfd, size) == -1) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to alloc inflight buffer\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to alloc inflight buffer\n", dev->ifname);
 		close(mfd);
 		return NULL;
 	}
 
 	ptr = mmap(0, size, PROT_READ | PROT_WRITE, MAP_SHARED, mfd, 0);
 	if (ptr == MAP_FAILED) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to mmap inflight buffer\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to mmap inflight buffer\n", dev->ifname);
 		close(mfd);
 		return NULL;
 	}
@@ -1604,9 +1601,8 @@ vhost_user_get_inflight_fd(struct virtio_net **pdev,
 	void *addr;
 
 	if (msg->size != sizeof(msg->payload.inflight)) {
-		VHOST_LOG_CONFIG(ERR,
-			"invalid get_inflight_fd message size is %d\n",
-			msg->size);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid get_inflight_fd message size is %d\n",
+			dev->ifname, msg->size);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -1621,8 +1617,8 @@ vhost_user_get_inflight_fd(struct virtio_net **pdev,
 		dev->inflight_info = rte_zmalloc_socket("inflight_info",
 				sizeof(struct inflight_mem_info), 0, numa_node);
 		if (!dev->inflight_info) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to alloc dev inflight area\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to alloc dev inflight area\n",
+					dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 		dev->inflight_info->fd = -1;
@@ -1631,10 +1627,10 @@ vhost_user_get_inflight_fd(struct virtio_net **pdev,
 	num_queues = msg->payload.inflight.num_queues;
 	queue_size = msg->payload.inflight.queue_size;
 
-	VHOST_LOG_CONFIG(INFO, "get_inflight_fd num_queues: %u\n",
-		msg->payload.inflight.num_queues);
-	VHOST_LOG_CONFIG(INFO, "get_inflight_fd queue_size: %u\n",
-		msg->payload.inflight.queue_size);
+	VHOST_LOG_CONFIG(INFO, "(%s) get_inflight_fd num_queues: %u\n",
+		dev->ifname, msg->payload.inflight.num_queues);
+	VHOST_LOG_CONFIG(INFO, "(%s) get_inflight_fd queue_size: %u\n",
+		dev->ifname, msg->payload.inflight.queue_size);
 
 	if (vq_is_packed(dev))
 		pervq_inflight_size = get_pervq_shm_size_packed(queue_size);
@@ -1642,10 +1638,9 @@ vhost_user_get_inflight_fd(struct virtio_net **pdev,
 		pervq_inflight_size = get_pervq_shm_size_split(queue_size);
 
 	mmap_size = num_queues * pervq_inflight_size;
-	addr = inflight_mem_alloc("vhost-inflight", mmap_size, &fd);
+	addr = inflight_mem_alloc(dev, "vhost-inflight", mmap_size, &fd);
 	if (!addr) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to alloc vhost inflight area\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to alloc vhost inflight area\n", dev->ifname);
 			msg->payload.inflight.mmap_size = 0;
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
@@ -1679,14 +1674,11 @@ vhost_user_get_inflight_fd(struct virtio_net **pdev,
 		}
 	}
 
-	VHOST_LOG_CONFIG(INFO,
-		"send inflight mmap_size: %"PRIu64"\n",
-		msg->payload.inflight.mmap_size);
-	VHOST_LOG_CONFIG(INFO,
-		"send inflight mmap_offset: %"PRIu64"\n",
-		msg->payload.inflight.mmap_offset);
-	VHOST_LOG_CONFIG(INFO,
-		"send inflight fd: %d\n", msg->fds[0]);
+	VHOST_LOG_CONFIG(INFO, "(%s) send inflight mmap_size: %"PRIu64"\n",
+			dev->ifname, msg->payload.inflight.mmap_size);
+	VHOST_LOG_CONFIG(INFO, "(%s) send inflight mmap_offset: %"PRIu64"\n",
+			dev->ifname, msg->payload.inflight.mmap_offset);
+	VHOST_LOG_CONFIG(INFO, "(%s) send inflight fd: %d\n", dev->ifname, msg->fds[0]);
 
 	return RTE_VHOST_MSG_RESULT_REPLY;
 }
@@ -1706,9 +1698,8 @@ vhost_user_set_inflight_fd(struct virtio_net **pdev, VhostUserMsg *msg,
 
 	fd = msg->fds[0];
 	if (msg->size != sizeof(msg->payload.inflight) || fd < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"invalid set_inflight_fd message size is %d,fd is %d\n",
-			msg->size, fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid set_inflight_fd message size is %d,fd is %d\n",
+			dev->ifname, msg->size, fd);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -1722,19 +1713,15 @@ vhost_user_set_inflight_fd(struct virtio_net **pdev, VhostUserMsg *msg,
 	else
 		pervq_inflight_size = get_pervq_shm_size_split(queue_size);
 
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd mmap_size: %"PRIu64"\n", mmap_size);
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd mmap_offset: %"PRIu64"\n", mmap_offset);
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd num_queues: %u\n", num_queues);
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd queue_size: %u\n", queue_size);
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd fd: %d\n", fd);
-	VHOST_LOG_CONFIG(INFO,
-		"set_inflight_fd pervq_inflight_size: %d\n",
-		pervq_inflight_size);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd mmap_size: %"PRIu64"\n",
+			dev->ifname, mmap_size);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd mmap_offset: %"PRIu64"\n",
+			dev->ifname, mmap_offset);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd num_queues: %u\n", dev->ifname, num_queues);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd queue_size: %u\n", dev->ifname, queue_size);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd fd: %d\n", dev->ifname, fd);
+	VHOST_LOG_CONFIG(INFO, "(%s) set_inflight_fd pervq_inflight_size: %d\n",
+			dev->ifname, pervq_inflight_size);
 
 	/*
 	 * If VQ 0 has already been allocated, try to allocate on the same
@@ -1747,8 +1734,8 @@ vhost_user_set_inflight_fd(struct virtio_net **pdev, VhostUserMsg *msg,
 		dev->inflight_info = rte_zmalloc_socket("inflight_info",
 				sizeof(struct inflight_mem_info), 0, numa_node);
 		if (dev->inflight_info == NULL) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to alloc dev inflight area\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to alloc dev inflight area\n",
+					dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 		dev->inflight_info->fd = -1;
@@ -1762,7 +1749,7 @@ vhost_user_set_inflight_fd(struct virtio_net **pdev, VhostUserMsg *msg,
 	addr = mmap(0, mmap_size, PROT_READ | PROT_WRITE, MAP_SHARED,
 		    fd, mmap_offset);
 	if (addr == MAP_FAILED) {
-		VHOST_LOG_CONFIG(ERR, "failed to mmap share memory.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to mmap share memory.\n", dev->ifname);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -1803,7 +1790,7 @@ vhost_user_set_vring_call(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	int expected_fds;
 
 	expected_fds = (msg->payload.u64 & VHOST_USER_VRING_NOFD_MASK) ? 0 : 1;
-	if (validate_msg_fds(msg, expected_fds) != 0)
+	if (validate_msg_fds(dev, msg, expected_fds) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	file.index = msg->payload.u64 & VHOST_USER_VRING_IDX_MASK;
@@ -1811,8 +1798,8 @@ vhost_user_set_vring_call(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		file.fd = VIRTIO_INVALID_EVENTFD;
 	else
 		file.fd = msg->fds[0];
-	VHOST_LOG_CONFIG(INFO,
-		"vring call idx:%d file:%d\n", file.index, file.fd);
+	VHOST_LOG_CONFIG(INFO, "(%s) vring call idx:%d file:%d\n",
+			dev->ifname, file.index, file.fd);
 
 	vq = dev->virtqueue[file.index];
 
@@ -1829,19 +1816,20 @@ vhost_user_set_vring_call(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	return RTE_VHOST_MSG_RESULT_OK;
 }
 
-static int vhost_user_set_vring_err(struct virtio_net **pdev __rte_unused,
+static int vhost_user_set_vring_err(struct virtio_net **pdev,
 			struct VhostUserMsg *msg,
 			int main_fd __rte_unused)
 {
+	struct virtio_net *dev = *pdev;
 	int expected_fds;
 
 	expected_fds = (msg->payload.u64 & VHOST_USER_VRING_NOFD_MASK) ? 0 : 1;
-	if (validate_msg_fds(msg, expected_fds) != 0)
+	if (validate_msg_fds(dev, msg, expected_fds) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (!(msg->payload.u64 & VHOST_USER_VRING_NOFD_MASK))
 		close(msg->fds[0]);
-	VHOST_LOG_CONFIG(INFO, "not implemented\n");
+	VHOST_LOG_CONFIG(INFO, "(%s) not implemented\n", dev->ifname);
 
 	return RTE_VHOST_MSG_RESULT_OK;
 }
@@ -1908,7 +1896,8 @@ vhost_check_queue_inflights_split(struct virtio_net *dev,
 				0, vq->numa_node);
 		if (!resubmit) {
 			VHOST_LOG_CONFIG(ERR,
-				"failed to allocate memory for resubmit info.\n");
+					"(%s) failed to allocate memory for resubmit info.\n",
+					dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 
@@ -1917,7 +1906,8 @@ vhost_check_queue_inflights_split(struct virtio_net *dev,
 				0, vq->numa_node);
 		if (!resubmit->resubmit_list) {
 			VHOST_LOG_CONFIG(ERR,
-				"failed to allocate memory for inflight desc.\n");
+					"(%s) failed to allocate memory for inflight desc.\n",
+					dev->ifname);
 			rte_free(resubmit);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
@@ -2004,7 +1994,8 @@ vhost_check_queue_inflights_packed(struct virtio_net *dev,
 				0, vq->numa_node);
 		if (resubmit == NULL) {
 			VHOST_LOG_CONFIG(ERR,
-				"failed to allocate memory for resubmit info.\n");
+					"(%s) failed to allocate memory for resubmit info.\n",
+					dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 
@@ -2013,7 +2004,8 @@ vhost_check_queue_inflights_packed(struct virtio_net *dev,
 				0, vq->numa_node);
 		if (resubmit->resubmit_list == NULL) {
 			VHOST_LOG_CONFIG(ERR,
-				"failed to allocate memory for resubmit desc.\n");
+					"(%s) failed to allocate memory for resubmit desc.\n",
+					dev->ifname);
 			rte_free(resubmit);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
@@ -2051,7 +2043,7 @@ vhost_user_set_vring_kick(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	int expected_fds;
 
 	expected_fds = (msg->payload.u64 & VHOST_USER_VRING_NOFD_MASK) ? 0 : 1;
-	if (validate_msg_fds(msg, expected_fds) != 0)
+	if (validate_msg_fds(dev, msg, expected_fds) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	file.index = msg->payload.u64 & VHOST_USER_VRING_IDX_MASK;
@@ -2059,8 +2051,8 @@ vhost_user_set_vring_kick(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		file.fd = VIRTIO_INVALID_EVENTFD;
 	else
 		file.fd = msg->fds[0];
-	VHOST_LOG_CONFIG(INFO,
-		"vring kick idx:%d file:%d\n", file.index, file.fd);
+	VHOST_LOG_CONFIG(INFO, "(%s) vring kick idx:%d file:%d\n",
+			dev->ifname, file.index, file.fd);
 
 	/* Interpret ring addresses only when ring is started. */
 	dev = translate_ring_addresses(dev, file.index);
@@ -2095,14 +2087,14 @@ vhost_user_set_vring_kick(struct virtio_net **pdev, struct VhostUserMsg *msg,
 
 	if (vq_is_packed(dev)) {
 		if (vhost_check_queue_inflights_packed(dev, vq)) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to inflights for vq: %d\n", file.index);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to inflights for vq: %d\n",
+					dev->ifname, file.index);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	} else {
 		if (vhost_check_queue_inflights_split(dev, vq)) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to inflights for vq: %d\n", file.index);
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to inflights for vq: %d\n",
+					dev->ifname, file.index);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	}
@@ -2122,7 +2114,7 @@ vhost_user_get_vring_base(struct virtio_net **pdev,
 	struct vhost_virtqueue *vq = dev->virtqueue[msg->payload.state.index];
 	uint64_t val;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	/* We have to stop the queue (virtio) if it is running. */
@@ -2144,9 +2136,9 @@ vhost_user_get_vring_base(struct virtio_net **pdev,
 		msg->payload.state.num = vq->last_avail_idx;
 	}
 
-	VHOST_LOG_CONFIG(INFO,
-		"vring base idx:%d file:%d\n", msg->payload.state.index,
-		msg->payload.state.num);
+	VHOST_LOG_CONFIG(INFO, "(%s) vring base idx:%d file:%d\n",
+			dev->ifname, msg->payload.state.index,
+			msg->payload.state.num);
 	/*
 	 * Based on current qemu vhost-user implementation, this message is
 	 * sent and only sent in vhost_vring_stop.
@@ -2201,17 +2193,17 @@ vhost_user_set_vring_enable(struct virtio_net **pdev,
 	bool enable = !!msg->payload.state.num;
 	int index = (int)msg->payload.state.index;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
-	VHOST_LOG_CONFIG(INFO,
-		"set queue enable: %d to qp idx: %d\n",
-		enable, index);
+	VHOST_LOG_CONFIG(INFO, "(%s) set queue enable: %d to qp idx: %d\n",
+			dev->ifname, enable, index);
 
 	if (enable && dev->virtqueue[index]->async) {
 		if (dev->virtqueue[index]->async->pkts_inflight_n) {
-			VHOST_LOG_CONFIG(ERR, "failed to enable vring. "
-			"async inflight packets must be completed first\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to enable vring. "
+			"async inflight packets must be completed first\n",
+			dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	}
@@ -2229,7 +2221,7 @@ vhost_user_get_protocol_features(struct virtio_net **pdev,
 	struct virtio_net *dev = *pdev;
 	uint64_t features, protocol_features;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	rte_vhost_driver_get_features(dev->ifname, &features);
@@ -2251,22 +2243,19 @@ vhost_user_set_protocol_features(struct virtio_net **pdev,
 	uint64_t protocol_features = msg->payload.u64;
 	uint64_t slave_protocol_features = 0;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	rte_vhost_driver_get_protocol_features(dev->ifname,
 			&slave_protocol_features);
 	if (protocol_features & ~slave_protocol_features) {
-		VHOST_LOG_CONFIG(ERR,
-			"(%d) received invalid protocol features.\n",
-			dev->vid);
+		VHOST_LOG_CONFIG(ERR, "(%s) received invalid protocol features.\n", dev->ifname);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
 	dev->protocol_features = protocol_features;
-	VHOST_LOG_CONFIG(INFO,
-		"negotiated Vhost-user protocol features: 0x%" PRIx64 "\n",
-		dev->protocol_features);
+	VHOST_LOG_CONFIG(INFO, "(%s) negotiated Vhost-user protocol features: 0x%" PRIx64 "\n",
+		dev->ifname, dev->protocol_features);
 
 	return RTE_VHOST_MSG_RESULT_OK;
 }
@@ -2281,18 +2270,17 @@ vhost_user_set_log_base(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	void *addr;
 	uint32_t i;
 
-	if (validate_msg_fds(msg, 1) != 0)
+	if (validate_msg_fds(dev, msg, 1) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (fd < 0) {
-		VHOST_LOG_CONFIG(ERR, "invalid log fd: %d\n", fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid log fd: %d\n", dev->ifname, fd);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
 	if (msg->size != sizeof(VhostUserLog)) {
-		VHOST_LOG_CONFIG(ERR,
-			"invalid log base msg size: %"PRId32" != %d\n",
-			msg->size, (int)sizeof(VhostUserLog));
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid log base msg size: %"PRId32" != %d\n",
+			dev->ifname, msg->size, (int)sizeof(VhostUserLog));
 		goto close_msg_fds;
 	}
 
@@ -2302,14 +2290,13 @@ vhost_user_set_log_base(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	/* Check for mmap size and offset overflow. */
 	if (off >= -size) {
 		VHOST_LOG_CONFIG(ERR,
-			"log offset %#"PRIx64" and log size %#"PRIx64" overflow\n",
-			off, size);
+				"(%s) log offset %#"PRIx64" and log size %#"PRIx64" overflow\n",
+				dev->ifname, off, size);
 		goto close_msg_fds;
 	}
 
-	VHOST_LOG_CONFIG(INFO,
-		"log mmap size: %"PRId64", offset: %"PRId64"\n",
-		size, off);
+	VHOST_LOG_CONFIG(INFO, "(%s) log mmap size: %"PRId64", offset: %"PRId64"\n",
+			dev->ifname, size, off);
 
 	/*
 	 * mmap from 0 to workaround a hugepage mmap bug: mmap will
@@ -2318,7 +2305,7 @@ vhost_user_set_log_base(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	addr = mmap(0, size + off, PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0);
 	close(fd);
 	if (addr == MAP_FAILED) {
-		VHOST_LOG_CONFIG(ERR, "mmap log base failed!\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap log base failed!\n", dev->ifname);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -2347,7 +2334,8 @@ vhost_user_set_log_base(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		 * caching will be done, which will impact performance
 		 */
 		if (!vq->log_cache)
-			VHOST_LOG_CONFIG(ERR, "Failed to allocate VQ logging cache\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate VQ logging cache\n",
+					dev->ifname);
 	}
 
 	/*
@@ -2364,15 +2352,17 @@ vhost_user_set_log_base(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	return RTE_VHOST_MSG_RESULT_ERR;
 }
 
-static int vhost_user_set_log_fd(struct virtio_net **pdev __rte_unused,
+static int vhost_user_set_log_fd(struct virtio_net **pdev,
 			struct VhostUserMsg *msg,
 			int main_fd __rte_unused)
 {
-	if (validate_msg_fds(msg, 1) != 0)
+	struct virtio_net *dev = *pdev;
+
+	if (validate_msg_fds(dev, msg, 1) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	close(msg->fds[0]);
-	VHOST_LOG_CONFIG(INFO, "not implemented.\n");
+	VHOST_LOG_CONFIG(INFO, "(%s) not implemented.\n", dev->ifname);
 
 	return RTE_VHOST_MSG_RESULT_OK;
 }
@@ -2393,12 +2383,11 @@ vhost_user_send_rarp(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	uint8_t *mac = (uint8_t *)&msg->payload.u64;
 	struct rte_vdpa_device *vdpa_dev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
-	VHOST_LOG_CONFIG(DEBUG,
-		":: mac: " RTE_ETHER_ADDR_PRT_FMT "\n",
-		mac[0], mac[1], mac[2], mac[3], mac[4], mac[5]);
+	VHOST_LOG_CONFIG(DEBUG, "(%s) MAC: " RTE_ETHER_ADDR_PRT_FMT "\n",
+		dev->ifname, mac[0], mac[1], mac[2], mac[3], mac[4], mac[5]);
 	memcpy(dev->mac.addr_bytes, mac, 6);
 
 	/*
@@ -2422,13 +2411,13 @@ vhost_user_net_set_mtu(struct virtio_net **pdev, struct VhostUserMsg *msg,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (msg->payload.u64 < VIRTIO_MIN_MTU ||
 			msg->payload.u64 > VIRTIO_MAX_MTU) {
-		VHOST_LOG_CONFIG(ERR, "Invalid MTU size (%"PRIu64")\n",
-				msg->payload.u64);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid MTU size (%"PRIu64")\n",
+				dev->ifname, msg->payload.u64);
 
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
@@ -2445,13 +2434,12 @@ vhost_user_set_req_fd(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	struct virtio_net *dev = *pdev;
 	int fd = msg->fds[0];
 
-	if (validate_msg_fds(msg, 1) != 0)
+	if (validate_msg_fds(dev, msg, 1) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (fd < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"Invalid file descriptor for slave channel (%d)\n",
-				fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid file descriptor for slave channel (%d)\n",
+				dev->ifname, fd);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -2547,7 +2535,7 @@ vhost_user_iotlb_msg(struct virtio_net **pdev, struct VhostUserMsg *msg,
 	uint16_t i;
 	uint64_t vva, len;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	switch (imsg->type) {
@@ -2585,8 +2573,8 @@ vhost_user_iotlb_msg(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		}
 		break;
 	default:
-		VHOST_LOG_CONFIG(ERR, "Invalid IOTLB message type (%d)\n",
-				imsg->type);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid IOTLB message type (%d)\n",
+				dev->ifname, imsg->type);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -2602,21 +2590,21 @@ vhost_user_set_postcopy_advise(struct virtio_net **pdev,
 #ifdef RTE_LIBRTE_VHOST_POSTCOPY
 	struct uffdio_api api_struct;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	dev->postcopy_ufd = syscall(__NR_userfaultfd, O_CLOEXEC | O_NONBLOCK);
 
 	if (dev->postcopy_ufd == -1) {
-		VHOST_LOG_CONFIG(ERR, "Userfaultfd not available: %s\n",
-			strerror(errno));
+		VHOST_LOG_CONFIG(ERR, "(%s) userfaultfd not available: %s\n",
+			dev->ifname, strerror(errno));
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 	api_struct.api = UFFD_API;
 	api_struct.features = 0;
 	if (ioctl(dev->postcopy_ufd, UFFDIO_API, &api_struct)) {
-		VHOST_LOG_CONFIG(ERR, "UFFDIO_API ioctl failure: %s\n",
-			strerror(errno));
+		VHOST_LOG_CONFIG(ERR, "(%s) UFFDIO_API ioctl failure: %s\n",
+			dev->ifname, strerror(errno));
 		close(dev->postcopy_ufd);
 		dev->postcopy_ufd = -1;
 		return RTE_VHOST_MSG_RESULT_ERR;
@@ -2640,12 +2628,12 @@ vhost_user_set_postcopy_listen(struct virtio_net **pdev,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	if (dev->mem && dev->mem->nregions) {
-		VHOST_LOG_CONFIG(ERR,
-			"Regions already registered at postcopy-listen\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) regions already registered at postcopy-listen\n",
+				dev->ifname);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 	dev->postcopy_listening = 1;
@@ -2659,7 +2647,7 @@ vhost_user_postcopy_end(struct virtio_net **pdev, struct VhostUserMsg *msg,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	dev->postcopy_listening = 0;
@@ -2681,7 +2669,7 @@ vhost_user_get_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	msg->payload.u64 = dev->status;
@@ -2697,13 +2685,13 @@ vhost_user_set_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 {
 	struct virtio_net *dev = *pdev;
 
-	if (validate_msg_fds(msg, 0) != 0)
+	if (validate_msg_fds(dev, msg, 0) != 0)
 		return RTE_VHOST_MSG_RESULT_ERR;
 
 	/* As per Virtio specification, the device status is 8bits long */
 	if (msg->payload.u64 > UINT8_MAX) {
-		VHOST_LOG_CONFIG(ERR, "Invalid VHOST_USER_SET_STATUS payload 0x%" PRIx64 "\n",
-				msg->payload.u64);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid VHOST_USER_SET_STATUS payload 0x%" PRIx64 "\n",
+				dev->ifname, msg->payload.u64);
 		return RTE_VHOST_MSG_RESULT_ERR;
 	}
 
@@ -2711,7 +2699,9 @@ vhost_user_set_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 
 	if ((dev->status & VIRTIO_DEVICE_STATUS_FEATURES_OK) &&
 	    (dev->flags & VIRTIO_DEV_FEATURES_FAILED)) {
-		VHOST_LOG_CONFIG(ERR, "FEATURES_OK bit is set but feature negotiation failed\n");
+		VHOST_LOG_CONFIG(ERR,
+				"(%s) FEATURES_OK bit is set but feature negotiation failed\n",
+				dev->ifname);
 		/*
 		 * Clear the bit to let the driver know about the feature
 		 * negotiation failure
@@ -2719,7 +2709,7 @@ vhost_user_set_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		dev->status &= ~VIRTIO_DEVICE_STATUS_FEATURES_OK;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "New device status(0x%08x):\n"
+	VHOST_LOG_CONFIG(INFO, "(%s) new device status(0x%08x):\n"
 			"\t-RESET: %u\n"
 			"\t-ACKNOWLEDGE: %u\n"
 			"\t-DRIVER: %u\n"
@@ -2727,6 +2717,7 @@ vhost_user_set_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 			"\t-DRIVER_OK: %u\n"
 			"\t-DEVICE_NEED_RESET: %u\n"
 			"\t-FAILED: %u\n",
+			dev->ifname,
 			dev->status,
 			(dev->status == VIRTIO_DEVICE_STATUS_RESET),
 			!!(dev->status & VIRTIO_DEVICE_STATUS_ACK),
@@ -2777,7 +2768,7 @@ static vhost_message_handler_t vhost_message_handlers[VHOST_USER_MAX] = {
 
 /* return bytes# of read on success or negative val on failure. */
 static int
-read_vhost_message(int sockfd, struct VhostUserMsg *msg)
+read_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg)
 {
 	int ret;
 
@@ -2786,23 +2777,22 @@ read_vhost_message(int sockfd, struct VhostUserMsg *msg)
 	if (ret <= 0) {
 		return ret;
 	} else if (ret != VHOST_USER_HDR_SIZE) {
-		VHOST_LOG_CONFIG(ERR, "Unexpected header size read\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) Unexpected header size read\n", dev->ifname);
 		close_msg_fds(msg);
 		return -1;
 	}
 
 	if (msg->size) {
 		if (msg->size > sizeof(msg->payload)) {
-			VHOST_LOG_CONFIG(ERR,
-				"invalid msg size: %d\n", msg->size);
+			VHOST_LOG_CONFIG(ERR, "(%s) invalid msg size: %d\n",
+					dev->ifname, msg->size);
 			return -1;
 		}
 		ret = read(sockfd, &msg->payload, msg->size);
 		if (ret <= 0)
 			return ret;
 		if (ret != (int)msg->size) {
-			VHOST_LOG_CONFIG(ERR,
-				"read control message failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) read control message failed\n", dev->ifname);
 			return -1;
 		}
 	}
@@ -2878,8 +2868,7 @@ vhost_user_check_and_alloc_queue_pair(struct virtio_net *dev,
 	}
 
 	if (vring_idx >= VHOST_MAX_VRING) {
-		VHOST_LOG_CONFIG(ERR,
-			"invalid vring index: %u\n", vring_idx);
+		VHOST_LOG_CONFIG(ERR, "(%s) invalid vring index: %u\n", dev->ifname, vring_idx);
 		return -1;
 	}
 
@@ -2942,21 +2931,18 @@ vhost_user_msg_handler(int vid, int fd)
 	if (!dev->notify_ops) {
 		dev->notify_ops = vhost_driver_callback_get(dev->ifname);
 		if (!dev->notify_ops) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to get callback ops for driver %s\n",
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to get callback ops for driver\n",
 				dev->ifname);
 			return -1;
 		}
 	}
 
-	ret = read_vhost_message(fd, &msg);
+	ret = read_vhost_message(dev, fd, &msg);
 	if (ret <= 0) {
 		if (ret < 0)
-			VHOST_LOG_CONFIG(ERR,
-				"vhost read message failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) vhost read message failed\n", dev->ifname);
 		else
-			VHOST_LOG_CONFIG(INFO,
-				"vhost peer closed\n");
+			VHOST_LOG_CONFIG(INFO, "(%s) vhost peer closed\n", dev->ifname);
 
 		return -1;
 	}
@@ -2966,19 +2952,18 @@ vhost_user_msg_handler(int vid, int fd)
 	if (request > VHOST_USER_NONE && request < VHOST_USER_MAX &&
 			vhost_message_str[request]) {
 		if (request != VHOST_USER_IOTLB_MSG)
-			VHOST_LOG_CONFIG(INFO, "read message %s\n",
-				vhost_message_str[request]);
+			VHOST_LOG_CONFIG(INFO, "(%s) read message %s\n",
+				dev->ifname, vhost_message_str[request]);
 		else
-			VHOST_LOG_CONFIG(DEBUG, "read message %s\n",
-				vhost_message_str[request]);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) read message %s\n",
+				dev->ifname, vhost_message_str[request]);
 	} else {
-		VHOST_LOG_CONFIG(DEBUG, "External request %d\n", request);
+		VHOST_LOG_CONFIG(DEBUG, "(%s) external request %d\n", dev->ifname, request);
 	}
 
 	ret = vhost_user_check_and_alloc_queue_pair(dev, &msg);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to alloc queue\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to alloc queue\n", dev->ifname);
 		return -1;
 	}
 
@@ -3041,21 +3026,18 @@ vhost_user_msg_handler(int vid, int fd)
 
 		switch (ret) {
 		case RTE_VHOST_MSG_RESULT_ERR:
-			VHOST_LOG_CONFIG(ERR,
-				"Processing %s failed.\n",
-				vhost_message_str[request]);
+			VHOST_LOG_CONFIG(ERR, "(%s) processing %s failed.\n",
+					dev->ifname, vhost_message_str[request]);
 			handled = true;
 			break;
 		case RTE_VHOST_MSG_RESULT_OK:
-			VHOST_LOG_CONFIG(DEBUG,
-				"Processing %s succeeded.\n",
-				vhost_message_str[request]);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) processing %s succeeded.\n",
+					dev->ifname, vhost_message_str[request]);
 			handled = true;
 			break;
 		case RTE_VHOST_MSG_RESULT_REPLY:
-			VHOST_LOG_CONFIG(DEBUG,
-				"Processing %s succeeded and needs reply.\n",
-				vhost_message_str[request]);
+			VHOST_LOG_CONFIG(DEBUG, "(%s) processing %s succeeded and needs reply.\n",
+					dev->ifname, vhost_message_str[request]);
 			send_vhost_reply(fd, &msg);
 			handled = true;
 			break;
@@ -3084,8 +3066,8 @@ vhost_user_msg_handler(int vid, int fd)
 
 	/* If message was not handled at this stage, treat it as an error */
 	if (!handled) {
-		VHOST_LOG_CONFIG(ERR,
-			"vhost message (req: %d) was not handled.\n", request);
+		VHOST_LOG_CONFIG(ERR, "(%s) vhost message (req: %d) was not handled.\n",
+				dev->ifname, request);
 		close_msg_fds(&msg);
 		ret = RTE_VHOST_MSG_RESULT_ERR;
 	}
@@ -3101,8 +3083,7 @@ vhost_user_msg_handler(int vid, int fd)
 		msg.fd_num = 0;
 		send_vhost_reply(fd, &msg);
 	} else if (ret == RTE_VHOST_MSG_RESULT_ERR) {
-		VHOST_LOG_CONFIG(ERR,
-			"vhost message handling failed.\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) vhost message handling failed.\n", dev->ifname);
 		return -1;
 	}
 
@@ -3139,8 +3120,8 @@ vhost_user_msg_handler(int vid, int fd)
 
 	if (!(dev->flags & VIRTIO_DEV_VDPA_CONFIGURED)) {
 		if (vdpa_dev->ops->dev_conf(dev->vid))
-			VHOST_LOG_CONFIG(ERR,
-					 "Failed to configure vDPA device\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to configure vDPA device\n",
+					dev->ifname);
 		else
 			dev->flags |= VIRTIO_DEV_VDPA_CONFIGURED;
 	}
@@ -3158,23 +3139,21 @@ static int process_slave_message_reply(struct virtio_net *dev,
 	if ((msg->flags & VHOST_USER_NEED_REPLY) == 0)
 		return 0;
 
-	ret = read_vhost_message(dev->slave_req_fd, &msg_reply);
+	ret = read_vhost_message(dev, dev->slave_req_fd, &msg_reply);
 	if (ret <= 0) {
 		if (ret < 0)
-			VHOST_LOG_CONFIG(ERR,
-				"vhost read slave message reply failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) vhost read slave message reply failed\n",
+					dev->ifname);
 		else
-			VHOST_LOG_CONFIG(INFO,
-				"vhost peer closed\n");
+			VHOST_LOG_CONFIG(INFO, "(%s) vhost peer closed\n", dev->ifname);
 		ret = -1;
 		goto out;
 	}
 
 	ret = 0;
 	if (msg_reply.request.slave != msg->request.slave) {
-		VHOST_LOG_CONFIG(ERR,
-			"Received unexpected msg type (%u), expected %u\n",
-			msg_reply.request.slave, msg->request.slave);
+		VHOST_LOG_CONFIG(ERR, "(%s) received unexpected msg type (%u), expected %u\n",
+				dev->ifname, msg_reply.request.slave, msg->request.slave);
 		ret = -1;
 		goto out;
 	}
@@ -3203,9 +3182,8 @@ vhost_user_iotlb_miss(struct virtio_net *dev, uint64_t iova, uint8_t perm)
 
 	ret = send_vhost_message(dev->slave_req_fd, &msg);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"Failed to send IOTLB miss message (%d)\n",
-				ret);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to send IOTLB miss message (%d)\n",
+				dev->ifname, ret);
 		return ret;
 	}
 
@@ -3227,9 +3205,8 @@ vhost_user_slave_config_change(struct virtio_net *dev, bool need_reply)
 
 	ret = send_vhost_slave_message(dev, &msg);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"Failed to send config change (%d)\n",
-				ret);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to send config change (%d)\n",
+				dev->ifname, ret);
 		return ret;
 	}
 
@@ -3274,8 +3251,8 @@ static int vhost_user_slave_set_vring_host_notifier(struct virtio_net *dev,
 
 	ret = send_vhost_slave_message(dev, &msg);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"Failed to set host notifier (%d)\n", ret);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to set host notifier (%d)\n",
+				dev->ifname, ret);
 		return ret;
 	}
 
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 5/9] vhost: improve socket layer logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (3 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 4/9] vhost: improve Vhost-user " Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 6/9] vhost: improve Virtio-net " Maxime Coquelin
                   ` (4 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch adds the Vhost socket path whenever possible in
order to make debugging possible when multiple Vhost
devices are in use. Some vhost-user layer functions are
modified to pass the device path down to the socket layer.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/socket.c     | 146 +++++++++++++++++------------------------
 lib/vhost/vhost_user.c |  26 ++++----
 lib/vhost/vhost_user.h |   4 +-
 3 files changed, 76 insertions(+), 100 deletions(-)

diff --git a/lib/vhost/socket.c b/lib/vhost/socket.c
index 82963c1e6d..ad3471d6a9 100644
--- a/lib/vhost/socket.c
+++ b/lib/vhost/socket.c
@@ -100,7 +100,7 @@ static struct vhost_user vhost_user = {
  * with number of fds read.
  */
 int
-read_fd_message(int sockfd, char *buf, int buflen, int *fds, int max_fds,
+read_fd_message(char *ifname, int sockfd, char *buf, int buflen, int *fds, int max_fds,
 		int *fd_num)
 {
 	struct iovec iov;
@@ -124,12 +124,13 @@ read_fd_message(int sockfd, char *buf, int buflen, int *fds, int max_fds,
 	ret = recvmsg(sockfd, &msgh, 0);
 	if (ret <= 0) {
 		if (ret)
-			VHOST_LOG_CONFIG(ERR, "recvmsg failed\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) recvmsg failed on fd %d (%s)\n",
+					ifname, sockfd, strerror(errno));
 		return ret;
 	}
 
 	if (msgh.msg_flags & (MSG_TRUNC | MSG_CTRUNC)) {
-		VHOST_LOG_CONFIG(ERR, "truncated msg\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) truncated msg (fd %d)\n", ifname, sockfd);
 		return -1;
 	}
 
@@ -152,7 +153,7 @@ read_fd_message(int sockfd, char *buf, int buflen, int *fds, int max_fds,
 }
 
 int
-send_fd_message(int sockfd, char *buf, int buflen, int *fds, int fd_num)
+send_fd_message(char *ifname, int sockfd, char *buf, int buflen, int *fds, int fd_num)
 {
 
 	struct iovec iov;
@@ -174,7 +175,7 @@ send_fd_message(int sockfd, char *buf, int buflen, int *fds, int fd_num)
 		msgh.msg_controllen = sizeof(control);
 		cmsg = CMSG_FIRSTHDR(&msgh);
 		if (cmsg == NULL) {
-			VHOST_LOG_CONFIG(ERR, "cmsg == NULL\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) cmsg == NULL\n", ifname);
 			errno = EINVAL;
 			return -1;
 		}
@@ -192,7 +193,8 @@ send_fd_message(int sockfd, char *buf, int buflen, int *fds, int fd_num)
 	} while (ret < 0 && errno == EINTR);
 
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,  "sendmsg error\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) sendmsg error on fd %d (%s)\n",
+				ifname, sockfd, strerror(errno));
 		return ret;
 	}
 
@@ -243,14 +245,14 @@ vhost_user_add_connection(int fd, struct vhost_user_socket *vsocket)
 			dev->async_copy = 1;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "new device, handle is %d, path is %s\n", vid, vsocket->path);
+	VHOST_LOG_CONFIG(INFO, "(%s) new device, handle is %d\n", vsocket->path, vid);
 
 	if (vsocket->notify_ops->new_connection) {
 		ret = vsocket->notify_ops->new_connection(vid);
 		if (ret < 0) {
 			VHOST_LOG_CONFIG(ERR,
-				"failed to add vhost user connection with fd %d\n",
-				fd);
+				"(%s) failed to add vhost user connection with fd %d\n",
+				vsocket->path, fd);
 			goto err_cleanup;
 		}
 	}
@@ -261,9 +263,8 @@ vhost_user_add_connection(int fd, struct vhost_user_socket *vsocket)
 	ret = fdset_add(&vhost_user.fdset, fd, vhost_user_read_cb,
 			NULL, conn);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to add fd %d into vhost server fdset\n",
-			fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to add fd %d into vhost server fdset\n",
+			vsocket->path, fd);
 
 		if (vsocket->notify_ops->destroy_connection)
 			vsocket->notify_ops->destroy_connection(conn->vid);
@@ -295,7 +296,8 @@ vhost_user_server_new_connection(int fd, void *dat, int *remove __rte_unused)
 	if (fd < 0)
 		return;
 
-	VHOST_LOG_CONFIG(INFO, "new vhost user connection is %d\n", fd);
+	VHOST_LOG_CONFIG(INFO, "(%s) new vhost user connection is %d\n",
+			vsocket->path, fd);
 	vhost_user_add_connection(fd, vsocket);
 }
 
@@ -343,13 +345,13 @@ create_unix_socket(struct vhost_user_socket *vsocket)
 	fd = socket(AF_UNIX, SOCK_STREAM, 0);
 	if (fd < 0)
 		return -1;
-	VHOST_LOG_CONFIG(INFO, "vhost-user %s: socket created, fd: %d\n",
-		vsocket->is_server ? "server" : "client", fd);
+	VHOST_LOG_CONFIG(INFO, "(%s) vhost-user %s: socket created, fd: %d\n",
+		vsocket->path, vsocket->is_server ? "server" : "client", fd);
 
 	if (!vsocket->is_server && fcntl(fd, F_SETFL, O_NONBLOCK)) {
 		VHOST_LOG_CONFIG(ERR,
-			"vhost-user: can't set nonblocking mode for socket, fd: "
-			"%d (%s)\n", fd, strerror(errno));
+			"(%s) vhost-user: can't set nonblocking mode for socket, fd: %d (%s)\n",
+			vsocket->path, fd, strerror(errno));
 		close(fd);
 		return -1;
 	}
@@ -382,12 +384,11 @@ vhost_user_start_server(struct vhost_user_socket *vsocket)
 	 */
 	ret = bind(fd, (struct sockaddr *)&vsocket->un, sizeof(vsocket->un));
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to bind to %s: %s; remove it and try again\n",
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to bind: %s; remove it and try again\n",
 			path, strerror(errno));
 		goto err;
 	}
-	VHOST_LOG_CONFIG(INFO, "bind to %s\n", path);
+	VHOST_LOG_CONFIG(INFO, "(%s) binding succeeded\n", path);
 
 	ret = listen(fd, MAX_VIRTIO_BACKLOG);
 	if (ret < 0)
@@ -397,8 +398,8 @@ vhost_user_start_server(struct vhost_user_socket *vsocket)
 		  NULL, vsocket);
 	if (ret < 0) {
 		VHOST_LOG_CONFIG(ERR,
-			"failed to add listen fd %d to vhost server fdset\n",
-			fd);
+			"(%s) failed to add listen fd %d to vhost server fdset\n",
+			path, fd);
 		goto err;
 	}
 
@@ -427,7 +428,7 @@ static struct vhost_user_reconnect_list reconn_list;
 static pthread_t reconn_tid;
 
 static int
-vhost_user_connect_nonblock(int fd, struct sockaddr *un, size_t sz)
+vhost_user_connect_nonblock(char *path, int fd, struct sockaddr *un, size_t sz)
 {
 	int ret, flags;
 
@@ -437,13 +438,12 @@ vhost_user_connect_nonblock(int fd, struct sockaddr *un, size_t sz)
 
 	flags = fcntl(fd, F_GETFL, 0);
 	if (flags < 0) {
-		VHOST_LOG_CONFIG(ERR,
-			"can't get flags for connfd %d\n", fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) can't get flags for connfd %d (%s)\n",
+				path, fd, strerror(errno));
 		return -2;
 	}
 	if ((flags & O_NONBLOCK) && fcntl(fd, F_SETFL, flags & ~O_NONBLOCK)) {
-		VHOST_LOG_CONFIG(ERR,
-				"can't disable nonblocking on fd %d\n", fd);
+		VHOST_LOG_CONFIG(ERR, "(%s) can't disable nonblocking on fd %d\n", path, fd);
 		return -2;
 	}
 	return 0;
@@ -466,21 +466,19 @@ vhost_user_client_reconnect(void *arg __rte_unused)
 		     reconn != NULL; reconn = next) {
 			next = TAILQ_NEXT(reconn, next);
 
-			ret = vhost_user_connect_nonblock(reconn->fd,
+			ret = vhost_user_connect_nonblock(reconn->vsocket->path, reconn->fd,
 						(struct sockaddr *)&reconn->un,
 						sizeof(reconn->un));
 			if (ret == -2) {
 				close(reconn->fd);
-				VHOST_LOG_CONFIG(ERR,
-					"reconnection for fd %d failed\n",
-					reconn->fd);
+				VHOST_LOG_CONFIG(ERR, "(%s) reconnection for fd %d failed\n",
+					reconn->vsocket->path, reconn->fd);
 				goto remove_fd;
 			}
 			if (ret == -1)
 				continue;
 
-			VHOST_LOG_CONFIG(INFO,
-				"%s: connected\n", reconn->vsocket->path);
+			VHOST_LOG_CONFIG(INFO, "(%s) connected\n", reconn->vsocket->path);
 			vhost_user_add_connection(reconn->fd, reconn->vsocket);
 remove_fd:
 			TAILQ_REMOVE(&reconn_list.head, reconn, next);
@@ -501,7 +499,7 @@ vhost_user_reconnect_init(void)
 
 	ret = pthread_mutex_init(&reconn_list.mutex, NULL);
 	if (ret < 0) {
-		VHOST_LOG_CONFIG(ERR, "failed to initialize mutex");
+		VHOST_LOG_CONFIG(ERR, "%s: failed to initialize mutex", __func__);
 		return ret;
 	}
 	TAILQ_INIT(&reconn_list.head);
@@ -510,10 +508,8 @@ vhost_user_reconnect_init(void)
 			     vhost_user_client_reconnect, NULL);
 	if (ret != 0) {
 		VHOST_LOG_CONFIG(ERR, "failed to create reconnect thread");
-		if (pthread_mutex_destroy(&reconn_list.mutex)) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to destroy reconnect mutex");
-		}
+		if (pthread_mutex_destroy(&reconn_list.mutex))
+			VHOST_LOG_CONFIG(ERR, "%s: failed to destroy reconnect mutex", __func__);
 	}
 
 	return ret;
@@ -527,27 +523,24 @@ vhost_user_start_client(struct vhost_user_socket *vsocket)
 	const char *path = vsocket->path;
 	struct vhost_user_reconnect *reconn;
 
-	ret = vhost_user_connect_nonblock(fd, (struct sockaddr *)&vsocket->un,
+	ret = vhost_user_connect_nonblock(vsocket->path, fd, (struct sockaddr *)&vsocket->un,
 					  sizeof(vsocket->un));
 	if (ret == 0) {
 		vhost_user_add_connection(fd, vsocket);
 		return 0;
 	}
 
-	VHOST_LOG_CONFIG(WARNING,
-		"failed to connect to %s: %s\n",
-		path, strerror(errno));
+	VHOST_LOG_CONFIG(WARNING, "(%s) failed to connect: %s\n", path, strerror(errno));
 
 	if (ret == -2 || !vsocket->reconnect) {
 		close(fd);
 		return -1;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "%s: reconnecting...\n", path);
+	VHOST_LOG_CONFIG(INFO, "(%s) reconnecting...\n", path);
 	reconn = malloc(sizeof(*reconn));
 	if (reconn == NULL) {
-		VHOST_LOG_CONFIG(ERR,
-			"failed to allocate memory for reconnect\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to allocate memory for reconnect\n", path);
 		close(fd);
 		return -1;
 	}
@@ -701,8 +694,7 @@ rte_vhost_driver_get_features(const char *path, uint64_t *features)
 	pthread_mutex_lock(&vhost_user.mutex);
 	vsocket = find_vhost_user_socket(path);
 	if (!vsocket) {
-		VHOST_LOG_CONFIG(ERR,
-			"socket file %s is not registered yet.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) socket file is not registered yet.\n", path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -714,9 +706,7 @@ rte_vhost_driver_get_features(const char *path, uint64_t *features)
 	}
 
 	if (vdpa_dev->ops->get_features(vdpa_dev, &vdpa_features) < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"failed to get vdpa features "
-				"for socket file %s.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to get vdpa features for socket file.\n", path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -754,8 +744,7 @@ rte_vhost_driver_get_protocol_features(const char *path,
 	pthread_mutex_lock(&vhost_user.mutex);
 	vsocket = find_vhost_user_socket(path);
 	if (!vsocket) {
-		VHOST_LOG_CONFIG(ERR,
-			"socket file %s is not registered yet.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) socket file is not registered yet.\n", path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -768,9 +757,8 @@ rte_vhost_driver_get_protocol_features(const char *path,
 
 	if (vdpa_dev->ops->get_protocol_features(vdpa_dev,
 				&vdpa_protocol_features) < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"failed to get vdpa protocol features "
-				"for socket file %s.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to get vdpa protocol features.\n",
+				path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -794,8 +782,7 @@ rte_vhost_driver_get_queue_num(const char *path, uint32_t *queue_num)
 	pthread_mutex_lock(&vhost_user.mutex);
 	vsocket = find_vhost_user_socket(path);
 	if (!vsocket) {
-		VHOST_LOG_CONFIG(ERR,
-			"socket file %s is not registered yet.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) socket file is not registered yet.\n", path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -807,9 +794,8 @@ rte_vhost_driver_get_queue_num(const char *path, uint32_t *queue_num)
 	}
 
 	if (vdpa_dev->ops->get_queue_num(vdpa_dev, &vdpa_queue_num) < 0) {
-		VHOST_LOG_CONFIG(ERR,
-				"failed to get vdpa queue number "
-				"for socket file %s.\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to get vdpa queue number.\n",
+				path);
 		ret = -1;
 		goto unlock_exit;
 	}
@@ -852,8 +838,8 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 	pthread_mutex_lock(&vhost_user.mutex);
 
 	if (vhost_user.vsocket_cnt == MAX_VHOST_SOCKET) {
-		VHOST_LOG_CONFIG(ERR,
-			"error: the number of vhost sockets reaches maximum\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) the number of vhost sockets reaches maximum\n",
+				path);
 		goto out;
 	}
 
@@ -863,16 +849,14 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 	memset(vsocket, 0, sizeof(struct vhost_user_socket));
 	vsocket->path = strdup(path);
 	if (vsocket->path == NULL) {
-		VHOST_LOG_CONFIG(ERR,
-			"error: failed to copy socket path string\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to copy socket path string\n", path);
 		vhost_user_socket_mem_free(vsocket);
 		goto out;
 	}
 	TAILQ_INIT(&vsocket->conn_list);
 	ret = pthread_mutex_init(&vsocket->conn_mutex, NULL);
 	if (ret) {
-		VHOST_LOG_CONFIG(ERR,
-			"error: failed to init connection mutex\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to init connection mutex\n", path);
 		goto out_free;
 	}
 	vsocket->vdpa_dev = NULL;
@@ -884,9 +868,8 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 	if (vsocket->async_copy &&
 		(flags & (RTE_VHOST_USER_IOMMU_SUPPORT |
 		RTE_VHOST_USER_POSTCOPY_SUPPORT))) {
-		VHOST_LOG_CONFIG(ERR, "error: enabling async copy and IOMMU "
-			"or post-copy feature simultaneously is not "
-			"supported\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) enabling async copy and IOMMU "
+			"or post-copy feature simultaneously is not supported\n", path);
 		goto out_mutex;
 	}
 
@@ -910,8 +893,8 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 	if (vsocket->async_copy) {
 		vsocket->supported_features &= ~(1ULL << VHOST_F_LOG_ALL);
 		vsocket->features &= ~(1ULL << VHOST_F_LOG_ALL);
-		VHOST_LOG_CONFIG(INFO,
-			"Logging feature is disabled in async copy mode\n");
+		VHOST_LOG_CONFIG(INFO, "(%s) logging feature is disabled in async copy mode\n",
+				path);
 	}
 
 	/*
@@ -925,9 +908,8 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 				(1ULL << VIRTIO_NET_F_HOST_TSO6) |
 				(1ULL << VIRTIO_NET_F_HOST_UFO);
 
-		VHOST_LOG_CONFIG(INFO,
-			"Linear buffers requested without external buffers, "
-			"disabling host segmentation offloading support\n");
+		VHOST_LOG_CONFIG(INFO, "(%s) Linear buffers requested without external buffers, "
+			"disabling host segmentation offloading support\n", path);
 		vsocket->supported_features &= ~seg_offload_features;
 		vsocket->features &= ~seg_offload_features;
 	}
@@ -942,8 +924,7 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 			~(1ULL << VHOST_USER_PROTOCOL_F_PAGEFAULT);
 	} else {
 #ifndef RTE_LIBRTE_VHOST_POSTCOPY
-		VHOST_LOG_CONFIG(ERR,
-			"Postcopy requested but not compiled\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) Postcopy requested but not compiled\n", path);
 		ret = -1;
 		goto out_mutex;
 #endif
@@ -970,8 +951,7 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 
 out_mutex:
 	if (pthread_mutex_destroy(&vsocket->conn_mutex)) {
-		VHOST_LOG_CONFIG(ERR,
-			"error: failed to destroy connection mutex\n");
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to destroy connection mutex\n", path);
 	}
 out_free:
 	vhost_user_socket_mem_free(vsocket);
@@ -1059,9 +1039,7 @@ rte_vhost_driver_unregister(const char *path)
 				goto again;
 			}
 
-			VHOST_LOG_CONFIG(INFO,
-				"free connfd = %d for device '%s'\n",
-				conn->connfd, path);
+			VHOST_LOG_CONFIG(INFO, "(%s) free connfd %d\n", path, conn->connfd);
 			close(conn->connfd);
 			vhost_destroy_device(conn->vid);
 			TAILQ_REMOVE(&vsocket->conn_list, conn, next);
@@ -1137,8 +1115,7 @@ rte_vhost_driver_start(const char *path)
 		 * rebuild the wait list of poll.
 		 */
 		if (fdset_pipe_init(&vhost_user.fdset) < 0) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to create pipe for vhost fdset\n");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to create pipe for vhost fdset\n", path);
 			return -1;
 		}
 
@@ -1146,8 +1123,7 @@ rte_vhost_driver_start(const char *path)
 			"vhost-events", NULL, fdset_event_dispatch,
 			&vhost_user.fdset);
 		if (ret != 0) {
-			VHOST_LOG_CONFIG(ERR,
-				"failed to create fdset handling thread");
+			VHOST_LOG_CONFIG(ERR, "(%s) failed to create fdset handling thread", path);
 
 			fdset_pipe_uninit(&vhost_user.fdset);
 			return -1;
diff --git a/lib/vhost/vhost_user.c b/lib/vhost/vhost_user.c
index c95eef8f5d..e207ace426 100644
--- a/lib/vhost/vhost_user.c
+++ b/lib/vhost/vhost_user.c
@@ -93,7 +93,7 @@ static const char *vhost_message_str[VHOST_USER_MAX] = {
 	[VHOST_USER_GET_STATUS] = "VHOST_USER_GET_STATUS",
 };
 
-static int send_vhost_reply(int sockfd, struct VhostUserMsg *msg);
+static int send_vhost_reply(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg);
 static int read_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg);
 
 static void
@@ -1175,7 +1175,7 @@ vhost_user_postcopy_register(struct virtio_net *dev, int main_fd,
 
 	/* Send the addresses back to qemu */
 	msg->fd_num = 0;
-	send_vhost_reply(main_fd, msg);
+	send_vhost_reply(dev, main_fd, msg);
 
 	/* Wait for qemu to acknowledge it got the addresses
 	 * we've got to wait before we're allowed to generate faults.
@@ -2772,7 +2772,7 @@ read_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg)
 {
 	int ret;
 
-	ret = read_fd_message(sockfd, (char *)msg, VHOST_USER_HDR_SIZE,
+	ret = read_fd_message(dev->ifname, sockfd, (char *)msg, VHOST_USER_HDR_SIZE,
 		msg->fds, VHOST_MEMORY_MAX_NREGIONS, &msg->fd_num);
 	if (ret <= 0) {
 		return ret;
@@ -2801,17 +2801,17 @@ read_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg)
 }
 
 static int
-send_vhost_message(int sockfd, struct VhostUserMsg *msg)
+send_vhost_message(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg)
 {
 	if (!msg)
 		return 0;
 
-	return send_fd_message(sockfd, (char *)msg,
+	return send_fd_message(dev->ifname, sockfd, (char *)msg,
 		VHOST_USER_HDR_SIZE + msg->size, msg->fds, msg->fd_num);
 }
 
 static int
-send_vhost_reply(int sockfd, struct VhostUserMsg *msg)
+send_vhost_reply(struct virtio_net *dev, int sockfd, struct VhostUserMsg *msg)
 {
 	if (!msg)
 		return 0;
@@ -2821,7 +2821,7 @@ send_vhost_reply(int sockfd, struct VhostUserMsg *msg)
 	msg->flags |= VHOST_USER_VERSION;
 	msg->flags |= VHOST_USER_REPLY_MASK;
 
-	return send_vhost_message(sockfd, msg);
+	return send_vhost_message(dev, sockfd, msg);
 }
 
 static int
@@ -2832,7 +2832,7 @@ send_vhost_slave_message(struct virtio_net *dev, struct VhostUserMsg *msg)
 	if (msg->flags & VHOST_USER_NEED_REPLY)
 		rte_spinlock_lock(&dev->slave_req_lock);
 
-	ret = send_vhost_message(dev->slave_req_fd, msg);
+	ret = send_vhost_message(dev, dev->slave_req_fd, msg);
 	if (ret < 0 && (msg->flags & VHOST_USER_NEED_REPLY))
 		rte_spinlock_unlock(&dev->slave_req_lock);
 
@@ -3007,7 +3007,7 @@ vhost_user_msg_handler(int vid, int fd)
 				(void *)&msg);
 		switch (ret) {
 		case RTE_VHOST_MSG_RESULT_REPLY:
-			send_vhost_reply(fd, &msg);
+			send_vhost_reply(dev, fd, &msg);
 			/* Fall-through */
 		case RTE_VHOST_MSG_RESULT_ERR:
 		case RTE_VHOST_MSG_RESULT_OK:
@@ -3038,7 +3038,7 @@ vhost_user_msg_handler(int vid, int fd)
 		case RTE_VHOST_MSG_RESULT_REPLY:
 			VHOST_LOG_CONFIG(DEBUG, "(%s) processing %s succeeded and needs reply.\n",
 					dev->ifname, vhost_message_str[request]);
-			send_vhost_reply(fd, &msg);
+			send_vhost_reply(dev, fd, &msg);
 			handled = true;
 			break;
 		default:
@@ -3053,7 +3053,7 @@ vhost_user_msg_handler(int vid, int fd)
 				(void *)&msg);
 		switch (ret) {
 		case RTE_VHOST_MSG_RESULT_REPLY:
-			send_vhost_reply(fd, &msg);
+			send_vhost_reply(dev, fd, &msg);
 			/* Fall-through */
 		case RTE_VHOST_MSG_RESULT_ERR:
 		case RTE_VHOST_MSG_RESULT_OK:
@@ -3081,7 +3081,7 @@ vhost_user_msg_handler(int vid, int fd)
 		msg.payload.u64 = ret == RTE_VHOST_MSG_RESULT_ERR;
 		msg.size = sizeof(msg.payload.u64);
 		msg.fd_num = 0;
-		send_vhost_reply(fd, &msg);
+		send_vhost_reply(dev, fd, &msg);
 	} else if (ret == RTE_VHOST_MSG_RESULT_ERR) {
 		VHOST_LOG_CONFIG(ERR, "(%s) vhost message handling failed.\n", dev->ifname);
 		return -1;
@@ -3180,7 +3180,7 @@ vhost_user_iotlb_miss(struct virtio_net *dev, uint64_t iova, uint8_t perm)
 		},
 	};
 
-	ret = send_vhost_message(dev->slave_req_fd, &msg);
+	ret = send_vhost_message(dev, dev->slave_req_fd, &msg);
 	if (ret < 0) {
 		VHOST_LOG_CONFIG(ERR, "(%s) failed to send IOTLB miss message (%d)\n",
 				dev->ifname, ret);
diff --git a/lib/vhost/vhost_user.h b/lib/vhost/vhost_user.h
index 16fe03f889..c8e299e30c 100644
--- a/lib/vhost/vhost_user.h
+++ b/lib/vhost/vhost_user.h
@@ -164,8 +164,8 @@ int vhost_user_msg_handler(int vid, int fd);
 int vhost_user_iotlb_miss(struct virtio_net *dev, uint64_t iova, uint8_t perm);
 
 /* socket.c */
-int read_fd_message(int sockfd, char *buf, int buflen, int *fds, int max_fds,
+int read_fd_message(char *ifname, int sockfd, char *buf, int buflen, int *fds, int max_fds,
 		int *fd_num);
-int send_fd_message(int sockfd, char *buf, int buflen, int *fds, int fd_num);
+int send_fd_message(char *ifname, int sockfd, char *buf, int buflen, int *fds, int fd_num);
 
 #endif
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 6/9] vhost: improve Virtio-net layer logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (4 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 5/9] vhost: improve socket " Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 7/9] vhost: remove multi-line logs Maxime Coquelin
                   ` (3 subsequent siblings)
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch standardizes logging done in Virtio-net, so that
the Vhost-user socket path is always prepended to the logs.
It will ease log analysis when multiple Vhost-user ports
are in use.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/virtio_net.c | 165 ++++++++++++++++++++---------------------
 1 file changed, 79 insertions(+), 86 deletions(-)

diff --git a/lib/vhost/virtio_net.c b/lib/vhost/virtio_net.c
index b3d954aab4..f19713137c 100644
--- a/lib/vhost/virtio_net.c
+++ b/lib/vhost/virtio_net.c
@@ -792,12 +792,12 @@ copy_vnet_hdr_to_desc(struct virtio_net *dev, struct vhost_virtqueue *vq,
 }
 
 static __rte_always_inline int
-async_iter_initialize(struct vhost_async *async)
+async_iter_initialize(struct virtio_net *dev, struct vhost_async *async)
 {
 	struct rte_vhost_iov_iter *iter;
 
 	if (unlikely(async->iovec_idx >= VHOST_MAX_ASYNC_VEC)) {
-		VHOST_LOG_DATA(ERR, "no more async iovec available\n");
+		VHOST_LOG_DATA(ERR, "(%s) no more async iovec available\n", dev->ifname);
 		return -1;
 	}
 
@@ -809,7 +809,8 @@ async_iter_initialize(struct vhost_async *async)
 }
 
 static __rte_always_inline int
-async_iter_add_iovec(struct vhost_async *async, void *src, void *dst, size_t len)
+async_iter_add_iovec(struct virtio_net *dev, struct vhost_async *async,
+		void *src, void *dst, size_t len)
 {
 	struct rte_vhost_iov_iter *iter;
 	struct rte_vhost_iovec *iovec;
@@ -818,7 +819,7 @@ async_iter_add_iovec(struct vhost_async *async, void *src, void *dst, size_t len
 		static bool vhost_max_async_vec_log;
 
 		if (!vhost_max_async_vec_log) {
-			VHOST_LOG_DATA(ERR, "no more async iovec available\n");
+			VHOST_LOG_DATA(ERR, "(%s) no more async iovec available\n", dev->ifname);
 			vhost_max_async_vec_log = true;
 		}
 
@@ -876,11 +877,11 @@ async_mbuf_to_desc_seg(struct virtio_net *dev, struct vhost_virtqueue *vq,
 		hpa = (void *)(uintptr_t)gpa_to_first_hpa(dev,
 				buf_iova + buf_offset, cpy_len, &mapped_len);
 		if (unlikely(!hpa)) {
-			VHOST_LOG_DATA(ERR, "(%d) %s: failed to get hpa.\n", dev->vid, __func__);
+			VHOST_LOG_DATA(ERR, "(%s) %s: failed to get hpa.\n", dev->ifname, __func__);
 			return -1;
 		}
 
-		if (unlikely(async_iter_add_iovec(async,
+		if (unlikely(async_iter_add_iovec(dev, async,
 						(void *)(uintptr_t)rte_pktmbuf_iova_offset(m,
 							mbuf_offset),
 						hpa, (size_t)mapped_len)))
@@ -951,8 +952,8 @@ mbuf_to_desc(struct virtio_net *dev, struct vhost_virtqueue *vq,
 	} else
 		hdr = (struct virtio_net_hdr_mrg_rxbuf *)(uintptr_t)hdr_addr;
 
-	VHOST_LOG_DATA(DEBUG, "(%d) RX: num merge buffers %d\n",
-		dev->vid, num_buffers);
+	VHOST_LOG_DATA(DEBUG, "(%s) RX: num merge buffers %d\n",
+		dev->ifname, num_buffers);
 
 	if (unlikely(buf_len < dev->vhost_hlen)) {
 		buf_offset = dev->vhost_hlen - buf_len;
@@ -970,7 +971,7 @@ mbuf_to_desc(struct virtio_net *dev, struct vhost_virtqueue *vq,
 	mbuf_offset = 0;
 
 	if (is_async) {
-		if (async_iter_initialize(async))
+		if (async_iter_initialize(dev, async))
 			return -1;
 	}
 
@@ -1133,14 +1134,14 @@ virtio_dev_rx_split(struct virtio_net *dev, struct vhost_virtqueue *vq,
 						pkt_len, buf_vec, &num_buffers,
 						avail_head, &nr_vec) < 0)) {
 			VHOST_LOG_DATA(DEBUG,
-				"(%d) failed to get enough desc from vring\n",
-				dev->vid);
+				"(%s) failed to get enough desc from vring\n",
+				dev->ifname);
 			vq->shadow_used_idx -= num_buffers;
 			break;
 		}
 
-		VHOST_LOG_DATA(DEBUG, "(%d) current index %d | end index %d\n",
-			dev->vid, vq->last_avail_idx,
+		VHOST_LOG_DATA(DEBUG, "(%s) current index %d | end index %d\n",
+			dev->ifname, vq->last_avail_idx,
 			vq->last_avail_idx + num_buffers);
 
 		if (mbuf_to_desc(dev, vq, pkts[pkt_idx], buf_vec, nr_vec,
@@ -1287,14 +1288,13 @@ virtio_dev_rx_single_packed(struct virtio_net *dev,
 
 	if (unlikely(vhost_enqueue_single_packed(dev, vq, pkt, buf_vec,
 						 &nr_descs) < 0)) {
-		VHOST_LOG_DATA(DEBUG,
-				"(%d) failed to get enough desc from vring\n",
-				dev->vid);
+		VHOST_LOG_DATA(DEBUG, "(%s) failed to get enough desc from vring\n",
+				dev->ifname);
 		return -1;
 	}
 
-	VHOST_LOG_DATA(DEBUG, "(%d) current index %d | end index %d\n",
-			dev->vid, vq->last_avail_idx,
+	VHOST_LOG_DATA(DEBUG, "(%s) current index %d | end index %d\n",
+			dev->ifname, vq->last_avail_idx,
 			vq->last_avail_idx + nr_descs);
 
 	vq_inc_last_avail_packed(vq, nr_descs);
@@ -1345,10 +1345,10 @@ virtio_dev_rx(struct virtio_net *dev, uint16_t queue_id,
 	struct vhost_virtqueue *vq;
 	uint32_t nb_tx = 0;
 
-	VHOST_LOG_DATA(DEBUG, "(%d) %s\n", dev->vid, __func__);
+	VHOST_LOG_DATA(DEBUG, "(%s) %s\n", dev->ifname, __func__);
 	if (unlikely(!is_valid_virt_queue_idx(queue_id, 0, dev->nr_vring))) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -1395,9 +1395,8 @@ rte_vhost_enqueue_burst(int vid, uint16_t queue_id,
 		return 0;
 
 	if (unlikely(!(dev->flags & VIRTIO_DEV_BUILTIN_VIRTIO_NET))) {
-		VHOST_LOG_DATA(ERR,
-			"(%d) %s: built-in vhost net backend is disabled.\n",
-			dev->vid, __func__);
+		VHOST_LOG_DATA(ERR, "(%s) %s: built-in vhost net backend is disabled.\n",
+			dev->ifname, __func__);
 		return 0;
 	}
 
@@ -1479,14 +1478,14 @@ virtio_dev_rx_async_submit_split(struct virtio_net *dev,
 
 		if (unlikely(reserve_avail_buf_split(dev, vq, pkt_len, buf_vec,
 						&num_buffers, avail_head, &nr_vec) < 0)) {
-			VHOST_LOG_DATA(DEBUG, "(%d) failed to get enough desc from vring\n",
-					dev->vid);
+			VHOST_LOG_DATA(DEBUG, "(%s) failed to get enough desc from vring\n",
+					dev->ifname);
 			vq->shadow_used_idx -= num_buffers;
 			break;
 		}
 
-		VHOST_LOG_DATA(DEBUG, "(%d) current index %d | end index %d\n",
-			dev->vid, vq->last_avail_idx, vq->last_avail_idx + num_buffers);
+		VHOST_LOG_DATA(DEBUG, "(%s) current index %d | end index %d\n",
+			dev->ifname, vq->last_avail_idx, vq->last_avail_idx + num_buffers);
 
 		if (mbuf_to_desc(dev, vq, pkts[pkt_idx], buf_vec, nr_vec, num_buffers, true) < 0) {
 			vq->shadow_used_idx -= num_buffers;
@@ -1505,8 +1504,8 @@ virtio_dev_rx_async_submit_split(struct virtio_net *dev,
 
 	n_xfer = async->ops.transfer_data(dev->vid, queue_id, async->iov_iter, 0, pkt_idx);
 	if (unlikely(n_xfer < 0)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: failed to transfer data for queue id %d.\n",
-				dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: failed to transfer data for queue id %d.\n",
+				dev->ifname, __func__, queue_id);
 		n_xfer = 0;
 	}
 
@@ -1619,12 +1618,12 @@ virtio_dev_rx_async_packed(struct virtio_net *dev, struct vhost_virtqueue *vq,
 
 	if (unlikely(vhost_enqueue_async_packed(dev, vq, pkt, buf_vec,
 					nr_descs, nr_buffers) < 0)) {
-		VHOST_LOG_DATA(DEBUG, "(%d) failed to get enough desc from vring\n", dev->vid);
+		VHOST_LOG_DATA(DEBUG, "(%s) failed to get enough desc from vring\n", dev->ifname);
 		return -1;
 	}
 
-	VHOST_LOG_DATA(DEBUG, "(%d) current index %d | end index %d\n",
-			dev->vid, vq->last_avail_idx, vq->last_avail_idx + *nr_descs);
+	VHOST_LOG_DATA(DEBUG, "(%s) current index %d | end index %d\n",
+			dev->ifname, vq->last_avail_idx, vq->last_avail_idx + *nr_descs);
 
 	return 0;
 }
@@ -1696,8 +1695,8 @@ virtio_dev_rx_async_submit_packed(struct virtio_net *dev,
 
 	n_xfer = async->ops.transfer_data(dev->vid, queue_id, async->iov_iter, 0, pkt_idx);
 	if (unlikely(n_xfer < 0)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: failed to transfer data for queue id %d.\n",
-				dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: failed to transfer data for queue id %d.\n",
+				dev->ifname, __func__, queue_id);
 		n_xfer = 0;
 	}
 
@@ -1837,8 +1836,8 @@ vhost_poll_enqueue_completed(struct virtio_net *dev, uint16_t queue_id,
 
 	n_cpl = async->ops.check_completed_copies(dev->vid, queue_id, 0, count);
 	if (unlikely(n_cpl < 0)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: failed to check completed copies for queue id %d.\n",
-				dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: failed to check completed copies for queue id %d.\n",
+				dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -1891,18 +1890,18 @@ rte_vhost_poll_enqueue_completed(int vid, uint16_t queue_id,
 	if (unlikely(!dev))
 		return 0;
 
-	VHOST_LOG_DATA(DEBUG, "(%d) %s\n", dev->vid, __func__);
+	VHOST_LOG_DATA(DEBUG, "(%s) %s\n", dev->ifname, __func__);
 	if (unlikely(!is_valid_virt_queue_idx(queue_id, 0, dev->nr_vring))) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
 	vq = dev->virtqueue[queue_id];
 
 	if (unlikely(!vq->async)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: async not registered for queue id %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: async not registered for queue id %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -1926,18 +1925,18 @@ rte_vhost_clear_queue_thread_unsafe(int vid, uint16_t queue_id,
 	if (!dev)
 		return 0;
 
-	VHOST_LOG_DATA(DEBUG, "(%d) %s\n", dev->vid, __func__);
+	VHOST_LOG_DATA(DEBUG, "(%s) %s\n", dev->ifname, __func__);
 	if (unlikely(!is_valid_virt_queue_idx(queue_id, 0, dev->nr_vring))) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
 	vq = dev->virtqueue[queue_id];
 
 	if (unlikely(!vq->async)) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: async not registered for queue id %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: async not registered for queue id %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -1953,10 +1952,10 @@ virtio_dev_rx_async_submit(struct virtio_net *dev, uint16_t queue_id,
 	struct vhost_virtqueue *vq;
 	uint32_t nb_tx = 0;
 
-	VHOST_LOG_DATA(DEBUG, "(%d) %s\n", dev->vid, __func__);
+	VHOST_LOG_DATA(DEBUG, "(%s) %s\n", dev->ifname, __func__);
 	if (unlikely(!is_valid_virt_queue_idx(queue_id, 0, dev->nr_vring))) {
-		VHOST_LOG_DATA(ERR, "(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+			dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -2005,9 +2004,8 @@ rte_vhost_submit_enqueue_burst(int vid, uint16_t queue_id,
 		return 0;
 
 	if (unlikely(!(dev->flags & VIRTIO_DEV_BUILTIN_VIRTIO_NET))) {
-		VHOST_LOG_DATA(ERR,
-			"(%d) %s: built-in vhost net backend is disabled.\n",
-			dev->vid, __func__);
+		VHOST_LOG_DATA(ERR, "(%s) %s: built-in vhost net backend is disabled.\n",
+			dev->ifname, __func__);
 		return 0;
 	}
 
@@ -2114,7 +2112,8 @@ parse_headers(struct rte_mbuf *m, uint8_t *l4_proto)
 }
 
 static __rte_always_inline void
-vhost_dequeue_offload_legacy(struct virtio_net_hdr *hdr, struct rte_mbuf *m)
+vhost_dequeue_offload_legacy(struct virtio_net *dev, struct virtio_net_hdr *hdr,
+		struct rte_mbuf *m)
 {
 	uint8_t l4_proto = 0;
 	struct rte_tcp_hdr *tcp_hdr = NULL;
@@ -2174,8 +2173,8 @@ vhost_dequeue_offload_legacy(struct virtio_net_hdr *hdr, struct rte_mbuf *m)
 			m->l4_len = sizeof(struct rte_udp_hdr);
 			break;
 		default:
-			VHOST_LOG_DATA(WARNING,
-				"unsupported gso type %u.\n", hdr->gso_type);
+			VHOST_LOG_DATA(WARNING, "(%s) unsupported gso type %u.\n",
+					dev->ifname, hdr->gso_type);
 			goto error;
 		}
 	}
@@ -2188,8 +2187,8 @@ vhost_dequeue_offload_legacy(struct virtio_net_hdr *hdr, struct rte_mbuf *m)
 }
 
 static __rte_always_inline void
-vhost_dequeue_offload(struct virtio_net_hdr *hdr, struct rte_mbuf *m,
-	bool legacy_ol_flags)
+vhost_dequeue_offload(struct virtio_net *dev, struct virtio_net_hdr *hdr,
+		struct rte_mbuf *m, bool legacy_ol_flags)
 {
 	struct rte_net_hdr_lens hdr_lens;
 	int l4_supported = 0;
@@ -2199,7 +2198,7 @@ vhost_dequeue_offload(struct virtio_net_hdr *hdr, struct rte_mbuf *m,
 		return;
 
 	if (legacy_ol_flags) {
-		vhost_dequeue_offload_legacy(hdr, m);
+		vhost_dequeue_offload_legacy(dev, hdr, m);
 		return;
 	}
 
@@ -2412,8 +2411,8 @@ copy_desc_to_mbuf(struct virtio_net *dev, struct vhost_virtqueue *vq,
 		if (mbuf_avail == 0) {
 			cur = rte_pktmbuf_alloc(mbuf_pool);
 			if (unlikely(cur == NULL)) {
-				VHOST_LOG_DATA(ERR, "Failed to "
-					"allocate memory for mbuf.\n");
+				VHOST_LOG_DATA(ERR, "(%s) failed to allocate memory for mbuf.\n",
+						dev->ifname);
 				error = -1;
 				goto out;
 			}
@@ -2433,7 +2432,7 @@ copy_desc_to_mbuf(struct virtio_net *dev, struct vhost_virtqueue *vq,
 	m->pkt_len    += mbuf_offset;
 
 	if (hdr)
-		vhost_dequeue_offload(hdr, m, legacy_ol_flags);
+		vhost_dequeue_offload(dev, hdr, m, legacy_ol_flags);
 
 out:
 
@@ -2447,7 +2446,7 @@ virtio_dev_extbuf_free(void *addr __rte_unused, void *opaque)
 }
 
 static int
-virtio_dev_extbuf_alloc(struct rte_mbuf *pkt, uint32_t size)
+virtio_dev_extbuf_alloc(struct virtio_net *dev, struct rte_mbuf *pkt, uint32_t size)
 {
 	struct rte_mbuf_ext_shared_info *shinfo = NULL;
 	uint32_t total_len = RTE_PKTMBUF_HEADROOM + size;
@@ -2471,7 +2470,7 @@ virtio_dev_extbuf_alloc(struct rte_mbuf *pkt, uint32_t size)
 						virtio_dev_extbuf_free, buf);
 	if (unlikely(shinfo == NULL)) {
 		rte_free(buf);
-		VHOST_LOG_DATA(ERR, "Failed to init shinfo\n");
+		VHOST_LOG_DATA(ERR, "(%s) failed to init shinfo\n", dev->ifname);
 		return -1;
 	}
 
@@ -2493,7 +2492,7 @@ virtio_dev_pktmbuf_prep(struct virtio_net *dev, struct rte_mbuf *pkt,
 		return 0;
 
 	/* attach an external buffer if supported */
-	if (dev->extbuf && !virtio_dev_extbuf_alloc(pkt, data_len))
+	if (dev->extbuf && !virtio_dev_extbuf_alloc(dev, pkt, data_len))
 		return 0;
 
 	/* check if chained buffers are allowed */
@@ -2525,12 +2524,12 @@ virtio_dev_tx_split(struct virtio_net *dev, struct vhost_virtqueue *vq,
 
 	rte_prefetch0(&vq->avail->ring[vq->last_avail_idx & (vq->size - 1)]);
 
-	VHOST_LOG_DATA(DEBUG, "(%d) %s\n", dev->vid, __func__);
+	VHOST_LOG_DATA(DEBUG, "(%s) %s\n", dev->ifname, __func__);
 
 	count = RTE_MIN(count, MAX_PKT_BURST);
 	count = RTE_MIN(count, free_entries);
-	VHOST_LOG_DATA(DEBUG, "(%d) about to dequeue %u buffers\n",
-			dev->vid, count);
+	VHOST_LOG_DATA(DEBUG, "(%s) about to dequeue %u buffers\n",
+			dev->ifname, count);
 
 	if (rte_pktmbuf_alloc_bulk(mbuf_pool, pkts, count))
 		return 0;
@@ -2559,9 +2558,8 @@ virtio_dev_tx_split(struct virtio_net *dev, struct vhost_virtqueue *vq,
 			 * is required. Drop this packet.
 			 */
 			if (!allocerr_warned) {
-				VHOST_LOG_DATA(ERR,
-					"Failed mbuf alloc of size %d from %s on %s.\n",
-					buf_len, mbuf_pool->name, dev->ifname);
+				VHOST_LOG_DATA(ERR, "(%s) failed mbuf alloc of size %d from %s.\n",
+					dev->ifname, buf_len, mbuf_pool->name);
 				allocerr_warned = true;
 			}
 			dropped += 1;
@@ -2573,8 +2571,7 @@ virtio_dev_tx_split(struct virtio_net *dev, struct vhost_virtqueue *vq,
 				mbuf_pool, legacy_ol_flags);
 		if (unlikely(err)) {
 			if (!allocerr_warned) {
-				VHOST_LOG_DATA(ERR,
-					"Failed to copy desc to mbuf on %s.\n",
+				VHOST_LOG_DATA(ERR, "(%s) failed to copy desc to mbuf.\n",
 					dev->ifname);
 				allocerr_warned = true;
 			}
@@ -2717,7 +2714,7 @@ virtio_dev_tx_batch_packed(struct virtio_net *dev,
 	if (virtio_net_with_host_offload(dev)) {
 		vhost_for_each_try_unroll(i, 0, PACKED_BATCH_SIZE) {
 			hdr = (struct virtio_net_hdr *)(desc_addrs[i]);
-			vhost_dequeue_offload(hdr, pkts[i], legacy_ol_flags);
+			vhost_dequeue_offload(dev, hdr, pkts[i], legacy_ol_flags);
 		}
 	}
 
@@ -2756,9 +2753,8 @@ vhost_dequeue_single_packed(struct virtio_net *dev,
 
 	if (unlikely(virtio_dev_pktmbuf_prep(dev, pkts, buf_len))) {
 		if (!allocerr_warned) {
-			VHOST_LOG_DATA(ERR,
-				"Failed mbuf alloc of size %d from %s on %s.\n",
-				buf_len, mbuf_pool->name, dev->ifname);
+			VHOST_LOG_DATA(ERR, "(%s) failed mbuf alloc of size %d from %s.\n",
+				dev->ifname, buf_len, mbuf_pool->name);
 			allocerr_warned = true;
 		}
 		return -1;
@@ -2768,8 +2764,7 @@ vhost_dequeue_single_packed(struct virtio_net *dev,
 				mbuf_pool, legacy_ol_flags);
 	if (unlikely(err)) {
 		if (!allocerr_warned) {
-			VHOST_LOG_DATA(ERR,
-				"Failed to copy desc to mbuf on %s.\n",
+			VHOST_LOG_DATA(ERR, "(%s) failed to copy desc to mbuf.\n",
 				dev->ifname);
 			allocerr_warned = true;
 		}
@@ -2885,16 +2880,14 @@ rte_vhost_dequeue_burst(int vid, uint16_t queue_id,
 		return 0;
 
 	if (unlikely(!(dev->flags & VIRTIO_DEV_BUILTIN_VIRTIO_NET))) {
-		VHOST_LOG_DATA(ERR,
-			"(%d) %s: built-in vhost net backend is disabled.\n",
-			dev->vid, __func__);
+		VHOST_LOG_DATA(ERR, "(%s) %s: built-in vhost net backend is disabled.\n",
+				dev->ifname, __func__);
 		return 0;
 	}
 
 	if (unlikely(!is_valid_virt_queue_idx(queue_id, 1, dev->nr_vring))) {
-		VHOST_LOG_DATA(ERR,
-			"(%d) %s: invalid virtqueue idx %d.\n",
-			dev->vid, __func__, queue_id);
+		VHOST_LOG_DATA(ERR, "(%s) %s: invalid virtqueue idx %d.\n",
+				dev->ifname, __func__, queue_id);
 		return 0;
 	}
 
@@ -2939,7 +2932,7 @@ rte_vhost_dequeue_burst(int vid, uint16_t queue_id,
 
 		rarp_mbuf = rte_net_make_rarp_packet(mbuf_pool, &dev->mac);
 		if (rarp_mbuf == NULL) {
-			VHOST_LOG_DATA(ERR, "Failed to make RARP packet.\n");
+			VHOST_LOG_DATA(ERR, "(%s) failed to make RARP packet.\n", dev->ifname);
 			count = 0;
 			goto out;
 		}
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 7/9] vhost: remove multi-line logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (5 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 6/9] vhost: improve Virtio-net " Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-27  4:57   ` Xia, Chenbo
  2022-01-26  9:55 ` [PATCH v3 8/9] vhost: differentiate IOTLB logs Maxime Coquelin
                   ` (2 subsequent siblings)
  9 siblings, 1 reply; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch replaces multi-lines logs in multiple single-
line logs in order to ease logs filtering based on their
socket path.

Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
---
 lib/vhost/socket.c     |  10 ++--
 lib/vhost/vhost.c      |   8 ++--
 lib/vhost/vhost_user.c | 103 ++++++++++++++++++++---------------------
 3 files changed, 59 insertions(+), 62 deletions(-)

diff --git a/lib/vhost/socket.c b/lib/vhost/socket.c
index ad3471d6a9..c2f8013cd5 100644
--- a/lib/vhost/socket.c
+++ b/lib/vhost/socket.c
@@ -868,8 +868,8 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 	if (vsocket->async_copy &&
 		(flags & (RTE_VHOST_USER_IOMMU_SUPPORT |
 		RTE_VHOST_USER_POSTCOPY_SUPPORT))) {
-		VHOST_LOG_CONFIG(ERR, "(%s) enabling async copy and IOMMU "
-			"or post-copy feature simultaneously is not supported\n", path);
+		VHOST_LOG_CONFIG(ERR, "(%s) async copy with IOMMU or post-copy not supported\n",
+				path);
 		goto out_mutex;
 	}
 
@@ -908,8 +908,10 @@ rte_vhost_driver_register(const char *path, uint64_t flags)
 				(1ULL << VIRTIO_NET_F_HOST_TSO6) |
 				(1ULL << VIRTIO_NET_F_HOST_UFO);
 
-		VHOST_LOG_CONFIG(INFO, "(%s) Linear buffers requested without external buffers, "
-			"disabling host segmentation offloading support\n", path);
+		VHOST_LOG_CONFIG(INFO, "(%s) Linear buffers requested without external buffers,\n",
+				path);
+		VHOST_LOG_CONFIG(INFO, "(%s) disabling host segmentation offloading support\n",
+				path);
 		vsocket->supported_features &= ~seg_offload_features;
 		vsocket->features &= ~seg_offload_features;
 	}
diff --git a/lib/vhost/vhost.c b/lib/vhost/vhost.c
index 3b05f17a50..cd62dc238b 100644
--- a/lib/vhost/vhost.c
+++ b/lib/vhost/vhost.c
@@ -1786,8 +1786,8 @@ rte_vhost_async_channel_unregister(int vid, uint16_t queue_id)
 	}
 
 	if (vq->async->pkts_inflight_n) {
-		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel. "
-			"async inflight packets must be completed before unregistration.\n",
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel.\n", dev->ifname);
+		VHOST_LOG_CONFIG(ERR, "(%s) inflight packets must be completed before unregistration.\n",
 			dev->ifname);
 		ret = -1;
 		goto out;
@@ -1821,8 +1821,8 @@ rte_vhost_async_channel_unregister_thread_unsafe(int vid, uint16_t queue_id)
 		return 0;
 
 	if (vq->async->pkts_inflight_n) {
-		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel. "
-			"async inflight packets must be completed before unregistration.\n",
+		VHOST_LOG_CONFIG(ERR, "(%s) failed to unregister async channel.\n", dev->ifname);
+		VHOST_LOG_CONFIG(ERR, "(%s) inflight packets must be completed before unregistration.\n",
 			dev->ifname);
 		return -1;
 	}
diff --git a/lib/vhost/vhost_user.c b/lib/vhost/vhost_user.c
index e207ace426..d54ac075cd 100644
--- a/lib/vhost/vhost_user.c
+++ b/lib/vhost/vhost_user.c
@@ -872,13 +872,13 @@ translate_ring_addresses(struct virtio_net *dev, int vq_index)
 	}
 
 	if (vq->last_used_idx != vq->used->idx) {
-		VHOST_LOG_CONFIG(WARNING,
-			"(%s) last_used_idx (%u) and vq->used->idx (%u) mismatches; "
-			"some packets maybe resent for Tx and dropped for Rx\n",
+		VHOST_LOG_CONFIG(WARNING, "(%s) last_used_idx (%u) and vq->used->idx (%u) mismatches;\n",
 			dev->ifname,
 			vq->last_used_idx, vq->used->idx);
 		vq->last_used_idx  = vq->used->idx;
 		vq->last_avail_idx = vq->used->idx;
+		VHOST_LOG_CONFIG(WARNING, "(%s) some packets maybe resent for Tx and dropped for Rx\n",
+			dev->ifname);
 	}
 
 	vq->access_ok = true;
@@ -1066,15 +1066,14 @@ dump_guest_pages(struct virtio_net *dev)
 	for (i = 0; i < dev->nr_guest_pages; i++) {
 		page = &dev->guest_pages[i];
 
-		VHOST_LOG_CONFIG(INFO,
-			"(%s) guest physical page region %u\n"
-			"\t guest_phys_addr: %" PRIx64 "\n"
-			"\t host_phys_addr : %" PRIx64 "\n"
-			"\t size           : %" PRIx64 "\n",
-			dev->ifname, i,
-			page->guest_phys_addr,
-			page->host_phys_addr,
-			page->size);
+		VHOST_LOG_CONFIG(INFO, "(%s) guest physical page region %u\n",
+				dev->ifname, i);
+		VHOST_LOG_CONFIG(INFO, "(%s)\tguest_phys_addr: %" PRIx64 "\n",
+				dev->ifname, page->guest_phys_addr);
+		VHOST_LOG_CONFIG(INFO, "(%s)\thost_phys_addr : %" PRIx64 "\n",
+				dev->ifname, page->host_phys_addr);
+		VHOST_LOG_CONFIG(INFO, "(%s)\tsize           : %" PRIx64 "\n",
+				dev->ifname, page->size);
 	}
 }
 #else
@@ -1133,7 +1132,8 @@ vhost_user_postcopy_region_register(struct virtio_net *dev,
 		return -1;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "(%s)\t userfaultfd registered for range : %" PRIx64 " - %" PRIx64 "\n",
+	VHOST_LOG_CONFIG(INFO,
+			"(%s)\t userfaultfd registered for range : %" PRIx64 " - %" PRIx64 "\n",
 			dev->ifname,
 			(uint64_t)reg_struct.range.start,
 			(uint64_t)reg_struct.range.start +
@@ -1218,8 +1218,7 @@ vhost_user_mmap_region(struct virtio_net *dev,
 
 	/* Check for memory_size + mmap_offset overflow */
 	if (mmap_offset >= -region->size) {
-		VHOST_LOG_CONFIG(ERR, "(%s) mmap_offset (%#"PRIx64") and memory_size "
-				"(%#"PRIx64") overflow\n",
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap_offset (%#"PRIx64") and memory_size (%#"PRIx64") overflow\n",
 				dev->ifname, mmap_offset, region->size);
 		return -1;
 	}
@@ -1248,8 +1247,7 @@ vhost_user_mmap_region(struct virtio_net *dev,
 		 * mmap() kernel implementation would return an error, but
 		 * better catch it before and provide useful info in the logs.
 		 */
-		VHOST_LOG_CONFIG(ERR, "(%s) mmap size (0x%" PRIx64 ") "
-				"or alignment (0x%" PRIx64 ") is invalid\n",
+		VHOST_LOG_CONFIG(ERR, "(%s) mmap size (0x%" PRIx64 ") or alignment (0x%" PRIx64 ") is invalid\n",
 				dev->ifname, region->size + mmap_offset, alignment);
 		return -1;
 	}
@@ -1285,24 +1283,22 @@ vhost_user_mmap_region(struct virtio_net *dev,
 		}
 	}
 
-	VHOST_LOG_CONFIG(INFO,
-			"(%s) guest memory region size: 0x%" PRIx64 "\n"
-			"\t guest physical addr: 0x%" PRIx64 "\n"
-			"\t guest virtual  addr: 0x%" PRIx64 "\n"
-			"\t host  virtual  addr: 0x%" PRIx64 "\n"
-			"\t mmap addr : 0x%" PRIx64 "\n"
-			"\t mmap size : 0x%" PRIx64 "\n"
-			"\t mmap align: 0x%" PRIx64 "\n"
-			"\t mmap off  : 0x%" PRIx64 "\n",
-			dev->ifname,
-			region->size,
-			region->guest_phys_addr,
-			region->guest_user_addr,
-			region->host_user_addr,
-			(uint64_t)(uintptr_t)mmap_addr,
-			mmap_size,
-			alignment,
-			mmap_offset);
+	VHOST_LOG_CONFIG(INFO, "(%s) guest memory region size: 0x%" PRIx64 "\n",
+			dev->ifname, region->size);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t guest physical addr: 0x%" PRIx64 "\n",
+			dev->ifname, region->guest_phys_addr);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t guest virtual  addr: 0x%" PRIx64 "\n",
+			dev->ifname, region->guest_user_addr);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t host  virtual  addr: 0x%" PRIx64 "\n",
+			dev->ifname, region->host_user_addr);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t mmap addr : 0x%" PRIx64 "\n",
+			dev->ifname, (uint64_t)(uintptr_t)mmap_addr);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t mmap size : 0x%" PRIx64 "\n",
+			dev->ifname, mmap_size);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t mmap align: 0x%" PRIx64 "\n",
+			dev->ifname, alignment);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t mmap off  : 0x%" PRIx64 "\n",
+			dev->ifname, mmap_offset);
 
 	return 0;
 }
@@ -2201,9 +2197,9 @@ vhost_user_set_vring_enable(struct virtio_net **pdev,
 
 	if (enable && dev->virtqueue[index]->async) {
 		if (dev->virtqueue[index]->async->pkts_inflight_n) {
-			VHOST_LOG_CONFIG(ERR, "(%s) failed to enable vring. "
-			"async inflight packets must be completed first\n",
-			dev->ifname);
+			VHOST_LOG_CONFIG(ERR,
+				"(%s) failed to enable vring. Inflight packets must be completed first\n",
+				dev->ifname);
 			return RTE_VHOST_MSG_RESULT_ERR;
 		}
 	}
@@ -2709,22 +2705,21 @@ vhost_user_set_status(struct virtio_net **pdev, struct VhostUserMsg *msg,
 		dev->status &= ~VIRTIO_DEVICE_STATUS_FEATURES_OK;
 	}
 
-	VHOST_LOG_CONFIG(INFO, "(%s) new device status(0x%08x):\n"
-			"\t-RESET: %u\n"
-			"\t-ACKNOWLEDGE: %u\n"
-			"\t-DRIVER: %u\n"
-			"\t-FEATURES_OK: %u\n"
-			"\t-DRIVER_OK: %u\n"
-			"\t-DEVICE_NEED_RESET: %u\n"
-			"\t-FAILED: %u\n",
-			dev->ifname,
-			dev->status,
-			(dev->status == VIRTIO_DEVICE_STATUS_RESET),
-			!!(dev->status & VIRTIO_DEVICE_STATUS_ACK),
-			!!(dev->status & VIRTIO_DEVICE_STATUS_DRIVER),
-			!!(dev->status & VIRTIO_DEVICE_STATUS_FEATURES_OK),
-			!!(dev->status & VIRTIO_DEVICE_STATUS_DRIVER_OK),
-			!!(dev->status & VIRTIO_DEVICE_STATUS_DEV_NEED_RESET),
+	VHOST_LOG_CONFIG(INFO, "(%s) new device status(0x%08x):\n", dev->ifname,
+			dev->status);
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-RESET: %u\n", dev->ifname,
+			(dev->status == VIRTIO_DEVICE_STATUS_RESET));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-ACKNOWLEDGE: %u\n", dev->ifname,
+			!!(dev->status & VIRTIO_DEVICE_STATUS_ACK));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-DRIVER: %u\n", dev->ifname,
+			!!(dev->status & VIRTIO_DEVICE_STATUS_DRIVER));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-FEATURES_OK: %u\n", dev->ifname,
+			!!(dev->status & VIRTIO_DEVICE_STATUS_FEATURES_OK));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-DRIVER_OK: %u\n", dev->ifname,
+			!!(dev->status & VIRTIO_DEVICE_STATUS_DRIVER_OK));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-DEVICE_NEED_RESET: %u\n", dev->ifname,
+			!!(dev->status & VIRTIO_DEVICE_STATUS_DEV_NEED_RESET));
+	VHOST_LOG_CONFIG(INFO, "(%s)\t-FAILED: %u\n", dev->ifname,
 			!!(dev->status & VIRTIO_DEVICE_STATUS_FAILED));
 
 	return RTE_VHOST_MSG_RESULT_OK;
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 8/9] vhost: differentiate IOTLB logs
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (6 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 7/9] vhost: remove multi-line logs Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-26  9:55 ` [PATCH v3 9/9] vhost: use proper logging type for data path Maxime Coquelin
  2022-01-27  5:37 ` [PATCH v3 0/9] vhost: improve logging Xia, Chenbo
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

Same logging messages were used for both IOTLB cache
insertion failure and IOTLB pending insertion failure.

This patch differentiate them to ease logs analysis.

Suggested-by: David Marchand <david.marchand@redhat.com>
Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/iotlb.c | 12 ++++++++----
 1 file changed, 8 insertions(+), 4 deletions(-)

diff --git a/lib/vhost/iotlb.c b/lib/vhost/iotlb.c
index afa86d7c2b..b24202a7eb 100644
--- a/lib/vhost/iotlb.c
+++ b/lib/vhost/iotlb.c
@@ -70,7 +70,8 @@ vhost_user_iotlb_pending_insert(struct virtio_net *dev, struct vhost_virtqueue *
 
 	ret = rte_mempool_get(vq->iotlb_pool, (void **)&node);
 	if (ret) {
-		VHOST_LOG_CONFIG(DEBUG, "(%s) IOTLB pool %s empty, clear entries\n",
+		VHOST_LOG_CONFIG(DEBUG,
+				"(%s) IOTLB pool %s empty, clear entries for pending insertion\n",
 				dev->ifname, vq->iotlb_pool->name);
 		if (!TAILQ_EMPTY(&vq->iotlb_pending_list))
 			vhost_user_iotlb_pending_remove_all(vq);
@@ -78,7 +79,8 @@ vhost_user_iotlb_pending_insert(struct virtio_net *dev, struct vhost_virtqueue *
 			vhost_user_iotlb_cache_random_evict(vq);
 		ret = rte_mempool_get(vq->iotlb_pool, (void **)&node);
 		if (ret) {
-			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB pool %s still empty, failure\n",
+			VHOST_LOG_CONFIG(ERR,
+					"(%s) IOTLB pool %s still empty, pending insertion failure\n",
 					dev->ifname, vq->iotlb_pool->name);
 			return;
 		}
@@ -167,7 +169,8 @@ vhost_user_iotlb_cache_insert(struct virtio_net *dev, struct vhost_virtqueue *vq
 
 	ret = rte_mempool_get(vq->iotlb_pool, (void **)&new_node);
 	if (ret) {
-		VHOST_LOG_CONFIG(DEBUG, "(%s) IOTLB pool %s empty, clear entries\n",
+		VHOST_LOG_CONFIG(DEBUG,
+				"(%s) IOTLB pool %s empty, clear entries for cache insertion\n",
 				dev->ifname, vq->iotlb_pool->name);
 		if (!TAILQ_EMPTY(&vq->iotlb_list))
 			vhost_user_iotlb_cache_random_evict(vq);
@@ -175,7 +178,8 @@ vhost_user_iotlb_cache_insert(struct virtio_net *dev, struct vhost_virtqueue *vq
 			vhost_user_iotlb_pending_remove_all(vq);
 		ret = rte_mempool_get(vq->iotlb_pool, (void **)&new_node);
 		if (ret) {
-			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB pool %s still empty, failure\n",
+			VHOST_LOG_CONFIG(ERR,
+					"(%s) IOTLB pool %s still empty, cache insertion failed\n",
 					dev->ifname, vq->iotlb_pool->name);
 			return;
 		}
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 9/9] vhost: use proper logging type for data path
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (7 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 8/9] vhost: differentiate IOTLB logs Maxime Coquelin
@ 2022-01-26  9:55 ` Maxime Coquelin
  2022-01-27  5:37 ` [PATCH v3 0/9] vhost: improve logging Xia, Chenbo
  9 siblings, 0 replies; 13+ messages in thread
From: Maxime Coquelin @ 2022-01-26  9:55 UTC (permalink / raw)
  To: dev, chenbo.xia, david.marchand; +Cc: Maxime Coquelin

This patch changes type from config to data for functions
called in the datapath.

Suggested-by: David Marchand <david.marchand@redhat.com>
Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>
---
 lib/vhost/vhost.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/vhost/vhost.c b/lib/vhost/vhost.c
index cd62dc238b..f59ca6c157 100644
--- a/lib/vhost/vhost.c
+++ b/lib/vhost/vhost.c
@@ -58,7 +58,7 @@ __vhost_iova_to_vva(struct virtio_net *dev, struct vhost_virtqueue *vq,
 
 		vhost_user_iotlb_pending_insert(dev, vq, iova, perm);
 		if (vhost_user_iotlb_miss(dev, iova, perm)) {
-			VHOST_LOG_CONFIG(ERR, "(%s) IOTLB miss req failed for IOVA 0x%" PRIx64 "\n",
+			VHOST_LOG_DATA(ERR, "(%s) IOTLB miss req failed for IOVA 0x%" PRIx64 "\n",
 				dev->ifname, iova);
 			vhost_user_iotlb_pending_remove(vq, iova, 1, perm);
 		}
@@ -420,7 +420,7 @@ translate_log_addr(struct virtio_net *dev, struct vhost_virtqueue *vq,
 
 		gpa = hva_to_gpa(dev, hva, exp_size);
 		if (!gpa) {
-			VHOST_LOG_CONFIG(ERR,
+			VHOST_LOG_DATA(ERR,
 				"(%s) failed to find GPA for log_addr: 0x%"
 				PRIx64 " hva: 0x%" PRIx64 "\n",
 				dev->ifname, log_addr, hva);
-- 
2.34.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* RE: [PATCH v3 7/9] vhost: remove multi-line logs
  2022-01-26  9:55 ` [PATCH v3 7/9] vhost: remove multi-line logs Maxime Coquelin
@ 2022-01-27  4:57   ` Xia, Chenbo
  0 siblings, 0 replies; 13+ messages in thread
From: Xia, Chenbo @ 2022-01-27  4:57 UTC (permalink / raw)
  To: Maxime Coquelin, dev, david.marchand

> -----Original Message-----
> From: Maxime Coquelin <maxime.coquelin@redhat.com>
> Sent: Wednesday, January 26, 2022 5:55 PM
> To: dev@dpdk.org; Xia, Chenbo <chenbo.xia@intel.com>;
> david.marchand@redhat.com
> Cc: Maxime Coquelin <maxime.coquelin@redhat.com>
> Subject: [PATCH v3 7/9] vhost: remove multi-line logs
> 
> This patch replaces multi-lines logs in multiple single-
> line logs in order to ease logs filtering based on their
> socket path.
> 
> Signed-off-by: Maxime Coquelin <maxime.coquelin@redhat.com>
> ---
>  lib/vhost/socket.c     |  10 ++--
>  lib/vhost/vhost.c      |   8 ++--
>  lib/vhost/vhost_user.c | 103 ++++++++++++++++++++---------------------
>  3 files changed, 59 insertions(+), 62 deletions(-)
> 
> --
> 2.34.1

Reviewed-by: Chenbo Xia <chenbo.xia@intel.com>


^ permalink raw reply	[flat|nested] 13+ messages in thread

* RE: [PATCH v3 0/9] vhost: improve logging
  2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
                   ` (8 preceding siblings ...)
  2022-01-26  9:55 ` [PATCH v3 9/9] vhost: use proper logging type for data path Maxime Coquelin
@ 2022-01-27  5:37 ` Xia, Chenbo
  2022-01-27  8:09   ` David Marchand
  9 siblings, 1 reply; 13+ messages in thread
From: Xia, Chenbo @ 2022-01-27  5:37 UTC (permalink / raw)
  To: Maxime Coquelin, dev, david.marchand

> -----Original Message-----
> From: Maxime Coquelin <maxime.coquelin@redhat.com>
> Sent: Wednesday, January 26, 2022 5:55 PM
> To: dev@dpdk.org; Xia, Chenbo <chenbo.xia@intel.com>;
> david.marchand@redhat.com
> Cc: Maxime Coquelin <maxime.coquelin@redhat.com>
> Subject: [PATCH v3 0/9] vhost: improve logging
> 
> This series aims at easing Vhost logs analysis, by
> prepending the Vhost-user socket path to all logs and to
> remove multi-line comments. Doing so, filtering Vhost-user
> ports logs is much easier.
> 
> Changes in v3:
> ==============
> - Fix various typos reported (Chenbo)
> - Revert one multi-line comment removal (Chenbo)
> 
> Changes in v2:
> ==============
> - Add missing socket paths (David)
> - avoid identical logs in iotlb code (David)
> - Use data log type when used in datapath (David)
> 
> Maxime Coquelin (9):
>   vhost: improve IOTLB logs
>   vhost: improve vDPA registration failure log
>   vhost: improve Vhost layer logs
>   vhost: improve Vhost-user layer logs
>   vhost: improve socket layer logs
>   vhost: improve Virtio-net layer logs
>   vhost: remove multi-line logs
>   vhost: differentiate IOTLB logs
>   vhost: use proper logging type for data path
> 
>  lib/vhost/iotlb.c      |  30 +-
>  lib/vhost/iotlb.h      |  10 +-
>  lib/vhost/socket.c     | 148 ++++-----
>  lib/vhost/vdpa.c       |   4 +-
>  lib/vhost/vhost.c      | 108 ++++---
>  lib/vhost/vhost_user.c | 678 ++++++++++++++++++++---------------------
>  lib/vhost/vhost_user.h |   4 +-
>  lib/vhost/virtio_net.c | 165 +++++-----
>  8 files changed, 548 insertions(+), 599 deletions(-)
> 
> --
> 2.34.1

Series applied to next-virtio/main, thanks

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 0/9] vhost: improve logging
  2022-01-27  5:37 ` [PATCH v3 0/9] vhost: improve logging Xia, Chenbo
@ 2022-01-27  8:09   ` David Marchand
  0 siblings, 0 replies; 13+ messages in thread
From: David Marchand @ 2022-01-27  8:09 UTC (permalink / raw)
  To: Xia, Chenbo; +Cc: Maxime Coquelin, dev

On Thu, Jan 27, 2022 at 6:37 AM Xia, Chenbo <chenbo.xia@intel.com> wrote:
> > From: Maxime Coquelin <maxime.coquelin@redhat.com>
> >
> > This series aims at easing Vhost logs analysis, by
> > prepending the Vhost-user socket path to all logs and to
> > remove multi-line comments. Doing so, filtering Vhost-user
> > ports logs is much easier.
> >
> > Changes in v3:
> > ==============
> > - Fix various typos reported (Chenbo)
> > - Revert one multi-line comment removal (Chenbo)
> >
> > Changes in v2:
> > ==============
> > - Add missing socket paths (David)
> > - avoid identical logs in iotlb code (David)
> > - Use data log type when used in datapath (David)
> >
> > Maxime Coquelin (9):
> >   vhost: improve IOTLB logs
> >   vhost: improve vDPA registration failure log
> >   vhost: improve Vhost layer logs
> >   vhost: improve Vhost-user layer logs
> >   vhost: improve socket layer logs
> >   vhost: improve Virtio-net layer logs
> >   vhost: remove multi-line logs
> >   vhost: differentiate IOTLB logs
> >   vhost: use proper logging type for data path
> >
> >  lib/vhost/iotlb.c      |  30 +-
> >  lib/vhost/iotlb.h      |  10 +-
> >  lib/vhost/socket.c     | 148 ++++-----
> >  lib/vhost/vdpa.c       |   4 +-
> >  lib/vhost/vhost.c      | 108 ++++---
> >  lib/vhost/vhost_user.c | 678 ++++++++++++++++++++---------------------
> >  lib/vhost/vhost_user.h |   4 +-
> >  lib/vhost/virtio_net.c | 165 +++++-----
> >  8 files changed, 548 insertions(+), 599 deletions(-)
> >
> > --
> > 2.34.1
>
> Series applied to next-virtio/main, thanks

For the series:
Reviewed-by: David Marchand <david.marchand@redhat.com>


-- 
David Marchand


^ permalink raw reply	[flat|nested] 13+ messages in thread

end of thread, other threads:[~2022-01-27  8:09 UTC | newest]

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-01-26  9:55 [PATCH v3 0/9] vhost: improve logging Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 1/9] vhost: improve IOTLB logs Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 2/9] vhost: improve vDPA registration failure log Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 3/9] vhost: improve Vhost layer logs Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 4/9] vhost: improve Vhost-user " Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 5/9] vhost: improve socket " Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 6/9] vhost: improve Virtio-net " Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 7/9] vhost: remove multi-line logs Maxime Coquelin
2022-01-27  4:57   ` Xia, Chenbo
2022-01-26  9:55 ` [PATCH v3 8/9] vhost: differentiate IOTLB logs Maxime Coquelin
2022-01-26  9:55 ` [PATCH v3 9/9] vhost: use proper logging type for data path Maxime Coquelin
2022-01-27  5:37 ` [PATCH v3 0/9] vhost: improve logging Xia, Chenbo
2022-01-27  8:09   ` David Marchand

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).