RomanNum3ral
/
scrapy
mirror of https://github.com/scrapy/scrapy.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #5926 from GeorgeA92/periodic_log_2 

periodic_log: implemented as separate extension
This commit is contained in:
Andrey Rakhmatullin 2023-08-30 22:29:54 +04:00 committed by GitHub
parent 0e7fc60b89 fe02642980
commit cddb8c15d6
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 454 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

112
docs/topics/extensions.rst
View File

@ -396,3 +396,115 @@ For more info see `Debugging in Python`_.
This extension only works on POSIX-compliant platforms (i.e. not Windows).
.. _Debugging in Python: https://pythonconquerstheuniverse.wordpress.com/2009/09/10/debugging-in-python/
Periodic log extension
~~~~~~~~~~~~~~~~~~~~~~
.. class:: PeriodicLog
This extension periodically logs rich stat data as a JSON object::
2023-08-04 02:30:57 [scrapy.extensions.logstats] INFO: Crawled 976 pages (at 162 pages/min), scraped 925 items (at 161 items/min)
2023-08-04 02:30:57 [scrapy.extensions.periodic_log] INFO: {
"delta": {
"downloader/request_bytes": 55582,
"downloader/request_count": 162,
"downloader/request_method_count/GET": 162,
"downloader/response_bytes": 618133,
"downloader/response_count": 162,
"downloader/response_status_count/200": 162,
"item_scraped_count": 161
},
"stats": {
"downloader/request_bytes": 338243,
"downloader/request_count": 992,
"downloader/request_method_count/GET": 992,
"downloader/response_bytes": 3836736,
"downloader/response_count": 976,
"downloader/response_status_count/200": 976,
"item_scraped_count": 925,
"log_count/INFO": 21,
"log_count/WARNING": 1,
"scheduler/dequeued": 992,
"scheduler/dequeued/memory": 992,
"scheduler/enqueued": 1050,
"scheduler/enqueued/memory": 1050
},
"time": {
"elapsed": 360.008903,
"log_interval": 60.0,
"log_interval_real": 60.006694,
"start_time": "2023-08-03 23:24:57",
"utcnow": "2023-08-03 23:30:57"
}
}
This extension logs the following configurable sections:
- ``"delta"`` shows how some numeric stats have changed since the last stats
log message.
The :setting:`PERIODIC_LOG_DELTA` setting determines the target stats. They
must have ``int`` or ``float`` values.
- ``"stats"`` shows the current value of some stats.
The :setting:`PERIODIC_LOG_STATS` setting determines the target stats.
- ``"time"`` shows detailed timing data.
The :setting:`PERIODIC_LOG_TIMING_ENABLED` setting determines whether or
not to show this section.
This extension logs data at the start, then on a fixed time interval
configurable through the :setting:`LOGSTATS_INTERVAL` setting, and finally
right before the crawl ends.
Example extension configuration:
.. code-block:: python
custom_settings = {
"LOG_LEVEL": "INFO",
"PERIODIC_LOG_STATS": {
"include": ["downloader/", "scheduler/", "log_count/", "item_scraped_count/"],
},
"PERIODIC_LOG_DELTA": {"include": ["downloader/"]},
"PERIODIC_LOG_TIMING_ENABLED": True,
"EXTENSIONS": {
"scrapy.extensions.periodic_log.PeriodicLog": 0,
},
}
.. setting:: PERIODIC_LOG_DELTA
PERIODIC_LOG_DELTA
""""""""""""""""""
Default: ``None``
* ``"PERIODIC_LOG_DELTA": True`` - show deltas for all ``int`` and ``float`` stat values.
* ``"PERIODIC_LOG_DELTA": {"include": ["downloader/", "scheduler/"]}`` - show deltas for stats with names containing any configured substring.
* ``"PERIODIC_LOG_DELTA": {"exclude": ["downloader/"]}`` - show deltas for all stats with names not containing any configured substring.
.. setting:: PERIODIC_LOG_STATS
PERIODIC_LOG_STATS
""""""""""""""""""
Default: ``None``
* ``"PERIODIC_LOG_STATS": True`` - show the current value of all stats.
* ``"PERIODIC_LOG_STATS": {"include": ["downloader/", "scheduler/"]}`` - show current values for stats with names containing any configured substring.
* ``"PERIODIC_LOG_STATS": {"exclude": ["downloader/"]}`` - show current values for all stats with names not containing any configured substring.
.. setting:: PERIODIC_LOG_TIMING_ENABLED
PERIODIC_LOG_TIMING_ENABLED
"""""""""""""""""""""""""""
Default: ``False``
``True`` enables logging of timing data (i.e. the ``"time"`` section).

140
scrapy/extensions/periodic_log.py Normal file
View File

@ -0,0 +1,140 @@
import logging
from datetime import datetime, timezone
from twisted.internet import task
from scrapy import signals
from scrapy.exceptions import NotConfigured
from scrapy.utils.serialize import ScrapyJSONEncoder
logger = logging.getLogger(__name__)
class PeriodicLog:
"""Log basic scraping stats periodically"""
def __init__(
self,
stats,
interval=60.0,
ext_stats={},
ext_delta={},
ext_timing_enabled=False,
):
self.stats = stats
self.interval = interval
self.multiplier = 60.0 / self.interval
self.task = None
self.encoder = ScrapyJSONEncoder(sort_keys=True, indent=4)
self.ext_stats_enabled = bool(ext_stats)
self.ext_stats_include = ext_stats.get("include", [])
self.ext_stats_exclude = ext_stats.get("exclude", [])
self.ext_delta_enabled = bool(ext_delta)
self.ext_delta_include = ext_delta.get("include", [])
self.ext_delta_exclude = ext_delta.get("exclude", [])
self.ext_timing_enabled = ext_timing_enabled
@classmethod
def from_crawler(cls, crawler):
interval = crawler.settings.getfloat("LOGSTATS_INTERVAL")
if not interval:
raise NotConfigured
try:
ext_stats = crawler.settings.getdict("PERIODIC_LOG_STATS")
except (TypeError, ValueError):
ext_stats = (
{"enabled": True}
if crawler.settings.getbool("PERIODIC_LOG_STATS")
else None
)
try:
ext_delta = crawler.settings.getdict("PERIODIC_LOG_DELTA")
except (TypeError, ValueError):
ext_delta = (
{"enabled": True}
if crawler.settings.getbool("PERIODIC_LOG_DELTA")
else None
)
ext_timing_enabled = crawler.settings.getbool(
"PERIODIC_LOG_TIMING_ENABLED", False
)
if not (ext_stats or ext_delta or ext_timing_enabled):
raise NotConfigured
o = cls(
crawler.stats,
interval,
ext_stats,
ext_delta,
ext_timing_enabled,
)
crawler.signals.connect(o.spider_opened, signal=signals.spider_opened)
crawler.signals.connect(o.spider_closed, signal=signals.spider_closed)
return o
def spider_opened(self, spider):
self.time_prev = datetime.now(tz=timezone.utc)
self.delta_prev = {}
self.stats_prev = {}
self.task = task.LoopingCall(self.log)
self.task.start(self.interval)
def log(self):
data = {}
if self.ext_timing_enabled:
data.update(self.log_timing())
if self.ext_delta_enabled:
data.update(self.log_delta())
if self.ext_stats_enabled:
data.update(self.log_crawler_stats())
logger.info(self.encoder.encode(data))
def log_delta(self):
num_stats = {
k: v
for k, v in self.stats._stats.items()
if isinstance(v, (int, float))
and self.param_allowed(k, self.ext_delta_include, self.ext_delta_exclude)
}
delta = {k: v - self.delta_prev.get(k, 0) for k, v in num_stats.items()}
self.delta_prev = num_stats
return {"delta": delta}
def log_timing(self):
now = datetime.now(tz=timezone.utc)
time = {
"log_interval": self.interval,
"start_time": self.stats._stats["start_time"],
"utcnow": now,
"log_interval_real": (now - self.time_prev).total_seconds(),
"elapsed": (now - self.stats._stats["start_time"]).total_seconds(),
}
self.time_prev = now
return {"time": time}
def log_crawler_stats(self):
stats = {
k: v
for k, v in self.stats._stats.items()
if self.param_allowed(k, self.ext_stats_include, self.ext_stats_exclude)
}
return {"stats": stats}
def param_allowed(self, stat_name, include, exclude):
if not include and not exclude:
return True
for p in exclude:
if p in stat_name:
return False
if exclude and not include:
return True
for p in include:
if p in stat_name:
return True
return False
def spider_closed(self, spider, reason):
self.log()
if self.task and self.task.running:
self.task.stop()

4
scrapy/settings/default_settings.py
View File

@ -242,6 +242,10 @@ METAREFRESH_MAXDELAY = 100
NEWSPIDER_MODULE = ""
PERIODIC_LOG_DELTA = None
PERIODIC_LOG_STATS = None
PERIODIC_LOG_TIMING_ENABLED = False
RANDOMIZE_DOWNLOAD_DELAY = True
REACTOR_THREADPOOL_MAXSIZE = 10

198
tests/test_extension_periodic_log.py Normal file
View File

@ -0,0 +1,198 @@
import datetime
import typing
import unittest
from scrapy.crawler import Crawler
from scrapy.extensions.periodic_log import PeriodicLog
from .spiders import MetaSpider
stats_dump_1 = {
"log_count/INFO": 10,
"log_count/WARNING": 1,
"start_time": datetime.datetime(2023, 6, 16, 8, 59, 18, 993170),
"scheduler/enqueued/memory": 190,
"scheduler/enqueued": 190,
"scheduler/dequeued/memory": 166,
"scheduler/dequeued": 166,
"downloader/request_count": 166,
"downloader/request_method_count/GET": 166,
"downloader/request_bytes": 56803,
"downloader/response_count": 150,
"downloader/response_status_count/200": 150,
"downloader/response_bytes": 595698,
"httpcompression/response_bytes": 3186068,
"httpcompression/response_count": 150,
"response_received_count": 150,
"request_depth_max": 9,
"dupefilter/filtered": 180,
"item_scraped_count": 140,
}
stats_dump_2 = {
"log_count/INFO": 12,
"log_count/WARNING": 1,
"start_time": datetime.datetime(2023, 6, 16, 8, 59, 18, 993170),
"scheduler/enqueued/memory": 337,
"scheduler/enqueued": 337,
"scheduler/dequeued/memory": 280,
"scheduler/dequeued": 280,
"downloader/request_count": 280,
"downloader/request_method_count/GET": 280,
"downloader/request_bytes": 95754,
"downloader/response_count": 264,
"downloader/response_status_count/200": 264,
"downloader/response_bytes": 1046274,
"httpcompression/response_bytes": 5614484,
"httpcompression/response_count": 264,
"response_received_count": 264,
"request_depth_max": 16,
"dupefilter/filtered": 320,
"item_scraped_count": 248,
}
class TestExtPeriodicLog(PeriodicLog):
def set_a(self):
self.stats._stats = stats_dump_1
def set_b(self):
self.stats._stats = stats_dump_2
def extension(settings=None):
return TestExtPeriodicLog.from_crawler(
Crawler(
MetaSpider,
settings=settings,
)
)
class TestPeriodicLog(unittest.TestCase):
def test_extension_enabled(self):
# Expected that settings for this extension loaded succesfully
# And on certain conditions - extension raising NotConfigured
# "PERIODIC_LOG_STATS": True -> set to {"enabled": True}
# due to TypeError exception from settings.getdict
assert extension({"PERIODIC_LOG_STATS": True, "LOGSTATS_INTERVAL": 60})
# "PERIODIC_LOG_STATS": "True" -> set to {"enabled": True}
# due to JSONDecodeError(ValueError) exception from settings.getdict
assert extension({"PERIODIC_LOG_STATS": "True", "LOGSTATS_INTERVAL": 60})
# The ame for PERIODIC_LOG_DELTA:
assert extension({"PERIODIC_LOG_DELTA": True, "LOGSTATS_INTERVAL": 60})
assert extension({"PERIODIC_LOG_DELTA": "True", "LOGSTATS_INTERVAL": 60})
def test_log_delta(self):
def emulate(settings=None):
spider = MetaSpider()
ext = extension(settings)
ext.spider_opened(spider)
ext.set_a()
a = ext.log_delta()
ext.set_a()
b = ext.log_delta()
ext.spider_closed(spider, reason="finished")
return ext, a, b
def check(settings: dict, condition: typing.Callable):
ext, a, b = emulate(settings)
assert list(a["delta"].keys()) == [
k for k, v in ext.stats._stats.items() if condition(k, v)
]
assert list(b["delta"].keys()) == [
k for k, v in ext.stats._stats.items() if condition(k, v)
]
# Including all
check({"PERIODIC_LOG_DELTA": True}, lambda k, v: isinstance(v, (int, float)))
# include:
check(
{"PERIODIC_LOG_DELTA": {"include": ["downloader/"]}},
lambda k, v: isinstance(v, (int, float)) and "downloader/" in k,
)
# include multiple
check(
{"PERIODIC_LOG_DELTA": {"include": ["downloader/", "scheduler/"]}},
lambda k, v: isinstance(v, (int, float))
and ("downloader/" in k or "scheduler/" in k),
)
# exclude
check(
{"PERIODIC_LOG_DELTA": {"exclude": ["downloader/"]}},
lambda k, v: isinstance(v, (int, float)) and "downloader/" not in k,
)
# exclude multiple
check(
{"PERIODIC_LOG_DELTA": {"exclude": ["downloader/", "scheduler/"]}},
lambda k, v: isinstance(v, (int, float))
and ("downloader/" not in k and "scheduler/" not in k),
)
# include exclude combined
check(
{"PERIODIC_LOG_DELTA": {"include": ["downloader/"], "exclude": ["bytes"]}},
lambda k, v: isinstance(v, (int, float))
and ("downloader/" in k and "bytes" not in k),
)
def test_log_stats(self):
def emulate(settings=None):
spider = MetaSpider()
ext = extension(settings)
ext.spider_opened(spider)
ext.set_a()
a = ext.log_crawler_stats()
ext.set_a()
b = ext.log_crawler_stats()
ext.spider_closed(spider, reason="finished")
return ext, a, b
def check(settings: dict, condition: typing.Callable):
ext, a, b = emulate(settings)
assert list(a["stats"].keys()) == [
k for k, v in ext.stats._stats.items() if condition(k, v)
]
assert list(b["stats"].keys()) == [
k for k, v in ext.stats._stats.items() if condition(k, v)
]
# Including all
check({"PERIODIC_LOG_STATS": True}, lambda k, v: True)
# include:
check(
{"PERIODIC_LOG_STATS": {"include": ["downloader/"]}},
lambda k, v: "downloader/" in k,
)
# include multiple
check(
{"PERIODIC_LOG_STATS": {"include": ["downloader/", "scheduler/"]}},
lambda k, v: "downloader/" in k or "scheduler/" in k,
)
# exclude
check(
{"PERIODIC_LOG_STATS": {"exclude": ["downloader/"]}},
lambda k, v: "downloader/" not in k,
)
# exclude multiple
check(
{"PERIODIC_LOG_STATS": {"exclude": ["downloader/", "scheduler/"]}},
lambda k, v: "downloader/" not in k and "scheduler/" not in k,
)
# include exclude combined
check(
{"PERIODIC_LOG_STATS": {"include": ["downloader/"], "exclude": ["bytes"]}},
lambda k, v: "downloader/" in k and "bytes" not in k,
)
#