Introduce 'TRACE' level logging and move all repetitive, less useful logs from DEBUG level to TRACE level

Author: diningPhilosopher64

Advanced-Usage.md

@@ -18,7 +18,7 @@ The following table describes all the environment variables that you can set to
 | **MWI_BASE_URL** | string | `"/matlab"` | Set to control the base URL of the app. MWI_BASE_URL should start with `/` or be `empty`. |
 | **MWI_APP_PORT** | integer | `8080` | Specify the port for the HTTP server to listen on. |
 | **MWI_APP_HOST** | string | `127.0.0.1` | Specify the host address to display the connection URL in the startup message.|
-| **MWI_LOG_LEVEL** | string | `"CRITICAL"` | Specify the Python log level to be one of the following `NOTSET`, `DEBUG`, `INFO`, `WARN`, `ERROR`, or `CRITICAL`. For more information on Python log levels, see [Logging Levels](https://docs.python.org/3/library/logging.html#logging-levels) .<br />The default value is `INFO`. |
+| **MWI_LOG_LEVEL** | string | `"CRITICAL"` | Specify the log level. Valid options are: `NOTSET`, `TRACE`, `DEBUG`, `INFO`, `WARN`, `ERROR`, `CRITICAL`. In addition to the standard Python [Log Levels (Python Documentation)](https://docs.python.org/3/library/logging.html#logging-levels), `matlab-proxy` supports a custom `TRACE` level. Use `TRACE` when you require more granular diagnostic information than `DEBUG` mode provides.<br />The default value is `INFO`. |
 | **MWI_LOG_FILE** | string | `"/tmp/logs.txt"` | Specify the full path to the file where you want debug logs from this integration to be written. |
 | **MWI_ENABLE_WEB_LOGGING** | string | `"True"` | Set this value to `"True"` to see additional web server logs. |
 | **MWI_CUSTOM_HTTP_HEADERS** | string  |`'{"Content-Security-Policy": "frame-ancestors *.example.com:*"}'`<br /> OR <br />`"/path/to/your/custom/http-headers.json"` |Specify valid HTTP headers as JSON data in a string format. <br /> Alternatively, specify the full path to the JSON file containing valid HTTP headers instead. These headers are injected into the HTTP response sent to the browser. </br> For  more information, see the [Custom HTTP Headers](#custom-http-headers) section.|
@@ -182,6 +182,6 @@ Note: Restarting MATLAB from within `matlab-proxy` will run the specified code a
 
 ----
 
-Copyright 2020-2025 The MathWorks, Inc.
+Copyright 2020-2026 The MathWorks, Inc.
 
 ----

matlab_proxy/app.py

@@ -589,7 +589,7 @@ async def matlab_view(req):
     # If we are trying to send request to matlab while the matlab_port is still not assigned
     # by embedded connector, return service not available and log a message
     if not matlab_port:
-        logger.debug(
+        logger.trace(
             "MATLAB hasn't fully started, please retry after embedded connector has started"
         )
         raise web.HTTPServiceUnavailable()
@@ -742,7 +742,7 @@ async def wsforward(ws_from, ws_to):
                 client_exceptions.ServerDisconnectedError,
                 client_exceptions.ClientConnectionError,
             ):
-                logger.debug(
+                logger.trace(
                     "Failed to forward HTTP request as MATLAB process may not be running."
                 )
                 raise web.HTTPServiceUnavailable()

matlab_proxy/app_state.py

@@ -995,7 +995,7 @@ async def __setup_env_for_matlab(self) -> dict:
         )
 
         # Env setup related to logging
-        # Very verbose logging in debug mode
+        # Very verbose logging in debug or trace mode (trace is lower level than debug, so the below condition will also be true for trace level)
         if logger.isEnabledFor(logging.getLevelName("DEBUG")):
             mwi_log_file = self.settings.get("mwi_log_file", None)
             # If a log file is supplied to write matlab-proxy server logs,
@@ -1017,8 +1017,12 @@ async def __setup_env_for_matlab(self) -> dict:
             logger.info(
                 f"Writing MATLAB process logs to: {matlab_env['MW_DIAGNOSTIC_DEST']}"
             )
+
+        if logger.isEnabledFor(logging.getLevelName("TRACE")):
+            trace_spec = ".*=fatal,critical,error,warning;connector::worker.*=all;connector::container::http=all;connector::lifecycle=all;connector::http::server=all"
+            existing_spec = matlab_env.get("MW_DIAGNOSTIC_SPEC", "")
             matlab_env["MW_DIAGNOSTIC_SPEC"] = (
-                "connector::http::server=all;connector::lifecycle=all"
+                f"{existing_spec};{trace_spec}" if existing_spec else trace_spec
             )
 
         # TODO Introduce a warmup flag to enable this?

matlab_proxy/util/__init__.py

@@ -315,14 +315,14 @@ async def acquire(self):
         await self._lock.acquire()
         # Store the current task or function information when the lock is acquired
         self._acquired_by = get_caller_name()
-        logger.debug(f"Lock acquired by '{self.acquired_by}()'")
+        logger.trace(f"Lock acquired by '{self.acquired_by}()'")
 
     async def release(self):
         """Releases the lock."""
         if self.locked():
             # Clear the owner information when the lock is released
             self._lock.release()
-            logger.debug(f"Lock released by '{self.acquired_by}()'")
+            logger.trace(f"Lock released by '{self.acquired_by}()'")
             self._acquired_by = None
 
         else:

matlab_proxy/util/mwi/embedded_connector/request.py

@@ -1,4 +1,4 @@
-# Copyright 2020-2024 The MathWorks, Inc.
+# Copyright 2020-2026 The MathWorks, Inc.
 
 """
 This file contains the methods to communicate with the embedded connector.
@@ -47,14 +47,14 @@ async def send_request(url: str, data: dict, method: str, headers: dict = None)
 
     try:
         async with aiohttp.ClientSession(trust_env=True) as session:
-            logger.debug(
+            logger.trace(
                 f"sending request: method={method}, url={url}, data={data}, headers={headers}, "
             )
 
             async with session.request(
                 method=method, url=url, data=data, headers=headers, ssl=False
             ) as resp:
-                logger.debug(f"response from endpoint{url} and resp={resp}")
+                logger.trace(f"response from endpoint{url} and resp={resp}")
                 if not resp.ok:
                     # Converting to dict and formatting for printing
                     data = json.loads(data)

matlab_proxy/util/mwi/logger.py

@@ -1,4 +1,4 @@
-# Copyright 2020-2025 The MathWorks, Inc.
+# Copyright 2020-2026 The MathWorks, Inc.
 """Functions to access & control the logging behavior of the app"""
 
 import logging
@@ -12,15 +12,54 @@
 
 from . import environment_variables as mwi_env
 
-logging.getLogger("aiohttp_session").setLevel(logging.ERROR)
+# Define TRACE level (more detailed than DEBUG)
+TRACE = 5
+
+
+class MwLogger(logging.Logger):
+    """Custom logger that adds TRACE level support (more detailed than DEBUG).
+
+    This logger class extends the standard Python logging.Logger to provide
+    an additional TRACE log level for ultra-detailed debugging that is more
+    granular than DEBUG.
+
+    Usage:
+        logger = mwi.logger.get()
+        logger.trace("Ultra-detailed trace: %s", data)
+    """
+
+    def trace(self, msg, *args, **kwargs):
+        """
+        Log a message at TRACE level.
+
+        TRACE level is more detailed than DEBUG and is intended for
+        ultra-detailed tracing information that is typically only needed
+        during deep debugging sessions.
+
+        Args:
+            msg: The message format string
+            *args: Arguments to merge into msg using string formatting
+            **kwargs: Additional keyword arguments passed to Logger.log()
+        """
+        self.log(TRACE, msg, *args, **kwargs)
+
+
+def _setup_logging_system():
+    """Initialize the custom logging system."""
+    logging.addLevelName(TRACE, "TRACE")
+    logging.setLoggerClass(MwLogger)
+    logging.getLogger("aiohttp_session").setLevel(logging.ERROR)
 
 
 def get(init=False):
     """Get the logger used by this application.
         Set init=True to initialize the logger
     Returns:
-        Logger: The logger used by this application.
+        MwLogger: The logger used by this application.
     """
+    # Always ensure logging system is set up first (registers MwLogger class)
+    _setup_logging_system()
+
     if init is True:
         return __set_logging_configuration()
 
@@ -40,7 +79,7 @@ def __get_mw_logger():
     """Returns logger for use in this app.
 
     Returns:
-        Logger: A logger object
+        MwLogger: A logger object with TRACE level support.
     """
     return logging.getLogger(__get_mw_logger_name())
 
@@ -49,9 +88,12 @@ def __set_logging_configuration():
     """Sets the logging environment for the app
 
     Returns:
-        Logger: Logger object with the set configuration.
+        MwLogger: Logger object with the set configuration.
     """
-    # Create the Logger for MATLABProxy
+    # Ensure the logging system is set up before creating the logger
+    _setup_logging_system()
+
+    # Create the Logger for MATLABProxy (will be MwLogger due to setLoggerClass)
     logger = __get_mw_logger()
 
     # log_level is either set by environment or is the default value.
@@ -142,7 +184,8 @@ def __is_invalid_log_level(log_level):
         Boolean: Whether log level  exists
     """
 
-    return not hasattr(logging, log_level)
+    # Check standard Python levels OR our custom TRACE level
+    return not (hasattr(logging, log_level) or log_level == "TRACE")
 
 
 def log_startup_info(title=None, matlab_urls=[]):
@@ -183,12 +226,15 @@ class _ColoredFormatter(logging.Formatter):
 
     def format(self, record):
         # Example: Add 'color' and 'end_color' attributes based on log level
-        if record.levelno == logging.INFO:
-            record.color = "\033[32m"  # Green
+        if record.levelno == TRACE:
+            record.color = "\033[36m"  # Cyan (light blue)
             record.end_color = "\033[0m"
         elif record.levelno == logging.DEBUG:
             record.color = "\033[94m"  # Blue
             record.end_color = "\033[0m"
+        elif record.levelno == logging.INFO:
+            record.color = "\033[32m"  # Green
+            record.end_color = "\033[0m"
         elif record.levelno == logging.WARNING:
             record.color = "\033[93m"  # Yellow
             record.end_color = "\033[0m"

matlab_proxy/util/mwi/token_auth.py

@@ -1,4 +1,4 @@
-# Copyright 2020-2025 The MathWorks, Inc.
+# Copyright 2020-2026 The MathWorks, Inc.
 
 # This file contains functions required to enable token based authentication in the server.
 
@@ -79,17 +79,17 @@ async def authenticate_request(request):
     Returns True when authentication is disabled.
     """
 
-    logger.debug(f"<======== Authenticate request: {request}")
+    logger.trace(f"<======== Authenticate request: {request}")
 
     if _is_mwi_token_auth_enabled(request):
-        logger.debug("Authentication is Enabled.")
+        logger.trace("Authentication is Enabled.")
         is_authenticated = (
             await _is_valid_token_in_session_cookie(request)
             or await _is_valid_token_in_headers(request)
             or await _is_valid_token_in_url_query(request)
         )
         if is_authenticated:
-            logger.debug("Authentication successful. ========>")
+            logger.trace("Authentication successful. ========>")
         else:
             logger.error("Token Authentication failed. ========>")
 
@@ -184,7 +184,7 @@ async def _store_token_hash_into_session(request):
 
     # Stash token hash in session for other endpoints
     session[await _get_token_name(request)] = await _get_token_hash(request)
-    logger.debug(f"Created session and saved cookie.")
+    logger.trace(f"Created session and saved cookie.")
 
 
 def _is_mwi_token_auth_enabled(request):
@@ -212,7 +212,7 @@ async def _is_valid_token(token, request):
     is_valid = compare_digest(token, await _get_token_hash(request)) or compare_digest(
         token, await _get_token(request)
     )
-    logger.debug("Token validation " + ("successful." if is_valid else "failed."))
+    logger.trace("Token validation " + ("successful." if is_valid else "failed."))
     return is_valid
 
 
@@ -225,16 +225,16 @@ async def _is_valid_token_in_session_cookie(request):
     Returns:
         Boolean : True if valid token is found
     """
-    logger.debug("Checking for token in session cookie...")
+    logger.trace("Checking for token in session cookie...")
     session = await get_session(request)
-    logger.debug(f"Got session cookie.")
+    logger.trace(f"Got session cookie.")
     token_name = await _get_token_name(request)
     if token_name in session:
         stored_session_token = session[token_name]
-        logger.debug(f"Found token in session cookie, validating...")
+        logger.trace(f"Found token in session cookie, validating...")
         return await _is_valid_token(stored_session_token, request)
 
-    logger.debug("Token not found in session cookie.")
+    logger.trace("Token not found in session cookie.")
     return False
 
 
@@ -247,18 +247,18 @@ async def _is_valid_token_in_url_query(request):
     Returns:
         Boolean : True if valid token is found
     """
-    logger.debug("Checking for token in url query...")
+    logger.trace("Checking for token in url query...")
     query_string = request.query_string
-    logger.debug(f"url query parameters found:{query_string}")
+    logger.trace(f"url query parameters found:{query_string}")
     if query_string:
         token_name = _get_token_name_for_http(request)
         parsed_token = parse_qs(request.query_string).get(token_name)
         if parsed_token:
             parsed_token = parsed_token[0]
-            logger.debug("parsed_token from url query string.")
+            logger.trace("parsed_token from url query string.")
             return await _is_valid_token(parsed_token, request)
 
-    logger.debug("Token not found in url query.")
+    logger.trace("Token not found in url query.")
     return False
 
 
@@ -273,17 +273,17 @@ async def _is_valid_token_in_headers(request):
     Returns:
         Boolean : True if valid token is found
     """
-    logger.debug("Checking for token in request headers...")
+    logger.trace("Checking for token in request headers...")
     headers = request.headers
     token_name = _get_token_name_for_http(request)
     if token_name in headers:
-        logger.debug(f"Token found in headers: {token_name}")
+        logger.trace(f"Token found in headers: {token_name}")
         is_valid_token = await _is_valid_token(headers[token_name], request)
         if is_valid_token:
             await _store_token_hash_into_session(request)
         return is_valid_token
 
-    logger.debug("Token not found in request headers.")
+    logger.trace("Token not found in request headers.")
     return False
 
 

tests/unit/util/mwi/test_logger.py

@@ -1,4 +1,4 @@
-# Copyright 2020-2025 The MathWorks, Inc.
+# Copyright 2020-2026 The MathWorks, Inc.
 """This file tests methods present in matlab_proxy/util/mwi_logger.py"""
 
 import logging
@@ -19,6 +19,7 @@ def test_get():
     logger = mwi_logger.get()
     # Okay to use hidden API for testing only.
     assert logger.name == mwi_logger.__get_mw_logger_name()
+    assert hasattr(logger, "trace"), "Logger returned by get() should support trace()"
 
 
 def test_get_mw_logger_name():
@@ -58,9 +59,11 @@ def test_get_with_environment_variables(monkeypatch, tmp_path, reset_logger_hand
 @pytest.mark.parametrize(
     "log_level, expected_level",
     [
+        ("TRACE", mwi_logger.TRACE),
         ("DEBUG", logging.DEBUG),
         ("INFO", logging.INFO),
         ("WARNING", logging.WARNING),
+        ("trace", mwi_logger.TRACE),
         ("debug", logging.DEBUG),
         ("info", logging.INFO),
         ("warning", logging.WARNING),
@@ -89,3 +92,34 @@ def test_set_logging_configuration_unknown_logging_levels(
     assert (
         logger.isEnabledFor(logging.INFO) == True
     ), "Error in initialising the default logger"
+
+
+def test_logger_has_trace_method(reset_logger_handlers):
+    """This test checks that the logger returned by get() has a trace() method"""
+    logger = mwi_logger.get(init=True)
+    assert hasattr(logger, "trace"), "Logger should have trace() method"
+
+
+def test_get_returns_custom_logger_instance(reset_logger_handlers):
+    """This test checks that get() returns the custom logger implementation."""
+    logger = mwi_logger.get(init=True)
+    assert isinstance(logger, mwi_logger.MwLogger)
+
+
+def test_trace_level_name_is_registered(reset_logger_handlers):
+    """This test checks that TRACE level has a registered logging name."""
+    mwi_logger.get()
+    assert logging.getLevelName(mwi_logger.TRACE) == "TRACE"
+
+
+def test_trace_logging_at_trace_level(monkeypatch, reset_logger_handlers, caplog):
+    """This test checks that trace() method logs at TRACE level when enabled"""
+    env_names_list = mwi_logger.get_environment_variable_names()
+    monkeypatch.setenv(env_names_list[0], "TRACE")
+
+    with caplog.at_level(mwi_logger.TRACE):
+        logger = mwi_logger.get(init=True)
+        logger.trace("Test trace message")
+
+    assert "Test trace message" in caplog.text
+    assert caplog.records[0].levelname == "TRACE"