Optimize logging to avoid temporary allocations; fix reflected XSS risk

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.

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
 

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:

src/pyrobusta/connectivity/wifi.py

@@ -18,27 +18,27 @@ 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)
 
     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
 
 

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

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):

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:

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)

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

src/pyrobusta/utils/logging.py

@@ -3,45 +3,68 @@
 """
 
 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():
     """
     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)

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)