Fix/logging bug fixes#3477
Conversation
The throttled ScriptIO buffer could strand output that was written but not yet drained, and it applied error styling using a single stream-wide flag read at drain time. Both surfaced as visible output-window bugs: - Trailing prints, logger records, and uncaught tracebacks were dropped when the runtime was disposed before the flush timer could tick. CPython lost trailing prints entirely (sys.stdout is the raw stream with no teardown flush); IronPython/CPython lost uncaught traceback bodies. - Normal output buffered before an error rendered with the red traceback styling and a repeated engine header, because DrainOutput read the _errored latch at drain time rather than per entry (most visible on CPython, which buffers its whole run until teardown). Fixes: - ScriptExecutor: synchronously flush runtime.OutputStream before disposing the runtime, so buffered output renders to the still-live window for every engine. - ScriptIO: capture the error state (and engine) on each PendingEntry when it is enqueued, and render each entry by its own state, so normal output keeps normal styling regardless of a later traceback. WriteError finalizes any buffered normal output before switching into error mode. Adds a Log Output Tests dev pulldown (IronPython/CPython/C#) covering stdout flush, all logger levels, cross-path ordering, emoji/unicode, and uncaught tracebacks.
Settings.smartbutton did sorted(get_pyrevit_env_vars().items()), which under IronPython 3 raised "TypeError: '<' not supported between 'tuple' and 'str'" when the sort fell back to comparing the dict's heterogeneous values. Python 2 tolerated ordering unlike types; Python 3 does not. Sort by the env var name only (str-coerced) so values are never compared
![devloai[bot]](https://avatars.githubusercontent.com/in/886113?s=60&v=4){kind=small}
There was a problem hiding this comment.
PR Summary:
- Fixes trailing output loss (esp. CPython, which buffers until teardown) by flushing
runtime.OutputStreambefore disposing the runtime inScriptExecutor. - Fixes normal output being retroactively rendered with error styling/header by tagging each buffered
ScriptIOentry with its own error state (PendingEntry) at enqueue time instead of reading a single stream-wide_erroredflag at drain time. - Fixes an IronPython 3 crash in the Settings dialog by sorting env vars by key only instead of
sorted(dict.items()). - Adds a new "Log Output Tests" pulldown (IronPython/CPython/C#) to pyRevitDevTools for regression coverage of flush timing, log levels, ordering, unicode, and tracebacks.
Review Summary:
Reviewed the ScriptIO/ScriptExecutor buffering changes against the runtime's engine lifecycle (IronPythonEngine, CPythonEngine, CLREngine) to confirm the output stream stays rooted (via the engine's I/O bindings) through teardown so the new Flush() call actually drains the right instance, and traced PendingEntry's per-entry state capture through EnqueuePending/FlushOneEntry/DrainOutput to confirm it correctly fixes the described "normal output styled as error" bug. Also checked a suspected race between FinalizePendingEntry and the _errored flip in WriteError, but traced the dispatcher-marshaling logic in ScriptOutput.write_log_record/ScriptLoggerService and confirmed script execution and error handling are confined to the main Revit thread with no message-pump yield point in that window, so it isn't an actual issue. The Settings.py sort fix and new dev-tools test scripts are straightforward and correctly scoped (CPython script explicitly uses Python 3 shebang, consistent with repo conventions for that engine). No PEP8/Black or IPY2712-scope violations found in the touched Python files. Overall this is a well-tested, well-reasoned fix with no actionable issues found worth blocking on.
Suggestions
There was a problem hiding this comment.
Pull request overview
This PR fixes multiple regressions in pyRevit’s Output Window rendering pipeline by ensuring buffered output is fully drained at teardown, and by tracking “error styling” per buffered entry rather than as a global latch. It also fixes a Settings dialog crash under IronPython 3 when sorting shared environment variables, and adds DevTools buttons to validate output behavior across IronPython/CPython/C#.
Changes:
- Ensure buffered output is flushed to the live Output Window before runtime disposal (
ScriptExecutor). - Prevent normal output from being retroactively rendered as traceback/error styling by capturing error state per buffered entry (
ScriptIO). - Fix Settings env var sorting for Py3 compatibility and add DevTools “Log Output Tests” scripts for regression validation across engines.
Reviewed changes
Copilot reviewed 10 out of 12 changed files in this pull request and generated no comments.
Show a summary per file
| File | Description |
|---|---|
| dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs | Flushes runtime.OutputStream prior to disposing the runtime to prevent trailing output loss. |
| dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs | Introduces per-entry buffered metadata (PendingEntry) so styling/rendering reflects state at enqueue-time, not drain-time. |
| extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py | Sorts env vars by key only (Py2/Py3-safe) to avoid IronPython 3 comparison errors. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/bundle.yaml | Adds a new DevTools pulldown grouping the new log/output regression tests. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/script.py | IronPython regression script covering flush, levels, ordering, unicode/emoji, and full traceback rendering. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/bundle.yaml | UI metadata for the IronPython log/output regression test button. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/script.py | CPython regression script covering flush, levels, ordering, unicode/emoji, and full traceback rendering. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/bundle.yaml | UI metadata for the CPython log/output regression test button. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/script.cs | CLR regression script validating buffered console output reaches the Output Window before command completion. |
| extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/bundle.yaml | UI metadata for the C# log/output regression test button. |
|
Thanks for giving it a go @ChrisCrosley |
|
📦 New work-in-progress (wip) builds are available for 6.5.4 |
|
📦 New work-in-progress (wip) builds are available for 6.5.4 |
Summary
Fixes two output-window regressions in the throttled console buffer, plus an IronPython 3 compatibility break in the Settings dialog.
Problems
sorted(dict.items())in the env vars list raisedTypeError: tuple < strunder Py3.Changes
runtime.OutputStreambefore disposing the runtime, draining buffered output to the live window for every engine.PendingEntry) and render per entry;WriteErrorfinalizes buffered normal output before switching to error mode.Testing
Built the 2025 Runtime (IPY2712PR + IPY342) and ran the new Log Output Tests buttons. Verified on IronPython 2/3, CPython, and C#:
Not included (known follow-ups)
printoutput (stdout encoding fixed at context init; ASCII/emoji unaffected).IExternalCommandexceptions surface via a Revit dialog rather than the output window (existing behavior, left as-is)Checklist
Before submitting your pull request, ensure the following requirements are met:
pipenv run black {source_file_or_directory}Related Issues
If applicable, link the issues resolved by this pull request: