logging cleanup to explicitly expect number values where appropriate

Author: mattsb42-aws

src/aws_encryption_sdk/internal/formatting/deserialize.py

@@ -344,7 +344,7 @@ def deserialize_frame(stream, header, verifier=None):
         (sequence_number,) = unpack_values(">I", stream, verifier)
         final_frame = True
     else:
-        _LOGGER.debug("Deserializing frame sequence number %s", int(sequence_number))
+        _LOGGER.debug("Deserializing frame sequence number %d", int(sequence_number))
     frame_data["final_frame"] = final_frame
     frame_data["sequence_number"] = sequence_number
     (frame_iv,) = unpack_values(">{iv_len}s".format(iv_len=header.algorithm.iv_len), stream, verifier)

src/aws_encryption_sdk/internal/formatting/encryption_context.py

@@ -150,7 +150,7 @@ def deserialize_encryption_context(serialized_encryption_context):
     encryption_context = {}
 
     dict_size, deserialized_size = read_short(source=serialized_encryption_context, offset=deserialized_size)
-    _LOGGER.debug("Found %s keys", dict_size)
+    _LOGGER.debug("Found %d keys", dict_size)
     for _ in range(dict_size):
         key_size, deserialized_size = read_short(source=serialized_encryption_context, offset=deserialized_size)
         key, deserialized_size = read_string(

src/aws_encryption_sdk/streaming_client.py

@@ -214,7 +214,7 @@ def read(self, b=-1):
         if b is None or b < 0:
             b = -1
 
-        _LOGGER.debug("Stream read called, requesting %s bytes", b)
+        _LOGGER.debug("Stream read called, requesting %d bytes", b)
         output = io.BytesIO()
 
         if not self._message_prepped:
@@ -234,7 +234,7 @@ def read(self, b=-1):
                 self.output_buffer = b""
 
         self.bytes_read += output.tell()
-        _LOGGER.debug("Returning %s bytes of %s bytes requested", output.tell(), b)
+        _LOGGER.debug("Returning %d bytes of %d bytes requested", output.tell(), b)
         return output.getvalue()
 
     def tell(self):
@@ -538,7 +538,7 @@ def _read_bytes_to_framed_body(self, b):
         :returns: Bytes read from source stream, encrypted, and serialized
         :rtype: bytes
         """
-        _LOGGER.debug("collecting %s bytes", b)
+        _LOGGER.debug("collecting %d bytes", b)
         _b = b
 
         if b > 0:
@@ -565,10 +565,11 @@ def _read_bytes_to_framed_body(self, b):
             # If finalizing on this pass, wait until final frame is written
             or (finalize and not final_frame_written)
         ):
-            is_final_frame = finalize and len(plaintext) < self.config.frame_length
-            bytes_in_frame = min(len(plaintext), self.config.frame_length)
+            current_plaintext_length = len(plaintext)
+            is_final_frame = finalize and current_plaintext_length < self.config.frame_length
+            bytes_in_frame = min(current_plaintext_length, self.config.frame_length)
             _LOGGER.debug(
-                "Writing %s bytes into%s frame %s",
+                "Writing %d bytes into%s frame %d",
                 bytes_in_frame,
                 " final" if is_final_frame else "",
                 self.sequence_number,
@@ -719,7 +720,7 @@ def _read_header(self):
             and header.frame_length > self.config.max_body_length
         ):
             raise CustomMaximumValueExceeded(
-                "Frame Size in header found larger than custom value: {found} > {custom}".format(
+                "Frame Size in header found larger than custom value: {found:d} > {custom:d}".format(
                     found=header.frame_length, custom=self.config.max_body_length
                 )
             )
@@ -758,7 +759,7 @@ def _prep_non_framed(self):
 
         if self.config.max_body_length is not None and self.body_length > self.config.max_body_length:
             raise CustomMaximumValueExceeded(
-                "Non-framed message content length found larger than custom value: {found} > {custom}".format(
+                "Non-framed message content length found larger than custom value: {found:d} > {custom:d}".format(
                     found=self.body_length, custom=self.config.max_body_length
                 )
             )
@@ -792,7 +793,7 @@ def _read_bytes_from_non_framed_body(self, b):
         _LOGGER.debug("starting non-framed body read")
         # Always read the entire message for non-framed message bodies.
         bytes_to_read = self.body_end - self.source_stream.tell()
-        _LOGGER.debug("%s bytes requested; reading %s bytes", b, bytes_to_read)
+        _LOGGER.debug("%d bytes requested; reading %d bytes", b, bytes_to_read)
         ciphertext = self.source_stream.read(bytes_to_read)
 
         if len(self.output_buffer) + len(ciphertext) < self.body_length:
@@ -821,13 +822,13 @@ def _read_bytes_from_framed_body(self, b):
         """
         plaintext = b""
         final_frame = False
-        _LOGGER.debug("collecting %s bytes", b)
+        _LOGGER.debug("collecting %d bytes", b)
         while len(plaintext) < b and not final_frame:
             _LOGGER.debug("Reading frame")
             frame_data, final_frame = aws_encryption_sdk.internal.formatting.deserialize.deserialize_frame(
                 stream=self.source_stream, header=self._header, verifier=self.verifier
             )
-            _LOGGER.debug("Read complete for frame %s", frame_data.sequence_number)
+            _LOGGER.debug("Read complete for frame %d", frame_data.sequence_number)
             if frame_data.sequence_number != self.last_sequence_number + 1:
                 raise SerializationError("Malformed message: frames out of order")
             self.last_sequence_number += 1
@@ -846,7 +847,8 @@ def _read_bytes_from_framed_body(self, b):
                 encrypted_data=frame_data,
                 associated_data=associated_data,
             )
