Skip to content

Commit 950170c

Browse files
jmcouffinjmcouffin
authored
Merge pull request #3477 from ChrisCrosley/fix/logging-bug-fixes
Fix/logging bug fixes
2 parents b96f5a1 + 45747a4 commit 950170c

12 files changed

Lines changed: 189 additions & 13 deletions

File tree

‎dev/pyRevitLabs.PyRevit.Runtime/ScriptExecutor.cs‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -168,6 +168,16 @@ private static int ExecuteScriptNow(ScriptData scriptData, ScriptRuntimeConfigs
168168
if (scriptExecConfigs.SendTelemetry)
169169
ScriptTelemetry.LogScriptTelemetryRecord(ref runtime);
170170

171+
// Drain any output still buffered by the engine (trailing prints,
172+
// logger records, uncaught tracebacks) to the live window before the
173+
// runtime and its window references are torn down below.
174+
try {
175+
runtime.OutputStream.Flush();
176+
}
177+
catch {
178+
// output rendering must never break command teardown
179+
}
180+
171181
// GC cleanups
172182
var re = runtime.ExecutionResult;
173183
runtime.Dispose();

‎dev/pyRevitLabs.PyRevit.Runtime/ScriptIO.cs‎

Lines changed: 32 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -12,9 +12,24 @@ namespace PyRevitLabs.PyRevit.Runtime {
1212
/// surface used by the script engines is implemented.
1313
/// </summary>
1414
public class ScriptIO : Stream, IDisposable {
15+
// A buffered output entry carries the error state captured when it was
16+
// enqueued, so normal output drained after an error is not retroactively
17+
// rendered as an error just because the stream later saw a traceback.
18+
private struct PendingEntry {
19+
public readonly string Text;
20+
public readonly bool IsError;
21+
public readonly ScriptEngineType Engine;
22+
23+
public PendingEntry(string text, bool isError, ScriptEngineType engine) {
24+
Text = text;
25+
IsError = isError;
26+
Engine = engine;
27+
}
28+
}
29+
1530
private WeakReference<ScriptRuntime> _runtime;
1631
private WeakReference<ScriptConsole> _gui;
17-
private readonly Queue<string> _pending = new Queue<string>();
32+
private readonly Queue<PendingEntry> _pending = new Queue<PendingEntry>();
1833
private int _pendingChars;
1934
private readonly StringBuilder _partial = new StringBuilder();
2035
private readonly object _logLock = new object();
@@ -183,7 +198,7 @@ public void WriteEntry(string content) {
183198
FinalizePendingEntry(splitLargeEntries: false);
184199

185200
while (_pendingChars > MaxPendingChars && _pending.Count > 1)
186-
_pendingChars -= _pending.Dequeue().Length;
201+
_pendingChars -= _pending.Dequeue().Text.Length;
187202

188203
pendingChars = _pendingChars;
189204
}
@@ -192,6 +207,11 @@ public void WriteEntry(string content) {
192207
}
193208

194209
public void WriteError(string error_msg, ScriptEngineType engineType) {
210+
// Close out any buffered normal output first so it keeps its own
211+
// (non-error) styling when it drains.
212+
lock (this) {
213+
FinalizePendingEntry(keepIncompleteShortcode: false);
214+
}
195215
_errored = true;
196216
_erroredEngine = engineType;
197217
foreach (string message_part in error_msg.SplitIntoChunks(1024)) {
@@ -238,7 +258,7 @@ public override void Write(byte[] buffer, int offset, int count) {
238258
FinalizePendingEntry();
239259

240260
while (_pendingChars > MaxPendingChars && _pending.Count > 1)
241-
_pendingChars -= _pending.Dequeue().Length;
261+
_pendingChars -= _pending.Dequeue().Text.Length;
242262

243263
pendingChars = _pendingChars;
244264
}
@@ -379,7 +399,7 @@ private void EnqueuePending(string entry) {
379399
if (entry.Length == 0)
380400
return;
381401

382-
_pending.Enqueue(entry);
402+
_pending.Enqueue(new PendingEntry(entry, _errored, _erroredEngine));
383403
_pendingChars += entry.Length;
384404
}
385405

@@ -466,7 +486,7 @@ private void FlushUpToBudget() {
466486

467487
private bool FlushOneEntry() {
468488
ScriptConsole output;
469-
string entry;
489+
PendingEntry entry;
470490
bool morePending;
471491

472492
lock (this) {
@@ -484,8 +504,8 @@ private bool FlushOneEntry() {
484504
}
485505

486506
entry = _pending.Dequeue();
487-
_pendingChars -= entry.Length;
488-
_lastEntryChars = entry.Length;
507+
_pendingChars -= entry.Text.Length;
508+
_lastEntryChars = entry.Text.Length;
489509
morePending = _pending.Count > 0;
490510
}
491511

@@ -498,13 +518,13 @@ private bool FlushOneEntry() {
498518
return true;
499519
}
500520

501-
private void DrainOutput(ScriptConsole output, string pending) {
502-
if (string.IsNullOrEmpty(pending))
521+
private void DrainOutput(ScriptConsole output, PendingEntry pending) {
522+
if (string.IsNullOrEmpty(pending.Text))
503523
return;
504524

505-
var prefixed = PrefixStartupOutput(pending);
506-
if (_errored)
507-
output.AppendError(prefixed, _erroredEngine);
525+
var prefixed = PrefixStartupOutput(pending.Text);
526+
if (pending.IsError)
527+
output.AppendError(prefixed, pending.Engine);
508528
else
509529
output.AppendHtmlFragment(prefixed, ScriptConsoleConfigs.DefaultBlock);
510530
}

‎extensions/pyRevitCore.extension/pyRevit.tab/pyRevit.panel/Settings.smartbutton/script.py‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -239,7 +239,10 @@ def _setup_user_extensions_list(self):
239239
def _setup_env_vars_list(self):
240240
"""Reads the pyRevit environment variables and updates the list"""
241241
env_vars_list = [
242-
EnvVariable(k, v) for k, v in sorted(envvars.get_pyrevit_env_vars().items())
242+
EnvVariable(k, v)
243+
for k, v in sorted(
244+
envvars.get_pyrevit_env_vars().items(), key=lambda kv: str(kv[0])
245+
)
243246
]
244247

245248
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‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
title: Test Log Output - CPython
2+
tooltip: >-
3+
Output/log regression test for the CPython engine: rapid stdout, every logger
4+
level, print/logger/print_html ordering, emoji and unicode, a trailing error
5+
log, and the full traceback from an uncaught exception must all render.
6+
context: zero-doc

‎extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CPython.pushbutton/script.py‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,47 @@
1+
#! python3
2+
# -*- coding: utf-8 -*-
3+
"""Verify stdout, every logger level, output ordering, and tracebacks render.
4+
5+
Exercises the buffered output path with a rapid stdout batch, each logger level,
6+
interleaved print/logger/print_html to check ordering, emoji and wide unicode, a
7+
trailing error-level log, and finally an uncaught exception. A correct run shows
8+
every section in the order below, then the full CPython traceback.
9+
"""
10+
from pyrevit import script
11+
12+
output = script.get_output()
13+
logger = script.get_logger()
14+
output.set_title('Log Output Test - CPython')
15+
16+
# Rapid, un-delayed writes exercise the batched stdout path.
17+
LINE_COUNT = 12
18+
for num in range(1, LINE_COUNT + 1):
19+
print('flush-test line {} of {}'.format(num, LINE_COUNT))
20+
21+
# Each level renders with its own styling. error/critical are styled log records
22+
# on the normal path, not the red traceback block; debug shows only in debug mode.
23+
logger.debug('debug level (visible only in debug mode)')
24+
logger.info('info level')
25+
logger.success('success level')
26+
logger.warning('warning level')
27+
logger.error('error level (styled log, not a traceback)')
28+
logger.critical('critical level')
29+
logger.deprecate('deprecate level')
30+
31+
# print, logger, and print_html travel different output paths; the rendered
32+
# order must match the emission order below.
33+
print('order 1 of 4: print')
34+
logger.warning('order 2 of 4: logger')
35+
output.print_html('<b>order 3 of 4: print_html</b>')
36+
print('order 4 of 4: print')
37+
38+
# Emoji shortcodes and wide unicode must survive the buffered path intact.
39+
print('emoji :thumbs_up: :OK_hand: wide 结构结构 end')
40+
41+
# A trailing error-level log must still reach the window at teardown.
42+
logger.error('trailing error log must be visible')
43+
44+
print('all sections above must be visible, then a full traceback below.')
45+
46+
# Uncaught on purpose: exercises the error path, not print/logging.
47+
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‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
title: Test Log Output - C#
2+
tooltip: >-
3+
Output regression test for the CLR engine (also covers VB.NET). The window
4+
must show every numbered line. CLR command exceptions surface through a Revit
5+
dialog rather than the output window, so there is no traceback check here.
6+
context: zero-doc

‎extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - CSharp.pushbutton/script.cs‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
using System;
2+
3+
using Autodesk.Revit.UI;
4+
using Autodesk.Revit.DB;
5+
6+
using pyRevitLabs.PyRevit.Runtime.Shared;
7+
8+
namespace LogOutputTest {
9+
// Verifies buffered Console output reaches the output window before the
10+
// command returns. CLR command exceptions surface through a Revit dialog
11+
// rather than the output window, so this engine has no traceback check.
12+
public class LogOutputTest : IExternalCommand {
13+
public ExecParams execParams;
14+
15+
public Result Execute(ExternalCommandData revit, ref string message, ElementSet elements) {
16+
const int lineCount = 12;
17+
18+
// Rapid, un-delayed writes exercise the batched output path.
19+
for (int num = 1; num <= lineCount; num++)
20+
Console.WriteLine(string.Format("flush-test line {0} of {1}", num, lineCount));
21+
22+
Console.WriteLine(string.Format(
23+
"PASS if lines 1..{0} above are all visible.", lineCount));
24+
25+
return Result.Succeeded;
26+
}
27+
}
28+
}

‎extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/bundle.yaml‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
title: Test Log Output - IronPython
2+
tooltip: >-
3+
Output/log regression test for the IronPython engine: rapid stdout, every
4+
logger level, print/logger/print_html ordering, emoji and unicode, a trailing
5+
error log, and the full traceback from an uncaught exception must all render.
6+
context: zero-doc

‎extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/Test Log Output - IronPython.pushbutton/script.py‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
# -*- coding: utf-8 -*-
2+
"""Verify stdout, every logger level, output ordering, and tracebacks render.
3+
4+
Exercises the buffered output path with a rapid stdout batch, each logger level,
5+
interleaved print/logger/print_html to check ordering, emoji and wide unicode, a
6+
trailing error-level log, and finally an uncaught exception. A correct run shows
7+
every section in the order below, then the full IronPython traceback.
8+
"""
9+
from pyrevit import script
10+
11+
output = script.get_output()
12+
logger = script.get_logger()
13+
output.set_title('Log Output Test - IronPython')
14+
15+
# Rapid, un-delayed writes exercise the batched stdout path.
16+
LINE_COUNT = 12
17+
for num in range(1, LINE_COUNT + 1):
18+
print('flush-test line {} of {}'.format(num, LINE_COUNT))
19+
20+
# Each level renders with its own styling. error/critical are styled log records
21+
# on the normal path, not the red traceback block; debug shows only in debug mode.
22+
logger.debug('debug level (visible only in debug mode)')
23+
logger.info('info level')
24+
logger.success('success level')
25+
logger.warning('warning level')
26+
logger.error('error level (styled log, not a traceback)')
27+
logger.critical('critical level')
28+
logger.deprecate('deprecate level')
29+
30+
# print, logger, and print_html travel different output paths; the rendered
31+
# order must match the emission order below.
32+
print('order 1 of 4: print')
33+
logger.warning('order 2 of 4: logger')
34+
output.print_html('<b>order 3 of 4: print_html</b>')
35+
print('order 4 of 4: print')
36+
37+
# Emoji shortcodes and wide unicode must survive the buffered path intact.
38+
print('emoji :thumbs_up: :OK_hand: wide 结构结构 end')
39+
40+
# A trailing error-level log must still reach the window at teardown.
41+
logger.error('trailing error log must be visible')
42+
43+
print('all sections above must be visible, then a full traceback below.')
44+
45+
# Uncaught on purpose: exercises the error path, not print/logging.
46+
raise RuntimeError('intentional test traceback - its full body must be visible')

‎extensions/pyRevitDevTools.extension/pyRevitDev.tab/Debug.panel/Log Output Tests.pulldown/bundle.yaml‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,4 @@
1+
layout:
2+
- Test Log Output - IronPython
3+
- Test Log Output - CPython
4+
- Test Log Output - CSharp

0 commit comments

Comments
 (0)