From dae445db3ab80d6f5b5fa20eda7b817d3e39f1b7 Mon Sep 17 00:00:00 2001 From: szeka9 Date: Sun, 2 Aug 2026 14:48:31 +0200 Subject: [PATCH] Optimize logging to avoid temporary allocations; fix reflected XSS risk Use conditional format string substitution instead of eagerly constructed log strings. Unify the logging format and avoid exposing exception messages to prevent reflected XSS. --- docs/application_development/security.md | 2 +- example/mip_repo/app.py | 2 +- src/pyrobusta/bindings/http_connection.py | 5 ++- src/pyrobusta/connectivity/wifi.py | 10 ++--- src/pyrobusta/protocol/http.py | 4 +- src/pyrobusta/protocol/http_basic_auth.py | 13 +++--- src/pyrobusta/server/http_server.py | 32 ++++++++------- src/pyrobusta/transport/connection.py | 10 ++--- src/pyrobusta/utils/iam.py | 4 +- src/pyrobusta/utils/logging.py | 49 +++++++++++++++++------ tests/unit/http_base.py | 2 + 11 files changed, 81 insertions(+), 52 deletions(-) diff --git a/docs/application_development/security.md b/docs/application_development/security.md index d84acad..71b0e6e 100644 --- a/docs/application_development/security.md +++ b/docs/application_development/security.md @@ -71,7 +71,7 @@ New users can be added programmatically through the IAM API: from pyrobusta.utils.iam import IAMDatabase iam_db = IAMDatabase("pyrobusta.passwd", "pyrobusta.roles") iam_db.load() -iam_db.create_user("johno", "john's-secret-password", ["role-1", "role-2"]) +iam_db.create_user("john", "john's-secret-password", ["role-1", "role-2"]) ``` Password verification uses PBKDF2-HMAC-SHA256 with a default iteration count of 5000. diff --git a/example/mip_repo/app.py b/example/mip_repo/app.py index 7539b3a..07502d3 100644 --- a/example/mip_repo/app.py +++ b/example/mip_repo/app.py @@ -36,7 +36,7 @@ def self_serve_mip_package(http_ctx, _): protocol = "https" if tls_enabled else "http" - logging.debug(f"[mip_repo] server_addr: {server_addr}") + logging.debug("mip_repo addr=[%s]", server_addr) append_package_files("/lib/pyrobusta", package_files, server_addr, protocol) return "application/json", package_files diff --git a/src/pyrobusta/bindings/http_connection.py b/src/pyrobusta/bindings/http_connection.py index d81be04..451c39e 100644 --- a/src/pyrobusta/bindings/http_connection.py +++ b/src/pyrobusta/bindings/http_connection.py @@ -58,7 +58,7 @@ async def _read_to_buf(self): timeout_seconds=self.RECV_TIMEOUT_SECONDS, ) self._recv_buf.write(request) - logging.debug(__name__ + f"._read_to_buf: [{request}]") + logging.debug("%s: request=[%s]", __name__, request) return len(request) async def _run_state_machine(self): @@ -76,8 +76,9 @@ async def _run_state_machine(self): except asyncio.TimeoutError: self._engine.abort(408) except Exception as e: # pylint: disable=W0718 + logging.warning("%s: error=[%s]", __name__, e) self._engine.abort(500) - self._engine.set_response_body(b"Read error: " + str(e).encode("ascii")) + self._engine.set_response_body(b"Internal Server Error") # [2] process request by state machine while True: diff --git a/src/pyrobusta/connectivity/wifi.py b/src/pyrobusta/connectivity/wifi.py index 291844d..e3afd58 100644 --- a/src/pyrobusta/connectivity/wifi.py +++ b/src/pyrobusta/connectivity/wifi.py @@ -18,13 +18,14 @@ def initialize(): password = get_config(CONF_WIFI_PASSWORD) if not ssid or not password: - logging.warning(__name__ + ": missing SSID/password") + logging.error("%s: missing SSID/password", __name__) return False sta_if = WLAN(STA_IF) sta_if.active(True) + addr = sta_if.ifconfig()[0] if sta_if.isconnected(): - logging.info(__name__ + f": already connected IP={sta_if.ifconfig()[0]}") + logging.info("%s: already connected ip=[%s]", __name__, addr) return True sta_if.connect(ssid, password) @@ -32,13 +33,12 @@ def initialize(): timeout = 30 while timeout > 0: if sta_if.isconnected(): - ip = sta_if.ifconfig()[0] - logging.info(__name__ + f": connected, IP={ip}") + logging.info("%s: connected, ip=[%s]", __name__, addr) return True sleep(1) timeout -= 1 - logging.warning(__name__ + ": connection failed") + logging.error("%s: connection failed", __name__) return False diff --git a/src/pyrobusta/protocol/http.py b/src/pyrobusta/protocol/http.py index dfe9d3a..1a7f420 100644 --- a/src/pyrobusta/protocol/http.py +++ b/src/pyrobusta/protocol/http.py @@ -630,9 +630,9 @@ def run(self, rx): self.abort(400) self.set_response_body(b"Malformed request") except Exception as e: # pylint: disable=W0718 - logging.warning(__name__ + f"._run_state_machine: {e}") + logging.warning("%s.run: error=[%s]", __name__, e) self.abort(500) - self.set_response_body(str(e).encode("ascii")) + self.set_response_body(b"Internal Server Error") # ======================================== # Helpers for routing, state machine logic diff --git a/src/pyrobusta/protocol/http_basic_auth.py b/src/pyrobusta/protocol/http_basic_auth.py index 513e75b..8de8907 100644 --- a/src/pyrobusta/protocol/http_basic_auth.py +++ b/src/pyrobusta/protocol/http_basic_auth.py @@ -36,7 +36,7 @@ PASS_ITER, USER_SECRET, ) -from pyrobusta.utils.logging import warning +from pyrobusta.utils import logging _DUMMY_ITER = 5000 _DUMMY_SALT = os.urandom(16) @@ -93,6 +93,7 @@ def _auth_user(self: HttpEngine, auth_provider: IAMDatabase, sessions=False): user_ok = user_info is not None if not (user_ok and hash_ok): + logging.info("authentication failed for user=[%s]", username) return None return username, user_info, is_session @@ -183,16 +184,16 @@ def apply_patches(auth_provider: IAMDatabase, sessions=False): raise ValueError if not get_config(CONF_TLS) and get_config(CONF_HTTP_AUTH): - insecure_auth_msg = "Authentication turned on without TLS" + insecure_auth_msg = "authentication turned on without TLS" if get_config(CONF_HTTP_INSECURE_AUTH): - warning(insecure_auth_msg) + logging.warning(insecure_auth_msg) else: raise ValueError(insecure_auth_msg) if get_config(CONF_HTTP_AUTH_MODE) != "browser": - warning( - "CSRF protection is disabled; authenticated browser " - "requests may be vulnerable to cross-site request forgery" + logging.warning( + "CSRF protection is disabled; " + "authenticated clients are vulnerable to CSRF attacks" ) def get_policy(route: str): diff --git a/src/pyrobusta/server/http_server.py b/src/pyrobusta/server/http_server.py index ef03d48..f276c24 100644 --- a/src/pyrobusta/server/http_server.py +++ b/src/pyrobusta/server/http_server.py @@ -78,9 +78,7 @@ def _init_pools(cls, max_clients): cls.RECV_BUF_MAX_BYTES + cls.SEND_BUF_MAX_BYTES + cls.CON_OVERHEAD_BYTES ) if is_low_memory: - logging.warning( - __name__ + ".init_pools: low-memory mode with reduced buffer size" - ) + logging.warning("%s: low-memory mode with reduced buffer size", __name__) recv_size = cls.RECV_BUF_MIN_BYTES if is_low_memory else cls.RECV_BUF_MAX_BYTES send_size = cls.SEND_BUF_MIN_BYTES if is_low_memory else cls.SEND_BUF_MAX_BYTES per_con = recv_size + send_size + cls.CON_OVERHEAD_BYTES @@ -93,7 +91,7 @@ def _init_pools(cls, max_clients): ) ) con_limit = min(usable // per_con, con_limit) - logging.info((__name__ + f".init_pools: {con_limit} connection(s) allowed")) + logging.info("%s: %s connection(s) allowed", __name__, con_limit) cls.RECV_POOL = MemoryPool(recv_size, con_limit, wrapper=SlidingBuffer) cls.SEND_POOL = MemoryPool(send_size, con_limit, wrapper=SlidingBuffer) @@ -145,22 +143,26 @@ async def _accept_socket(self, reader, writer): if recv_buf is None or send_buf is None: logging.debug( - __name__ - + ": connection from " - + writer.get_extra_info("peername")[0] - + " rejected (server at capacity)" + "%s: connection from %s rejected (server at capacity)", + __name__, + writer.get_extra_info("peername")[0], ) writer.close() await writer.wait_closed() return client = HttpConnection(reader, writer, recv_buf, send_buf) - logging.debug(__name__ + f": accept {client.id}") + logging.debug("%s: accept client=[%s]", __name__, client.id) self.ACTIVE_CLIENTS.append(client) async with client: await client.run() except Exception as e: # pylint: disable=W0718 - logging.warning(__name__ + f": error in run(): {e}") + logging.warning( + "%s: client=[%s] error=[%s]", + __name__, + writer.get_extra_info("peername")[0], + e, + ) finally: if send_buf: send_buf.consume() @@ -186,7 +188,7 @@ async def start_socket_server(self): raise RuntimeError("Unable to initialize IAM") http.enable_optional_features(auth_provider=self._iam_db) - logging.debug(__name__ + f"registered routes: {http.HttpEngine.ROUTES}") + logging.debug("%s: registered routes: %s", __name__, http.HttpEngine.ROUTES) self._max_clients = get_config(CONF_SOCKET_MAX_CON) self._init_pools(self._max_clients) ssl_ctx = None @@ -207,18 +209,18 @@ async def start_socket_server(self): backlog=max(1, self._max_clients), ssl=ssl_ctx, ) - logging.info(__name__ + ": started") + logging.info("%s: started", __name__) except MemoryError as e: - logging.warning(__name__ + f": allocation failed - {e}") + logging.error("%s: allocation error=[%s]", __name__, e) async def terminate(self): """ Terminate HTTP server and drop clients. """ - logging.info(__name__ + ": terminated") + logging.info("%s: terminated", __name__) while self.ACTIVE_CLIENTS: client = self.ACTIVE_CLIENTS[0] - logging.debug(__name__ + f": {client.id} dropped") + logging.debug("%s: client=[%s] dropped", __name__, client.id) self.ACTIVE_CLIENTS.remove(client) await client.close() if self._server: diff --git a/src/pyrobusta/transport/connection.py b/src/pyrobusta/transport/connection.py index 880d2ab..e48b3df 100644 --- a/src/pyrobusta/transport/connection.py +++ b/src/pyrobusta/transport/connection.py @@ -48,7 +48,7 @@ async def read( if not self.connected: raise OSError(f"{self.id} already closed") - logging.debug(__name__ + f": read from {self.id}") + logging.debug("%s: read from client=[%s]", __name__, self.id) self.last_event = ticks_ms() if timeout_seconds: request = await asyncio.wait_for( @@ -68,7 +68,7 @@ async def write(self, data: bytes | bytearray | memoryview): if not self.connected: raise OSError(f"{self.id} already closed") - logging.debug(__name__ + f": write to {self.id}") + logging.debug("%s: write to client=[%s]", __name__, self.id) self._writer.write(data) await self._writer.drain() self.last_event = ticks_ms() @@ -78,13 +78,13 @@ async def close(self): Close the connection, update the internal state accordingly. """ if not self.connected: - logging.warning(f"{self.id} already closed") + logging.warning("%s: client=[%s] already closed", __name__, self.id) return self.connected = False - logging.debug(__name__ + f": close connection: {self.id}") + logging.debug("%s: close connection to client=[%s]", __name__, self.id) try: self._writer.close() await self._writer.wait_closed() except OSError as e: - logging.warning(__name__ + f": error while closing {self.id}: {e}") + logging.warning("%s: client=[%s] error=[%s]", __name__, self.id, e) diff --git a/src/pyrobusta/utils/iam.py b/src/pyrobusta/utils/iam.py index 60baccf..22c9db3 100644 --- a/src/pyrobusta/utils/iam.py +++ b/src/pyrobusta/utils/iam.py @@ -9,7 +9,7 @@ from pyrobusta.utils.config import PYROBUSTA_VERSION from pyrobusta.utils.crypto import pbkdf2_sha256, validate_password from pyrobusta.utils.lexpath import iterate_segments -from pyrobusta.utils.logging import warning +from pyrobusta.utils import logging MAX_ROLES = 32 NO_POLICY = 2**MAX_ROLES @@ -66,7 +66,7 @@ def load( self._users = users self._attribute_tree = attribute_tree except OSError as e: - warning(f"Unable to open configuration: {e}") + logging.error("%s: unable to open config: error=[%s]", __name__, e) return False finally: # Clean up temporary data structures diff --git a/src/pyrobusta/utils/logging.py b/src/pyrobusta/utils/logging.py index 98db3d7..a966c50 100644 --- a/src/pyrobusta/utils/logging.py +++ b/src/pyrobusta/utils/logging.py @@ -3,10 +3,13 @@ """ from pyrobusta.utils.config import get_config, CONF_LOG_LEVEL +from pyrobusta.utils.clock import ticks_ms -_LOG_LEVEL_WARNING = 0 -_LOG_LEVEL_INFO = 1 -_LOG_LEVEL_DEBUG = 2 +_LOG_LEVEL_OFF = -1 # Disable all logging +_LOG_LEVEL_ERROR = 0 +_LOG_LEVEL_WARNING = 1 +_LOG_LEVEL_INFO = 2 +_LOG_LEVEL_DEBUG = 3 def current_log_level(): @@ -14,34 +17,54 @@ def current_log_level(): Determine current log level from the config. """ current = get_config(CONF_LOG_LEVEL) - if current == "debug": - return _LOG_LEVEL_DEBUG - if current == "info": - return _LOG_LEVEL_INFO + if current == "off": + return _LOG_LEVEL_OFF + if current == "error": + return _LOG_LEVEL_ERROR if current == "warning": return _LOG_LEVEL_WARNING + if current == "info": + return _LOG_LEVEL_INFO + if current == "debug": + return _LOG_LEVEL_DEBUG return _LOG_LEVEL_WARNING -def warning(log): +def error(fmt, *args): + """ + Print error messages. + """ + if current_log_level() >= _LOG_LEVEL_ERROR: + if args: + fmt = fmt % args + print(ticks_ms(), "ERROR", fmt) + + +def warning(fmt, *args): """ Print warning messages. """ if current_log_level() >= _LOG_LEVEL_WARNING: - print(f"[WARN] {log}") + if args: + fmt = fmt % args + print(ticks_ms(), "WARN", fmt) -def info(log): +def info(fmt, *args): """ Print info messages. """ if current_log_level() >= _LOG_LEVEL_INFO: - print(f"[INFO] {log}") + if args: + fmt = fmt % args + print(ticks_ms(), "INFO", fmt) -def debug(log): +def debug(fmt, *args): """ Print debug messages. """ if current_log_level() >= _LOG_LEVEL_DEBUG: - print(f"[DEBUG] {log}") + if args: + fmt = fmt % args + print(ticks_ms(), "DEBUG", fmt) diff --git a/tests/unit/http_base.py b/tests/unit/http_base.py index cd927dd..3bb9b97 100644 --- a/tests/unit/http_base.py +++ b/tests/unit/http_base.py @@ -62,6 +62,8 @@ def setUp(self): # Patch config/iam module # ----------------------- self.config = dict(self.base_config) + if "log_level" not in self.config: + self.config["log_level"] = "off" self.config_module = load_module("pyrobusta/utils/config.py") self.patch_config_loader(self.config, self.config_module)