From 3bf828f602247b6af2b7ccd45eb45fc86d67b597 Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Mon, 5 Oct 2015 13:36:25 -0700 Subject: [PATCH 1/3] Add a more useful log message when failing to connect --- src/core/iomgr/tcp_client_posix.c | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/src/core/iomgr/tcp_client_posix.c b/src/core/iomgr/tcp_client_posix.c index 346566866a2..aca2691c416 100644 --- a/src/core/iomgr/tcp_client_posix.c +++ b/src/core/iomgr/tcp_client_posix.c @@ -141,7 +141,8 @@ static void on_writable(grpc_exec_ctx *exec_ctx, void *acp, int success) { err = getsockopt(fd->fd, SOL_SOCKET, SO_ERROR, &so_error, &so_error_size); } while (err < 0 && errno == EINTR); if (err < 0) { - gpr_log(GPR_ERROR, "getsockopt(ERROR): %s", strerror(errno)); + gpr_log(GPR_ERROR, "failed to connect to '%s': getsockopt(ERROR): %s", + ac->addr_str, strerror(errno)); goto finish; } else if (so_error != 0) { if (so_error == ENOBUFS) { @@ -166,10 +167,14 @@ static void on_writable(grpc_exec_ctx *exec_ctx, void *acp, int success) { } else { switch (so_error) { case ECONNREFUSED: - gpr_log(GPR_ERROR, "socket error: connection refused"); + gpr_log( + GPR_ERROR, + "failed to connect to '%s': socket error: connection refused", + ac->addr_str); break; default: - gpr_log(GPR_ERROR, "socket error: %d", so_error); + gpr_log(GPR_ERROR, "failed to connect to '%s': socket error: %d", + ac->addr_str, so_error); break; } goto finish; @@ -181,7 +186,8 @@ static void on_writable(grpc_exec_ctx *exec_ctx, void *acp, int success) { goto finish; } } else { - gpr_log(GPR_ERROR, "on_writable failed during connect"); + gpr_log(GPR_ERROR, "failed to connect to '%s': timeout occurred", + ac->addr_str); goto finish; } From c6c3189f3dca4880d05cf0492c28d0988b06367e Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Mon, 5 Oct 2015 14:00:19 -0700 Subject: [PATCH 2/3] Add more verbose traces for debug output --- test/core/util/port_posix.c | 14 ++++++++++++-- tools/run_tests/run_tests.py | 10 +++++++--- 2 files changed, 19 insertions(+), 5 deletions(-) diff --git a/test/core/util/port_posix.c b/test/core/util/port_posix.c index 887079e0f8a..0a50660586a 100644 --- a/test/core/util/port_posix.c +++ b/test/core/util/port_posix.c @@ -213,15 +213,25 @@ static void got_port_from_server(grpc_exec_ctx *exec_ctx, void *arg, size_t i; int port = 0; portreq *pr = arg; + int failed = 0; + + if (!response) { + failed = 1; + gpr_log(GPR_DEBUG, + "failed port pick from server: retrying [response=NULL]"); + } else if (response->status != 200) { + failed = 1; + gpr_log(GPR_DEBUG, "failed port pick from server: status=%d", + response->status); + } - if (!response || response->status != 200) { + if (failed) { grpc_httpcli_request req; memset(&req, 0, sizeof(req)); GPR_ASSERT(pr->retries < 10); pr->retries++; req.host = pr->server; req.path = "/get"; - gpr_log(GPR_DEBUG, "failed port pick from server: retrying"); sleep(1); grpc_httpcli_get(exec_ctx, pr->ctx, &pr->pollset, &req, GRPC_TIMEOUT_SECONDS_TO_DEADLINE(10), got_port_from_server, diff --git a/tools/run_tests/run_tests.py b/tools/run_tests/run_tests.py index 38c06764b9b..9ed8ef33e1f 100755 --- a/tools/run_tests/run_tests.py +++ b/tools/run_tests/run_tests.py @@ -715,17 +715,21 @@ def _start_port_server(port_server_port): try: version = urllib2.urlopen('http://localhost:%d/version' % port_server_port, timeout=1).read() + print 'detected port server running' running = True except Exception: + print 'failed to detect port server: %s' % sys.exc_info()[0] running = False if running: with open('tools/run_tests/port_server.py') as f: current_version = hashlib.sha1(f.read()).hexdigest() running = (version == current_version) if not running: + print 'port_server version mismatch: killing the old one' urllib2.urlopen('http://localhost:%d/quit' % port_server_port).read() time.sleep(1) if not running: + print 'starting port_server' port_log = open('portlog.txt', 'w') port_server = subprocess.Popen( ['python', 'tools/run_tests/port_server.py', '-p', '%d' % port_server_port], @@ -737,7 +741,7 @@ def _start_port_server(port_server_port): if waits > 10: port_server.kill() if port_server.poll() is not None: - print "port_server failed to start" + print 'port_server failed to start' port_log = open('portlog.txt', 'r').read() print port_log sys.exit(1) @@ -746,11 +750,11 @@ def _start_port_server(port_server_port): timeout=1).read() break except socket.timeout: - print "waiting for port_server" + print 'waiting for port_server: timeout' time.sleep(0.5) waits += 1 except urllib2.URLError: - print "waiting for port_server" + print 'waiting for port_server: urlerror' time.sleep(0.5) waits += 1 except: From 0d6499e7e1fc9c9d4e1b7369a28f1ef95006714f Mon Sep 17 00:00:00 2001 From: Craig Tiller Date: Mon, 5 Oct 2015 14:00:47 -0700 Subject: [PATCH 3/3] Add more verbose traces for port_server usage --- test/core/util/port_posix.c | 14 ++++++++++++-- tools/run_tests/run_tests.py | 10 +++++++--- 2 files changed, 19 insertions(+), 5 deletions(-) diff --git a/test/core/util/port_posix.c b/test/core/util/port_posix.c index 887079e0f8a..0a50660586a 100644 --- a/test/core/util/port_posix.c +++ b/test/core/util/port_posix.c @@ -213,15 +213,25 @@ static void got_port_from_server(grpc_exec_ctx *exec_ctx, void *arg, size_t i; int port = 0; portreq *pr = arg; + int failed = 0; + + if (!response) { + failed = 1; + gpr_log(GPR_DEBUG, + "failed port pick from server: retrying [response=NULL]"); + } else if (response->status != 200) { + failed = 1; + gpr_log(GPR_DEBUG, "failed port pick from server: status=%d", + response->status); + } - if (!response || response->status != 200) { + if (failed) { grpc_httpcli_request req; memset(&req, 0, sizeof(req)); GPR_ASSERT(pr->retries < 10); pr->retries++; req.host = pr->server; req.path = "/get"; - gpr_log(GPR_DEBUG, "failed port pick from server: retrying"); sleep(1); grpc_httpcli_get(exec_ctx, pr->ctx, &pr->pollset, &req, GRPC_TIMEOUT_SECONDS_TO_DEADLINE(10), got_port_from_server, diff --git a/tools/run_tests/run_tests.py b/tools/run_tests/run_tests.py index 38c06764b9b..9ed8ef33e1f 100755 --- a/tools/run_tests/run_tests.py +++ b/tools/run_tests/run_tests.py @@ -715,17 +715,21 @@ def _start_port_server(port_server_port): try: version = urllib2.urlopen('http://localhost:%d/version' % port_server_port, timeout=1).read() + print 'detected port server running' running = True except Exception: + print 'failed to detect port server: %s' % sys.exc_info()[0] running = False if running: with open('tools/run_tests/port_server.py') as f: current_version = hashlib.sha1(f.read()).hexdigest() running = (version == current_version) if not running: + print 'port_server version mismatch: killing the old one' urllib2.urlopen('http://localhost:%d/quit' % port_server_port).read() time.sleep(1) if not running: + print 'starting port_server' port_log = open('portlog.txt', 'w') port_server = subprocess.Popen( ['python', 'tools/run_tests/port_server.py', '-p', '%d' % port_server_port], @@ -737,7 +741,7 @@ def _start_port_server(port_server_port): if waits > 10: port_server.kill() if port_server.poll() is not None: - print "port_server failed to start" + print 'port_server failed to start' port_log = open('portlog.txt', 'r').read() print port_log sys.exit(1) @@ -746,11 +750,11 @@ def _start_port_server(port_server_port): timeout=1).read() break except socket.timeout: - print "waiting for port_server" + print 'waiting for port_server: timeout' time.sleep(0.5) waits += 1 except urllib2.URLError: - print "waiting for port_server" + print 'waiting for port_server: urlerror' time.sleep(0.5) waits += 1 except: