Logging overhaul

 * Add more logging to the pool when acquiring and releasing connections.
 * Improved log format:
   * All debug messages should not start with `[#hhhh]  x:` where `hhhh` is the
     hex representation of the local port number of the connection or 0000 if
     there is none. `x` is one of `C` if it's the driver writing/opening/closing
     onto the socket, `S` if it's the driver reading/receiving an error from
     the socket and `_` if it's not communication between the server and the
     driver.
   * Reduced logging noise in routing table.
 * API docs: explain how to manually log the async task id.
 * Logging helpers `neo4j.debug`:
   * Add config options to decide if thread id and/or task id should be logged.
   * Their docs make clear that the logging format is not following semver.
   * Changed logging format to accommodate the new config options.

Author: robsdedude

docs/source/api.rst

@@ -1462,6 +1462,8 @@ following code:
     ...
 
 
+.. _logging-ref:
+
 *******
 Logging
 *******
@@ -1472,6 +1474,11 @@ not able to connect to the database server or if undesired behavior is observed.
 
 There are different ways of enabling logging as listed below.
 
+.. note::
+
+    For an improved logging experience with the async driver, please see
+    :ref:`async-logging-ref`.
+
 Simple Approach
 ===============
 
@@ -1484,8 +1491,8 @@ Context Manager
     :members:
     :special-members: __enter__, __exit__
 
-Full Controll
-=============
+Full Control
+============
 
 .. code-block:: python
 
@@ -1502,7 +1509,7 @@ Full Controll
     logging.getLogger("neo4j").addHandler(handler)
     # make sure the logger logs on the desired log level
     logging.getLogger("neo4j").setLevel(logging.DEBUG)
-    # from now on, DEBUG logging to stderr is enabled in the driver
+    # from now on, DEBUG logging to stdout is enabled in the driver
 
 
 *********

docs/source/async_api.rst

@@ -648,3 +648,52 @@ successfully executed on the server side or not, when a cancellation happens:
 ``await transaction.commit()`` and other methods can throw
 :exc:`asyncio.CancelledError` but still have managed to complete from the
 server's perspective.
+
+
+.. _async-logging-ref:
+
+*************
+Async Logging
+*************
+
+For the most parts, logging works the same way as in the synchronous driver.
+See :ref:`logging-ref` for more information.
+
+However, when following the manual approach to logging, it is recommended to
+include information about the current async task in the log record.
+Like so:
+
+.. code-block:: python
+
+    import asyncio
+    import logging
+    import sys
+
+    class TaskIdFilter(logging.Filter):
+        """Injecting async task id into log records."""
+
+        def filter(self, record):
+            try:
+                record.taskId = id(asyncio.current_task())
+            except RuntimeError:
+                record.taskId = None
+            return True
+
+
+    # attache the filter injecting the task id to the driver's logger
+    logging.getLogger("neo4j").addFilter(TaskIdFilter())
+
+    # create a handler, e.g. to log to stdout
+    handler = logging.StreamHandler(sys.stdout)
+    # configure the handler to your liking
+    handler.setFormatter(logging.Formatter(
+        "[%(levelname)-8s] [Task %(taskId)-15s] %(asctime)s  %(message)s"
+        # or when using threading AND asyncio
+        # "[%(levelname)-8s] [Thread %(thread)d] [Task %(taskId)-15s] "
+        # "%(asctime)s  %(message)s"
+    ))
+    # add the handler to the driver's logger
+    logging.getLogger("neo4j").addHandler(handler)
+    # make sure the logger logs on the desired log level
+    logging.getLogger("neo4j").setLevel(logging.DEBUG)
+    # from now on, DEBUG logging to stdout is enabled in the driver

neo4j/_async/io/_bolt.py

@@ -160,6 +160,10 @@ def __del__(self):
         if not asyncio.iscoroutinefunction(self.close):
             self.close()
 
+    @property
+    def connection_id(self):
+        return self.server_info._metadata.get("connection_id", "<unknown id>")
+
     @property
     @abc.abstractmethod
     def supports_multiple_results(self):
@@ -689,7 +693,8 @@ async def _set_defunct(self, message, error=None, silent=False):
         user_cancelled = isinstance(error, asyncio.CancelledError)
 
         if error:
-            log.debug("[#%04X]  %r", self.local_port, error)
+            log.debug("[#%04X] _: <CONNECTION> error: %r", self.local_port,
+                      error)
         if not user_cancelled:
             log.error(message)
         # We were attempting to receive data but the connection
@@ -751,7 +756,7 @@ async def close(self):
             try:
                 await self._send_all()
             except (OSError, BoltError, DriverError) as exc:
-                log.debug("[#%04X]  ignoring failed close %r",
+                log.debug("[#%04X]  _: <CONNECTION> ignoring failed close %r",
                           self.local_port, exc)
         log.debug("[#%04X]  C: <CLOSE>", self.local_port)
         try:
@@ -770,7 +775,7 @@ def kill(self):
         try:
             self.socket.kill()
         except OSError as exc:
-            log.debug("[#%04X]  ignoring failed kill %r",
+            log.debug("[#%04X]  _: <CONNECTION> ignoring failed kill %r",
                       self.local_port, exc)
         finally:
             self._closed = True

neo4j/_async/io/_bolt3.py

@@ -111,7 +111,7 @@ def __init__(self, *args, **kwargs):
         )
 
     def _on_server_state_change(self, old_state, new_state):
-        log.debug("[#%04X]  State: %s > %s", self.local_port,
+        log.debug("[#%04X]  _: <CONNECTION> state: %s > %s", self.local_port,
                   old_state.name, new_state.name)
 
     @property

neo4j/_async/io/_bolt4.py

@@ -69,7 +69,7 @@ def __init__(self, *args, **kwargs):
         )
 
     def _on_server_state_change(self, old_state, new_state):
-        log.debug("[#%04X]  State: %s > %s", self.local_port,
+        log.debug("[#%04X]  _: <CONNECTION> state: %s > %s", self.local_port,
                   old_state.name, new_state.name)
 
     @property
@@ -426,7 +426,8 @@ def on_success(metadata):
                 if isinstance(recv_timeout, int) and recv_timeout > 0:
                     self.socket.settimeout(recv_timeout)
                 else:
-                    log.info("[#%04X]  Server supplied an invalid value for "
+                    log.info("[#%04X]  _: <CONNECTION> Server supplied an "
+                             "invalid value for "
                              "connection.recv_timeout_seconds (%r). Make sure "
                              "the server and network is set up correctly.",
                              self.local_port, recv_timeout)

neo4j/_async/io/_bolt5.py

@@ -66,7 +66,7 @@ def __init__(self, *args, **kwargs):
         )
 
     def _on_server_state_change(self, old_state, new_state):
-        log.debug("[#%04X]  State: %s > %s", self.local_port,
+        log.debug("[#%04X]  _: <CONNECTION> state: %s > %s", self.local_port,
                   old_state.name, new_state.name)
 
     @property
@@ -104,7 +104,8 @@ def on_success(metadata):
                 if isinstance(recv_timeout, int) and recv_timeout > 0:
                     self.socket.settimeout(recv_timeout)
                 else:
-                    log.info("[#%04X]  Server supplied an invalid value for "
+                    log.info("[#%04X]  _: <CONNECTION> Server supplied an "
+                             "invalid value for "
                              "connection.recv_timeout_seconds (%r). Make sure "
                              "the server and network is set up correctly.",
                              self.local_port, recv_timeout)