fix for CLR_EXCEPTION_System.NullReferenceException_80004003_Microsoft.VisualStudio.InteractiveWindow.dll #26770

ivanbasov · 2018-05-10T21:43:32Z

Customer scenario

Visual Studio closes or restarts and attempts to close and restart Roslyn which attempts to do the same with Interactive Host. Interactive Host attempts to send a message that it is closing back to Roslyn. However, Roslyn disappears just before. This is a race condition.

Bugs this fixes

https://devdiv.visualstudio.com/DevDiv/_workitems/edit/514822

Workarounds, if any

No

Risk

Low

Performance impact

None

Is this a regression from a previous update?

No

Root cause analysis

We haven't considered all possible timing combinations happening between threads.

How was the bug found?

Customer reports (Watson)

ivanbasov · 2018-05-11T01:15:00Z

retest this please #Resolved

ivanbasov · 2018-05-11T19:26:10Z

@tmat, @jinujoseph please review #Resolved

ivanbasov · 2018-05-14T16:58:09Z

@tmat, @jinujoseph please review. This is a regression fix we are going to insert into 15.7 servicing. #Resolved

tmat · 2018-05-14T21:35:03Z

src/Interactive/Features/Interactive/Core/InteractiveHost.RemoteService.cs

                        }
                    }
+
+                    await _host.TryGetOrCreateRemoteServiceAsync(processPendingOutput: true).ConfigureAwait(false);


await _host.TryGetOrCreateRemoteServiceAsync(processPendingOutput: true).ConfigureAwait(false); [](start = 20, length = 95)

Why is it ok to run this outside of the lock now? #Resolved

tmat · 2018-05-14T23:27:43Z

                else

if (previousService == null) return default; #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:348 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:27:55Z

            Debug.Assert(currentRemoteService != null);

if (currentRemoteService == null) return default; #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:328 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:31:12Z

        return (_lazyRemoteService?.InitializedService != null &&

Extract variable. #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:73 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:31:34Z

    public void Dispose()

Comment: Dispose may be called anytime. #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:227 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:32:30Z

    private TextWriter _output;

lock (_outputGuard) { _output.Write ... } #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:41 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:32:46Z

    private TextWriter _errorOutput;

lock (_errorOutputGuard) { _errorOutput.Write ... } #Resolved

Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:42 in 9973ba0. [](commit_id = 9973ba0, deletion_comment = False)

tmat · 2018-05-14T23:33:11Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

-        {
-            ReportProcessExited(process);
-            return TryGetOrCreateRemoteServiceAsync(processPendingOutput: true);
-        }


Keep #Resolved

tmat · 2018-05-14T23:33:30Z

src/Interactive/Features/Interactive/Core/InteractiveHost.RemoteService.cs

                            _processExitHandlerStatus = ProcessExitHandlerStatus.Handled;
                            // Should set _processExitHandlerStatus before calling OnProcessExited to avoid deadlocks.
                            // Calling the host should be within the lock to prevent its disposing during the execution.
-                            await _host.OnProcessExited(Process).ConfigureAwait(false);


await _host.OnProcessExited(Process).ConfigureAwait(false); [](start = 27, length = 60)

Move outside of the lock and keep. #Resolved

_host?.OnProcessExited

In reply to: 188128872 [](ancestors = 188128872)

tmat · 2018-05-14T23:33:59Z

src/Interactive/Features/Interactive/Core/InteractiveHost.RemoteService.cs

                }
            }

            internal void Dispose(bool joinThreads)


internal void Dispose(bool joinThreads) [](start = 11, length = 40)

Comment: may be called anytime #Resolved

tmat · 2018-05-14T23:37:47Z

        DisposeRemoteService(disposing: true);

before disposing remote service

