From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mails.dpdk.org (mails.dpdk.org [217.70.189.124]) by inbox.dpdk.org (Postfix) with ESMTP id C5F1CA0350; Thu, 23 Dec 2021 09:37:44 +0100 (CET) Received: from [217.70.189.124] (localhost [127.0.0.1]) by mails.dpdk.org (Postfix) with ESMTP id B799E41152; Thu, 23 Dec 2021 09:37:37 +0100 (CET) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by mails.dpdk.org (Postfix) with ESMTP id D888841142 for ; Thu, 23 Dec 2021 09:37:35 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1640248655; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=ScOTJKSy5HnU+4Eq0/8FGmCWp3zPURtjfjI0dwg0yj8=; b=iVkPTxL2bJAlY3J+VkQzydvPCnue0quRLQWuMijdRrMWEDfdfWPtukHRqorgKfrEit7a+n AbThO5W3+QDjVZcABPrg8X9NjOUe7u0XAR/yizS4bac4oth9C+HONjyxuLc6jtvI7fPqYU sX51vBbBEjMNuuQKjcGaiJDxZrVkMMM= Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id us-mta-486-reaFOoaOP1a0FO5uNNNLYw-1; Thu, 23 Dec 2021 03:37:33 -0500 X-MC-Unique: reaFOoaOP1a0FO5uNNNLYw-1 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 9A17E344AF; Thu, 23 Dec 2021 08:37:32 +0000 (UTC) Received: from max-t490s.redhat.com (unknown [10.39.208.14]) by smtp.corp.redhat.com (Postfix) with ESMTP id 698A660BD8; Thu, 23 Dec 2021 08:37:31 +0000 (UTC) From: Maxime Coquelin To: dev@dpdk.org, chenbo.xia@intel.com, david.marchand@redhat.com Cc: Maxime Coquelin Subject: [PATCH 3/7] vhost: improve socket layer logs Date: Thu, 23 Dec 2021 09:36:55 +0100 Message-Id: <20211223083659.245766-4-maxime.coquelin@redhat.com> In-Reply-To: <20211223083659.245766-1-maxime.coquelin@redhat.com> References: <20211223083659.245766-1-maxime.coquelin@redhat.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=maxime.coquelin@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Transfer-Encoding: 8bit Content-Type: text/plain; charset="US-ASCII" X-BeenThere: dev@dpdk.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org This patch adds the Vhost socket path whenever possible in order to make debugging possible when multiple Vhost devices are in use. Signed-off-by: Maxime Coquelin --- lib/vhost/socket.c | 129 ++++++++++++++++++--------------------------- 1 file changed, 51 insertions(+), 78 deletions(-) diff --git a/lib/vhost/socket.c b/lib/vhost/socket.c index 82963c1e6d..fd6b3a3ee4 100644 --- a/lib/vhost/socket.c +++ b/lib/vhost/socket.c @@ -124,12 +124,12 @@ 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, "recvmsg failed (fd %d)\n", sockfd); return ret; } if (msgh.msg_flags & (MSG_TRUNC | MSG_CTRUNC)) { - VHOST_LOG_CONFIG(ERR, "truncated msg\n"); + VHOST_LOG_CONFIG(ERR, "truncated msg (fd %d)\n", sockfd); return -1; } @@ -192,7 +192,7 @@ 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, "sendmsg error (fd %d)\n", sockfd); return ret; } @@ -243,14 +243,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 +261,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 +294,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 +343,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 +382,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 +396,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; } @@ -437,13 +436,11 @@ 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, "can't get flags for connfd %d\n", fd); 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, "can't disable nonblocking on fd %d\n", fd); return -2; } return 0; @@ -471,16 +468,14 @@ vhost_user_client_reconnect(void *arg __rte_unused) 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); @@ -510,10 +505,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, "failed to destroy reconnect mutex"); } return ret; @@ -534,20 +527,17 @@ vhost_user_start_client(struct vhost_user_socket *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 +691,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 +703,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 +741,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 +754,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 +779,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 +791,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 +835,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 +846,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 +865,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 +890,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 +905,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 +921,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 +948,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 +1036,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 +1112,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 +1120,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; -- 2.31.1