[mod] debug mode: log HTTP requests with network name

For example wikipedia requests use the logger name "searx.network.wikipedia"

Log is disable when searx_debug is False

2 files changed, 44 insertions, 14 deletions

diff --git a/searx/network/client.py b/searx/network/client.py
index 187ae5366..e1abff05a 100644
--- a/searx/network/client.py
+++ b/searx/network/client.py
@@ -194,7 +194,7 @@ def new_client(
         # pylint: disable=too-many-arguments
         enable_http, verify, enable_http2,
         max_connections, max_keepalive_connections, keepalive_expiry,
-        proxies, local_address, retries, max_redirects  ):
+        proxies, local_address, retries, max_redirects, hook_log_response  ):
     limit = httpx.Limits(
         max_connections=max_connections,
         max_keepalive_connections=max_keepalive_connections,
@@ -221,7 +221,17 @@ def new_client(
         mounts['http://'] = AsyncHTTPTransportNoHttp()
 
     transport = get_transport(verify, enable_http2, local_address, None, limit, retries)
-    return httpx.AsyncClient(transport=transport, mounts=mounts, max_redirects=max_redirects)
+
+    event_hooks = None
+    if hook_log_response:
+        event_hooks = {'response': [ hook_log_response ]}
+
+    return httpx.AsyncClient(
+        transport=transport,
+        mounts=mounts,
+        max_redirects=max_redirects,
+        event_hooks=event_hooks,
+    )
 
 
 def get_loop():
@@ -231,7 +241,7 @@ def get_loop():
 
 def init():
     # log
-    for logger_name in ('hpack.hpack', 'hpack.table'):
+    for logger_name in ('hpack.hpack', 'hpack.table', 'httpx._client'):
         logging.getLogger(logger_name).setLevel(logging.WARNING)
 
     # loop
diff --git a/searx/network/network.py b/searx/network/network.py
index d09a2ee0e..9954f0507 100644
--- a/searx/network/network.py
+++ b/searx/network/network.py
@@ -10,9 +10,11 @@ from itertools import cycle
 
 import httpx
 
+from searx import logger, searx_debug
 from .client import new_client, get_loop
 
 
+logger = logger.getChild('network')
 DEFAULT_NAME = '__DEFAULT__'
 NETWORKS = {}
 # requests compatibility when reading proxy settings from settings.yml
@@ -41,7 +43,7 @@ class Network:
         'enable_http', 'verify', 'enable_http2',
         'max_connections', 'max_keepalive_connections', 'keepalive_expiry',
         'local_addresses', 'proxies', 'max_redirects', 'retries', 'retry_on_http_error',
-        '_local_addresses_cycle', '_proxies_cycle', '_clients'
+        '_local_addresses_cycle', '_proxies_cycle', '_clients', '_logger'
     )
 
     def __init__(
@@ -57,7 +59,8 @@ class Network:
             local_addresses=None,
             retries=0,
             retry_on_http_error=None,
-            max_redirects=30 ):
+            max_redirects=30,
+            logger_name=None):
 
         self.enable_http = enable_http
         self.verify = verify
@@ -73,6 +76,7 @@ class Network:
         self._local_addresses_cycle = self.get_ipaddress_cycle()
         self._proxies_cycle = self.get_proxy_cycles()
         self._clients = {}
+        self._logger = logger.getChild(logger_name) if logger_name else logger
         self.check_parameters()
 
     def check_parameters(self):
@@ -130,12 +134,25 @@ class Network:
             # pylint: disable=stop-iteration-return
             yield tuple((pattern, next(proxy_url_cycle)) for pattern, proxy_url_cycle in proxy_settings.items())
 
+    async def log_response(self, response: httpx.Response):
+        request = response.request
+        status = f"{response.status_code} {response.reason_phrase}"
+        response_line = f"{response.http_version} {status}"
+        if hasattr(response, "_elapsed"):
+            elapsed_time = f"{response.elapsed.total_seconds()} sec"
+        else:
+            elapsed_time = "stream"
+        self._logger.debug(
+            f'HTTP Request: {request.method} {request.url} "{response_line}" ({elapsed_time})'
+        )
+
     def get_client(self, verify=None, max_redirects=None):
         verify = self.verify if verify is None else verify
         max_redirects = self.max_redirects if max_redirects is None else max_redirects
         local_address = next(self._local_addresses_cycle)
         proxies = next(self._proxies_cycle)  # is a tuple so it can be part of the key
         key = (verify, max_redirects, local_address, proxies)
+        hook_log_response = self.log_response if searx_debug else None
         if key not in self._clients or self._clients[key].is_closed:
             self._clients[key] = new_client(
                 self.enable_http,
@@ -147,7 +164,8 @@ class Network:
                 dict(proxies),
                 local_address,
                 0,
-                max_redirects
+                max_redirects,
+                hook_log_response
             )
         return self._clients[key]
 
@@ -243,11 +261,13 @@ def initialize(settings_engines=None, settings_outgoing=None):
         'retry_on_http_error': None,
     }
 
-    def new_network(params):
+    def new_network(params, logger_name=None):
         nonlocal default_params
         result = {}
         result.update(default_params)
         result.update(params)
+        if logger_name:
+            result['logger_name'] = logger_name
         return Network(**result)
 
     def iter_networks():
@@ -263,13 +283,13 @@ def initialize(settings_engines=None, settings_outgoing=None):
     if NETWORKS:
         done()
     NETWORKS.clear()
-    NETWORKS[DEFAULT_NAME] = new_network({})
-    NETWORKS['ipv4'] = new_network({'local_addresses': '0.0.0.0'})
-    NETWORKS['ipv6'] = new_network({'local_addresses': '::'})
+    NETWORKS[DEFAULT_NAME] = new_network({}, logger_name='default')
+    NETWORKS['ipv4'] = new_network({'local_addresses': '0.0.0.0'}, logger_name='ipv4')
+    NETWORKS['ipv6'] = new_network({'local_addresses': '::'}, logger_name='ipv6')
 
     # define networks from outgoing.networks
     for network_name, network in settings_outgoing['networks'].items():
-        NETWORKS[network_name] = new_network(network)
+        NETWORKS[network_name] = new_network(network, logger_name=network_name)
 
     # define networks from engines.[i].network (except references)
     for engine_name, engine, network in iter_networks():
@@ -280,9 +300,9 @@ def initialize(settings_engines=None, settings_outgoing=None):
                     network[attribute_name] = getattr(engine, attribute_name)
                 else:
                     network[attribute_name] = attribute_value
-            NETWORKS[engine_name] = new_network(network)
+            NETWORKS[engine_name] = new_network(network, logger_name=engine_name)
         elif isinstance(network, dict):
-            NETWORKS[engine_name] = new_network(network)
+            NETWORKS[engine_name] = new_network(network, logger_name=engine_name)
 
     # define networks from engines.[i].network (references)
     for engine_name, engine, network in iter_networks():
@@ -295,7 +315,7 @@ def initialize(settings_engines=None, settings_outgoing=None):
     if 'image_proxy' not in NETWORKS:
         image_proxy_params = default_params.copy()
         image_proxy_params['enable_http2'] = False
-        NETWORKS['image_proxy'] = new_network(image_proxy_params)
+        NETWORKS['image_proxy'] = new_network(image_proxy_params, logger_name='image_proxy')
 
 
 @atexit.register