diff --git a/src/ckpool.c b/src/ckpool.c index 52ca62dd..86ad3890 100644 --- a/src/ckpool.c +++ b/src/ckpool.c @@ -733,31 +733,33 @@ json_t *json_rpc_call(connsock_t *cs, const char *rpc_req) char *http_req = NULL; json_error_t err_val; json_t *val = NULL; + tv_t stt_tv, fin_tv; + double elapsed; int len, ret; if (unlikely(cs->fd < 0)) { - LOGWARNING("FD %d invalid in json_rpc_call", cs->fd); + LOGWARNING("FD %d invalid in %s", cs->fd, __func__); goto out; } if (unlikely(!cs->url)) { - LOGWARNING("No URL in json_rpc_call"); + LOGWARNING("No URL in %s", __func__); goto out; } if (unlikely(!cs->port)) { - LOGWARNING("No port in json_rpc_call"); + LOGWARNING("No port in %s", __func__); goto out; } if (unlikely(!cs->auth)) { - LOGWARNING("No auth in json_rpc_call"); + LOGWARNING("No auth in %s", __func__); goto out; } if (unlikely(!rpc_req)) { - LOGWARNING("Null rpc_req passed to json_rpc_call"); + LOGWARNING("Null rpc_req passed to %s", __func__); goto out; } len = strlen(rpc_req); if (unlikely(!len)) { - LOGWARNING("Zero length rpc_req passed to json_rpc_call"); + LOGWARNING("Zero length rpc_req passed to %s", __func__); goto out; } http_req = ckalloc(len + 256); // Leave room for headers @@ -770,31 +772,52 @@ json_t *json_rpc_call(connsock_t *cs, const char *rpc_req) cs->auth, cs->url, cs->port, len, rpc_req); len = strlen(http_req); + tv_time(&stt_tv); ret = write_socket(cs->fd, http_req, len); if (ret != len) { - LOGWARNING("Failed to write to socket in json_rpc_call"); + tv_time(&fin_tv); + elapsed = tvdiff(&fin_tv, &stt_tv); + LOGWARNING("Failed to write to socket in %s (%.10s...) %.3fs", + __func__, rpc_req, elapsed); goto out_empty; } ret = read_socket_line(cs, &timeout); if (ret < 1) { - LOGWARNING("Failed to read socket line in json_rpc_call"); + tv_time(&fin_tv); + elapsed = tvdiff(&fin_tv, &stt_tv); + LOGWARNING("Failed to read socket line in %s (%.10s...) %.3fs", + __func__, rpc_req, elapsed); goto out_empty; } if (strncasecmp(cs->buf, "HTTP/1.1 200 OK", 15)) { - LOGWARNING("HTTP response not ok: %s", cs->buf); + tv_time(&fin_tv); + elapsed = tvdiff(&fin_tv, &stt_tv); + LOGWARNING("HTTP response to (%.10s...) %.3fs not ok: %s", + rpc_req, elapsed, cs->buf); goto out_empty; } do { ret = read_socket_line(cs, &timeout); if (ret < 1) { - LOGWARNING("Failed to read http socket lines in json_rpc_call"); + tv_time(&fin_tv); + elapsed = tvdiff(&fin_tv, &stt_tv); + LOGWARNING("Failed to read http socket lines in %s (%.10s...) %.3fs", + __func__, rpc_req, elapsed); goto out_empty; } } while (strncmp(cs->buf, "{", 1)); + tv_time(&fin_tv); + elapsed = tvdiff(&fin_tv, &stt_tv); + if (elapsed > 5.0) { + LOGWARNING("HTTP socket read+write took %.3fs in %s (%.10s...)", + elapsed, __func__, rpc_req); + } val = json_loads(cs->buf, 0, &err_val); - if (!val) - LOGWARNING("JSON decode failed(%d): %s", err_val.line, err_val.text); + if (!val) { + LOGWARNING("JSON decode (%.10s...) failed(%d): %s", + rpc_req, err_val.line, err_val.text); + } out_empty: empty_socket(cs->fd); empty_buffer(cs);