Add some HPACK logging.

Author: Lukasa

hyper/__init__.py

@@ -17,3 +17,7 @@
     raise ImportError("hyper only supports Python 3.3 or higher.")
 
 __all__ = [HTTP20Response, HTTP20Connection]
+
+# Set default logging handler.
+import logging
+logging.getLogger(__name__).addHandler(logging.NullHandler())

hyper/http20/hpack.py

@@ -8,18 +8,23 @@
 Implements the version dated January 9, 2014.
 """
 import collections
+import logging
 
 from .huffman import HuffmanDecoder, HuffmanEncoder
 from hyper.http20.huffman_constants import (
     REQUEST_CODES, REQUEST_CODES_LENGTH, RESPONSE_CODES, RESPONSE_CODES_LENGTH
 )
 
+log = logging.getLogger(__name__)
+
 
 def encode_integer(integer, prefix_bits):
     """
     This encodes an integer according to the wacky integer encoding rules
     defined in the HPACK spec.
     """
+    log.debug("Encoding %d with %d bits.", integer, prefix_bits)
+
     max_number = (2 ** prefix_bits) - 1
 
     if (integer < max_number):
@@ -63,6 +68,8 @@ def decode_integer(data, prefix_bits):
                 number += next_byte * multiple(index)
                 break
 
+    log.debug("Decoded %d consuming %d bytes.", number, index + 1)
+
     return (number, index + 1)
 
 
@@ -163,6 +170,12 @@ def header_table_size(self):
 
     @header_table_size.setter
     def header_table_size(self, value):
+        log.debug(
+            "Setting header table size to %d from %d",
+            value,
+            self._header_table_size
+        )
+
         # If the new value is larger than the current one, no worries!
         # Otherwise, we may need to shrink the header table.
         if value < self._header_table_size:
@@ -178,6 +191,10 @@ def header_table_size(self, value):
                 # to be removed from the reference set.
                 self.reference_set.discard((n, v))
 
+                log.debug(
+                    "Removed %s: %s from the encoder header table", n, v
+                )
+
         self._header_table_size = value
 
     def encode(self, headers, huffman=True):
@@ -202,6 +219,8 @@ def encode(self, headers, huffman=True):
         Literal text values may optionally be Huffman encoded. For now we don't
         do that, because it's an extra bit of complication, but we will later.
         """
+        log.debug("HPACK encoding %s", headers)
+
         # First, turn the headers into a list of tuples if possible. This is
         # the natural way to interact with them in HPACK.
         if isinstance(headers, dict):
@@ -225,6 +244,7 @@ def encode(self, headers, huffman=True):
         # reference set, just emit an 'empty the reference set' message.
         if (len(self.reference_set - incoming_set) >
                                                (len(self.reference_set) // 2)):
+            log.debug("Emptying the encoder reference set.")
             header_block = b'\x80'  # Indexed representation of 0.
 
             # Remove everything from the reference set.
@@ -234,6 +254,8 @@ def encode(self, headers, huffman=True):
 
         header_block += self.add(to_add, huffman)
 
+        log.debug("Encoded header block to %s", header_block)
+
         return header_block
 
     def remove(self, to_remove):
@@ -242,6 +264,8 @@ def remove(self, to_remove):
         them. These must be in the header table, so must be represented as
         their indexed form.
         """
+        log.debug("Removing %s from the header table", to_remove)
+
         encoded = []
 
         for name, value in to_remove:
@@ -274,6 +298,8 @@ def add(self, to_add, huffman=False):
         This function takes a set of header key-value tuples and serializes
         them for adding to the header table.
         """
+        log.debug("Adding %s to the header table", to_add)
+
         encoded = []
 
         for name, value in to_add:
@@ -360,6 +386,8 @@ def _add_to_header_table(self, name, value):
             # be removed from the reference set.
             self.reference_set.discard((n, v))
 
+            log.debug("Evicted %s: %s from the header table", n, v)
+
     def _encode_indexed(self, index):
         """
         Encodes a header using the indexed representation.
@@ -493,6 +521,12 @@ def header_table_size(self):
 
     @header_table_size.setter
     def header_table_size(self, value):
+        log.debug(
+            "Resizing decoder header table to %d from %d",
+            value,
+            self._header_table_size
+        )
+
         # If the new value is larger than the current one, no worries!
         # Otherwise, we may need to shrink the header table.
         if value < self._header_table_size:
@@ -508,12 +542,16 @@ def header_table_size(self, value):
                 # to be removed from the reference set.
                 self.reference_set.discard((n, v))
 
+                log.debug("Evicting %s: %s from the header table", n, v)
+
         self._header_table_size = value
 
     def decode(self, data):
         """
         Takes an HPACK-encoded header block and decodes it into a header set.
         """
+        log.debug("Decoding %s", data)
+
         headers = set()
         data_len = len(data)
         current_index = 0
@@ -571,6 +609,8 @@ def _add_to_header_table(self, name, value):
             # be removed from the reference set.
             self.reference_set.discard((n, v))
 
+            log.debug("Evicting %s: %s from the header table", n, v)
+
     def _decode_indexed(self, data):
         """
         Decodes a header represented using the indexed representation.
@@ -598,9 +638,15 @@ def _decode_indexed(self, data):
         # Since this updates the reference set, don't bother returning the
         # header.
         if header in self.reference_set:
+            log.debug(
+                "Removed %s from the reference set, consumed %d",
+                header,
+                consumed
+            )
             self.reference_set.remove(header)
             return None, consumed
         else:
+            log.debug("Decoded %s, consumed %d", header, consumed)
             self.reference_set.add(header)
             return header, consumed
 
@@ -666,4 +712,11 @@ def _decode_literal(self, data, should_index):
 
         header = (name, value)
 
+        log.debug(
+            "Decoded %s, consumed %d, indexed %s",
+            header,
+            consumed,
+            should_index
+        )
+
         return header, total_consumed

hyper/http20/tls.py

@@ -17,7 +17,6 @@
 # to.
 _context = None
 
-
 def wrap_socket(socket, server_hostname):
     """
     A vastly simplified SSL wrapping function. We'll probably extend this to