refactor!: polish logging across the codebase (#1005)

### Description

Logging polish across the whole codebase:
- Fix typos & grammar
- Unify logger usage
- Remove useless debug logs
- Rebalance a few log levels

### Breaking changes

The typed public API is unchanged, but log output changes in a few minor
ways:

- `error` -> `warning` for the local no-op `metamorph()` / `reboot()` /
`add_webhook()` messages and the Scrapy scheduler skip.
- `info` -> `debug` for the "unknown platform event" message.
- Internal logger names changed from `apify` to `apify.<module>` for the
charging, proxy, and events modules.

Author: vdusek

docs/04_upgrading/upgrading_to_v4.md

@@ -244,4 +244,17 @@ yield scrapy.Request(url, meta={'since': datetime(2024, 1, 1)})
 
 # After (v4): store a JSON-serializable value.
 yield scrapy.Request(url, meta={'since': datetime(2024, 1, 1).isoformat()})
-```Pickle
+```
+
+## Logging changes
+
+The typed public API is unchanged, so your code keeps working without edits. Only log output changes. Adjust your setup if you parse logs, route them by logger name, or assert on log records, for example in tests.
+
+### Rebalanced log levels
+
+- The local no-op messages from `Actor.metamorph()`, `Actor.reboot()`, and `Actor.add_webhook()`, logged when the Actor runs outside the Apify platform, are now `warning` instead of `error`. The Scrapy scheduler message for a request that can't be converted to an Apify request changed the same way.
+- The "unknown platform event" message is now `debug` instead of `info`.
+
+### Module-qualified logger names
+
+The charging, proxy, and events modules now log under their own child loggers (`apify._charging`, `apify._proxy_configuration`, and `apify.events._apify_event_manager`) instead of the generic `apify` logger. These child loggers still propagate to `apify`, so a handler attached to `apify` keeps receiving their records. Update only configuration that targets the exact `apify` logger name for these messages.

src/apify/_actor.py

@@ -1162,7 +1162,7 @@ async def metamorph(
             custom_after_sleep: How long to sleep for after the metamorph, to wait for the container to be stopped.
         """
         if not self.is_at_home():
-            self.log.error('Actor.metamorph() is only supported when running on the Apify platform.')
+            self.log.warning('Actor.metamorph() is only supported when running on the Apify platform.')
             return
 
         if custom_after_sleep is None:
@@ -1172,6 +1172,7 @@ async def metamorph(
         if not self.configuration.actor_run_id:
             raise RuntimeError('actor_run_id cannot be None when running on the Apify platform.')
 
+        self.log.debug(f'Metamorphing the Actor run into target Actor {target_actor_id!r}.')
         await self.apify_client.run(self.configuration.actor_run_id).metamorph(
             target_actor_id=target_actor_id,
             run_input=run_input,
@@ -1198,7 +1199,7 @@ async def reboot(
             custom_after_sleep: How long to sleep for after the reboot, to wait for the container to be stopped.
         """
         if not self.is_at_home():
-            self.log.error('Actor.reboot() is only supported when running on the Apify platform.')
+            self.log.warning('Actor.reboot() is only supported when running on the Apify platform.')
             return
 
         if self._is_rebooting:
@@ -1243,6 +1244,7 @@ async def safe_dispatch(listener: Any, data: Any) -> None:
             except TimeoutError:
                 self.log.warning('Pre-reboot event listeners did not finish within timeout; proceeding with reboot')
 
+            self.log.debug('Rebooting the Actor run.')
             await self.apify_client.run(self.configuration.actor_run_id).reboot()
         except BaseException:
             # Reset the flag so that a failed or cancelled reboot can be retried.
@@ -1277,7 +1279,7 @@ async def add_webhook(self, webhook: Webhook, *, idempotency_key: str | None = N
             )
 
         if not self.is_at_home():
-            self.log.error('Actor.add_webhook() is only supported when running on the Apify platform.')
+            self.log.warning('Actor.add_webhook() is only supported when running on the Apify platform.')
             return
 
         # If is_at_home() is True, config.actor_run_id is always set
@@ -1454,9 +1456,9 @@ def _get_remaining_time(self) -> timedelta | None:
             return max(self.configuration.timeout_at - datetime.now(tz=UTC), timedelta(0))
 
         self.log.warning(
-            'Using `inherit` argument is only possible when the Actor'
-            ' is running on the Apify platform and when the timeout for the Actor run is set. '
-            f'{self.is_at_home()=}, {self.configuration.timeout_at=}'
+            'Using the `inherit` argument is only possible when the Actor is running on the Apify platform and '
+            'the timeout for the Actor run is set.',
+            extra={'is_at_home': self.is_at_home(), 'timeout_at': self.configuration.timeout_at},
         )
         return None
 

src/apify/_charging.py

@@ -5,6 +5,7 @@
 from dataclasses import dataclass
 from datetime import UTC, datetime
 from decimal import Decimal
+from logging import getLogger
 from typing import TYPE_CHECKING, Literal, Protocol, TypedDict
 
 from pydantic import ConfigDict
@@ -19,7 +20,6 @@
 from apify_client._models import PricingPerEvent as ClientPricingPerEvent
 
 from apify._utils import ReentrantLock, docs_group, ensure_context
-from apify.log import logger
 from apify.storages import Dataset
 
 if TYPE_CHECKING:
@@ -29,6 +29,8 @@
 
     from apify._configuration import Configuration
 
+logger = getLogger(__name__)
+
 charging_manager_ctx: ContextVar[ChargingManager | None] = ContextVar('charging_manager_ctx', default=None)
 """Holds the current `ChargingManager` instance, if any.
 
@@ -450,6 +452,7 @@ async def charge(self, event_name: str, *, count: int = 1) -> ChargeResult:
                     pass
                 elif event_name in self._pricing_info:
                     await self._client.run(self._actor_run_id).charge(event_name, count=charged_count)
+                    logger.debug(f"Charged {charged_count} occurrence(s) of event '{event_name}'.")
                 elif event_name in self._tier_priced_events:
                     logger.warning(
                         f"Event '{event_name}' is tier-priced and is not chargeable via the pay-per-event API."

src/apify/_proxy_configuration.py

@@ -3,6 +3,7 @@
 import json
 import re
 from dataclasses import dataclass, field
+from logging import getLogger
 from re import Pattern
 from typing import TYPE_CHECKING, Any
 
@@ -22,13 +23,14 @@
 from apify._configuration import Configuration
 from apify._consts import ApifyEnvVars
 from apify._utils import docs_group
-from apify.log import logger
 
 if TYPE_CHECKING:
     from apify_client import ApifyClientAsync
 
     from apify import Request
 
+logger = getLogger(__name__)
+
 APIFY_PROXY_VALUE_REGEX = re.compile(r'^[\w._~]+$')
 COUNTRY_CODE_REGEX = re.compile(r'^[A-Z]{2}$')
 # ISO 3166-2 subdivision codes are 1-3 uppercase alphanumeric characters, e.g. 'CA', 'NSW', '9' (Wien, AT-9)

src/apify/events/_apify_event_manager.py

@@ -3,6 +3,7 @@
 import asyncio
 import contextlib
 import time
+from logging import getLogger
 from typing import TYPE_CHECKING, Annotated, Self
 
 import websockets.asyncio.client
@@ -17,7 +18,6 @@
 
 from apify._utils import docs_group
 from apify.events._types import DeprecatedEvent, EventMessage, SystemInfoEventData, UnknownEvent
-from apify.log import logger
 
 if TYPE_CHECKING:
     from collections.abc import Generator
@@ -28,6 +28,8 @@
     from apify._configuration import Configuration
 
 
+logger = getLogger(__name__)
+
 event_data_adapter = TypeAdapter[EventMessage | DeprecatedEvent | UnknownEvent](
     Annotated[EventMessage, Discriminator('name')] | DeprecatedEvent | UnknownEvent
 )
@@ -195,7 +197,7 @@ async def _handle_platform_message(self, message: str | bytes) -> None:
                 return
 
             if isinstance(parsed_message, UnknownEvent):
-                logger.info(
+                logger.debug(
                     f'Unknown message received: event_name={parsed_message.name}, event_data={parsed_message.data}'
                 )
                 return

src/apify/scrapy/middlewares/apify_proxy.py

@@ -72,7 +72,6 @@ async def process_request(self, request: Request) -> None:
         Raises:
             ValueError: If username and password are not provided in the proxy URL.
         """
-        Actor.log.debug(f'ApifyHttpProxyMiddleware.process_request: request={request}')
         url = await self._get_new_proxy_url()
 
         if not (url.username and url.password):
@@ -82,8 +81,6 @@ async def process_request(self, request: Request) -> None:
         basic_auth_header = get_basic_auth_header(url.username, url.password)
         request.headers[b'Proxy-Authorization'] = basic_auth_header
 
-        Actor.log.debug(f'ApifyHttpProxyMiddleware.process_request: updated request.meta={request.meta}')
-
     def process_exception(
         self,
         request: Request,
@@ -100,10 +97,6 @@ def process_exception(
             process_exception() methods of installed middleware, until no middleware is left and the default
             exception handling kicks in.
         """
-        Actor.log.debug(
-            f'ApifyHttpProxyMiddleware.process_exception: request={request}, exception={exception}',
-        )
-
         if isinstance(exception, TunnelError):
             Actor.log.warning(
                 f'ApifyHttpProxyMiddleware: TunnelError occurred for request="{request}", '

src/apify/scrapy/pipelines/actor_dataset_push.py

@@ -1,6 +1,5 @@
 from __future__ import annotations
 
-from logging import getLogger
 from typing import TYPE_CHECKING
 
 from itemadapter.adapter import ItemAdapter
@@ -10,8 +9,6 @@
 if TYPE_CHECKING:
     from scrapy import Item
 
-logger = getLogger(__name__)
-
 
 class ActorDatasetPushPipeline:
     """A Scrapy pipeline for pushing items to an Actor's default dataset.
@@ -25,6 +22,5 @@ async def process_item(
     ) -> Item:
         """Pushes the provided Scrapy item to the Actor's default dataset."""
         item_dict = ItemAdapter(item).asdict()
-        logger.debug(f'Pushing item={item_dict} to the dataset.')
         await Actor.push_data(item_dict)
         return item

src/apify/scrapy/requests.py

@@ -61,8 +61,6 @@ def to_apify_request(scrapy_request: ScrapyRequest, spider: Spider) -> ApifyRequ
         logger.warning('Failed to convert to Apify request: Scrapy request must be a ScrapyRequest instance.')
         return None
 
-    logger.debug(f'to_apify_request was called (scrapy_request={scrapy_request})...')
-
     # Configuration to behave as similarly as possible to Scrapy's default RFPDupeFilter.
     #
     # The body is stored twice on purpose: as `payload` (used for the extended unique key) and inside the serialized
@@ -150,7 +148,6 @@ def to_apify_request(scrapy_request: ScrapyRequest, spider: Spider) -> ApifyRequ
     # a second base64 layer would only add ~33% overhead on the enqueue path.
     apify_request.user_data['scrapy_request'] = scrapy_request_json
 
-    logger.debug(f'scrapy_request was converted to the apify_request={apify_request}')
     return apify_request
 
 
@@ -171,14 +168,10 @@ def to_scrapy_request(apify_request: ApifyRequest, spider: Spider) -> ScrapyRequ
     if not isinstance(cast('Any', apify_request), ApifyRequest):
         raise TypeError('apify_request must be an apify.Request instance')
 
-    logger.debug(f'to_scrapy_request was called (apify_request={apify_request})...')
-
     # If the apify_request comes from the Scrapy
     if 'scrapy_request' in apify_request.user_data:
         # Deserialize the Scrapy ScrapyRequest from the apify_request by parsing the stored JSON and reconstructing
         # the Scrapy ScrapyRequest object from its dictionary representation.
-        logger.debug('Restoring the Scrapy ScrapyRequest from the apify_request...')
-
         scrapy_request_json = apify_request.user_data['scrapy_request']
         if not isinstance(scrapy_request_json, str):
             raise TypeError('the stored scrapy_request must be a string')
@@ -194,8 +187,6 @@ def to_scrapy_request(apify_request: ApifyRequest, spider: Spider) -> ScrapyRequ
         if not isinstance(scrapy_request, ScrapyRequest):
             raise TypeError('scrapy_request must be an instance of the ScrapyRequest class')
 
-        logger.debug(f'Scrapy ScrapyRequest successfully reconstructed (scrapy_request={scrapy_request})...')
-
         # Update the meta field with the meta field from the apify_request
         meta = scrapy_request.meta or {}
         meta.update({'apify_request_unique_key': apify_request.unique_key})
@@ -204,8 +195,6 @@ def to_scrapy_request(apify_request: ApifyRequest, spider: Spider) -> ScrapyRequ
 
     # If the apify_request comes directly from the Scrapy, typically start URLs.
     else:
-        logger.debug('Gonna create a new Scrapy ScrapyRequest (cannot be restored)')
-
         scrapy_request = ScrapyRequest(
             url=apify_request.url,
             method=apify_request.method,
@@ -222,5 +211,4 @@ def to_scrapy_request(apify_request: ApifyRequest, spider: Spider) -> ScrapyRequ
     if apify_request.user_data:
         scrapy_request.meta['userData'] = apify_request.user_data
 
-    logger.debug(f'an apify_request was converted to the scrapy_request={scrapy_request}')
     return scrapy_request

src/apify/scrapy/scheduler.py

@@ -134,17 +134,14 @@ def enqueue_request(self, request: Request) -> bool:
         Returns:
             True if the request was successfully enqueued, False otherwise.
         """
-        logger.debug(f'ApifyScheduler.enqueue_request was called (scrapy_request={request})...')
-
         if not isinstance(self.spider, Spider):
             raise TypeError('self.spider must be an instance of the Spider class')
 
         apify_request = to_apify_request(request, spider=self.spider)
         if apify_request is None:
-            logger.error(f'Request {request} could not be converted to Apify request.')
+            logger.warning(f'Request {request} could not be converted to Apify request; skipping it.')
             return False
 
-        logger.debug(f'Converted to apify_request: {apify_request}')
         if not isinstance(self._rq, RequestQueue):
             raise TypeError('self._rq must be an instance of the RequestQueue class')
 
@@ -156,7 +153,6 @@ def enqueue_request(self, request: Request) -> bool:
             logger.exception('Failed to enqueue the request to the request queue.')
             raise
 
-        logger.debug(f'rq.add_request result: {result}')
         return not bool(result.was_already_present)
 
     def next_request(self) -> Request | None:
@@ -165,7 +161,6 @@ def next_request(self) -> Request | None:
         Returns:
             The next request, or None if there are no more requests.
         """
-        logger.debug('next_request called...')
         if not isinstance(self._rq, RequestQueue):
             raise TypeError('self._rq must be an instance of the RequestQueue class')
 
@@ -177,7 +172,6 @@ def next_request(self) -> Request | None:
             logger.exception('Failed to fetch the next request from the request queue.')
             raise
 
-        logger.debug(f'Fetched apify_request: {apify_request}')
         if apify_request is None:
             return None
 
@@ -206,5 +200,4 @@ def next_request(self) -> Request | None:
         if scrapy_request is None:
             return None
 
-        logger.debug(f'Converted to scrapy_request: {scrapy_request}')
         return scrapy_request

src/apify/storage_clients/_apify/_alias_resolving.py

@@ -1,6 +1,5 @@
 from __future__ import annotations
 
-import logging
 from asyncio import Lock
 from functools import cached_property
 from logging import getLogger
@@ -225,7 +224,7 @@ async def store_mapping(self, storage_id: str) -> None:
         alias_map[self._storage_key] = storage_id
 
         if not self._configuration.is_at_home:
-            logging.getLogger(__name__).debug(
+            logger.debug(
                 'AliasResolver storage limited retention is only supported on Apify platform. Storage is not exported.'
             )
             return