This is an automated email from the ASF dual-hosted git repository. chug pushed a commit to branch dev-protocol-adaptors-2 in repository https://gitbox.apache.org/repos/asf/qpid-dispatch.git
The following commit(s) were added to refs/heads/dev-protocol-adaptors-2 by this push: new a5cefb5 DISPATCH-1820: Improve logging to investigate TCP test hangs a5cefb5 is described below commit a5cefb5e34f4a3fa9c763f3e3a29b187a2e85472 Author: Chuck Rolke <c...@apache.org> AuthorDate: Tue Nov 3 14:41:52 2020 -0500 DISPATCH-1820: Improve logging to investigate TCP test hangs --- tests/TCP_echo_client.py | 1 + tests/TCP_echo_server.py | 28 ++++++++++++---- tests/system_tests_tcp_adaptor.py | 67 +++++++++++++++++++++++++++++---------- 3 files changed, 74 insertions(+), 22 deletions(-) diff --git a/tests/TCP_echo_client.py b/tests/TCP_echo_client.py index ae5364c..8465ad5 100755 --- a/tests/TCP_echo_client.py +++ b/tests/TCP_echo_client.py @@ -94,6 +94,7 @@ class TcpEchoClient(): self._thread.start() def run(self): + self.logger.log("%s Client is starting up" % (self.prefix)) try: start_time = time.time() self.is_running = True diff --git a/tests/TCP_echo_server.py b/tests/TCP_echo_server.py index 34f72bb..d8a23d4 100755 --- a/tests/TCP_echo_server.py +++ b/tests/TCP_echo_server.py @@ -123,11 +123,19 @@ class TcpEchoServer(): total_echoed = 0 # set up listening socket - self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - self.sock.bind((self.HOST, self.port)) - self.sock.listen() - self.sock.setblocking(False) - self.logger.log('%s Listening on host:%s, port:%d' % (self.prefix, self.HOST, self.port)) + try: + self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + self.sock.bind((self.HOST, self.port)) + self.sock.listen() + self.sock.setblocking(False) + self.logger.log('%s Listening on host:%s, port:%d' % (self.prefix, self.HOST, self.port)) + except Exception as exc: + self.error = ('%s Opening listen socket %s:%d exception: %s' % + (self.prefix, self.HOST, self.port, traceback.format_exc())) + logger.log(self.error) + sel.unregister(sock) + sock.close() + return 1 # set up selector sel = selectors.DefaultSelector() @@ -183,10 +191,18 @@ class TcpEchoServer(): try: recv_data = sock.recv(1024) except ConnectionResetError as exc: - logger.log('%s Connection to %s:%d closed by peer' % (self.prefix, data.addr[0], data.addr[1])) + logger.log('%s Connection to %s:%d closed by peer' % + (self.prefix, data.addr[0], data.addr[1])) sel.unregister(sock) sock.close() return 0 + except Exception as exc: + self.error = ('%s Connection to %s:%d exception: %s' % + (self.prefix, data.addr[0], data.addr[1], traceback.format_exc())) + logger.log(self.error) + sel.unregister(sock) + sock.close() + return 1 if recv_data: data.outb += recv_data logger.log('%s read from: %s:%d len:%d: %s' % (self.prefix, data.addr[0], data.addr[1], len(recv_data), diff --git a/tests/system_tests_tcp_adaptor.py b/tests/system_tests_tcp_adaptor.py index c2df88d..e290cec 100644 --- a/tests/system_tests_tcp_adaptor.py +++ b/tests/system_tests_tcp_adaptor.py @@ -23,8 +23,8 @@ from __future__ import absolute_import from __future__ import print_function import os +import time import traceback -from time import sleep from threading import Event from threading import Timer @@ -48,6 +48,8 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): tcp_client_listener_port = None tcp_server_listener_port = None + echo_timeout = 30 # local timeout to wait for one echo client to finish + @classmethod def setUpClass(cls): """Start a router""" @@ -81,14 +83,22 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): router('A', 'interior', cls.amqp_listener_port, cls.tcp_client_listener_port, cls.tcp_server_listener_port, "some_address", "best_site") - cls.logger = Logger(title="TcpAdaptorOneRouterEcho-testClass", print_to_console=True) + cls.logger = Logger(title="TcpAdaptorOneRouterEcho-testClass", + print_to_console=True, + save_for_dump=False) + cls.logger.log(" amqp_listener_port : %d" % cls.amqp_listener_port) + cls.logger.log(" tcp_client_listener_port : %d" % cls.tcp_client_listener_port) + cls.logger.log(" tcp_server_listener_port : %d" % cls.tcp_server_listener_port) - def do_test_echo(self, test_name, logger, host, port, size, count): + def do_test_echo(self, test_name, logger, host, port, size, count, print_client_logs): # Run echo client. Return true if it works. name = "%s_%s_%s_%s" % (test_name, port, size, count) client_prefix = "ECHO_CLIENT %s" % name - client_logger = Logger(title=client_prefix, print_to_console=False, save_for_dump=True) + client_logger = Logger(title=client_prefix, + print_to_console=print_client_logs, + save_for_dump=False) result = True # assume it works + start_time = time.time() try: # start client client = TcpEchoClient(prefix=client_prefix, @@ -103,7 +113,13 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): # wait for client to finish keep_waiting = True while keep_waiting: - sleep(0.1) + time.sleep(0.1) + elapsed = time.time() - start_time + if elapsed > self.echo_timeout: + client.error = "TIMEOUT - local wait time exceeded" + logger.log("%s %s" % (name, client.error)) + keep_waiting = False + result = False if client.error is not None: logger.log("%s Client stopped with error: %s" % (name, client.error)) keep_waiting = False @@ -121,10 +137,12 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): (name, traceback.format_exc())) result = False + # wait for client to exit + client.wait() + if not result: - # On failure, dump the client log through the test log. Compound logs here we go - for line in client_logger.logs: - logger.log("Failed client log: %s" % line) + pass + return result def test_01_tcp_echo_one_router(self): @@ -133,10 +151,16 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): Run many echo clients. :return: """ + # define logging + print_logs_server = True + print_logs_client = True + # start echo server test_name = "test_01_tcp_echo_one_router" server_prefix = "ECHO_SERVER %s" % test_name - server_logger = Logger(title=test_name, print_to_console=False, save_for_dump=True) + server_logger = Logger(title=test_name, + print_to_console=print_logs_server, + save_for_dump=False) server = TcpEchoServer(prefix=server_prefix, port=self.tcp_server_listener_port, timeout=TIMEOUT, @@ -145,13 +169,23 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): # run series of clients to test result = True - for size in [1]: - for count in [1]: - test_info = "Starting echo client %s host:localhost, port:%d, size:%d, count:%d" % \ - (test_name, self.tcp_client_listener_port, size, count) - self.logger.log(test_info) - result = self.do_test_echo(test_name, self.logger, "localhost", - self.tcp_client_listener_port, size, count) + for size in [1, 50, 1000]: + for count in [1, 10]: + # make sure server is still running + if server.error is not None: + logger.log("%s Server stopped with error: %s" % (name, server.error)) + result = False + if server.exit_status is not None: + logger.log("%s Server stopped with status: %s" % (name, server.exit_status)) + result = False + # run another test client + if result: + test_info = "Starting echo client %s host:localhost, port:%d, size:%d, count:%d" % \ + (test_name, self.tcp_client_listener_port, size, count) + self.logger.log(test_info) + result = self.do_test_echo(test_name, self.logger, "localhost", + self.tcp_client_listener_port, size, count, + print_logs_client) if not result: break if not result: @@ -159,6 +193,7 @@ class TcpAdaptorOneRouterEcho(TestCase, Process): # stop echo server server.wait() assert result, "Test case failed %s" % test_info + self.logger.log("Test test_01_tcp_echo_one_router: SUCCESS") if __name__== '__main__': unittest.main(main_module()) --------------------------------------------------------------------- To unsubscribe, e-mail: commits-unsubscr...@qpid.apache.org For additional commands, e-mail: commits-h...@qpid.apache.org