feat: add timestamp parsing for container execution logs (#1343) - #1740
feat: add timestamp parsing for container execution logs (#1343)#1740sufirehman wants to merge 4 commits into
Conversation
…reen-coding-solutions#1343) Pass `--timestamps` to `docker logs` so each line is prefixed with an RFC3339Nano timestamp. A new module-level helper `_parse_timestamped_log_lines()` parses those prefixed lines into `{timestamp, content}` dicts, falling back to `{timestamp: None, ...}` for lines that don't match. `_add_to_current_run_log()` now branches on log type: CONTAINER_EXECUTION entries store `stdout_entries`/`stderr_entries` (lists of the parsed dicts) instead of plain strings. All other log types (SETUP_COMMAND, FLOW_COMMAND, NETWORK_STATS, EXCEPTION) are unchanged and continue to use plain `stdout`/`stderr` keys. Tests cover the parser (normal, fallback, empty input) and confirm the correct key shape for CONTAINER_EXECUTION, SETUP_COMMAND, and FLOW_COMMAND log entries.
|
Hi @ArneTR, this PR has been open since June 23 without any feedback yet, so just checking in. I've since resolved a merge conflict in lib/scenario_runner.py that came up from recent upstream changes, and the timestamp parsing tests still pass cleanly against the merged code. No rush at all if you're busy, just wanted to make sure it hadn't slipped through unnoticed. Happy to adjust the approach if anything needs changing. |
|
Hey @sufirehman, sorry for the this. The PR simply slipped through 😨 Reviewing now |
|
@coderabbitai review |
✅ Action performedReview finished.
|
📝 WalkthroughWalkthroughDocker container logs are now requested with timestamps and parsed into timestamp/content entries with null-byte normalization and unmatched-line fallback handling. Container execution records store structured stdout and stderr entry arrays, while setup and flow command records retain sanitized stdout and stderr strings. Tests cover parsing behavior, empty input, fallback cases, and the log-record shapes for each supported log type. 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
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 |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (1)
tests/test_runner.py (1)
981-1060: 🎯 Functional Correctness | 🟠 Major | ⚡ Quick win
test_logs_structurewill now fail: it still asserts plainstdout/stderrfor container-execution entries.
_add_to_current_run_log(lib/scenario_runner.py, lines 2063-2086) now storesstdout_entries/stderr_entriesinstead ofstdout/stderrforLogType.CONTAINER_EXECUTION. This test wasn't updated: line 1016'sassert "stdout" in log_entry or "stderr" in log_entrywill fail on the container-execution entry produced by thecapture_logs.ymlrun, and the content check at line 1051 ("stdout" in log_entry and "Test log from container" in log_entry["stdout"]) will never match, sofound_container_executionstaysFalse, failing line 1060 too.Please update this test to branch on
log_entry["type"]and checkstdout_entries/stderr_entries(with per-entrycontent) forCONTAINER_EXECUTION, while keeping the plainstdout/stderrchecks for the other types. Worth also checking the siblingcapture_logs_with_null_bytes.yml/capture_logs_with_invalid_character.ymltests for the same pattern.
🧹 Nitpick comments (1)
lib/scenario_runner.py (1)
2063-2102: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winExtract the repeated str/bytes coercion into one helper.
The str/decode/fallback logic (
isinstance(..., str)→hasattr(..., 'decode')→str(...)) is duplicated four times across theCONTAINER_EXECUTIONand non-container branches. This also triggers the four Ruff B009 warnings ("Do not callgetattrwith a constant attribute value") flagged on lines 2071, 2080, 2090, 2098. Consolidating into one helper removes the duplication and the lint warnings at once.♻️ Proposed refactor
+def _coerce_to_text(data): + if isinstance(data, str): + return data + if hasattr(data, 'decode'): + return data.decode('UTF-8', errors='replace') + return str(data) + def _add_to_current_run_log(self, container_name, log_type, log_id, cmd, phase, stdout=None, stderr=None, flow=None, exception_class=None): ... if log_type == LogType.CONTAINER_EXECUTION: if stdout is not None: - if isinstance(stdout, str): - stdout_str = stdout - elif hasattr(stdout, 'decode') and callable(getattr(stdout, 'decode')): - stdout_str = stdout.decode('UTF-8', errors='replace') - else: - stdout_str = str(stdout) - stdout_str = utils.filter_sensitive_data(stdout_str) + stdout_str = utils.filter_sensitive_data(_coerce_to_text(stdout)) log_entry['stdout_entries'] = _parse_timestamped_log_lines(stdout_str) if stderr is not None: - if isinstance(stderr, str): - stderr_str = stderr - elif hasattr(stderr, 'decode') and callable(getattr(stderr, 'decode')): - stderr_str = stderr.decode('UTF-8', errors='replace') - else: - stderr_str = str(stderr) - stderr_str = utils.filter_sensitive_data(stderr_str) + stderr_str = utils.filter_sensitive_data(_coerce_to_text(stderr)) log_entry['stderr_entries'] = _parse_timestamped_log_lines(stderr_str) else: if stdout is not None: - if isinstance(stdout, str): - log_entry['stdout'] = stdout.replace('\x00', '0x00') - elif hasattr(stdout, 'decode') and callable(getattr(stdout, 'decode')): - log_entry['stdout'] = stdout.decode('UTF-8', errors='replace').replace('\x00', '0x00') - else: - log_entry['stdout'] = str(stdout).replace('\x00', '0x00') - log_entry['stdout'] = utils.filter_sensitive_data(log_entry['stdout']) + log_entry['stdout'] = utils.filter_sensitive_data(_coerce_to_text(stdout).replace('\x00', '0x00')) if stderr is not None: - ... (same pattern) + log_entry['stderr'] = utils.filter_sensitive_data(_coerce_to_text(stderr).replace('\x00', '0x00'))Source: Linters/SAST tools
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 3e26cb20-4cf1-4d98-ba08-e66bae94de0f
📒 Files selected for processing (2)
lib/scenario_runner.pytests/test_runner.py
ArneTR
left a comment
ArneTR
left a comment
There was a problem hiding this comment.
Thanks for the PR. I now had time to review it.
I made remarks in the code directly where appropriate.
But overall this PR does not fully implement the idea intended.
- It does not show in the frontend. Although discussed that we do not want to touch the interleaving and phase splitting in the frontend, it should still show in the legacy box. I made an idea in the code how to achieve this
- Not implemented is the fact that
docker execcalls will not have timestamps. Since they typically make up the majority of our logs I feel this must be part of the implementation. Would be great if you supply some ideas here how to achieve this. As David said: This might be a trickier one though :)
If you feel this is too tough to implement I can understand. But I feel for only having timestamps in thedocker logsthis PR is currently not enough to merge.
| else: | ||
| log_entry['stderr'] = str(stderr).replace('\x00', '0x00') # we just force it to a string. This can garble output a bit though | ||
| log_entry['stderr'] = utils.filter_sensitive_data(log_entry['stderr']) | ||
| if log_type == LogType.CONTAINER_EXECUTION: |
There was a problem hiding this comment.
This is very duplicated code. I feel this whole function should be refactored to be more compact and not branch into two big branches with identical sub-branches
| else: | ||
| stdout_str = str(stdout) | ||
| stdout_str = utils.filter_sensitive_data(stdout_str) | ||
| log_entry['stdout_entries'] = _parse_timestamped_log_lines(stdout_str) |
There was a problem hiding this comment.
Storing in this element is useful. But in the end it still must be copied as string only int stdout / stderr. Otherwise the logs currently do not show in the frontend
|
Hey @ArneTR, thanks for the review! Points 1 and 2 make sense, I'll fix the frontend display and clean up the branching in _add_to_current_run_log. For the docker exec timestamps, I looked into it and the issue is structural: exec output bypasses the Docker daemon's log driver so there's no --timestamps equivalent available. I'll add a comment explaining this as a known gap rather than pushing a streaming workaround that would only give host-receipt timestamps with buffering issues. Let me know if you'd rather I take a different approach there. Will push the fix shortly. |
|
Hi @ArneTR, pushed the updated implementation:
Let me know if anything else needs adjusting. |
…utput handling Container log entries stored stdout_entries/stderr_entries (timestamped, parsed from `docker logs -t`) but never populated the plain stdout/stderr fields, so the frontend's legacy log box showed nothing for container output. _add_to_current_run_log now also joins the parsed entries' content into stdout/stderr for that log type. Collapse the near-duplicate stdout/stderr branches in _add_to_current_run_log into a single loop, extracting the repeated isinstance/decode/str-fallback conversion into a new module-level _stringify_process_output helper. Document why docker exec output (setup-commands and flow-commands) can't get the same per-line timestamps as `docker logs -t`: exec bypasses the daemon's logging driver entirely, and output is only ever read back as one fully-buffered blob after the process exits, so even host-side receipt timestamps would be false precision.
ArneTR
left a comment
ArneTR
left a comment
There was a problem hiding this comment.
The function is a lot clear now, ty.
I have made a remark where I think it can further be improved.
Will follow up on how to extend the PR.
| log_entry[f'{key}_entries'] = entries | ||
| # Must also be copied as plain string: the (legacy) frontend log box reads | ||
| # stdout/stderr directly and does not know about the *_entries structure. | ||
| log_entry[key] = '\n'.join(entry['content'] for entry in entries) |
There was a problem hiding this comment.
why this operation? and not just have the following else-branch unconditional. joining the entries here should be the same as setting log_entry[key] = value_str or?
|
The remark that docker exec simply cannot do what we need at the moment is nice to have in the comments. To make this achievable I think GMT should inject the functionality we need into the container. Here an idea, happy for your thoughs and remarks:
This way we can then run Considerations
This makes the PR bigger, but would fulfill the whole functionality. It requires some C work, but I guess also something a bit out of the ordinary :) Let me know how you feel about extending the PR like this and if you feel you want to take this on. |
|
Hey @ArneTR, good question on the join. They're actually not equivalent in this case. _parse_timestamped_log_lines reads value_str but doesn't mutate it, so value_str at that point still contains the raw docker logs -t output with RFC3339Nano timestamps prefixed on every line (e.g. "2025-09-17T06:46:17.013138795Z hello from container"). Using value_str directly for the plain field would put raw timestamped text into stdout/stderr, which breaks the legacy frontend display. The join reconstructs the timestamp-stripped version, which is what the frontend actually needs. I've added a clarifying comment in the code to make this explicit. On the ts_x idea: I think it's a genuinely interesting approach and worth doing properly. A statically linked C binary with process inheritance, no shell dependency, and overhead benchmarking is meaningfully different in scope from what this PR set out to address though. Rather than extending this PR further, would it make sense to merge what's here (docker logs timestamps working and tested end to end) and open a follow-up issue for ts_x with your design notes as the starting point? Happy to open that issue if that works for you. |
2 participants
Description
Implements Option 1 (Integrated Timestamp Storage) from the issue, scoped specifically to LogType.CONTAINER_EXECUTION. Adds the --timestamps flag to the docker logs call in _read_container_logs(), parses each line's RFC3339Nano timestamp prefix into {timestamp, content} entries, and stores them as stdout_entries/stderr_entries for container logs only. SETUP_COMMAND and FLOW_COMMAND log types keep their existing plain stdout/stderr string structure completely unchanged.
Related Issue
Closes #1343
Motivation and Context
Container logs span multiple phases (BOOT, IDLE, RUNTIME) and are currently stored as a single undifferentiated block per phase. Docker's --timestamps flag gives per-line RFC3339Nano timestamps for free, which lets us time-key container log lines for future phase-splitting and analysis, as proposed by @ArneTR.
How Has This Been Tested?
Added 6 tests: timestamp parsing on normal docker --timestamps output, fallback to {timestamp: None, content: line} for any line that doesn't match the expected format, empty input handling, and three tests confirming CONTAINER_EXECUTION entries use the new structure while SETUP_COMMAND and FLOW_COMMAND entries remain plain strings, completely unaffected. All 6 tests pass. (Note: the existing test teardown calls Tests.reset_db(), which requires the test Postgres container to be running; this is unrelated to the change and fails identically on main without the test Docker stack started.)
Scope notes
Per discussion with @ArneTR, this PR does not touch frontend display. Per his guidance, the plan for a follow-up is to simply prepend each line with its timestamp in the Logs tab, similar to how
docker logs -tdisplays output, with no interleaving logic for now.Types of changes
Summary
{timestamp, content}entries, withNonefor unmatched lines.stdout_entries/stderr_entrieswhile preserving plain strings for setup and flow commands.Frontend display and phase detection remain out of scope.