Merge pull request #436 from fredthomsen/logging

Logging enhancement

Author: Lukasa

CONTRIBUTORS.rst

@@ -108,3 +108,7 @@ In chronological order:
 
   - Added support for equality testing to ``h2.settings.Settings`` objects.
 
+- Fred Thomsen (@fredthomsen)
+
+  - Added logging.
+

HISTORY.rst

@@ -11,7 +11,7 @@ API Changes (Backward-Compatible)
   events.
 - Rather than reject outbound Connection-specific headers, h2 will now
   normalize the header block by removing them.
-- Implement equality for the ``Settings`` class.
+- Implement equality for the ``h2.settings.Settings`` class.
 - Added ``h2.settings.SettingCodes``, an enum that is used to store all the
   HTTP/2 setting codes. This allows us to use a better printed representation of
   the setting code in most places that it is used.
@@ -24,7 +24,10 @@ API Changes (Backward-Compatible)
   3.0.0.
 - Added an optional ``pad_length`` parameter to ``H2Connection.send_data``
   to allow the user to include padding on a data frame.
-
+- Added a new parameter to the ``h2.config.H2Configuration`` initializer which
+  takes a logger.  This allows us to log by providing a logger that conforms
+  to the requirements of this module so that it can be used in different
+  environments.
 
 Bugfixes
 ~~~~~~~~

h2/config.py

@@ -25,6 +25,24 @@ def __set__(self, instance, value):
         setattr(instance, self.attr_name, value)
 
 
+class DummyLogger(object):
+    """
+    An Logger object that does not actual logging, hence a DummyLogger.
+
+    For the class the log operation is merely a no-op.  The intent is to avoid
+    conditionals being sprinkled throughout the hyper-h2 code for calls to
+    logging functions when no logger is passed into the corresponding object.
+    """
+    def __init__(self, *vargs):
+        pass
+
+    def debug(self, *vargs, **kwargs):
+        """
+        No-op logging. Only level needed for now.
+        """
+        pass
+
+
 class H2Configuration(object):
     """
     An object that controls the way a single HTTP/2 connection behaves.
@@ -70,6 +88,14 @@ class H2Configuration(object):
         be skipped, and allow the object to receive headers that may be illegal
         according to RFC 7540. Defaults to ``True``.
     :type validate_inbound_headers: ``bool``
+
+    :param logger: A logger that conforms to the requirements for this module,
+        those being no I/O and no context switches, which is needed in order
+        to run in asynchronous operation.
+
+        .. versionadded:: 2.6.0
+
+    :type logger: ``logging.Logger``
     """
     client_side = _BooleanConfigOption('client_side')
     validate_outbound_headers = _BooleanConfigOption(
@@ -87,12 +113,14 @@ def __init__(self,
                  header_encoding='utf-8',
                  validate_outbound_headers=True,
                  normalize_outbound_headers=True,
-                 validate_inbound_headers=True):
+                 validate_inbound_headers=True,
+                 logger=None):
         self.client_side = client_side
         self.header_encoding = header_encoding
         self.validate_outbound_headers = validate_outbound_headers
         self.normalize_outbound_headers = normalize_outbound_headers
         self.validate_inbound_headers = validate_inbound_headers
+        self.logger = logger or DummyLogger(__name__)
 
     @property
     def header_encoding(self):

h2/connection.py