-            _LOGGER.debug("bytes collected: %s", len(plaintext))
+            plaintext_length = len(plaintext)
+            _LOGGER.debug("bytes collected: %d", plaintext_length)
         if final_frame:
             _LOGGER.debug("Reading footer")
             self.footer = aws_encryption_sdk.internal.formatting.deserialize.deserialize_footer(

test/functional/test_f_aws_encryption_sdk_client.py

@@ -685,6 +685,7 @@ def _prep_plaintext_and_logs(log_catcher, plaintext_length):
 
 
 def _look_in_logs(log_catcher, plaintext):
+    # Verify that no plaintext chunks are in the logs
     logs = log_catcher.text
     # look for every possible 32-byte chunk
     start = 0
@@ -698,25 +699,33 @@ def _look_in_logs(log_catcher, plaintext):
         end += 1
 
 
+def _error_check(capsys_instance):
+    # Verify that no error were caught and ignored.
+    # The intent is to catch logging errors, but others will be caught as well.
+    stderr = capsys_instance.readouterr().err
+    assert 'Call stack:' not in stderr
+
+
 @pytest.mark.parametrize("frame_size", (0, LINE_LENGTH // 2, LINE_LENGTH, LINE_LENGTH * 2))
 @pytest.mark.parametrize(
     "plaintext_length", (1, LINE_LENGTH // 2, LINE_LENGTH, int(LINE_LENGTH * 1.5), LINE_LENGTH * 2)
 )
-def test_plaintext_logs_oneshot(caplog, plaintext_length, frame_size):
+def test_plaintext_logs_oneshot(caplog, capsys, plaintext_length, frame_size):
     plaintext, key_provider = _prep_plaintext_and_logs(caplog, plaintext_length)
 
     _ciphertext, _header = aws_encryption_sdk.encrypt(
         source=plaintext, key_provider=key_provider, frame_length=frame_size
     )
 
     _look_in_logs(caplog, plaintext)
+    _error_check(capsys)
 
 
 @pytest.mark.parametrize("frame_size", (0, LINE_LENGTH // 2, LINE_LENGTH, LINE_LENGTH * 2))
 @pytest.mark.parametrize(
     "plaintext_length", (1, LINE_LENGTH // 2, LINE_LENGTH, int(LINE_LENGTH * 1.5), LINE_LENGTH * 2)
 )
-def test_plaintext_logs_stream(caplog, plaintext_length, frame_size):
+def test_plaintext_logs_stream(caplog, capsys, plaintext_length, frame_size):
     plaintext, key_provider = _prep_plaintext_and_logs(caplog, plaintext_length)
 
     ciphertext = b""
@@ -727,3 +736,4 @@ def test_plaintext_logs_stream(caplog, plaintext_length, frame_size):
             ciphertext += line
 
     _look_in_logs(caplog, plaintext)
+    _error_check(capsys)