Vsvim: Runtime exception on file close

[EdwinVanRooij]

ActivityLog.xml.txt

When I exit a file using my custom keybinding (which works correctly) nnoremap <leader>q :q!<CR>, an exception popup is opened right after the editor window of the file closes: see image.

The referred activity log in the popup is provided as .txt in this issue as well, as is the rest of my .vimrc.

vimrc.txt

[jnothstine]

I see this happen quite frequently. I see it most frequently when I open a file and just look at it and then close the file.

Sent from Mail for Windows 10

From: Edwin
Sent: Wednesday, May 8, 2019 4:29 AM
To: VsVim/VsVim
Cc: Subscribed
Subject: [VsVim/VsVim] Runtime exception on file close (#2533)

ActivityLog.xml.txt
When I exit a file using my custom keybinding (which works correctly) nnoremap q :q!, an exception popup is opened right after the editor window of the file closes: see image.
The referred activity log in the popup is provided as .txt in this issue as well, as is the rest of my .vimrc.
vimrc.txt
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.

[ricksladkey]

Also reported in issue #2528.

Yes, I have seen this problem as well, but the stack trace indicates that it is a Visual Studio bug related to the recent support in Visual Studio for multiple carets / selections. Unfortunately since it certainly looks like VsVim caused the exception, it may be hard to convince Visual Studio that the problem is not VsVim.

I believe the only ways of avoiding it are to either:

• try to find a workaround so that we do not trigger the bug in Visual Studio, or
• report the problem and hope that it gets fixed.

[jaredpar]

The stack trace is so thin here, just a single method. It's hard to tell what we're even doing here that could be causing this.

[ricksladkey]

@jaredpar I see now that the stack trace reported here is different (and even thinner) than the one I captured when I also experienced the same exception:

  <entry>
    <record>2453</record>
    <time>2019/05/08 19:38:39.349</time>
    <type>Error</type>
    <source>Editor or Editor Extension</source>
    <description>System.InvalidOperationException: Unable to get TextViewLine containing insertion point.&#x000D;&#x000A;
   at Microsoft.VisualStudio.Text.MultiSelection.Implementation.SelectionUIProperties.get_ContainingTextViewLine()&#x000D;&#x000A;
--- End of stack trace from previous location where exception was thrown ---&#x000D;&#x000A; 
  at Microsoft.VisualStudio.Telemetry.WindowsErrorReporting.WatsonReport.GetClrWatsonExceptionInfo(Exception exceptionObject)</description>
  </entry>

I will try to reproduce this under the debugger, since I believe I can make it happen.

[ricksladkey]

Well, this is fascinating. The invalid operation exception after :q is coming from VsVim:

    Microsoft.VisualStudio.Platform.VSEditor.dll!Microsoft.VisualStudio.Text.MultiSelection.Implementation.SelectionUIProperties.ContainingTextViewLine.get()   Unknown
    Microsoft.VisualStudio.Platform.VSEditor.dll!Microsoft.VisualStudio.Text.Editor.Implementation.CaretElement.ContainingTextViewLine.get()    Unknown
>   Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaret.IsRealCaretVisible.get() Line 109    C#
    Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaret.UpdateCaretCore() Line 549   C#
    Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaret.UpdateCaret() Line 539   C#
    Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaret.CaretDisplay.set(Vim.UI.Wpf.CaretDisplay value) Line 68  C#
    Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaretController.UpdateCaretDisplay() Line 138  C#
    Vim.UI.Wpf.dll!Vim.UI.Wpf.Implementation.BlockCaret.BlockCaretController.OnCaretRelatedEvent(object sender, object args) Line 49    C#
    [Native to Managed Transition]  
    [Managed to Native Transition]  
    mscorlib.dll!System.Delegate.DynamicInvokeImpl(object[] args)   Unknown
    mscorlib.dll!System.Delegate.DynamicInvoke(object[] args)   Unknown
    Vim.Core.dll!Microsoft.FSharp.Control.FSharpDelegateEvent<System.EventHandler<Vim.SwitchModeEventArgs>>.Trigger(object[] args)  Unknown
    Vim.Core.dll!Vim.StandardEvent<Vim.SwitchModeEventArgs>.Trigger(object sender, Vim.SwitchModeEventArgs args) Line 43    F#
    Vim.Core.dll!Vim.ModeMap.SwitchMode(Vim.ModeKind kind, Vim.ModeArgument arg) Line 150   F#
    Vim.Core.dll!Vim.VimBuffer.SwitchMode(Vim.ModeKind modeKind, Vim.ModeArgument modeArgument) Line 726    F#
    Vim.Core.dll!Vim.VimBuffer.SwitchPreviousMode() Line 738    F#
    Vim.Core.dll!Vim.VimBuffer.ProcessOneKeyInput(Vim.KeyInput keyInput) Line 551   F#

but, incredibly, it is being reported by Visual Studio even though VsVim is catching that exception!

                try
                {
                    var caret = _textView.Caret;
=>                  var line = caret.ContainingTextViewLine;
                    return line.VisibilityState != VisibilityState.Unattached && _textView.HasAggregateFocus;
                }
                catch (InvalidOperationException)
                {
                    // InvalidOperationException is thrown when we ask for ContainingTextViewLine and the view
                    // is not yet completely rendered.  It's safe to say at this point that the caret is not 
                    // visible
                    return false;
                }

The implication is that the ITextView class is re-throwing or otherwise re-processing that exception through another channel. Perhaps by hanging onto the exception and the fact that an error occurred.

It's easy enough to avoid this exception because _textView.IsClosed is true, so that should avoid the exception from happening. I'll make that change.

But if we can catch exceptions and still have them reported elsewhere, the environment is an utter minefield because we can't tell the difference between a handled exception and an unhandled one and we can't prevent exceptions we catch from bubbling up to the user.

[jaredpar]

but, incredibly, it is being reported by Visual Studio even though VsVim is catching that exception!

That seems quite bizarre to do.

The implication is that the ITextView class is re-throwing or otherwise re-processing that exception through another channel.

I _think_ what they're doing here is triggering a non-fatal Watson report. It's a way for the editor team to get data on the places where this type of programming error occurs. But I would also expect they wouldn't trigger a user facing exception when that happens, just silently report. Looks like my expectations are off here.

Either way, your fix should take care of the problem.

[olegtk]

No, the editor is not reporting exceptions handled by extensions. The call stack above should not cause the exception dialog and ActivityLog entry if Vim.UI.Wpf.Implementation.BlockCaret.BlockCaret.IsRealCaretVisible handles the exception.
It's probably a red herring, there is a known editor bug related to SelectionUIProperties.get_ContainingTextViewLine and VsVim perhaps just happen to trigger it.

[ricksladkey]

@olegtk

No, the editor is not reporting exceptions handled by extensions. The call stack above should not cause the exception dialog ...

I admit that it hard to believe, but I did not expect that you would reject the outcome of my detailed investigation so definitively! I guess I will have write a trivial sample extension that repros the symptom.

I will respond with my test extension over at the Visual Studio defect I reported here:

• https://developercommunity.visualstudio.com/content/problem/566964/exceptions-caught-and-handled-by-extensions-are-st.html

[olegtk]

Well, editor extensions and components throw so many exceptions we would see this dialog all the time so I'm confident this is not the case. Having said that, handling exceptions in an extensible system as you pointed out is a tricky business, that's why the message is intentionally vague: "This may be caused by an extension" and Editor or Editor Extension. This is likely an editor's bug, perhaps on some code path we introduced asynchrony by scheduling work to happen after layout. Having a repro with test extension of just VsVim repro steps would definitely help figuring this out. Thanks!

[ricksladkey]

@olegtk I disassembled the relevant Visual Studio code and it seems that that specific function (as opposed to any function throwing any exception), throws its own exception, catches it itself, reports it, and then I'm not sure, but maybe returns null? The try / filter / catch is not being properly disassembled into C# by my tool.

The C# might look something like this:

```C#
var result = /* some other method /;
if (result != null) return result;
try
{
throw new InvalidOperationException("...");
}
catch (Exception ex) when (ex is InvalidOperationException)
{
/ some internal helper */.LogError(ex);
}
return result;

which is seems pretty bizarre to me, but explains the symptoms we are seeing.

Here is the raw MSIL:

```MSIL
instance class [Microsoft.VisualStudio.Text.UI]Microsoft.VisualStudio.Text.Formatting.ITextViewLine get_ContainingTextViewLine () cil managed 
{
    // Method begins at RVA 0x50cd8
    // Code size 56 (0x38)
    .maxstack 2
    .locals init (
        [0] class [Microsoft.VisualStudio.Text.UI]Microsoft.VisualStudio.Text.Formatting.ITextViewLine,
        [1] class [mscorlib]System.InvalidOperationException,
        [2] class [Microsoft.VisualStudio.Text.UI]Microsoft.VisualStudio.Text.Formatting.ITextViewLine
    )

    IL_0000: ldarg.0
    IL_0001: ldloca.s 0
    IL_0003: callvirt instance bool [Microsoft.VisualStudio.Text.UI]Microsoft.VisualStudio.Text.AbstractSelectionPresentationProperties::TryGetContainingTextViewLine(class [Microsoft.VisualStudio.Text.UI]Microsoft.VisualStudio.Text.Formatting.ITextViewLine&)
    IL_0008: brfalse.s IL_000c

    IL_000a: ldloc.0
    IL_000b: ret

    IL_000c: nop
    .try
    {
        IL_000d: ldstr "Unable to get TextViewLine containing insertion point."
        IL_0012: newobj instance void [mscorlib]System.InvalidOperationException::.ctor(string)
        IL_0017: throw
    } // end .try
    filter
    {
        IL_0018: isinst [mscorlib]System.InvalidOperationException
        IL_001d: dup
        IL_001e: brtrue.s IL_0024

        IL_0020: pop
        IL_0021: ldc.i4.0
        IL_0022: br.s IL_002f

        IL_0024: stloc.1
        IL_0025: ldarg.0
        IL_0026: ldloc.1
        IL_0027: call instance bool Microsoft.VisualStudio.Text.MultiSelection.Implementation.SelectionUIProperties::LogException(class [mscorlib]System.Exception)
        IL_002c: ldc.i4.0
        IL_002d: cgt.un

        IL_002f: endfilter
    } // end filter
    catch
    {
        IL_0031: pop
        IL_0032: ldnull
        IL_0033: stloc.2
        IL_0034: leave.s IL_0036
    } // end handler

    IL_0036: ldloc.2
    IL_0037: ret
} // end of method SelectionUIProperties::get_ContainingTextViewLine

[ricksladkey]

@olegtk In any case, I'm certain that this exception is the only exception thrown between the closing of the document window and the reporting of the dialog, because I was in the debugger and the debugger logs all thrown exceptions to the output window. Furthermore, my exception settings were to break on that specific exception.

[ricksladkey]

@olegtk I analyzed the "other" issue, which is a different function, but exhibits the same symptoms of "an uncatchable exception" here:

• https://github.com/VsVim/VsVim/issues/2538#issuecomment-494166578

[olegtk]

Oh, you are right, including your original claim :), we do show this error dialog on handled exceptions.
I'm also right because this is not intentional. Looking at the code history it seems the intent of using GuardedOperations.HandleException in these places was to log fault telemetry so we could investigate later, but not to show the error dialog.
We are going to fix it as https://developercommunity.visualstudio.com/content/problem/566964/exceptions-caught-and-handled-by-extensions-are-st.html, thanks for reporting it!

[ricksladkey]

@olegtk Woohoo! Teamwork! Thanks for looking into this for us.