feat: build log messages lazily

Author: BobTheBuidler

Diff for: docs/filters.rst

@@ -654,7 +654,7 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                     # from our in-memory cache
                     block_when = get_block_when(block_number)
 
-                    logger.debug(f"Processing event {evt['event']}, block: {evt['blockNumber']} count: {evt['blockNumber']}")
+                    logger.debug("Processing event %s, block: %s count: %s", evt['event'], block_number, block_number)
                     processed = self.state.process_event(block_when, evt)
                     all_processed.append(processed)
 
@@ -726,7 +726,8 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                 # Print some diagnostics to logs to try to fiddle with real world JSON-RPC API performance
                 estimated_end_block = min(current_block + chunk_size, end_block)
                 logger.debug(
-                    f"Scanning token transfers for blocks: {current_block} - {estimated_end_block}, chunk size {chunk_size}, last chunk scan took {last_scan_duration}, last logs found {last_logs_found}"
+                    "Scanning token transfers for blocks: %s - %s, chunk size %s, last chunk scan took %s, last logs found %s",
+                    current_block, estimated_end_block, chunk_size, last_scan_duration, last_logs_found,
                 )
 
                 start = time.time()
@@ -778,7 +779,9 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
                 if i < retries - 1:
                     # Give some more verbose info than the default middleware
                     logger.warning(
-                        f"Retrying events for block range {start_block} - {end_block} ({end_block-start_block}) failed with {e} , retrying in {delay} seconds")
+                        "Retrying events for block range %s - %s (%s) failed with %s , retrying in %s seconds",
+                        start_block, end_block, end_block-start_block, e, delay,
+                    )
                     # Decrease the `eth_getBlocks` range
                     end_block = start_block + ((end_block - start_block) // 2)
                     # Let the JSON-RPC to recover e.g. from restart
@@ -832,7 +835,7 @@ The script can be run with: ``python ./eventscanner.py <your JSON-RPC API URL>``
             to_block=to_block
         )
 
-        logger.debug(f"Querying eth_getLogs with the following parameters: {event_filter_params}")
+        logger.debug("Querying eth_getLogs with the following parameters: %s", event_filter_params)
 
         # Call JSON-RPC API on your Ethereum node.
         # get_logs() returns raw AttributedDict entries

Diff for: web3/_utils/caching/request_caching_validation.py

