search

rubberduck-vba / Rubberduck

Every programmer needs a rubberduck. COM add-in for the VBA & VB6 IDE (VBE).
https://rubberduckvba.com
GNU General Public License v3.0
1.91k stars 299 forks source link

Excel hangs at exit after running RDVBA tests #5903

Open pchemguy opened 2 years ago

pchemguy commented 2 years ago

Rubberduck version information

Version 2.5.2.5871 OS: Microsoft Windows NT 6.2.9200.0, x64 Host Product: Microsoft Office XP x86 Host Version: 10.0.6501 Host Executable: EXCEL.EXE

and

Version 2.5.2.5871 OS: Microsoft Windows NT 10.0.17763.0, x64 Host Product: Microsoft Office 2016 x64 Host Version: 16.0.4266.1001 Host Executable: EXCEL.EXE

Description The following example contains three VBA modules: two classes and one regular. After I run RubberDuck VBA tests and then try to close Excel, Excel hangs while actively using the CPU. Running the tests once does not reproduce this issue every time, but when I do at least two runs, it seems that the issue is reproduced every time. The same behavior is observed in both environments.

In the MRE provided, the issue can be avoided if either the object assertion "Assert.IsNotNothing dbm" is replaced with a scalar assertion "Assert.IsTrue Not dbm Is Nothing" (as illustrated using the conditional compilation constant. The issue also occurs with empty "Class_Terminate" methods but is gone if these methods are completely removed.

To Reproduce Steps to reproduce the behavior:

  1. Set "#Const USE_ASSERT_OBJECT = True" in ModuleTests.bas
  2. Run tests either via "Run All Test" or "Run selected test".
  3. Repeat step No.2 2-3 times.
  4. Close Excel.
  5. Observe the increased and steady level of CPU usage by Excel.exe process (Excel does not close).

When "#Const USE_ASSERT_OBJECT = True", the immediate output should be something like this:

14:11:49.21: ModuleInitialize
14:11:49.22: ModuleCleanup - Assert = Nothing
14:12:04.80: Class2 Class_Terminate                     <= Large delay and out of expected order
14:12:04.80: Class1 Class_Terminate                     <= Large delay and out of expected order

When "#Const USE_ASSERT_OBJECT = False", the immediate output should be something like this:

14:17:29.61: ModuleInitialize
14:17:29.61: Class2 Class_Terminate                     <= No delay and follows expected order
14:17:29.61: Class1 Class_Terminate                     <= No delay and follows expected order
14:17:29.62: ModuleCleanup - Assert = Nothing

With "#Const USE_ASSERT_OBJECT = False" set, the reported issue does not occur (Excel closes normally).

Expected behavior Excel should close and classes must terminate before ModuleCleanup.

Logfile Immediate output associated with the log below:

14:22:25.89: ModuleInitialize
14:22:25.90: ModuleCleanup - Assert = Nothing
14:22:50.07: Class2 Class_Terminate
14:22:50.07: Class1 Class_Terminate
2021-11-25 14:22:24.0636;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:24.0646;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:24.0646;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:24.0646;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:24.0806;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:24.0806;INFO-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82;System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Rubberduck.UI.Command.MenuItems.CommandBars.RubberduckCommandBar.<OnSelectionChange>d__9.MoveNext() in C:\projects\rubberduck\Rubberduck.Core\UI\Command\MenuItems\CommandBars\RubberduckCommandBar.cs:line 82
2021-11-25 14:22:25.8769;DEBUG-2.5.2.5871;Rubberduck.UI.Command.MenuItems.ParentMenus.ParentMenuItemBase;(60659387) Executing click handler for menu item '&Run All Tests', hash code 11166096;
2021-11-25 14:22:25.8769;INFO-2.5.2.5871;Rubberduck.Parsing.VBA.RubberduckParserState;RubberduckParserState (62) is invoking StateChanged (Busy);
2021-11-25 14:22:25.8769;TRACE-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;CancellationTokenSource was already disposed for OnParserStateChanged.;
2021-11-25 14:22:25.9058;INFO-2.5.2.5871;Rubberduck.Parsing.VBA.RubberduckParserState;RubberduckParserState (63) is invoking StateChanged (Ready);
2021-11-25 14:22:25.9058;TRACE-2.5.2.5871;Rubberduck.UI.Command.MenuItems.CommandBars.AppCommandBarBase;CancellationTokenSource was already disposed for OnParserStateChanged.;
2021-11-25 14:22:53.5737;DEBUG-2.5.2.5871;Rubberduck.UI.Command.MenuItems.ParentMenus.ParentMenuItemBase;(7649781) Executing click handler for menu item 'S&ettings', hash code 55677218;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.IndentCurrentModuleCommand was registered with id 50137;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.CodePaneRefactorRenameCommand was registered with id 50152;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorEncapsulateFieldCommand was registered with id 49847;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorExtractMethodCommand was registered with id 49817;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorMoveCloserToUsageCommand was registered with id 49792;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.CodeExplorerCommand was registered with id 50004;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.ExportAllCommand was registered with id 50119;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.FindSymbolCommand was registered with id 49767;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.IndentCurrentProcedureCommand was registered with id 49934;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.InspectionResultsCommand was registered with id 50165;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.ReparseCommand was registered with id 50114;
2021-11-25 14:22:59.2783;TRACE-2.5.2.5871;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ComCommands.TestExplorerCommand was registered with id 49986;
2021-11-25 14:22:59.2783;INFO-2.5.2.5871;Rubberduck.Common.LogLevelHelper;Minimum log level changing from Trace to Off;

Additional context MCVE.xls

Individual modules from the xls above:

ModuleTests.bas

Attribute VB_Name = "ModuleTests"
'@TestModule
Option Explicit
Option Private Module

Private Assert As Rubberduck.PermissiveAssertClass

#Const USE_ASSERT_OBJECT = True

'@ModuleInitialize
Private Sub ModuleInitialize()
    PrintMsg "ModuleInitialize"
    Set Assert = New Rubberduck.PermissiveAssertClass
End Sub

'@ModuleCleanup
Private Sub ModuleCleanup()
    Set Assert = Nothing
    PrintMsg "ModuleCleanup - Assert = Nothing"
End Sub

Public Sub PrintMsg(Optional ByRef Msg As String = vbNullString)
    Debug.Print Format(Time(), "hh:mm:ss") & _
                Format(CStr((Timer * 100 Mod 100) / 100), ".00") & ": " & Msg
End Sub

'@TestMethod("Factory")
Private Sub ztcCreate_VerifiesDefaultManager()
    Dim dbm As Class2
    Set dbm = Class2.Create()
    #If USE_ASSERT_OBJECT Then
        Assert.IsNotNothing dbm
    #Else
        Assert.IsTrue Not dbm Is Nothing
    #End If
End Sub

Class1.cls

VERSION 1.0 CLASS
BEGIN
  MultiUse = -1  'True
END
Attribute VB_Name = "Class1"
Attribute VB_GlobalNameSpace = False
Attribute VB_Creatable = False
Attribute VB_PredeclaredId = True
Attribute VB_Exposed = False
'@PredeclaredId
Option Explicit

Public Function Create() As Class1
    Dim Instance As Class1
    Set Instance = New Class1
    Set Create = Instance
End Function

Private Sub Class_Terminate()
    PrintMsg "Class1 Class_Terminate"
End Sub

Class2.cls

VERSION 1.0 CLASS
BEGIN
  MultiUse = -1  'True
END
Attribute VB_Name = "Class2"
Attribute VB_GlobalNameSpace = False
Attribute VB_Creatable = False
Attribute VB_PredeclaredId = True
Attribute VB_Exposed = False
'@PredeclaredId
Option Explicit

Private Type TClass2
    DllMan As Class1
End Type
Private this As TClass2

Public Function Create() As Class2
    Dim Instance As Class2
    Set Instance = New Class2
    Instance.Init
    Set Create = Instance
End Function

Friend Sub Init()
    Dim FileNames As Variant
    Set this.DllMan = Class1.Create()
End Sub

Private Sub Class_Terminate()
    PrintMsg "Class2 Class_Terminate"
End Sub
pchemguy commented 2 years ago

Also see Cristian Buse's answer here https://stackoverflow.com/questions/70098835/excel-hangs-at-exit-after-running-rdvba-tests

MDoerner commented 2 years ago

Thanks for reporting.

This seems to be the same issue as #5898.

This isust likely an issue with how the objects are released on shutdown. The VBE is very uncompromising there and makes assumptions that are only valid with deterministic memory management. This caused us problems before, which we thought to be fixed, but they reappeared now.

There is a PR #5899 in the pipeline which may or may not help with this issue.

Reproducing the issue is rather hard for us since it seems to be caused by a race condition on shutdown.