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.92k stars 302 forks source link

Excel freezes after adding a module in the code explorer #5066

Open Greedquest opened 5 years ago

Greedquest commented 5 years ago

Rubberduck version information

Version 2.4.1.4795
OS: Microsoft Windows NT 10.0.17763.0, x64
Host Product: Microsoft Office x86
Host Version: 16.0.11328.20368
Host Executable: EXCEL.EXE

Description Recently when adding a new module with the Rubberduck Code Explorer, it's been leading to some error messages and unresponsive behaviour. Basically, the mouse turns to a blue circle, and after a minute or so (following the adding) I get a

Microsoft Excel is waiting for another application to complete an OLE action.

message box. After another couple of minutes I get a second box (the same message), and when I click okay on that the application becomes responsive again, the module has been added and I can continue as normal.

To Reproduce Add a module from the code Explorer to an existing folder

Logfile In this log I clicked the add module button at just after 15:23:05ish, the first error appeared at 15:24:45ish and the second at 15:27:40ish, after which everything was fine.

2019-07-24 15:23:01.1970;INFO-2.4.1.4795;Rubberduck.Common.LogLevelHelper;Minimum log level changing from Debug to Trace;
2019-07-24 15:23:09.5596;INFO-2.4.1.4795;Rubberduck.Parsing.VBA.RubberduckParserState;RubberduckParserState (9) is invoking StateChanged (Busy);
2019-07-24 15:23:09.6201;INFO-2.4.1.4795;Rubberduck.Parsing.VBA.RubberduckParserState;RubberduckParserState (10) is invoking StateChanged (Ready);
2019-07-24 15:23:09.6201;TRACE-2.4.1.4795;Rubberduck.VBEditor.WindowsApi.SubclassManager;Subclassed hWnd 0x001D0C6A as CodePane.;
2019-07-24 15:24:47.2614;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.CodePaneRefactorRenameCommand was registered with id 49266;
2019-07-24 15:24:47.2614;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorEncapsulateFieldCommand was registered with id 49380;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorMoveCloserToUsageCommand was registered with id 49341;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.CodeExplorerCommand was registered with id 49262;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ExportAllCommand was registered with id 49308;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.FindSymbolCommand was registered with id 49377;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentModuleCommand was registered with id 49355;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentProcedureCommand was registered with id 49261;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.InspectionResultsCommand was registered with id 49324;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ReparseCommand was registered with id 49309;
2019-07-24 15:24:47.2654;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.TestExplorerCommand was registered with id 49350;
2019-07-24 15:27:33.8072;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.CodePaneRefactorRenameCommand was registered with id 49309;
2019-07-24 15:27:33.8072;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorEncapsulateFieldCommand was registered with id 49324;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorMoveCloserToUsageCommand was registered with id 49377;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.CodeExplorerCommand was registered with id 49308;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ExportAllCommand was registered with id 49262;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.FindSymbolCommand was registered with id 49380;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentModuleCommand was registered with id 49261;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentProcedureCommand was registered with id 49355;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.InspectionResultsCommand was registered with id 49266;
2019-07-24 15:27:33.8112;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ReparseCommand was registered with id 49313;
2019-07-24 15:27:33.8271;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.TestExplorerCommand was registered with id 49385;
2019-07-24 15:27:38.7304;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.CodePaneRefactorRenameCommand was registered with id 49385;
2019-07-24 15:27:38.7304;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorEncapsulateFieldCommand was registered with id 49313;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorMoveCloserToUsageCommand was registered with id 49266;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.CodeExplorerCommand was registered with id 49355;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ExportAllCommand was registered with id 49261;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.FindSymbolCommand was registered with id 49380;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentModuleCommand was registered with id 49262;
2019-07-24 15:27:38.7344;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentProcedureCommand was registered with id 49308;
2019-07-24 15:27:38.7518;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.InspectionResultsCommand was registered with id 49377;
2019-07-24 15:27:38.7518;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ReparseCommand was registered with id 49324;
2019-07-24 15:27:38.7518;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.TestExplorerCommand was registered with id 49309;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.CodePaneRefactorRenameCommand was registered with id 49324;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorEncapsulateFieldCommand was registered with id 49377;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.Refactorings.RefactorMoveCloserToUsageCommand was registered with id 49308;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.CodeExplorerCommand was registered with id 49262;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ExportAllCommand was registered with id 49380;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.FindSymbolCommand was registered with id 49261;
2019-07-24 15:27:48.8817;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentModuleCommand was registered with id 49355;
2019-07-24 15:27:48.8897;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.IndentCurrentProcedureCommand was registered with id 49266;
2019-07-24 15:27:48.8897;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.InspectionResultsCommand was registered with id 49313;
2019-07-24 15:27:48.8897;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.ReparseCommand was registered with id 49385;
2019-07-24 15:27:48.8897;TRACE-2.4.1.4795;Rubberduck.Common.Hotkeys.Hotkey;Hotkey for the associated command Rubberduck.UI.Command.TestExplorerCommand was registered with id 49393;
retailcoder commented 5 years ago

The log doesn't show any button was clicked... is this still an issue? could #5053 be related?

Greedquest commented 5 years ago

@retailcoder actually the problem seems to have vanished with some update which is good. Although I'll just double check at some point today whether it could be a problem with an old version of the file I'm working on.

ChrisBrackett commented 5 years ago

I'm still experiencing this issue in 2.4.1.4925 when adding either a code module, class module or userform by right-clicking in Code Explorer. It looks like the module was added immediately but I got the same blue spinning wait indicator. The right-click menu didn't disappear and appeared on top of all other windows, even when switching apps. I couldn't get back to the VBE window (it was open but wouldn't take focus) but I could get back to MS Excel though it was locked up. RD status eventually changed to "Busy".

After 1 minute 30 seconds I got notification:

"Microsoft Excel is waiting for another application to complete an OLE action."

I clicked OK and focus switched back to the VBE and I was unable to switch to Excel.

After 4 minutes 30 seconds I got the "OLE action" message again, clicked OK and was able to interact with Excel and the VBE again. The Code Inspections window looked busy, with the ducks moving in a circle. I let it run for a couple of minutes (with the opened project it usually takes less than 10 seconds to refresh RD). When I manually refreshed, everything was back to normal.

Also, the issue hasn't been consistent. There are times I inserted modules using RD without issue. Can't remember which builds but the problem has been intermittent.

Same issue when inserting via the green plus button in Code Explorer. The issue did -not- occur when inserting a test module.

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

Logfile Logfile.txt

bclothier commented 5 years ago

Note; with merging of PR #5258 and #5262 this may have been fixed. Please try the the build 5169 or newer.

MDoerner commented 5 years ago

The easiest solution for this is to remove ResolvedDeclarations and ResolvingDeclarations from the AllowedRunStates in the TestEngine.

The problem essentially is as follows. We suspend the parser when we run tests. This requires a lock the parsing process takes as well in order to avoid having the action to run under parser suspension to run while a parse is in progress. Now, the problem is that the tests request the suspension on the UI thread. This is bad, because the CE's event handler for the change to the ready state pushes a task to the UI thread and waits for its completion. Unfortunately, since the UI thread is still waiting for the lock, the task cannot be executed. Thus, we have a deadlock.