lock (_outputGuard) _output = TextWriter.Null;
lock (_errorOutputGuard) _errorOutput = TextWriter.Null;
}
``` #Resolved

---
Refers to: src/Interactive/Features/Interactive/Core/InteractiveHost.cs:230 in 9973ba0. [](commit_id = 9973ba043a399d5232fbd0e0fdbab8220706c553, deletion_comment = False)

cston · 2018-05-15T15:00:39Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

+
+            lock(_errorOutputGuard)
+            {
+                _errorOutputGuard = TextWriter.Null;


_errorOutput = ... #Resolved

cston · 2018-05-15T15:01:40Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

        private TextWriter _output;
        private TextWriter _errorOutput;
+        private object _outputGuard;
+        private object _errorOutputGuard;


readonly for both. And do we need two lock objects or could the same object be used for both _output and _errorOutput? #Resolved

Thanks!

Added readonly

Discussed with Tomas to use a common lock or separate ones and found that separate ones should be better to avoid two channels to be executed independently.

In reply to: 188322002 [](ancestors = 188322002)

cston · 2018-05-15T15:03:18Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

-            var writer = error ? ErrorOutput : Output;
+            var writer = error ? _errorOutput : _output;
            writer.Write(buffer, 0, count);
        }


Do we need to lock around writer.Write()? #Resolved

Yes.

In reply to: 188322596 [](ancestors = 188322596)

tmat · 2018-05-15T16:56:31Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

+                lock (_errorOutputGuard)
+                {
+                    _errorOutput.WriteLine(FeaturesResources.Failed_to_launch_0_process_exit_code_colon_1_with_output_colon, _hostPath, process.ExitCode);
+                    _errorOutput.WriteLine(process.StandardError.ReadToEnd());


process.StandardError.ReadToEnd() [](start = 43, length = 33)

Move process.StandardError.ReadToEnd() out of the lock. #Resolved

tmat · 2018-05-15T16:57:51Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

        }
-
-        public TextWriter Output
+        public void SetOutput(TextWriter value)


missing line break #Resolved

tmat · 2018-05-15T16:59:42Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

-                // disposed or not reset:
-                Debug.Assert(currentRemoteService != null);
+                // Remote service may be disposed anytime.
+                if (currentRemoteService == null) { return default; }


{ [](start = 50, length = 1)

style: braces on separate lines #Resolved

tmat · 2018-05-15T16:59:46Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

                    }
                    else
                    {
+                        if (previousService == null) { return default; }


{ return default; } [](start = 53, length = 19)

style: braces on separate lines #Resolved

This needs to go after newService.Dispose(joinThreads: false);

Actually, even better: just move if (currentRemoteService == null) { return default; } as the first statement of the for loop and then this is not needed

In reply to: 188362651 [](ancestors = 188362651)

tmat

🕐

tmat · 2018-05-15T19:47:19Z

src/Interactive/Features/Interactive/Core/InteractiveHost.cs

-                oldOutput.Flush();
-            }
+            var oldOutput = Interlocked.Exchange(ref _output, value);
+            oldOutput.Flush();


Perhaps we should now do this:

lock (_outputGuard) { _output.Flush(); _output = value; }

And then call SetOutput(TextWriter.Null); from Dispose #Resolved

tmat

…Microsoft.VisualStudio.InteractiveWindow.dll (dotnet#26770)" This reverts commit db46bcf.

…Microsoft.VisualStudio.InteractiveWindow.dll (#26770)" (#26892) This reverts commit db46bcf.

…t.VisualStudio.InteractiveWindow.dll (dotnet#26770)

fix to discuss

ffae317

ivanbasov added Bug Area-Interactive Tenet-Reliability Customer telemetry indicates that the product is failing in a crash/hang/dataloss manner. labels May 10, 2018

ivanbasov added this to the 15.7 milestone May 10, 2018

ivanbasov requested review from jinujoseph and tmat May 10, 2018 21:43

ivanbasov requested a review from a team as a code owner May 10, 2018 21:43

iteration 2

9973ba0

tmat reviewed May 14, 2018

View reviewed changes

feedback addressed

1ad541e

ivanbasov requested a review from cston May 15, 2018 00:46

cston reviewed May 15, 2018

View reviewed changes

tmat reviewed May 15, 2018

View reviewed changes

tmat requested changes May 15, 2018

View reviewed changes

feedback addressed

7d60431

cston approved these changes May 15, 2018

View reviewed changes

jinujoseph added the Needs Shiproom Approval label May 15, 2018

tmat reviewed May 15, 2018

View reviewed changes

test fix. feedback

835f004

tmat approved these changes May 15, 2018

View reviewed changes

jinujoseph added Approved to merge and removed Needs Shiproom Approval labels May 15, 2018

ivanbasov merged commit db46bcf into dotnet:dev15.7.x May 15, 2018

ivanbasov deleted the interactive branch May 15, 2018 23:53

agocke added a commit to agocke/roslyn that referenced this pull request May 16, 2018

Revert "fix for CLR_EXCEPTION_System.NullReferenceException_80004003_…

9233a8f

…Microsoft.VisualStudio.InteractiveWindow.dll (dotnet#26770)" This reverts commit db46bcf.

agocke mentioned this pull request May 16, 2018

Revert "fix for CLR_EXCEPTION_System.NullReferenceException_80004003_… #26892

Merged

ivanbasov restored the interactive branch May 16, 2018 18:09

ivanbasov mentioned this pull request May 16, 2018

fix for CLR_EXCEPTION_System.NullReferenceException_80004003_Microsoft.VisualStudio.InteractiveWindow.dll (master) #26910

Merged

agocke added a commit that referenced this pull request May 16, 2018

Revert "fix for CLR_EXCEPTION_System.NullReferenceException_80004003_…

dab02c2

…Microsoft.VisualStudio.InteractiveWindow.dll (#26770)" (#26892) This reverts commit db46bcf.

ivanbasov added a commit to ivanbasov/roslyn that referenced this pull request Jun 13, 2018

fix for CLR_EXCEPTION_System.NullReferenceException_80004003_Microsof…

f7e7c77

…t.VisualStudio.InteractiveWindow.dll (dotnet#26770)

fix for CLR_EXCEPTION_System.NullReferenceException_80004003_Microsoft.VisualStudio.InteractiveWindow.dll #26770

fix for CLR_EXCEPTION_System.NullReferenceException_80004003_Microsoft.VisualStudio.InteractiveWindow.dll #26770

Uh oh!

Conversation

ivanbasov commented May 10, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Customer scenario

Bugs this fixes

Workarounds, if any

Risk

Performance impact

Is this a regression from a previous update?

Root cause analysis

How was the bug found?

Uh oh!

ivanbasov commented May 11, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ivanbasov commented May 11, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ivanbasov commented May 14, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

tmat May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmat May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmat May 14, 2018

Choose a reason for hiding this comment

Uh oh!

tmat May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmat commented May 14, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cston May 15, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cston May 15, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ivanbasov May 15, 2018

Choose a reason for hiding this comment

Uh oh!

cston May 15, 2018 • edited by ivanbasov Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tmat May 15, 2018

ivanbasov commented May 10, 2018 •

edited

Loading

ivanbasov commented May 11, 2018 •

edited

Loading

ivanbasov commented May 11, 2018 •

edited

Loading

ivanbasov commented May 14, 2018 •

edited

Loading

tmat May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

tmat May 14, 2018 •

edited by ivanbasov

Loading

tmat May 14, 2018 •

edited by ivanbasov

Loading

tmat May 14, 2018 •

edited by ivanbasov

Loading

tmat commented May 14, 2018 •

edited by ivanbasov

Loading

cston May 15, 2018 •

edited by ivanbasov

Loading

cston May 15, 2018 •

edited by ivanbasov

Loading

cston May 15, 2018 •

edited by ivanbasov

Loading

tmat May 15, 2018 •

edited by ivanbasov

Loading

tmat May 15, 2018 •

edited by ivanbasov

Loading

tmat May 15, 2018 •

edited by ivanbasov

Loading

tmat May 15, 2018 •

edited by ivanbasov

Loading

tmat May 15, 2018 •

edited

Loading

tmat May 15, 2018 •

edited by ivanbasov

Loading