Use %s instead of $s for the log message placeholder when logging the response code received from Redshift.
Description
This adjusts the log placeholder to avoid TypeError being raised when constructing the log message.
Motivation and Context
This change allows us to inspect the response code returned from Redshift. I was seeing "Server refuses SSL" messages from the driver, and after increasing the log level to DEBUG thought I would see what the code actually was, but then saw this in the logs instead:
[2024-04-02 16:40:28,247] Sending SSLRequestMessage to BE
[2024-04-02 16:40:28,279] Failed to emit log record
[2024-04-02 16:40:28,280] Traceback (most recent call last):
[2024-04-02 16:40:28,280] File "/usr/local/airflow/config/cloudwatch_logging.py", line 162, in emit
self.handler.emit(record)
[2024-04-02 16:40:28,281] File "/usr/local/airflow/.local/lib/python3.11/site-packages/watchtower/__init__.py", line 396, in emit
if message.getMessage() == "":
^^^^^^^^^^^^^^^^^^^^
[2024-04-02 16:40:28,281] File "/usr/local/lib/python3.11/logging/__init__.py", line 377, in getMessage
msg = msg % self.args
~~~~^~~~~~~~~~~
[2024-04-02 16:40:28,281] TypeError: not all arguments converted during string formatting
[2024-04-02 16:40:28,281] Task failed with exception
Traceback (most recent call last):
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 433, in _execute_task
result = execute_callable(context=context, **execute_callable_kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/sensors/base.py", line 265, in execute
raise e
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/sensors/base.py", line 247, in execute
poke_return = self.poke(context)
^^^^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/providers/common/sql/sensors/sql.py", line 96, in poke
records = hook.get_records(self.sql, self.parameters)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/providers/common/sql/hooks/sql.py", line 261, in get_records
return self.run(sql=sql, parameters=parameters, handler=fetch_all_handler)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/providers/common/sql/hooks/sql.py", line 391, in run
with closing(self.get_conn()) as conn:
^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/airflow/providers/amazon/aws/hooks/redshift_sql.py", line 200, in get_conn
return redshift_connector.connect(**conn_kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/redshift_connector/__init__.py", line 376, in connect
return Connection(
^^^^^^^^^^^
File "/usr/local/airflow/.local/lib/python3.11/site-packages/redshift_connector/core.py", line 657, in __init__
raise InterfaceError("Server refuses SSL")
redshift_connector.error.InterfaceError: Server refuses SSL
This updates the log message placeholder, so it is consistent with other messages in core.py.
Testing
As the code resides in core.py which has quite a low test coverage, I instead set up the following file to verify my changes:
import logging
if __name__ == '__main__':
_logger: logging.Logger = logging.getLogger(__name__)
logging.basicConfig(level=logging.DEBUG)
resp = bytes([1, 2, 3])
_logger.debug("Server response code when attempting to establish ssl connection: %s", resp)
_logger.debug("Server response code when attempting to establish ssl connection: $s", resp)
Output:
DEBUG:__main__:Server response code when attempting to establish ssl connection: b'\x01\x02\x03'
--- Logging error ---
Traceback (most recent call last):
File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 1110, in emit
msg = self.format(record)
^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 953, in format
return fmt.format(record)
^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 687, in format
record.message = record.getMessage()
^^^^^^^^^^^^^^^^^^^
File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 377, in getMessage
msg = msg % self.args
~~~~^~~~~~~~~~~
TypeError: not all arguments converted during string formatting
Call stack:
File "/Users/martynas/IdeaProjects/amazon-redshift-python-driver/test/log_test.py", line 8, in <module>
_logger.debug("Server response code when attempting to establish ssl connection: $s", resp)
Message: 'Server response code when attempting to establish ssl connection: $s'
Arguments: (b'\x01\x02\x03',)
Screenshots (if appropriate)
Types of changes
[x] Bug fix (non-breaking change which fixes an issue)
[ ] New feature (non-breaking change which adds functionality)
Checklist
[x] Local run of ./build.sh succeeds
[x] Code changes have been run against the repository's pre-commit hooks
Use
%s
instead of$s
for the log message placeholder when logging the response code received from Redshift.Description
This adjusts the log placeholder to avoid
TypeError
being raised when constructing the log message.Motivation and Context
This change allows us to inspect the response code returned from Redshift. I was seeing "Server refuses SSL" messages from the driver, and after increasing the log level to
DEBUG
thought I would see what the code actually was, but then saw this in the logs instead:This updates the log message placeholder, so it is consistent with other messages in
core.py
.Testing
As the code resides in
core.py
which has quite a low test coverage, I instead set up the following file to verify my changes:Output:
Screenshots (if appropriate)
Types of changes
Checklist
./build.sh
succeedspytest test/unit
and they are passing.