Fixes #155 - selecting outermost scope crashes debug host. #156

rkeithhill · 2016-02-15T00:28:20Z

Because we use AddScript, that adds another scope not associated with any filename. That resulted in a StackFrame ScriptPath with a null value. Later, VSCode sent us a request for soruce with a sourceReference value of null. That caused the JSON deserialization of that message to throw and that crashed the debug host. I made two changes. First, when we construct the StackFrameDetails, if the PowerShell CallStackFrame.ScriptName is null, we use the string "" instead for ScriptPath. The second change was to ExecuteScriptAtPath. Essentially, if you do not pass args we now use AddCommand(scriptPath) which does not add the extra stack frame. If you do use args then we still use AddScript. You will see the extra outermost stack frame of ", ". What is somewhat useful about this is that you can open Script variables to look at $MyInvocation.Line to see how the script was invoked with the args.

Because we use AddScript, that adds another scope not associated with any filename. That resulted in a StackFrame ScriptPath with a null value. Later, VSCode sent us a request for soruce with a sourceReference value of null. That caused the JSON deserialization of that message to throw and that crashed the debug host. I made two changes. First, when we construct the StackFrameDetails, if the PowerShell CallStackFrame.ScriptName is null, we use the string "<No File>" instead for ScriptPath. The second change was to ExecuteScriptAtPath. Essentially, if you do not pass args we now use AddCommand(scriptPath) which does not add the extra stack frame. If you do use args then we still use AddScript. You will see the extra outermost stack frame of "<ScriptBlock>, <NoFile>". What is somewhat useful about this is that you can open Script variables to look at $MyInvocation.Line to see how the script was invoked with the args.

daviwil · 2016-02-15T00:56:24Z

Looks great! Had to restart the CI build because of a test hang :/ You can merge it anytime though.

daviwil · 2016-02-15T00:56:49Z

The test hang is an old recurring one, not to imply that your change caused it ;)

daviwil · 2016-02-15T01:05:33Z

Argh, another hang. Bad luck on Appveyor today!

rkeithhill · 2016-02-15T01:19:53Z

So if I debug that test ServiceExecutesReplCommandAndReceivesInputPrompt it passes. If I just run it, it fails. A timing thing?

rkeithhill · 2016-02-15T01:38:57Z

Hmm, if I debug the unit test printf style, it seems the output is off by one:

The Key Value should be in index 1 not two.

daviwil · 2016-02-15T01:43:13Z

Yeah, there's a funky timing issue with that one for some reason... There's some kind of bug in OutputDebouncer but I haven't been able to find a consistent repro to help diagnose a fix. Only appears on AppVeyor for me. Strange thing is that I put a hack in that test to avoid it and it still seems to get hit for you.

rkeithhill · 2016-02-15T01:51:19Z

In my case, the extra newline is appearing between Name: John and Key Value which the test hack doesn't invoke in my case because the extra line is not before Name: John.

rkeithhill · 2016-02-15T02:20:32Z

Does this printf (action breakpoint) output tell you anything:

Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) read output "\r\n                $NameField = New-Object System.Management.Automation.Host.FieldDescription \"Name\"\r\n                $NameField.SetParameterType([System.String])\r\n                $fields = [System.Management.Automation.Host.FieldDescription[]]($NameField)\r\n                $host.ui.Prompt($null, $null, $fields)\r\n\r\nName: John\r\n"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) nextOutputString is ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) foud new line? true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "                $NameField = New-Object System.Management.Automation.Host.FieldDescription \"Name\""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "                $NameField.SetParameterType([System.String])"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "                $fields = [System.Management.Automation.Host.FieldDescription[]]($NameField)"
Lock Dispose 14696841
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "                $host.ui.Prompt($null, $null, $fields)"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "Name: John"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $NameField = New-Object System.Management.Automation.Host.FieldDescription \"Name\""  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $NameField.SetParameterType([System.String])"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $fields = [System.Management.Automation.Host.FieldDescription[]]($NameField)"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $host.ui.Prompt($null, $null, $fields)"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  ""  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "Name: John"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  ""  /  lineHasNewLine true
Lock Dispose 14696841
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) read output "\r\nKey  Value\r\n---  -----\r\nName John \r\n\r\n\r\n\r\nPS C:\\Users\\Keith\\GitHub\\rkeithhill\\PowerShellEditorServices\\test\\PowerShellEditorServices.Test.Host\\bin\\Debug\r\n"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) nextOutputString is ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) foud new line? true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "Key  Value"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "---  -----"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "Name John "
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: "PS C:\\Users\\Keith\\GitHub\\rkeithhill\\PowerShellEditorServices\\test\\PowerShellEditorServices.Test.Host\\bin\\Debug"
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) enqueuing line: ""
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "Key  Value"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "---  -----"  /  lineHasNewLine true

daviwil · 2016-02-15T02:22:47Z

Awesome! I was just about to do something like that, thanks for the log. I'll analyze this for a bit and let you know.

After some thought, I think this is a bug in the OutputReader that I'm using to read buffered output. I can see where there might be a cause that an empty string is being returned when no output is ready yet. Your log should help me come up with the reason why

