[Bug] Backend certification tool app fails due to incorrect loguru message formatting

Describe the bug

It happens occasionally that back-end certification tool app fails with error which causes certification tool to stall. Logs collected directly from back-end docker container:

INFO     | 2025-07-23 15:54:33.136 | app.test_engine.models.test_step:__print_log_separator:95 | --------------------------------------------------------------------------------
INFO     | 2025-07-23 15:54:33.137 | app.test_engine.models.test_step:mark_as_executing:64 | Executing Test Step: Step2: Set Reader Device Under Test in polling mode
ERROR    | 2025-07-23 15:54:33.139 | test_collections.aliro.support.aliro_test_case:wrapper:34 | Error occurred during script: KeyError: KeyError('"type"')

After adding additional traceback log problematic place is in:

  File "/app/./app/socket_connection_manager.py", line 76, in broadcast
    await connection.send_text(message)
  File "/usr/local/lib/python3.10/dist-packages/starlette/websockets.py", line 163, in send_text
    await self.send({"type": "websocket.send", "text": data})
  File "/usr/local/lib/python3.10/dist-packages/starlette/websockets.py", line 87, in send
    raise RuntimeError('Cannot call "send" once a close message has been sent.')
RuntimeError: Cannot call "send" once a close message has been sent.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/app/./test_collections/aliro/support/aliro_test_case.py", line 32, in wrapper
    await func(*args, **kwargs)
  File "/app/./test_collections/aliro/nfc_reader/rd_nfc_stdtxn_20/rd_nfc_stdtxn_20.py", line 71, in execute
    await self.send_prompt_request(
  File "/app/./app/user_prompt_support/user_prompt_support.py", line 34, in send_prompt_request
    response = await user_prompt_manager.send_prompt_request(prompt_request)
  File "/app/./app/user_prompt_support/user_prompt_manager.py", line 136, in send_prompt_request
    await self.__send_prompt_exchange(self.__current_prompt_exchange)
  File "/app/./app/user_prompt_support/user_prompt_manager.py", line 185, in __send_prompt_exchange
    await self.__send_message(prompt_exchange.as_dictionary())
  File "/app/./app/user_prompt_support/user_prompt_manager.py", line 179, in __send_message
    await socket_connection_manager.broadcast(message)
  File "/app/./app/socket_connection_manager.py", line 87, in broadcast
    logger.warning(
  File "/usr/local/lib/python3.10/dist-packages/loguru/_logger.py", line 2052, in warning
    __self._log("WARNING", False, __self._options, __message, args, kwargs)
  File "/usr/local/lib/python3.10/dist-packages/loguru/_logger.py", line 2021, in _log
    log_record["message"] = message.format(*args, **kwargs)
KeyError: '"type"'

Here are problematic lines:
https://github.com/project-chip/certification-tool-backend/blob/2154a06f77f17607936444741ce844ef3779906b/app/socket_connection_manager.py#L87-L89

            except RuntimeError as e:
                logger.warning(
                    f'Failed to send: "{message}" to socket: "{connection}."',
                    'Error:"{e}"',
                )
                raise e

logger.warning uses overloaded warning method which expects args and kwargs in this case (according to traceback log):

  File "/usr/local/lib/python3.10/dist-packages/loguru/_logger.py", line 2052, in warning
    __self._log("WARNING", False, __self._options, __message, args, kwargs)
  File "/usr/local/lib/python3.10/dist-packages/loguru/_logger.py", line 2021, in _log
    log_record["message"] = message.format(*args, **kwargs)
KeyError: '"type"'

After catching the error I was able do display message variable content which looks like that:

"{"type": "test_log_records", "payload": [{"level": "INFO", "timestamp": 1753353614.745642, "message": "This is a test cleanup", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.752091, "message": "Test Suite Completed [ERROR]: NFC Reader", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.753233, "message": "################################################################################", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.785377, "message": "Test Run Completed [ERROR]", "test_suite_execution_index": null, "test_case_execution_index": null, "test_step_execution_index": null}]}"

Note that message content contains curly brackets. So what happens here:

                logger.warning(
                    f'Failed to send: "{message}" to socket: "{connection}."',
                    'Error:"{e}"',
                )

First argument is a formatted string which after injection of message content will contain curly brackets and then such content goes to overloaded warning method which then tries to use format method on that string, but there are no keys defined like type and it fails to teardown the test correctly.

Sample code which will reproduce the error:

from loguru import logger


message = '{"type": "test_log_records", "payload": [{"level": "INFO", "timestamp": 1753353614.745642, "message": "This is a test cleanup", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.752091, "message": "Test Suite Completed [ERROR]: NFC Reader", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.753233, "message": "################################################################################", "test_suite_execution_index": 0, "test_case_execution_index": null, "test_step_execution_index": null}, {"level": "INFO", "timestamp": 1753353614.785377, "message": "Test Run Completed [ERROR]", "test_suite_execution_index": null, "test_case_execution_index": null, "test_step_execution_index": null}]}'
logger.warning(f'This is a warning "{message}"', 'Error: "{e}"')

Safe solution to handle that situation would be either do not inject message or use single argument in warning method of logger which does not use string format method.

aliro-certification-tool-backend-1_stdout-traceback.log

Steps to reproduce the behavior

Just run a lot lot of tests with test harness.
The issue was reproduced with use of aliro-certification-tool mostly observed after running plenty of RD-NFC-STDTXN-2.0 test.

Expected behavior

Test should teardown correctly.

Log files

No response

PICS file

No response

Screenshots

No response

Environment

• TH version https://github.com/csa-access-control/aliro-certification-tool/releases/tag/dryrun%2Ftest_event4-2024-aliro_specification_v0.9.0-v1.0
• OS: backend running on Rasberry Pi Ubuntu 22.04.5 LTS

Additional Information

No response

Start in app/socket_connection_manager.py around the broadcast method and its exception handler at lines 76-89. Review the Loguru warning call using the JSON-like message, then reproduce with the supplied sample or by running many tests with the harness. Done means the socket-send failure is logged without a KeyError and the test teardown completes correctly.