From 196a2258ac33b6369efbf8979d5246e203dddbf2 Mon Sep 17 00:00:00 2001 From: Milind Changire Date: Thu, 25 Oct 2018 13:05:13 +0530 Subject: transport: log socket closures more verbose Problem: Intentional and unintentional socket closures cannot be identified Solution: Log intentional socket closures with at least INFO log level Change-Id: Ic02c882b16ab2193e57f8c3e6c3a82c4fe0f6875 fixes: bz#1642800 Signed-off-by: Milind Changire --- rpc/rpc-transport/socket/src/socket.c | 54 ++++++++++++++++++++++++++++------- 1 file changed, 43 insertions(+), 11 deletions(-) diff --git a/rpc/rpc-transport/socket/src/socket.c b/rpc/rpc-transport/socket/src/socket.c index 9d926e6e078..4368f3fcc1a 100644 --- a/rpc/rpc-transport/socket/src/socket.c +++ b/rpc/rpc-transport/socket/src/socket.c @@ -687,8 +687,10 @@ __socket_rwv(rpc_transport_t *this, struct iovec *vector, int count, } else { ret = __socket_cached_read(this, opvector, opcount); if (ret == 0) { - gf_log(this->name, GF_LOG_DEBUG, "EOF on socket (errno:%d:%s)", - errno, strerror(errno)); + gf_log(this->name, GF_LOG_INFO, + "EOF on socket %d " + "(errno:%d:%s); returning ENODATA", + sock, errno, strerror(errno)); errno = ENODATA; ret = -1; } @@ -804,6 +806,9 @@ __socket_shutdown(rpc_transport_t *this) why it failed to shutdown in normal cases */ gf_log(this->name, GF_LOG_DEBUG, "shutdown() returned %d. %s", ret, strerror(errno)); + } else { + gf_log(this->name, GF_LOG_INFO, "intentional socket shutdown(%d)", + priv->sock); } return ret; @@ -893,6 +898,8 @@ __socket_server_bind(rpc_transport_t *this) if ((ret == -1) && (ECONNREFUSED == errno)) { sys_unlink(((struct sockaddr_un *)&unix_addr)->sun_path); } + gf_log(this->name, GF_LOG_INFO, + "closing (AF_UNIX) reuse check socket %d", reuse_check_sock); sys_close(reuse_check_sock); } } @@ -3030,13 +3037,19 @@ socket_server_event_handler(int fd, int idx, int gen, void *data, int poll_in, new_trans = GF_CALLOC(1, sizeof(*new_trans), gf_common_mt_rpc_trans_t); if (!new_trans) { sys_close(new_sock); + gf_log(this->name, GF_LOG_WARNING, + "transport object allocation failure; " + "closed newly accepted socket %d", + new_sock); goto out; } ret = pthread_mutex_init(&new_trans->lock, NULL); if (ret == -1) { gf_log(this->name, GF_LOG_WARNING, - "pthread_mutex_init() failed: %s", strerror(errno)); + "pthread_mutex_init() failed: %s; closing newly accepted " + "socket %d", + strerror(errno), new_sock); sys_close(new_sock); GF_FREE(new_trans); goto out; @@ -3053,7 +3066,9 @@ socket_server_event_handler(int fd, int idx, int gen, void *data, int poll_in, ret = getsockname(new_sock, SA(&new_trans->myinfo.sockaddr), &new_trans->myinfo.sockaddr_len); if (ret == -1) { - gf_log(this->name, GF_LOG_WARNING, "getsockname on %d failed (%s)", + gf_log(this->name, GF_LOG_WARNING, + "getsockname on socket %d " + "failed (errno:%s); closing newly accepted socket", new_sock, strerror(errno)); sys_close(new_sock); GF_FREE(new_trans->name); @@ -3067,6 +3082,10 @@ socket_server_event_handler(int fd, int idx, int gen, void *data, int poll_in, ret = socket_init(new_trans); if (ret != 0) { + gf_log(this->name, GF_LOG_WARNING, + "initialization of new_trans " + "failed; closing newly accepted socket %d", + new_sock); sys_close(new_sock); GF_FREE(new_trans->name); GF_FREE(new_trans); @@ -3168,6 +3187,7 @@ socket_server_event_handler(int fd, int idx, int gen, void *data, int poll_in, } if (ret == -1) { + gf_log(this->name, GF_LOG_WARNING, "closing newly accepted socket"); sys_close(new_sock); /* this unref is to actually cause the destruction of * the new_trans since we've failed at everything so far @@ -3499,8 +3519,8 @@ socket_connect(rpc_transport_t *this, int port) socket_event_handler or socket_poller */ shutdown(priv->sock, SHUT_RDWR); ret = 0; - gf_log(this->name, GF_LOG_TRACE, - "@@@ client shutdown(%d, SHUT_RDWR)", priv->sock); + gf_log(this->name, GF_LOG_INFO, + "intentional client shutdown(%d, SHUT_RDWR)", priv->sock); } priv->connected = 0; @@ -3512,7 +3532,10 @@ socket_connect(rpc_transport_t *this, int port) priv->idx = event_register(ctx->event_pool, priv->sock, socket_event_handler, this, 1, 1); if (priv->idx == -1) { - gf_log("", GF_LOG_WARNING, "failed to register the event"); + gf_log("", GF_LOG_WARNING, + "failed to register the event; " + "closing socket %d", + priv->sock); sys_close(priv->sock); priv->sock = -1; ret = -1; @@ -3645,7 +3668,9 @@ socket_listen(rpc_transport_t *this) ret = __socket_nonblock(priv->sock); if (ret == -1) { - gf_log(this->name, GF_LOG_ERROR, "NBIO on %d failed (%s)", + gf_log(this->name, GF_LOG_ERROR, + "NBIO on socket %d failed " + "(errno:%s); closing socket", priv->sock, strerror(errno)); sys_close(priv->sock); priv->sock = -1; @@ -3657,6 +3682,10 @@ socket_listen(rpc_transport_t *this) if ((ret == -EADDRINUSE) || (ret == -1)) { /* logged inside __socket_server_bind() */ + gf_log(this->name, GF_LOG_ERROR, + "__socket_server_bind failed;" + "closing socket %d", + priv->sock); sys_close(priv->sock); priv->sock = -1; goto unlock; @@ -3669,8 +3698,9 @@ socket_listen(rpc_transport_t *this) if (ret == -1) { gf_log(this->name, GF_LOG_ERROR, - "could not set socket %d to listen mode (%s)", priv->sock, - strerror(errno)); + "could not set socket %d to listen mode (errno:%s); " + "closing socket", + priv->sock, strerror(errno)); sys_close(priv->sock); priv->sock = -1; goto unlock; @@ -3683,7 +3713,9 @@ socket_listen(rpc_transport_t *this) if (priv->idx == -1) { gf_log(this->name, GF_LOG_WARNING, - "could not register socket %d with events", priv->sock); + "could not register socket %d with events; " + "closing socket", + priv->sock); ret = -1; sys_close(priv->sock); priv->sock = -1; -- cgit