daviwil · 2016-02-15T02:38:59Z

The last line in this sequence seems wrong to me:

Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $fields = [System.Management.Automation.Host.FieldDescription[]]($NameField)"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "                $host.ui.Prompt($null, $null, $fields)"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  ""  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  "Name: John"  /  lineHasNewLine true
Microsoft.PowerShell.EditorServices.Test.Host.OutputReader.ReadLine(string) buffered nextOutputString:  ""  /  lineHasNewLine true

I think the logic for lineHasNewLine is incorrectly marking the last item as a newline when the final segment is an empty string. Let me see if I can come up with a fix

daviwil · 2016-02-15T02:40:02Z

And I think this is only when the lines that are read are being enqueued into the buffer.

daviwil · 2016-02-15T03:17:59Z

I think I have a fix for this, will submit as a separate PR

daviwil · 2016-02-15T03:27:53Z

Lets see if this fixes it: #158

rkeithhill · 2016-02-15T03:57:02Z

Hmm, is this hanging again? The unit tests did all pass before I pushed the merged changes from PR #158.

daviwil · 2016-02-15T04:02:00Z

Damn... Hanging on the same test. This is really annoying.

daviwil · 2016-02-15T04:06:28Z

The unfortunate thing is that there's no reliable way to debug these issues on the CI server. The best I can usually do is enable RDP and then remote desktop into the machine and try to read the logs. I'll take a look at it some more tomorrow. You can go ahead and merge the PR if you like or you can keep it open so we can try any new bug fixes that I figure out.

rkeithhill · 2016-02-15T08:02:42Z

FWIW unit tests pass much more consistently now on my dev PC. Occasionally the tests hang and when I attach the debugger, I see that Shutdown is waiting for output to flush on one thread:

    mscorlib.dll!System.Threading.ManualResetEventSlim.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) Line 662 C#
    mscorlib.dll!System.Threading.Tasks.Task.SpinThenBlockingWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) Line 3320  C#
    mscorlib.dll!System.Threading.Tasks.Task.InternalWait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) Line 3252  C#
    mscorlib.dll!System.Threading.Tasks.Task.Wait(int millisecondsTimeout, System.Threading.CancellationToken cancellationToken) Line 3167  C#
    mscorlib.dll!System.Threading.Tasks.Task.Wait() Line 3054   C#
>   Microsoft.PowerShell.EditorServices.Protocol.dll!Microsoft.PowerShell.EditorServices.Protocol.Server.LanguageServer.Shutdown() Line 86  C#
...

daviwil · 2016-02-15T16:14:20Z

Jeez, even with a CPU load generator I can't make these issues repro on my machine. Seems like I need to specify a timeout there at the very least, but I need to check and see why it would be hanging anyway. Might be that the client's stream has disconnected before the final flush can occur so the SendEvent method in OutputDebouncer.OnFlush can't complete. That should throw an error, though...

If you're able to reproduce that issue locally again sometime today, could you email me a dump of the host process? It'd be helpful to see what state everything is in at that point.

daviwil · 2016-02-16T02:13:03Z

Thanks to the dump you sent I was able to reproduce and fix the latest hang issue. Sync, merge, and try again if you don't mind :)

rkeithhill · 2016-02-16T03:08:16Z

Yay! The tests passed with no hangs!

…ackframe Fixes #155 - selecting outermost scope crashes debug host.

daviwil · 2016-02-16T03:09:12Z

That's awesome. Thanks a lot for the debugging help!

rkeithhill · 2016-02-16T03:09:41Z

No problem. Hopefully that's the end of the unit test hangs (crossing my fingers). :-)

daviwil · 2016-02-16T03:10:06Z

Haha, I'm sure I'll find a way to create some more soon ;)

msftclas added the cla-already-signed label Feb 15, 2016

daviwil mentioned this pull request Feb 15, 2016

Tests using OutputReader hang intermittently #157

Closed

Merge branch 'master' into rkeithhill/addscript-extra-stackframe

84be130

Merge branch 'master' into rkeithhill/addscript-extra-stackframe

a2e206c

rkeithhill added a commit that referenced this pull request Feb 16, 2016

Merge pull request #156 from rkeithhill/rkeithhill/addscript-extra-st…

3c1e119

…ackframe Fixes #155 - selecting outermost scope crashes debug host.

rkeithhill merged commit 3c1e119 into PowerShell:master Feb 16, 2016

rkeithhill deleted the rkeithhill/addscript-extra-stackframe branch February 16, 2016 03:09

Fixes #155 - selecting outermost scope crashes debug host. #156

Fixes #155 - selecting outermost scope crashes debug host. #156

Uh oh!

Conversation

rkeithhill commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

rkeithhill commented Feb 15, 2016

Uh oh!

daviwil commented Feb 15, 2016

Uh oh!

daviwil commented Feb 16, 2016

Uh oh!

rkeithhill commented Feb 16, 2016

Uh oh!

daviwil commented Feb 16, 2016

Uh oh!

rkeithhill commented Feb 16, 2016

Uh oh!

daviwil commented Feb 16, 2016

Uh oh!

Uh oh!