Skip to content
This repository was archived by the owner on Jul 20, 2026. It is now read-only.

fix: make Scrapy framework logs visible through structlog - #87

Merged
damo-da merged 1 commit into
mainfrom
fix/scrapy-log-visibility
Jun 23, 2026
Merged

fix: make Scrapy framework logs visible through structlog#87
damo-da merged 1 commit into
mainfrom
fix/scrapy-log-visibility

Conversation

@damo-da

@damo-da damo-da commented Jun 23, 2026

Copy link
Copy Markdown
Member

Summary

Scrapy's own framework logs — Spider opened, Closing spider, Dumping Scrapy stats, and download/callback errors — were being silently dropped. This is why the 5-week scraper outage (#86) completed as green CronJobs with no visible sign of failure: the spiders' own self.logger messages showed, but Scrapy's lifecycle/stats/error logs did not.

Root cause

ngm/logging.py pinned each scrapy logger with the structlog handler and propagate=False. But Scrapy's startup runs dictConfig(DEFAULT_LOGGING), which strips the handlers back off the scrapy logger. Confirmed at runtime:

after project setup:        scrapy  propagate=False  handlers=1
after scrapy configure:     scrapy  propagate=False  handlers=0   <-- handler removed

With propagate=False and no handler, scrapy.core.engine (and children's) records had nowhere to go — INFO framework logs vanished entirely; only >=WARNING leaked via Python's lastResort in plain text.

Fix

  • Don't pin per-library handlers with propagate=False; let them propagate to the single root structlog handler (which dictConfig leaves intact).
  • Set the handler level (Scrapy resets the root level to NOTSET on init, so the handler must do the filtering).
  • LOG_ENABLED = False so Scrapy doesn't install a competing root handler (keeps output as clean structlog JSON).

Verification (throwaway DB, never prod)

Before: a crawl emitted only the asyncio selector line + deprecation warnings.
After:

{"event":"Overridden settings:..", "logger":"scrapy.crawler", ...}
{"event":"Spider opened", "logger":"scrapy.core.engine", ...}
{"event":"Closing spider (finished)", "logger":"scrapy.core.engine", ...}
{"event":"Dumping Scrapy stats:\n{...}", "logger":"scrapy.statscollectors", ...}

DEBUG noise (e.g. Crawled (200)) stays filtered at INFO. Crawl behaviour is unchanged — toggling LOG_ENABLED produced identical request scheduling.

Test plan

  • py_compile + black --check + ruff pass
  • Framework logs (Spider opened / stats / settings) now render via structlog
  • LOG_ENABLED on/off is crawl-neutral
  • After merge + image build, confirm a real CronJob logs the stats summary

🤖 Generated with Claude Code

Scrapy's framework logs (spider opened/closed, "Dumping Scrapy stats",
download/callback errors) were being silently dropped — which is how the
5-week scraper outage completed as green jobs with no sign of trouble.

Root cause: configure_logging() pinned the scrapy loggers with a handler and
propagate=False. But Scrapy's own startup runs dictConfig(DEFAULT_LOGGING),
which strips the handlers back off the `scrapy` logger. With propagate=False
those records then had nowhere to go (no handler, no propagation), so all of
Scrapy's INFO framework logs vanished (only >=WARNING leaked via lastResort
in plain text).

Fix: let library loggers propagate to the single root structlog handler
instead of pinning per-logger handlers; set the handler level (Scrapy resets
the root level to NOTSET, so the handler must filter); and set LOG_ENABLED
= False so Scrapy doesn't install a competing root handler.

Verified vs a throwaway DB: "Overridden settings", "Spider opened",
"Closing spider", and "Dumping Scrapy stats" now render as structlog JSON
(previously absent). Change is crawl-neutral (LOG_ENABLED on/off produce
identical crawl behaviour).

Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
@coderabbitai

coderabbitai Bot commented Jun 23, 2026

Copy link
Copy Markdown
Contributor

Warning

Review limit reached

@damo-da, we couldn't start this review because you've reached your PR review rate limit.

More reviews will be available in 29 minutes and 39 seconds. Learn how PR review limits work.

Your organization has used up its prepaid credits, and credit purchases are no longer available. Enable the review add-on in the billing tab to keep reviews running — you're only billed for reviews past your plan's rate limits ($0.25/file).

⌛ How to resolve this issue?

After more reviews become available, a review can be triggered using the @coderabbitai review command as a PR comment. Alternatively, push new commits to this PR.

To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based credits.

🚦 How do rate limits work?

CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan refill rate.

For paid Pro and Pro+ PR reviews, CodeRabbit uses rolling per-developer review limits. Reviews become available again as older review attempts age out of the rolling limit window.

Please see our Fair Usage Limits Policy for further information.

ℹ️ Review info
⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 3c380375-a9dc-43ad-8261-36a83d5e4d2c

