feat(package)!: Emit structured JSON logs.#2339
Conversation
|
Note Reviews pausedIt looks like this branch is under active development. To avoid overwhelming you with review comments due to an influx of new commits, CodeRabbit has automatically paused this review. You can configure this behavior by changing the Use the following commands to manage reviews:
Use the checkboxes below for quick actions:
Walkthrough
ChangesJSON structured logging with Celery integration
Logging documentation and guidance
Estimated code review effort🎯 3 (Moderate) | ⏱️ ~20 minutes 🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches🧪 Generate unit tests (beta)
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. Comment |
rishikeshdevsot
changed the title
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@components/clp-py-utils/clp_py_utils/clp_logging.py`:
- Line 65: The _TIMESTAMP_PROCESSOR call at line 65 uses TimeStamper which
captures the current time when the formatter runs, causing queued or delayed log
records to get incorrect timestamps. Instead of calling _TIMESTAMP_PROCESSOR
with TimeStamper, directly build the ISO timestamp from record.created, which
Python's logging module sets when the LogRecord is created. This ensures the
timestamp reflects when the event occurred, not when the formatter executed.
In `@components/clp-py-utils/pyproject.toml`:
- Line 18: The structlog dependency version in the pyproject.toml file is set to
a floor of 25.5.0, but the code only uses contextvars helpers, JSONRenderer, and
TimeStamper which are all available in much earlier versions. Lower the
structlog version requirement to the minimum version that actually provides all
the necessary features (21.2.0 based on the structlog documentation) to avoid
creating unnecessary resolver conflicts for consumers who may have an older
compatible version already pinned.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: ASSERTIVE
Plan: Pro
Run ID: 46d8f17a-4407-4092-a777-2d23829890fa
⛔ Files ignored due to path filters (1)
components/clp-py-utils/uv.lockis excluded by!**/*.lock
📒 Files selected for processing (2)
components/clp-py-utils/clp_py_utils/clp_logging.pycomponents/clp-py-utils/pyproject.toml
| event_dict["stack"] = self.formatStack(record.stack_info) | ||
|
|
||
| merge_contextvars(None, method_name, event_dict) | ||
| _TIMESTAMP_PROCESSOR(None, method_name, event_dict) |
There was a problem hiding this comment.
🧩 Analysis chain
🏁 Script executed:
cat -n components/clp-py-utils/clp_py_utils/clp_logging.py | head -100Repository: y-scope/clp
Length of output: 3862
🌐 Web query:
Python logging LogRecord.created attribute timestamp
💡 Result:
In Python's logging module, the LogRecord.created attribute represents the time at which the LogRecord was created [1][2]. Its value is a float expressing the time in seconds since the epoch [1][3]. In modern versions of Python, this value is derived from time.time_ns divided by 1e9 to ensure precision [1][2][3]. In earlier versions of Python, it was typically generated using time.time [3]. When using the logging module's format strings, you can include this timestamp using the %(created)f placeholder [1][2]. Key related attributes also include: - %(asctime)s: A human-readable representation of the creation time [1][2]. - %(msecs)d: The millisecond portion of the creation time [1][2]. - %(relativeCreated)d: The time in milliseconds when the record was created, relative to when the logging module was first loaded [1][2].
Citations:
- 1: https://docs.python.org/3/_sources/library/logging.rst.txt
- 2: https://github.com/python/cpython/blob/main/Doc/library/logging.rst
- 3: fedora-python/cpython@1316692
🌐 Web query:
structlog TimeStamper processor when does it capture timestamp
💡 Result:
The structlog TimeStamper processor captures the timestamp at the exact moment the processor function is executed within the log processing pipeline [1][2]. When you use TimeStamper in your processor chain, it functions as a callable that accepts the event dictionary (event_dict). When that processor is called by structlog during the logging process, it invokes the underlying time-fetching mechanism (such as time.time or datetime.datetime.now) to retrieve the current time and immediately injects it into the event dictionary under the configured key [1][2]. Because processors are executed sequentially in the order they appear in your structlog configuration, the timestamp is captured at the specific stage in the pipeline where the TimeStamper is placed [1][2]. If it is the first processor, it captures the time immediately when the log call is initiated; if placed later, it captures the time only after preceding processors have finished their work.
Citations:
- 1: https://www.structlog.org/en/25.2.0/_modules/structlog/processors.html
- 2: https://www.structlog.org/en/24.2.0/_modules/structlog/processors.html
🏁 Script executed:
python3 << 'PY'
from datetime import datetime, timezone
# Test with a sample timestamp that includes fractional seconds
test_created = 1234567890.123456
# The proposed conversion
dt = datetime.fromtimestamp(test_created, timezone.utc)
iso_str = dt.isoformat().replace("+00:00", "Z")
print(f"Input timestamp: {test_created}")
print(f"Converted ISO string: {iso_str}")
# Verify it matches the expected format
import re
iso_pattern = r'^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z$'
if re.match(iso_pattern, iso_str):
print("✓ Format matches expected ISO 8601 with Z suffix")
else:
print("✗ Format does not match expected ISO 8601")
PYRepository: y-scope/clp
Length of output: 189
🏁 Script executed:
# Check if datetime/timezone are already imported
grep -n "from datetime import\|import datetime" components/clp-py-utils/clp_py_utils/clp_logging.py
# Search for other TimeStamper usage in the codebase
rg "TimeStamper" components/clp-py-utils/Repository: y-scope/clp
Length of output: 201
Use the LogRecord creation time for timestamp.
Line 65 stamps when the formatter runs because TimeStamper calls current-time helpers internally; queued, forwarded, or delayed records can then get formatter-run timestamps instead of event-creation timestamps. Build the ISO timestamp from record.created, which Python's logging module sets when the LogRecord is created.
🛠️ Proposed fix
+from datetime import datetime, timezone
+
import structlog
from structlog.contextvars import (
bind_contextvars,
@@
-_TIMESTAMP_PROCESSOR = structlog.processors.TimeStamper(fmt="iso", utc=True, key="timestamp")
_JSON_RENDERER = structlog.processors.JSONRenderer()
@@
- _TIMESTAMP_PROCESSOR(None, method_name, event_dict)
+ event_dict["timestamp"] = (
+ datetime.fromtimestamp(record.created, timezone.utc)
+ .isoformat()
+ .replace("+00:00", "Z")
+ )
rendered_log = _JSON_RENDERER(None, method_name, event_dict)🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@components/clp-py-utils/clp_py_utils/clp_logging.py` at line 65, The
_TIMESTAMP_PROCESSOR call at line 65 uses TimeStamper which captures the current
time when the formatter runs, causing queued or delayed log records to get
incorrect timestamps. Instead of calling _TIMESTAMP_PROCESSOR with TimeStamper,
directly build the ISO timestamp from record.created, which Python's logging
module sets when the LogRecord is created. This ensures the timestamp reflects
when the event occurred, not when the formatter executed.
| "result>=0.17.0", | ||
| "sqlalchemy>=2.0.46", | ||
| "StrEnum>=0.4.15", | ||
| "structlog>=25.5.0", |
There was a problem hiding this comment.
🧹 Nitpick | 🔵 Trivial | ⚡ Quick win
Lower the structlog floor unless 25.5.0-specific behaviour is required.
The reviewed code only needs contextvars helpers plus JSONRenderer/TimeStamper; the structlog 25.5.0 docs list these contextvars APIs as added by 21.2.0 or earlier, while the renderer and timestamper are older processors. Keeping >=25.5.0 can create avoidable resolver conflicts for consumers with an older compatible structlog already pinned. (structlog.org)
♻️ Proposed dependency floor
- "structlog>=25.5.0",
+ "structlog>=21.2.0",📝 Committable suggestion
‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.
| "structlog>=25.5.0", | |
| "structlog>=21.2.0", |
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@components/clp-py-utils/pyproject.toml` at line 18, The structlog dependency
version in the pyproject.toml file is set to a floor of 25.5.0, but the code
only uses contextvars helpers, JSONRenderer, and TimeStamper which are all
available in much earlier versions. Lower the structlog version requirement to
the minimum version that actually provides all the necessary features (21.2.0
based on the structlog documentation) to avoid creating unnecessary resolver
conflicts for consumers who may have an older compatible version already pinned.
… logging setups and controls
junhaoliao
changed the title
There was a problem hiding this comment.
Actionable comments posted: 1
♻️ Duplicate comments (1)
components/clp-py-utils/clp_py_utils/clp_logging.py (1)
28-36: 🎯 Functional Correctness | 🟠 Major | ⚡ Quick winUse record creation time for foreign log timestamps.
Line 35 stamps time at formatter execution, not
LogRecordcreation time. With delayed/queued handlers, that can skewtimestampfrom when the event actually happened.🛠️ Suggested fix
+from datetime import datetime, timezone @@ +def _add_foreign_record_created_timestamp( + _: object, __: str, event_dict: dict[str, object] +) -> dict[str, object]: + record = event_dict.get("_record") + if isinstance(record, logging.LogRecord): + event_dict["timestamp"] = ( + datetime.fromtimestamp(record.created, timezone.utc) + .isoformat() + .replace("+00:00", "Z") + ) + return event_dict + _FOREIGN_PRE_CHAIN: tuple[Processor, ...] = ( @@ - structlog.processors.TimeStamper(fmt="iso", utc=True, key="timestamp"), + _add_foreign_record_created_timestamp, )🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@components/clp-py-utils/clp_py_utils/clp_logging.py` around lines 28 - 36, The TimeStamper processor in the _FOREIGN_PRE_CHAIN tuple is generating a timestamp at processor execution time rather than using the LogRecord creation time, which can cause timestamp inaccuracy when handlers are delayed or queued. Replace the structlog.processors.TimeStamper call to instead extract the timestamp from the LogRecord's creation time, which is available in the stdlib integration context. You should create a custom processor or use structlog's built-in mechanism to access _record.created and convert it to ISO format with UTC timezone, then assign it to the timestamp key, ensuring the timestamp reflects when the logging event actually occurred rather than when it was processed.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@docs/src/dev-docs/logging.md`:
- Around line 34-42: Add GitHub source code links to the logging documentation
to help developers navigate from the reference material to the actual
implementation. Insert links using the DOCS_VAR_CLP_GIT_REF variable that point
to the clp_py_utils/clp_logging.py file and the clp_rust_utils logging module
directory. These links should be added near the table describing the log fields
or in the section that references these modules, making it easier for developers
to explore the actual code implementation mentioned in the development guidance.
---
Duplicate comments:
In `@components/clp-py-utils/clp_py_utils/clp_logging.py`:
- Around line 28-36: The TimeStamper processor in the _FOREIGN_PRE_CHAIN tuple
is generating a timestamp at processor execution time rather than using the
LogRecord creation time, which can cause timestamp inaccuracy when handlers are
delayed or queued. Replace the structlog.processors.TimeStamper call to instead
extract the timestamp from the LogRecord's creation time, which is available in
the stdlib integration context. You should create a custom processor or use
structlog's built-in mechanism to access _record.created and convert it to ISO
format with UTC timezone, then assign it to the timestamp key, ensuring the
timestamp reflects when the logging event actually occurred rather than when it
was processed.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: ASSERTIVE
Plan: Pro
Run ID: 681342e0-ce89-463a-b5a8-353892ca90ea
⛔ Files ignored due to path filters (5)
components/clp-mcp-server/uv.lockis excluded by!**/*.lockcomponents/clp-package-utils/uv.lockis excluded by!**/*.lockcomponents/clp-py-utils/uv.lockis excluded by!**/*.lockcomponents/job-orchestration/uv.lockis excluded by!**/*.lockintegration-tests/uv.lockis excluded by!**/*.lock
📒 Files selected for processing (6)
components/clp-py-utils/clp_py_utils/clp_logging.pycomponents/clp-py-utils/pyproject.tomlcomponents/job-orchestration/job_orchestration/executor/compress/celery.pycomponents/job-orchestration/job_orchestration/executor/query/celery.pydocs/src/dev-docs/index.mddocs/src/dev-docs/logging.md
…ng and level filtering
…onent-specific loggers
| [`clp_py_utils.clp_logging.get_logger`][clp-py-logging] and | ||
| [`clp_py_utils.clp_logging.configure_logging`][clp-py-logging]. |
There was a problem hiding this comment.
shouldn't this be structlog.get_logger()? I thought we want to transition to using structloggers right? that's why we added structlog.configure?
There was a problem hiding this comment.
right, sorry for the confusion. the recommendation was written before i added structlog.configure(). btw, i think we should wrap the structlog.configure() into a method; otherwise the method is called unconditionally when the module is imported, which is some side effect that might be undesirable
There was a problem hiding this comment.
Good point. Also I think "developer guidance" section should go right after the components table. A reader of this doc mostly cares about how they should be logging.
| ] | ||
|
|
||
| # Processor chain for events emitted through structlog loggers before they reach | ||
| # ``ProcessorFormatter``. |
There was a problem hiding this comment.
| # ``ProcessorFormatter``. | |
| # `ProcessorFormatter`. |
LinZhihao-723
left a comment
LinZhihao-723
left a comment
There was a problem hiding this comment.
- Only reviewed the logging doc.
- Didin't review the Python and WebUI guidelines carefully. Focused on the Rust side.
Co-authored-by: Lin Zhihao <59785146+LinZhihao-723@users.noreply.github.com>
Co-authored-by: Lin Zhihao <59785146+LinZhihao-723@users.noreply.github.com>
…ity" This reverts commit 1f7e0eb.
LinZhihao-723
left a comment
LinZhihao-723
left a comment
There was a problem hiding this comment.
I found this is missing in the latest version otherwise lgtm.
3 participants
Description
Note
BREAKING CHANGE:
clp_py_utils.clp_loggingnow emit JSON logs instead of the previoustext format.
%(asctime)stext.Celery's own startup banner and early Python warnings can still appear as non-JSON process output,
but CLP logger records and Celery logger records after logging setup use JSON.
Adds a reusable bind_log_context helper and formatter for appending scoped correlation fields to CLP logs, such asjob_id,task_idetc.Updates CLP's shared Python logging setup so CLP logger records are emitted as structured JSON while preserving the existing stdlib logging call sites.
Existing callers can keep using:
clp_py_utils.clp_logging.get_loggerclp_py_utils.clp_logging.configure_logginglogging.LoggerAPIscelery.utils.log.get_task_loggerThe shared formatter is implemented with
structlog.stdlib.ProcessorFormatter, so stdlib records and Celery-configured task loggers use the same JSON renderer. No service code needs to swap to structlog loggers in this PR.This follows structlog's documented
ProcessorFormatterstandard-library integration: stdlib/Celery records are processed withforeign_pre_chain, structlog-originated records are prepared withProcessorFormatter.wrap_for_formatter, stdlibextra={...}fields are preserved withstructlog.stdlib.ExtraAdder, andstructlog.contextvars.merge_contextvarsis configured so future contextvars-bound fields flow through the formatter.The JSON records include:
timestampeventloggerlevelexception, whenexc_infois presentstack, whenstack_infois presentThis PR configures support for contextvars-backed fields, but it does not currently bind or emit any correlation fields. It only changes the shared formatter output to structured JSON and applies that formatter to CLP-owned stdlib/Celery logger records.
Longer term, we should transition CLP-owned Python code to structlog loggers directly and avoid adding new stdlib logger call sites. This PR keeps stdlib compatibility because it is the least disruptive bridge for the current services, especially Celery workers whose task loggers are created by Celery. For the same compatibility reason,
clp_py_utils.clp_logging.get_loggerstill configures handlers as it did before; moving handler setup to a single service bootstrap path should be a separate cleanup instead of being bundled into this formatter change.If we later add per-job/per-task correlation fields in a follow-up PR, the formatter side is already ready because
structlog.contextvars.merge_contextvarsis in the processor chain. The remaining work is to bind and clear fields at request/task boundaries using structlog's native contextvars API:structlog.contextvars.bound_contextvars(...)for scoped context.structlog.contextvars.bind_contextvars(...),structlog.contextvars.unbind_contextvars(...), andstructlog.contextvars.clear_contextvars()for explicit lifecycle management.A small CLP wrapper can still make sense later if we need CLP-specific behavior that structlog does not provide directly, such as enforcing a fixed correlation field schema or mapping CLP domain objects into log fields. For this PR, deferring that wrapper keeps the first step focused on the operational log format change without adding an unused API surface.
Logging style references:
Checklist
breaking change.
Validation performed
Setup: rebuilt
build/clp-packagewithtask packagebefore running runtime validation. The generated image used by Docker Compose and Helm wasclp-package:dev-junhao-08c6(sha256:08c657258de039943cd76df8304d4e4ae4de95f53fcaf9c4be6d5dd6df9c2639).Scenario 1: Docker Compose package startup
Task: Start the rebuilt CLP package with Docker Compose and verify services become healthy.
Command:
Output:
Scenario 2: Docker Compose package compression
Task: Submit a compression job through the rebuilt Docker Compose package.
Command:
Output:
Scenario 3: Docker Compose service log output
Task: Confirm Docker Compose Python service logger records are emitted as JSON, including Celery task logger records.
Command:
Output:
Explanation: CLP-owned service records are JSON. Celery's startup banner and early Python warnings remain plain process output, but Celery logger records and CLP task logger records are JSON after logging setup.
Scenario 4: Helm/kind package startup
Task: Start the Helm chart through
set-up-test.shusing the rebuilt package image and verify all pods become ready.Command:
Output:
Scenario 5: Kubernetes service log output
Task: Confirm Kubernetes Python service logger records are JSON when CLP is started by
set-up-test.sh.Command:
Output:
Explanation: The scheduler records are JSON under
kubectl logs, and Celery logger records are JSON after Celery logging setup. Celery's startup banner remains plain output.Summary by CodeRabbit
Release Notes