diff --git a/dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs b/dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs index c9e0f7b9c..cffd5af33 100644 --- a/dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs +++ b/dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs @@ -168,6 +168,16 @@ private static int ExecuteScriptNow(ScriptData scriptData, ScriptRuntimeConfigs if (scriptExecConfigs.SendTelemetry) ScriptTelemetry.LogScriptTelemetryRecord(ref runtime); + // Drain any output still buffered by the engine (trailing prints, + // logger records, uncaught tracebacks) to the live window before the + // runtime and its window references are torn down below. + try { + runtime.OutputStream.Flush(); + } + catch { + // output rendering must never break command teardown + } + // GC cleanups var re = runtime.ExecutionResult; runtime.Dispose(); diff --git a/dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs b/dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs index 0aba555aa..cfca1bc67 100644 --- a/dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs +++ b/dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs @@ -12,9 +12,24 @@ namespace PyRevitLabs.PyRevit.Runtime { /// surface used by the script engines is implemented. /// public class ScriptIO : Stream, IDisposable { + // A buffered output entry carries the error state captured when it was + // enqueued, so normal output drained after an error is not retroactively + // rendered as an error just because the stream later saw a traceback. + private struct PendingEntry { + public readonly string Text; + public readonly bool IsError; + public readonly ScriptEngineType Engine; + + public PendingEntry(string text, bool isError, ScriptEngineType engine) { + Text = text; + IsError = isError; + Engine = engine; + } + } + private WeakReference _runtime; private WeakReference _gui; - private readonly Queue _pending = new Queue(); + private readonly Queue _pending = new Queue(); private int _pendingChars; private readonly StringBuilder _partial = new StringBuilder(); private readonly object _logLock = new object(); @@ -183,7 +198,7 @@ public void WriteEntry(string content) { FinalizePendingEntry(splitLargeEntries: false); while (_pendingChars > MaxPendingChars && _pending.Count > 1) - _pendingChars -= _pending.Dequeue().Length; + _pendingChars -= _pending.Dequeue().Text.Length; pendingChars = _pendingChars; } @@ -192,6 +207,11 @@ public void WriteEntry(string content) { } public void WriteError(string error_msg, ScriptEngineType engineType) { + // Close out any buffered normal output first so it keeps its own + // (non-error) styling when it drains. + lock (this) { + FinalizePendingEntry(keepIncompleteShortcode: false); + } _errored = true; _erroredEngine = engineType; foreach (string message_part in error_msg.SplitIntoChunks(1024)) { @@ -238,7 +258,7 @@ public override void Write(byte[] buffer, int offset, int count) { FinalizePendingEntry(); while (_pendingChars > MaxPendingChars && _pending.Count > 1) - _pendingChars -= _pending.Dequeue().Length; + _pendingChars -= _pending.Dequeue().Text.Length; pendingChars = _pendingChars; } @@ -379,7 +399,7 @@ private void EnqueuePending(string entry) { if (entry.Length == 0) return; - _pending.Enqueue(entry); + _pending.Enqueue(new PendingEntry(entry, _errored, _erroredEngine)); _pendingChars += entry.Length; } @@ -466,7 +486,7 @@ private void FlushUpToBudget() { private bool FlushOneEntry() { ScriptConsole output; - string entry; + PendingEntry entry; bool morePending; lock (this) { @@ -484,8 +504,8 @@ private bool FlushOneEntry() { } entry = _pending.Dequeue(); - _pendingChars -= entry.Length; - _lastEntryChars = entry.Length; + _pendingChars -= entry.Text.Length; + _lastEntryChars = entry.Text.Length; morePending = _pending.Count > 0; } @@ -498,13 +518,13 @@ private bool FlushOneEntry() { return true; } - private void DrainOutput(ScriptConsole output, string pending) { - if (string.IsNullOrEmpty(pending)) + private void DrainOutput(ScriptConsole output, PendingEntry pending) { + if (string.IsNullOrEmpty(pending.Text)) return; - var prefixed = PrefixStartupOutput(pending); - if (_errored) - output.AppendError(prefixed, _erroredEngine); + var prefixed = PrefixStartupOutput(pending.Text); + if (pending.IsError) + output.AppendError(prefixed, pending.Engine); else output.AppendHtmlFragment(prefixed, ScriptConsoleConfigs.DefaultBlock); } diff --git a/extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py b/extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py index 48dd2d595..90772f7ef 100644 --- a/extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py +++ b/extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py @@ -239,7 +239,10 @@ def _setup_user_extensions_list(self): def _setup_env_vars_list(self): """Reads the pyRevit environment variables and updates the list""" env_vars_list = [ - EnvVariable(k, v) for k, v in sorted(envvars.get_pyrevit_env_vars().items()) + EnvVariable(k, v) + for k, v in sorted( + envvars.get_pyrevit_env_vars().items(), key=lambda kv: str(kv[0]) + ) ] self.envvars_lb.ItemsSource = env_vars_list diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/bundle.yaml b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/bundle.yaml new file mode 100644 index 000000000..a4b0d8170 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/bundle.yaml @@ -0,0 +1,6 @@ +title: Test Log Output - CPython +tooltip: >- + Output/log regression test for the CPython engine: rapid stdout, every logger + level, print/logger/print_html ordering, emoji and unicode, a trailing error + log, and the full traceback from an uncaught exception must all render. +context: zero-doc diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/script.py b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/script.py new file mode 100644 index 000000000..533ff0033 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/script.py @@ -0,0 +1,47 @@ +#! python3 +# -*- coding: utf-8 -*- +"""Verify stdout, every logger level, output ordering, and tracebacks render. + +Exercises the buffered output path with a rapid stdout batch, each logger level, +interleaved print/logger/print_html to check ordering, emoji and wide unicode, a +trailing error-level log, and finally an uncaught exception. A correct run shows +every section in the order below, then the full CPython traceback. +""" +from pyrevit import script + +output = script.get_output() +logger = script.get_logger() +output.set_title('Log Output Test - CPython') + +# Rapid, un-delayed writes exercise the batched stdout path. +LINE_COUNT = 12 +for num in range(1, LINE_COUNT + 1): + print('flush-test line {} of {}'.format(num, LINE_COUNT)) + +# Each level renders with its own styling. error/critical are styled log records +# on the normal path, not the red traceback block; debug shows only in debug mode. +logger.debug('debug level (visible only in debug mode)') +logger.info('info level') +logger.success('success level') +logger.warning('warning level') +logger.error('error level (styled log, not a traceback)') +logger.critical('critical level') +logger.deprecate('deprecate level') + +# print, logger, and print_html travel different output paths; the rendered +# order must match the emission order below. +print('order 1 of 4: print') +logger.warning('order 2 of 4: logger') +output.print_html('order 3 of 4: print_html') +print('order 4 of 4: print') + +# Emoji shortcodes and wide unicode must survive the buffered path intact. +print('emoji :thumbs_up: :OK_hand: wide 结构结构 end') + +# A trailing error-level log must still reach the window at teardown. +logger.error('trailing error log must be visible') + +print('all sections above must be visible, then a full traceback below.') + +# Uncaught on purpose: exercises the error path, not print/logging. +raise RuntimeError('intentional test traceback - its full body must be visible') diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/bundle.yaml b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/bundle.yaml new file mode 100644 index 000000000..f0b849c5f --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/bundle.yaml @@ -0,0 +1,6 @@ +title: Test Log Output - C# +tooltip: >- + Output regression test for the CLR engine (also covers VB.NET). The window + must show every numbered line. CLR command exceptions surface through a Revit + dialog rather than the output window, so there is no traceback check here. +context: zero-doc diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/script.cs b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/script.cs new file mode 100644 index 000000000..122d68af6 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/script.cs @@ -0,0 +1,28 @@ +using System; + +using Autodesk.Revit.UI; +using Autodesk.Revit.DB; + +using pyRevitLabs.PyRevit.Runtime.Shared; + +namespace LogOutputTest { + // Verifies buffered Console output reaches the output window before the + // command returns. CLR command exceptions surface through a Revit dialog + // rather than the output window, so this engine has no traceback check. + public class LogOutputTest : IExternalCommand { + public ExecParams execParams; + + public Result Execute(ExternalCommandData revit, ref string message, ElementSet elements) { + const int lineCount = 12; + + // Rapid, un-delayed writes exercise the batched output path. + for (int num = 1; num <= lineCount; num++) + Console.WriteLine(string.Format("flush-test line {0} of {1}", num, lineCount)); + + Console.WriteLine(string.Format( + "PASS if lines 1..{0} above are all visible.", lineCount)); + + return Result.Succeeded; + } + } +} diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/bundle.yaml b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/bundle.yaml new file mode 100644 index 000000000..e528b5f34 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/bundle.yaml @@ -0,0 +1,6 @@ +title: Test Log Output - IronPython +tooltip: >- + Output/log regression test for the IronPython engine: rapid stdout, every + logger level, print/logger/print_html ordering, emoji and unicode, a trailing + error log, and the full traceback from an uncaught exception must all render. +context: zero-doc diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/script.py b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/script.py new file mode 100644 index 000000000..d06b2c3e8 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/script.py @@ -0,0 +1,46 @@ +# -*- coding: utf-8 -*- +"""Verify stdout, every logger level, output ordering, and tracebacks render. + +Exercises the buffered output path with a rapid stdout batch, each logger level, +interleaved print/logger/print_html to check ordering, emoji and wide unicode, a +trailing error-level log, and finally an uncaught exception. A correct run shows +every section in the order below, then the full IronPython traceback. +""" +from pyrevit import script + +output = script.get_output() +logger = script.get_logger() +output.set_title('Log Output Test - IronPython') + +# Rapid, un-delayed writes exercise the batched stdout path. +LINE_COUNT = 12 +for num in range(1, LINE_COUNT + 1): + print('flush-test line {} of {}'.format(num, LINE_COUNT)) + +# Each level renders with its own styling. error/critical are styled log records +# on the normal path, not the red traceback block; debug shows only in debug mode. +logger.debug('debug level (visible only in debug mode)') +logger.info('info level') +logger.success('success level') +logger.warning('warning level') +logger.error('error level (styled log, not a traceback)') +logger.critical('critical level') +logger.deprecate('deprecate level') + +# print, logger, and print_html travel different output paths; the rendered +# order must match the emission order below. +print('order 1 of 4: print') +logger.warning('order 2 of 4: logger') +output.print_html('order 3 of 4: print_html') +print('order 4 of 4: print') + +# Emoji shortcodes and wide unicode must survive the buffered path intact. +print('emoji :thumbs_up: :OK_hand: wide 结构结构 end') + +# A trailing error-level log must still reach the window at teardown. +logger.error('trailing error log must be visible') + +print('all sections above must be visible, then a full traceback below.') + +# Uncaught on purpose: exercises the error path, not print/logging. +raise RuntimeError('intentional test traceback - its full body must be visible') diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/bundle.yaml b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/bundle.yaml new file mode 100644 index 000000000..4a6ef6ab7 --- /dev/null +++ b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/bundle.yaml @@ -0,0 +1,4 @@ +layout: + - Test Log Output - IronPython + - Test Log Output - CPython + - Test Log Output - CSharp diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.dark.png b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.dark.png new file mode 100644 index 000000000..30c639078 Binary files /dev/null and b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.dark.png differ diff --git a/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.png b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.png new file mode 100644 index 000000000..c29a19509 Binary files /dev/null and b/extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/icon.png differ