@@ -506,6 +506,9 @@ def _begin_new_stream(self, stream_id, allowed_ids):
         :param stream_id: The ID of the stream to open.
         :param allowed_ids: What kind of stream ID is allowed.
         """
+        self.config.logger.debug(
+            "Attempting to initiate stream ID %d", stream_id
+        )
         outbound = self._stream_id_is_outbound(stream_id)
         highest_stream_id = (
             self.highest_outbound_stream_id if outbound else
@@ -526,10 +529,12 @@ def _begin_new_stream(self, stream_id, allowed_ids):
             inbound_window_size=self.local_settings.initial_window_size,
             outbound_window_size=self.remote_settings.initial_window_size
         )
+        self.config.logger.debug("Stream ID %d created", stream_id)
         s.max_inbound_frame_size = self.max_inbound_frame_size
         s.max_outbound_frame_size = self.max_outbound_frame_size
 
         self.streams[stream_id] = s
+        self.config.logger.debug("Current streams: %s", self.streams.keys())
 
         if outbound:
             self.highest_outbound_stream_id = stream_id
@@ -543,6 +548,7 @@ def initiate_connection(self):
         Provides any data that needs to be sent at the start of the connection.
         Must be called for both clients and servers.
         """
+        self.config.logger.debug("Initializing connection")
         self.state_machine.process_input(ConnectionInputs.SEND_SETTINGS)
         if self.config.client_side:
             preamble = b'PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n'
@@ -552,6 +558,9 @@ def initiate_connection(self):
         f = SettingsFrame(0)
         for setting, value in self.local_settings.items():
             f.settings[setting] = value
+        self.config.logger.debug(
+            "Send Settings frame: %s", self.local_settings
+        )
 
         self._data_to_send += preamble + f.serialize()
 
@@ -588,8 +597,11 @@ def initiate_upgrade_connection(self, settings_header=None):
             For servers, returns nothing.
         :rtype: ``bytes`` or ``None``
         """
-        frame_data = None
+        self.config.logger.debug(
+            "Upgrade connection. Current settings: %s", self.local_settings
+        )
 
+        frame_data = None
         # Begin by getting the preamble in place.
         self.initiate_connection()
 
@@ -617,6 +629,7 @@ def initiate_upgrade_connection(self, settings_header=None):
             ConnectionInputs.SEND_HEADERS if self.config.client_side
             else ConnectionInputs.RECV_HEADERS
         )
+        self.config.logger.debug("Process input %s", connection_input)
         self.state_machine.process_input(connection_input)
 
         # Set up stream 1.
@@ -686,9 +699,12 @@ def get_next_available_stream_id(self):
         # No streams have been opened yet, so return the lowest allowed stream
         # ID.
         if not self.highest_outbound_stream_id:
-            return 1 if self.config.client_side else 2
-
-        next_stream_id = self.highest_outbound_stream_id + 2
+            next_stream_id = 1 if self.config.client_side else 2
+        else:
+            next_stream_id = self.highest_outbound_stream_id + 2
+        self.config.logger.debug(
+            "Next available stream ID %d", next_stream_id
+        )
         if next_stream_id > self.HIGHEST_ALLOWED_STREAM_ID:
             raise NoAvailableStreamIDError("Exhausted allowed stream IDs")
 
@@ -798,6 +814,10 @@ def send_headers(self, stream_id, headers, end_stream=False,
 
         :returns: Nothing
         """
+        self.config.logger.debug(
+            "Send headers on stream ID %d", stream_id
+        )
+
         # Check we can open the stream.
         if stream_id not in self.streams:
             max_open_streams = self.remote_settings.max_concurrent_streams
@@ -871,6 +891,9 @@ def send_data(self, stream_id, data, end_stream=False, pad_length=None):
         :type pad_length: ``int``
         :returns: Nothing
         """
+        self.config.logger.debug(
+            "Send data on stream ID %d with len %d", stream_id, len(data)
+        )
         frame_size = len(data)
         if pad_length is not None:
             if not isinstance(pad_length, int):
@@ -879,6 +902,9 @@ def send_data(self, stream_id, data, end_stream=False, pad_length=None):
                 raise ValueError("pad_length must be within range: [0, 255]")
             # Account for padding bytes plus the 1-byte padding length field.
             frame_size += pad_length + 1
+        self.config.logger.debug(
+            "Frame size on stream ID %d is %d", stream_id, frame_size
+        )
 
         if frame_size > self.local_flow_control_window(stream_id):
             raise FlowControlError(
@@ -899,6 +925,10 @@ def send_data(self, stream_id, data, end_stream=False, pad_length=None):
         self._prepare_for_sending(frames)
 
         self.outbound_flow_control_window -= frame_size
+        self.config.logger.debug(
+            "Outbound flow control window size is %d",
+            self.outbound_flow_control_window
+        )
         assert self.outbound_flow_control_window >= 0
 
     def end_stream(self, stream_id):
@@ -912,6 +942,7 @@ def end_stream(self, stream_id):
         :type stream_id: ``int``
         :returns: Nothing
         """
+        self.config.logger.debug("End stream ID %d", stream_id)
         self.state_machine.process_input(ConnectionInputs.SEND_DATA)
         frames = self.streams[stream_id].end_stream()
         self._prepare_for_sending(frames)
@@ -953,6 +984,10 @@ def increment_flow_control_window(self, increment, stream_id=None):
             f.window_increment = increment
             frames = [f]
 
+        self.config.logger.debug(
+            "Increase stream ID %d flow control window by %d",
+            stream_id, increment
+        )
         self._prepare_for_sending(frames)
 
     def push_stream(self, stream_id, promised_stream_id, request_headers):
@@ -977,6 +1012,10 @@ def push_stream(self, stream_id, promised_stream_id, request_headers):
             :class:`HeaderTuple <hpack:hpack.HeaderTuple>` objects.
         :returns: Nothing
         """
+        self.config.logger.debug(
+            "Send Push Promise frame on stream ID %d", stream_id
+        )
+
         if not self.remote_settings.enable_push:
             raise ProtocolError("Remote peer has disabled stream push")
 
@@ -1010,6 +1049,8 @@ def ping(self, opaque_data):
                             PING frame.
         :returns: Nothing
         """
+        self.config.logger.debug("Send Ping frame")
+
         if not isinstance(opaque_data, bytes) or len(opaque_data) != 8:
             raise ValueError("Invalid value for ping data: %r" % opaque_data)
 
@@ -1035,6 +1076,7 @@ def reset_stream(self, stream_id, error_code=0):
         :type error_code: ``int``
         :returns: Nothing
         """
+        self.config.logger.debug("Reset stream ID %d", stream_id)
         self.state_machine.process_input(ConnectionInputs.SEND_RST_STREAM)
         stream = self._get_stream_by_id(stream_id)
         frames = stream.reset_stream(error_code)
@@ -1057,6 +1099,7 @@ def close_connection(self, error_code=0, additional_data=None,
             by the sender. Defaults to ``highest_inbound_stream_id``.
         :returns: Nothing
         """
+        self.config.logger.debug("Close connection")
         self.state_machine.process_input(ConnectionInputs.SEND_GOAWAY)
 
         # Additional_data must be bytes
@@ -1081,6 +1124,9 @@ def update_settings(self, new_settings):
 
         :param new_settings: A dictionary of {setting: new value}
         """
+        self.config.logger.debug(
+            "Update connection settings to %s", new_settings
+        )
         self.state_machine.process_input(ConnectionInputs.SEND_SETTINGS)
         self.local_settings.update(new_settings)
         s = SettingsFrame(0)
@@ -1314,6 +1360,10 @@ def acknowledge_received_data(self, acknowledged_size, stream_id):
         :returns: Nothing
         :rtype: ``None``
         """
+        self.config.logger.debug(
+            "Ack received data on stream ID %d with size %d",
+            stream_id, acknowledged_size
+        )
         if stream_id <= 0:
             raise ValueError(
                 "Stream ID %d is not valid for acknowledge_received_data" %
@@ -1459,6 +1509,10 @@ def receive_data(self, data):
         :returns: A list of events that the remote peer triggered by sending
             this data.
         """
+        self.config.logger.debug(
+            "Process received data on connection. Received data: %r", data
+        )
+
         events = []
         self.incoming_buffer.add_data(data)
         self.incoming_buffer.max_frame_size = self.max_inbound_frame_size