summaryrefslogtreecommitdiffstats
path: root/rpc
diff options
context:
space:
mode:
authorMilind Changire <mchangir@redhat.com>2018-10-25 13:05:13 +0530
committerAmar Tumballi <amarts@redhat.com>2018-10-26 04:07:01 +0000
commit196a2258ac33b6369efbf8979d5246e203dddbf2 (patch)
tree7f8c8cd89470328516e503eadc48a4fd2e056fb0 /rpc
parentc66ea8566d18230ce20b55640b25a06f6f56ec7d (diff)
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 <mchangir@redhat.com>
Diffstat (limited to 'rpc')
-rw-r--r--rpc/rpc-transport/socket/src/socket.c54
1 files 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;