📥 Commits

Reviewing files that changed from the base of the PR and between dd0da7c and d74e64c.

📒 Files selected for processing (2)
  • ngm/logging.py
  • ngm/ngscrape/settings.py
✨ Finishing Touches
🧪 Generate unit tests (beta)
  • Create PR with unit tests
  • Commit unit tests in branch fix/scrapy-log-visibility

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request refactors the logging configuration to ensure Scrapy's framework logs are correctly captured and routed through the root handler. It disables Scrapy's built-in logging and removes the explicit propagation block for several loggers. The review feedback suggests keeping noisy third-party loggers (such as boto3 and sqlalchemy) set to WARNING level to avoid console flooding during debug mode, and updating the settings comments to clarify that Scrapy's internal LOG_LEVEL setting is now ignored.

Important

The consumer version of Gemini Code Assist on GitHub is being sunset. Starting June 18, 2026, new organization installations will be blocked, and all code review activity will officially cease on July 17, 2026.
For more details on the timeline and next steps, please review the Help Documentation.

Comment thread ngm/logging.py
Comment on lines +64 to +69
# Route everything through the single root handler above. We deliberately do
# NOT pin per-library handlers with propagate=False: Scrapy's startup runs
# dictConfig(DEFAULT_LOGGING), which strips handlers off the `scrapy` logger.
# With propagate=False that left `scrapy` (and its children's) records with
# nowhere to go, silently dropping all of Scrapy's framework logs (spider
# open/close, stats, errors). Letting them propagate to root keeps them.

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

By removing the explicit logger configuration loop, third-party loggers like sqlalchemy.engine, boto3, botocore, and urllib3 will now propagate to the root logger and inherit its log level. When DEBUG mode is enabled, these libraries will flood the console with extremely verbose logs (such as every SQL query, AWS API request/response, and HTTP connection pool state), making local debugging very difficult and potentially leaking sensitive data in non-production environments.

We should explicitly set these noisy third-party loggers to WARNING level to keep the logs clean.

Suggested change
# Route everything through the single root handler above. We deliberately do
# NOT pin per-library handlers with propagate=False: Scrapy's startup runs
# dictConfig(DEFAULT_LOGGING), which strips handlers off the `scrapy` logger.
# With propagate=False that left `scrapy` (and its children's) records with
# nowhere to go, silently dropping all of Scrapy's framework logs (spider
# open/close, stats, errors). Letting them propagate to root keeps them.
# Route everything through the single root handler above. We deliberately do
# NOT pin per-library handlers with propagate=False: Scrapy's startup runs
# dictConfig(DEFAULT_LOGGING), which strips handlers off the `scrapy` logger.
# With propagate=False that left `scrapy` (and its children's) records with
# nowhere to go, silently dropping all of Scrapy's framework logs (spider
# open/close, stats, errors). Letting them propagate to root keeps them.
# Set sensible default levels for noisy third-party loggers
for noisy_logger in ["sqlalchemy.engine", "boto3", "botocore", "urllib3"]:
logging.getLogger(noisy_logger).setLevel(logging.WARNING)

Comment thread ngm/ngscrape/settings.py
Comment on lines +32 to +36
# Logging is owned by ngm.logging.setup() (structlog). Disable Scrapy's own
# logging install so it doesn't add a competing root handler; combined with
# routing scrapy loggers through the root structlog handler (see ngm/logging.py)
# this keeps Scrapy's framework logs (spider open/close, stats, errors) visible.
LOG_ENABLED = False

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Since LOG_ENABLED is set to False, Scrapy's internal logging configuration is completely bypassed. As a result, the LOG_LEVEL = "INFO" setting (on line 30) is now ignored by Scrapy. To avoid developer confusion, we should document this behavior in the comment so it's clear that log levels must be configured via environment variables (like LOG_LEVEL or DEBUG) instead of the Scrapy settings file.

Suggested change
# Logging is owned by ngm.logging.setup() (structlog). Disable Scrapy's own
# logging install so it doesn't add a competing root handler; combined with
# routing scrapy loggers through the root structlog handler (see ngm/logging.py)
# this keeps Scrapy's framework logs (spider open/close, stats, errors) visible.
LOG_ENABLED = False
# Logging is owned by ngm.logging.setup() (structlog). Disable Scrapy's own
# logging install so it doesn't add a competing root handler; combined with
# routing scrapy loggers through the root structlog handler (see ngm/logging.py)
# this keeps Scrapy's framework logs (spider open/close, stats, errors) visible.
# Note: This makes the Scrapy `LOG_LEVEL` setting ignored; log levels are instead
# controlled via the `LOG_LEVEL` or `DEBUG` environment variables.
LOG_ENABLED = False

@damo-da
damo-da merged commit 783a67f into main Jun 23, 2026
4 checks passed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant