diff --git a/jupyterhub/proxy.py b/jupyterhub/proxy.py index 87b47a6c..8d92eb94 100644 --- a/jupyterhub/proxy.py +++ b/jupyterhub/proxy.py @@ -48,7 +48,7 @@ from jupyterhub.traitlets import Command from . import utils from .metrics import CHECK_ROUTES_DURATION_SECONDS, PROXY_POLL_DURATION_SECONDS from .objects import Server -from .utils import AnyTimeoutError, exponential_backoff, url_escape_path, url_path_join +from .utils import exponential_backoff, url_escape_path, url_path_join def _one_at_a_time(method): @@ -766,24 +766,36 @@ class ConfigurableHTTPProxy(Proxy): self._write_pid_file() - def _check_process(): - status = self.proxy_process.poll() - if status is not None: - with self.proxy_process: - e = RuntimeError("Proxy failed to start with exit code %i" % status) - raise e from None + async def watch_process(): + """Watch proxy process for early termination - for server in (public_server, api_server): - for i in range(10): - _check_process() - try: - await server.wait_up(1) - except AnyTimeoutError: - continue - else: - break - await server.wait_up(1) - _check_process() + so we don't keep waiting for connections after the proxy exits + """ + while True: + status = self.proxy_process.poll() + if status is not None: + with self.proxy_process: + e = RuntimeError( + f"Proxy failed to start with exit code {status}" + ) + raise e from None + + await asyncio.wait([servers_ready], timeout=0.5) + # stop watching the process when the connections + # have finished (success or failure) + if servers_ready.done(): + return + + servers_ready = asyncio.gather( + *(server.wait_up(10) for server in (public_server, api_server)) + ) + + process_ended = asyncio.ensure_future(watch_process()) + # wait for process to crash or servers to be ready, + # whichever comes first + # don't need to handle exceptions here, + # as the underlying exceptions have informative error messages + await asyncio.wait_for(asyncio.gather(process_ended, servers_ready), timeout=15) self.log.debug("Proxy started and appears to be up") pc = PeriodicCallback(self.check_running, 1e3 * self.check_running_interval) self._check_running_callback = pc diff --git a/jupyterhub/utils.py b/jupyterhub/utils.py index 4db7ffe0..e703d9fd 100644 --- a/jupyterhub/utils.py +++ b/jupyterhub/utils.py @@ -15,6 +15,7 @@ import ssl import string import sys import threading +import time import uuid import warnings from binascii import b2a_hex @@ -93,6 +94,8 @@ def can_connect(ip, port): except OSError as e: if e.errno not in {errno.ECONNREFUSED, errno.ETIMEDOUT}: app_log.error("Unexpected error connecting to %s:%i %s", ip, port, e) + else: + app_log.debug("Server at %s:%i not ready: %s", ip, port, e) return False else: return True @@ -245,6 +248,8 @@ async def wait_for_server(ip, port, timeout=10): """Wait for any server to show up at ip:port.""" if ip in {'', '0.0.0.0', '::'}: ip = '127.0.0.1' + app_log.debug("Waiting %ss for server at %s:%s", timeout, ip, port) + tic = time.perf_counter() await exponential_backoff( lambda: can_connect(ip, port), "Server at {ip}:{port} didn't respond in {timeout} seconds".format( @@ -252,6 +257,8 @@ async def wait_for_server(ip, port, timeout=10): ), timeout=timeout, ) + toc = time.perf_counter() + app_log.debug("Server at %s:%s responded in %.2fs", ip, port, toc - tic) async def wait_for_http_server(url, timeout=10, ssl_context=None): @@ -259,12 +266,13 @@ async def wait_for_http_server(url, timeout=10, ssl_context=None): Any non-5XX response code will do, even 404. """ - loop = ioloop.IOLoop.current() - tic = loop.time() client = AsyncHTTPClient() if ssl_context: client.ssl_options = ssl_context + app_log.debug("Waiting %ss for server at %s", timeout, url) + tic = time.perf_counter() + async def is_reachable(): try: r = await client.fetch(url, follow_redirects=False) @@ -297,6 +305,8 @@ async def wait_for_http_server(url, timeout=10, ssl_context=None): ), timeout=timeout, ) + toc = time.perf_counter() + app_log.debug("Server at %s responded in %.2fs", url, toc - tic) return re