Fix/logging bug fixes

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();

dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs

@@ -12,9 +12,24 @@ namespace PyRevitLabs.PyRevit.Runtime {
     /// surface used by the script engines is implemented.
     /// </summary>
     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<ScriptRuntime> _runtime;
         private WeakReference<ScriptConsole> _gui;
-        private readonly Queue<string> _pending = new Queue<string>();
+        private readonly Queue<PendingEntry> _pending = new Queue<PendingEntry>();
         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);
         }

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

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

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('<b>order 3 of 4: print_html</b>')
+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')

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

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;
+        }
+    }
+}

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

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('<b>order 3 of 4: print_html</b>')
+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')

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