@@ -73,7 +73,7 @@ def is_beyond_validation_threshold(
         else:
             provider.logger.error(
                 "Invalid request_cache_validation_threshold value. This should not "
-                f"have happened. Request not cached.\n    threshold: {threshold}"
+                "have happened. Request not cached.\n    threshold: %s", threshold
             )
             return False
     except Exception as e:
@@ -128,7 +128,7 @@ def validate_from_blocknum_in_result(
         else:
             provider.logger.error(
                 "Could not find block number in result. This should not have happened. "
-                f"Request not cached.\n    result: {result}",
+                "Request not cached.\n    result: %s", result
             )
             return False
     except Exception as e:
@@ -198,7 +198,7 @@ async def async_is_beyond_validation_threshold(
         else:
             provider.logger.error(
                 "Invalid request_cache_validation_threshold value. This should not "
-                f"have happened. Request not cached.\n    threshold: {threshold}"
+                "have happened. Request not cached.\n    threshold: %s", threshold
             )
             return False
     except Exception as e:
@@ -253,7 +253,7 @@ async def async_validate_from_blocknum_in_result(
         else:
             provider.logger.error(
                 "Could not find block number in result. This should not have happened. "
-                f"Request not cached.\n    result: {result}",
+                "Request not cached.\n    result: %s", result
             )
             return False
     except Exception as e:

Diff for: web3/_utils/http_session_manager.py

@@ -81,14 +81,14 @@ def cache_and_return_session(
 
         with self._lock:
             cached_session, evicted_items = self.session_cache.cache(cache_key, session)
-            self.logger.debug(f"Session cached: {endpoint_uri}, {cached_session}")
+            self.logger.debug("Session cached: %s, %s", endpoint_uri, cached_session)
 
         if evicted_items is not None:
             evicted_sessions = evicted_items.values()
             for evicted_session in evicted_sessions:
                 self.logger.debug(
-                    "Session cache full. Session evicted from cache: "
-                    f"{evicted_session}",
+                    "Session cache full. Session evicted from cache: %s",
+                    evicted_session,
                 )
             threading.Timer(
                 # If `request_timeout` is `None`, don't wait forever for the closing
@@ -167,7 +167,7 @@ def _handle_streaming_response(
     def _close_evicted_sessions(self, evicted_sessions: List[requests.Session]) -> None:
         for evicted_session in evicted_sessions:
             evicted_session.close()
-            self.logger.debug(f"Closed evicted session: {evicted_session}")
+            self.logger.debug("Closed evicted session: %s", evicted_session)
 
     # -- async -- #
 
@@ -195,7 +195,7 @@ async def async_cache_and_return_session(
                     cache_key, session
                 )
                 self.logger.debug(
-                    f"Async session cached: {endpoint_uri}, {cached_session}"
+                    "Async session cached: %s, %s", endpoint_uri, cached_session
                 )
 
             else:
@@ -215,16 +215,18 @@ async def async_cache_and_return_session(
                 )
                 if warning:
                     self.logger.debug(
-                        f"{warning}: {endpoint_uri}, {cached_session}. "
-                        f"Creating and caching a new async session for uri."
+                        "%s: %s, %s. Creating and caching a new async session for uri.",
+                        warning,
+                        endpoint_uri,
+                        cached_session,
                     )
 
                     self.session_cache._data.pop(cache_key)
                     if not session_is_closed:
                         # if loop was closed but not the session, close the session
                         await cached_session.close()
                     self.logger.debug(
-                        f"Async session closed and evicted from cache: {cached_session}"
+                        "Async session closed and evicted from cache: %s", cached_session
                     )
 
                     # replace stale session with a new session at the cache key
@@ -238,7 +240,7 @@ async def async_cache_and_return_session(
                         cache_key, _session
                     )
                     self.logger.debug(
-                        f"Async session cached: {endpoint_uri}, {cached_session}"
+                        "Async session cached: %s, %s", endpoint_uri, cached_session
                     )
 
         if evicted_items is not None:
@@ -248,8 +250,8 @@ async def async_cache_and_return_session(
             evicted_sessions = list(evicted_items.values())
             for evicted_session in evicted_sessions:
                 self.logger.debug(
-                    "Async session cache full. Session evicted from cache: "
-                    f"{evicted_session}",
+                    "Async session cache full. Session evicted from cache: %s",
+                    evicted_session,
                 )
             # Kick off an asyncio `Task` to close the evicted sessions. In the case
             # that the cache filled very quickly and some sessions have been evicted
@@ -323,10 +325,10 @@ async def _async_close_evicted_sessions(
 
         for evicted_session in evicted_sessions:
             await evicted_session.close()
-            self.logger.debug(f"Closed evicted async session: {evicted_session}")
+            self.logger.debug("Closed evicted async session: %s", evicted_session)
 
         if any(not evicted_session.closed for evicted_session in evicted_sessions):
             self.logger.warning(
-                "Some evicted async sessions were not properly closed: "
-                f"{evicted_sessions}"
+                "Some evicted async sessions were not properly closed: %s",
+                evicted_sessions
             )

Diff for: web3/_utils/validation.py

@@ -396,7 +396,7 @@ def validate_rpc_response_and_raise_if_error(
 
         response = apply_error_formatters(error_formatters, response)
         if logger is not None:
-            logger.debug(f"RPC error response: {response}")
+            logger.debug("RPC error response: %s", response)
 
         raise web3_rpc_error
 

Diff for: web3/manager.py

@@ -159,7 +159,7 @@ def _make_request(
         request_func = provider.request_func(
             cast("Web3", self.w3), cast("MiddlewareOnion", self.middleware_onion)
         )
-        self.logger.debug(f"Making request. Method: {method}")
+        self.logger.debug("Making request. Method: %s", method)
         return request_func(method, params)
 
     async def _coro_make_request(
@@ -169,7 +169,7 @@ async def _coro_make_request(
         request_func = await provider.request_func(
             cast("AsyncWeb3", self.w3), cast("MiddlewareOnion", self.middleware_onion)
         )
-        self.logger.debug(f"Making request. Method: {method}")
+        self.logger.debug("Making request. Method: %s", method)
         return await request_func(method, params)
 
     #
@@ -366,9 +366,12 @@ async def socket_request(
     ) -> RPCResponse:
         provider = cast(PersistentConnectionProvider, self._provider)
         self.logger.debug(
-            "Making request to open socket connection and waiting for response: "
-            f"{provider.get_endpoint_uri_or_ipc_path()},\n    method: {method},\n"
-            f"    params: {params}"
+            "Making request to open socket connection and waiting for response: %s,\n"
+            "    method: %s,\n"
+            "    params: %s",
+            provider.get_endpoint_uri_or_ipc_path(),
+            method,
+            params,
         )
         rpc_request = await self.send(method, params)
         provider._request_processor.cache_request_information(
@@ -388,9 +391,12 @@ async def send(self, method: RPCEndpoint, params: Any) -> RPCRequest:
             middleware_onion,
         )
         self.logger.debug(
-            "Sending request to open socket connection: "
-            f"{provider.get_endpoint_uri_or_ipc_path()},\n    method: {method},\n"
-            f"    params: {params}"
+            "Sending request to open socket connection: %s,\n"
+            "    method: %s,\n"
+            "    params: %s",
+            provider.get_endpoint_uri_or_ipc_path(),
+            method,
+            params,
         )
         return await send_func(method, params)
 
@@ -404,7 +410,7 @@ async def recv_for_request(self, rpc_request: RPCRequest) -> RPCResponse:
         )
         self.logger.debug(
             "Getting response for request from open socket connection:\n"
-            f"    request: {rpc_request}"
+            "    request: %s", rpc_request,
         )
         response = await recv_func(rpc_request)
         try:
@@ -417,8 +423,8 @@ async def recv_for_request(self, rpc_request: RPCRequest) -> RPCResponse:
     async def recv(self) -> Union[RPCResponse, FormattedEthSubscriptionResponse]:
         provider = cast(PersistentConnectionProvider, self._provider)
         self.logger.debug(
-            "Getting next response from open socket connection: "
-            f"{provider.get_endpoint_uri_or_ipc_path()}"
+            "Getting next response from open socket connection: %s",
+            provider.get_endpoint_uri_or_ipc_path()
         )
         # pop from the queue since the listener task is responsible for reading
         # directly from the socket
@@ -501,9 +507,11 @@ async def _process_response(
                     # subscription as it comes in
                     request_info.subscription_id = subscription_id
                     provider.logger.debug(
-                        "Caching eth_subscription info:\n    "
-                        f"cache_key={cache_key},\n    "
-                        f"request_info={request_info.__dict__}"
+                        "Caching eth_subscription info:\n"
+                        "    cache_key=%s,\n"
+                        "    request_info=%s",
+                        cache_key,
+                        request_info.__dict__,
                     )
                     self._request_processor._request_information_cache.cache(
                         cache_key, request_info

Diff for: web3/providers/ipc.py

@@ -196,15 +196,15 @@ def _make_request(self, request: bytes) -> RPCResponse:
     @handle_request_caching
     def make_request(self, method: RPCEndpoint, params: Any) -> RPCResponse:
         self.logger.debug(
-            f"Making request IPC. Path: {self.ipc_path}, Method: {method}"
+            "Making request IPC. Path: %s, Method: %s", self.ipc_path, method
         )
         request = self.encode_rpc_request(method, params)
         return self._make_request(request)
 
     def make_batch_request(
         self, requests: List[Tuple[RPCEndpoint, Any]]
     ) -> List[RPCResponse]:
-        self.logger.debug(f"Making batch request IPC. Path: {self.ipc_path}")
+        self.logger.debug("Making batch request IPC. Path: %s", self.ipc_path)
         request_data = self.encode_batch_rpc_request(requests)
         response = cast(List[RPCResponse], self._make_request(request_data))
         return sort_batch_response_by_response_ids(response)

Diff for: web3/providers/legacy_websocket.py

@@ -137,7 +137,7 @@ async def coro_make_request(self, request_data: bytes) -> RPCResponse:
     @handle_request_caching
     def make_request(self, method: RPCEndpoint, params: Any) -> RPCResponse:
         self.logger.debug(
-            f"Making request WebSocket. URI: {self.endpoint_uri}, " f"Method: {method}"
+            "Making request WebSocket. URI: %s, Method: %s", self.endpoint_uri, method
         )
         request_data = self.encode_rpc_request(method, params)
         future = asyncio.run_coroutine_threadsafe(
@@ -149,8 +149,8 @@ def make_batch_request(
         self, requests: List[Tuple[RPCEndpoint, Any]]
     ) -> List[RPCResponse]:
         self.logger.debug(
-            f"Making batch request WebSocket. URI: {self.endpoint_uri}, "
-            f"Methods: {requests}"
+            "Making batch request WebSocket. URI: %s, Methods: %s",
+            self.endpoint_uri, requests,
         )
         request_data = self.encode_batch_rpc_request(requests)
         future = asyncio.run_coroutine_threadsafe(

Diff for: web3/providers/persistent/persistent.py

@@ -171,19 +171,15 @@ async def connect(self) -> None:
         while _connection_attempts != self._max_connection_retries:
             try:
                 _connection_attempts += 1
-                self.logger.info(
-                    f"Connecting to: {self.get_endpoint_uri_or_ipc_path()}"
-                )
+                self.logger.info("Connecting to: %s", self.get_endpoint_uri_or_ipc_path())
                 await self._provider_specific_connect()
                 self._message_listener_task = asyncio.create_task(
                     self._message_listener()
                 )
                 self._message_listener_task.add_done_callback(
                     self._message_listener_callback
                 )
-                self.logger.info(
-                    f"Successfully connected to: {self.get_endpoint_uri_or_ipc_path()}"
-                )
+                self.logger.info("Successfully connected to: %s", self.get_endpoint_uri_or_ipc_path())
                 break
             except (WebSocketException, OSError) as e:
                 if _connection_attempts == self._max_connection_retries:
@@ -192,8 +188,9 @@ async def connect(self) -> None:
                         f"Retries exceeded max of {self._max_connection_retries}."
                     ) from e
                 self.logger.info(
-                    f"Could not connect to: {self.get_endpoint_uri_or_ipc_path()}. "
-                    f"Retrying in {round(_backoff_time, 1)} seconds.",
+                    "Could not connect to: %s. Retrying in %s seconds.",
+                    self.get_endpoint_uri_or_ipc_path(),
+                    round(_backoff_time, 1),
                     exc_info=True,
                 )
                 await asyncio.sleep(_backoff_time)
@@ -213,9 +210,7 @@ async def disconnect(self) -> None:
 
         await self._provider_specific_disconnect()
         self._request_processor.clear_caches()
-        self.logger.info(
-            f"Successfully disconnected from: {self.get_endpoint_uri_or_ipc_path()}"
-        )
+        self.logger.info("Successfully disconnected from: %s", self.get_endpoint_uri_or_ipc_path())
 
     @async_handle_send_caching
     async def send_request(self, method: RPCEndpoint, params: Any) -> RPCRequest:
@@ -332,9 +327,9 @@ def _raise_stray_errors_from_cache(self) -> None:
 
     async def _message_listener(self) -> None:
         self.logger.info(
-            f"{self.__class__.__qualname__} listener background task started. Storing "
+            "%s listener background task started. Storing "
             "all messages in appropriate request processor queues / caches to be "
-            "processed."
+            "processed.", self.__class__.__qualname__
         )
         while True:
             # the use of sleep(0) seems to be the most efficient way to yield control
@@ -358,8 +353,8 @@ async def _message_listener(self) -> None:
                 self._raise_stray_errors_from_cache()
             except PersistentConnectionClosedOK as e:
                 self.logger.info(
-                    "Message listener background task has ended gracefully: "
-                    f"{e.user_message}"
+                    "Message listener background task has ended gracefully: %s",
+                    e.user_message,
                 )
                 # trigger a return to end the listener task and initiate the callback fn
                 return
@@ -377,8 +372,8 @@ def _error_log_listener_task_exception(self, e: Exception) -> None:
         """
         self.logger.error(
             "Exception caught in listener, error logging and keeping "
-            "listener background task alive."
-            f"\n    error={e.__class__.__name__}: {e}"
+            "listener background task alive.\n    error=%s: %s",
+            e.__class__.__name__, e
         )
 
     def _handle_listener_task_exceptions(self) -> None:
@@ -410,9 +405,7 @@ async def _match_response_id_to_request_id() -> RPCResponse:
                 self._handle_listener_task_exceptions()
 
                 if request_cache_key in self._request_processor._request_response_cache:
-                    self.logger.debug(
-                        f"Popping response for id {request_id} from cache."
-                    )
+                    self.logger.debug("Popping response for id %s from cache.", request_id)
                     popped_response = await self._request_processor.pop_raw_response(
                         cache_key=request_cache_key,
                     )