diff --git a/sapphire/connection_manager.py b/sapphire/connection_manager.py index 9c67d318..0c9e03a8 100644 --- a/sapphire/connection_manager.py +++ b/sapphire/connection_manager.py @@ -131,9 +131,7 @@ def serve(self, timeout, continue_cb=None, shutdown_delay=SHUTDOWN_DELAY): launches = 0 running = 0 workers = [] - LOG.debug( - "accepting requests (worker limit: %d, timeout: %r)", self._limit, timeout - ) + LOG.debug("accepting requests (workers: %d, timeout: %r)", self._limit, timeout) try: while not self._job.is_complete() and self._can_continue(continue_cb): # launch workers @@ -149,7 +147,7 @@ def serve(self, timeout, continue_cb=None, shutdown_delay=SHUTDOWN_DELAY): # manage workers if running >= self._limit: - LOG.debug("worker limit (%d) hit, waiting...", len(workers)) + LOG.debug("worker limit (%d) hit, waiting...", running) if self._job.worker_complete.wait(1): self._job.worker_complete.clear() workers = self._join_workers(workers) @@ -157,10 +155,14 @@ def serve(self, timeout, continue_cb=None, shutdown_delay=SHUTDOWN_DELAY): LOG.debug("removed completed workers (%d active)", running) finally: - LOG.debug("%d requests in %0.3f seconds", launches, time() - start_time) - LOG.debug("shutting down, waiting for %d worker(s)...", len(workers)) + LOG.debug( + "serve exit: %d request(s) in %0.3fs, waiting for %d worker(s)...", + launches, + time() - start_time, + running, + ) if not self._job.is_complete(): - LOG.debug("job was incomplete") + LOG.debug("job not complete") self._job.finish() # use shutdown_delay to avoid cutting off connections workers = self._join_workers(workers, timeout=shutdown_delay) @@ -171,7 +173,7 @@ def serve(self, timeout, continue_cb=None, shutdown_delay=SHUTDOWN_DELAY): worker.close() # join remaining workers if self._join_workers(workers, timeout=30): - LOG.error("Failed to close workers") + LOG.error("Failed to close %d workers", len(workers)) raise RuntimeError("Failed to close workers") # return False only if there was a timeout diff --git a/sapphire/job.py b/sapphire/job.py index cc86ada5..17236cc1 100644 --- a/sapphire/job.py +++ b/sapphire/job.py @@ -82,26 +82,22 @@ def __init__( self.forever = forever self.server_map = server_map self.worker_complete = Event() - self._build_queue(optional_files) + self._build_pending(optional_files) - def _build_queue(self, optional_files): + def _build_pending(self, optional_files): # build file list to track files that must be served # this is intended to only be called once by __init__() for entry in self._wwwroot.rglob("*"): - if not entry.is_file(): - continue location = entry.relative_to(self._wwwroot).as_posix() # do not add optional files to queue of required files if optional_files and location in optional_files: - LOG.debug("optional: %r", location) continue if "?" in str(entry): - LOG.warning( - "Cannot add files with '?' in path. Skipping %r", str(entry) - ) + LOG.warning("Path cannot contain '?', skipping '%s'", entry) continue - self._pending.files.add(str(entry.resolve())) - LOG.debug("required: %r", location) + if entry.is_file(): + self._pending.files.add(str(entry.resolve())) + LOG.debug("required: %r", location) # if nothing was found check if the path exists if not self._pending.files and not self._wwwroot.is_dir(): raise OSError(f"'{self._wwwroot}' does not exist") @@ -109,17 +105,16 @@ def _build_queue(self, optional_files): for redirect, resource in self.server_map.redirect.items(): if resource.required: self._pending.files.add(redirect) - LOG.debug( - "%s: %r -> %r", - "required" if resource.required else "optional", - redirect, - resource.target, - ) + LOG.debug("required: %r -> %r", redirect, resource.target) for dyn_resp, resource in self.server_map.dynamic.items(): if resource.required: self._pending.files.add(dyn_resp) - LOG.debug("%s: %r -> %r", "required", dyn_resp, resource.target) - LOG.debug("%d files required to serve", len(self._pending.files)) + LOG.debug("required: %r -> %r", dyn_resp, resource.target) + LOG.debug( + "job has %d required and %d optional file(s)", + len(self._pending.files), + len(optional_files) if optional_files else 0, + ) @classmethod def lookup_mime(cls, url): diff --git a/sapphire/worker.py b/sapphire/worker.py index b336c00f..fc4e7e59 100644 --- a/sapphire/worker.py +++ b/sapphire/worker.py @@ -155,15 +155,11 @@ def handle_request(cls, conn, serv_job): conn.sendall( cls._4xx_page(405, "Method Not Allowed", serv_job.auto_close) ) - LOG.debug( - "405 method %r (%d to go)", - request.method, - serv_job.pending, - ) + LOG.debug("405 method %r (%d to go)", request.method, serv_job.pending) return # lookup resource - LOG.debug("lookup_resource(%r)", request.url.path) + LOG.debug("lookup resource %r", request.url.path) resource = serv_job.lookup_resource(request.url.path) if resource: if resource.type in (Resource.URL_FILE, Resource.URL_INCLUDE): @@ -184,7 +180,12 @@ def handle_request(cls, conn, serv_job): # send response if resource is None: conn.sendall(cls._4xx_page(404, "Not Found", serv_job.auto_close)) - LOG.debug("404 %r (%d to go)", request.url.path, serv_job.pending) + LOG.debug( + "404 '%s%s' (%d to go)", + "..." if len(request.url.path) > 40 else "", + request.url.path[-40:], + serv_job.pending, + ) elif resource.type == Resource.URL_REDIRECT: redirect_to = [quote(resource.target)] if request.url.query: @@ -221,10 +222,12 @@ def handle_request(cls, conn, serv_job): LOG.debug("403 %r (%d to go)", request.url.path, serv_job.pending) else: # serve the file - LOG.debug("target %r", str(resource.target)) data_size = resource.target.stat().st_size LOG.debug( - "sending: %s bytes, mime: %r", format(data_size, ","), resource.mime + "sending: %s, %r, '%s'", + f"{data_size:,}B", + resource.mime, + resource.target, ) with resource.target.open("rb") as in_fp: conn.sendall(cls._200_header(data_size, resource.mime))