CodeLens blocking execution of code and also auto formatting i.e. F8/Format Document not working

[brwilkinson]

System Details

code -v 

1.23.1
d0182c3417d225529c6d5ad24b7572815d0de9ac
x64

$pseditor.EditorServicesVersion

1.7.0.0

code --list-extensions --show-versions
AwesomeAutomationTeam.azureautomation@0.6.2
bierner.color-info@0.5.0
DavidAnson.vscode-markdownlint@0.16.0
docsmsft.docs-authoring-pack@0.0.2
docsmsft.docs-markdown@0.0.2
eamodio.gitlens@8.3.0
eriklynd.json-tools@1.0.2
formulahendry.code-runner@0.9.3
ipedrazas.kubernetes-snippets@0.1.9
mindginative.terraform-snippets@2.0.1
mohsen1.prettify-json@0.0.3
ms-azuretools.vscode-azureappservice@0.8.1
ms-azuretools.vscode-azurefunctions@0.9.0
ms-azuretools.vscode-azurestorage@0.3.1
ms-azuretools.vscode-azureterraform@0.2.0
ms-azuretools.vscode-cosmosdb@0.7.1
ms-docfx.DocFX@0.1.3
ms-kubernetes-tools.vscode-kubernetes-tools@0.1.9
ms-mssql.mssql@1.3.1
ms-python.python@2018.4.0
ms-toolsai.vscode-ai@0.1.8
ms-vscode.azure-account@0.4.0
ms-vscode.azurecli@0.4.1
ms-vscode.csharp@1.15.2
ms-vscode.PowerShell@1.7.0
ms-vscode.vscode-azureextensionpack@0.0.9
ms-vsts.team@1.133.0
msazurermtools.azurerm-vscode-tools@0.4.2
mshdinsight.azure-hdinsight@0.0.16
PeterJausovec.vscode-docker@0.0.26
PKief.material-icon-theme@3.4.0
redhat.vscode-yaml@0.0.12
usqlextpublisher.usql-vscode-ext@0.2.13
VisualStudioOnlineApplicationInsights.application-insights@0.4.2
vsciot-vscode.azure-iot-edge@0.3.0
vsciot-vscode.azure-iot-toolkit@0.6.1

$PSVersionTable

Name                           Value
----                           -----
PSVersion                      6.1.0-preview.2
PSEdition                      Core
GitCommitId                    v6.1.0-preview.2
OS                             Microsoft Windows 10.0.17672
Platform                       Win32NT
PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0...}
PSRemotingProtocolVersion      2.3
SerializationVersion           1.1.0.1
WSManStackVersion              3.0

Issue Description

When I press F8, nothing happens, I only see output after 30 seconds up to 3 minutes.

The Integrated console just shows the last of the debug output

#-- Waiting for EditorServicesHost to complete execution ---------------------

However if I actually change the ps1 file that is open I see in the powershell extension log , that things are happening.
E.g. formatting and it also shows the language service is connected.

5/19/2018 2:32:24 PM [NORMAL] - Connecting to language service on port 13493...
5/19/2018 2:32:24 PM [NORMAL] - Language service connected.
5/19/2018 2:35:17 PM [VERBOSE] - Formatting on type at position {"line":35,"character":0} -

However the logs in the integrated console/terminal shows the same thing as the logs that I have attached.

#-- Waiting for EditorServicesHost to complete execution ---------------------

The F8 is non responsive. . . the commands are being queued somewhere however since after around ~2 minutes I will see the output.

E.g.
if I have this in the ps1 file, then I press F8 twice, nothing happens, then around 2 minutes later I see the output

gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
     99   524.29     519.61     101.13    5652   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
     99   524.38     519.73     101.17    5652   1 pwsh

I can type in the terminal the whole time.

e.g. typing in the terminal/console

Get-date
> Saturday, May 19, 2018 2:39:00 PM

However if I am pressing F8 on the ps1 script, nothing happens again. . . for about 2 minutes. . . then the result returns again.

I have this experience 100% of the time with both ps 6 and ps 5.1.

Sometimes I can write code for up to 15 minutes without this occurring. . . Mostly the Integrated Console is just unusable.

This is not a new issue, it has always been like this. Also I do screen shares with customers that I work with daily and I see the exact same issues with all of them. There are also references to this issue in pretty much Every Video from the PowerShell Conferences in both US and EU that have been published.
If you have a Windows 10 machine try it for yourself, it's easy to repro.

Between VSCode.exe --> winpty-agent.exe --> conhost.exe --> pwsh.exe --> The PowerShell extension --> PowerShell EditorServices I am not really sure where to look.

For the past two weeks I have been trying anything I can think off to work out what is causing the issue. . . including migrating my workflow to use pscore 6.0 and also using the Insider version, plus removing all extensions.

The main reason I am reporting is now is because, I actually decided to turn off the debug logging, incase it was part of the problem. . . so I switched it off. . .

"powershell.developer.editorServicesLogLevel": "Error",

Then for the first time ever, when I actually switched it on again, I actually started to see the diagnostics logs, that I had actually never seen before 😊

"powershell.developer.editorServicesLogLevel": "Diagnostic",

So I hope with these I can actually determine what is causing this long term issue.
Although for some reason the logs only seem to show the startup ? the last thing I see is:

#-- Waiting for EditorServicesHost to complete execution ---------------------

I have tried both

"terminal.integrated.rendererType": "canvas",

and
"terminal.integrated.rendererType": "dom",
these do not make any difference.

My extension are set to auto update, I deleted any extensions that I don't actually use everyday.
I have worked in both VSCode and the VSCode Insiders and this is the same issue on both.

Logs attached, they actually just show extactly what I now see in the console which is up to the following line and then nothing after ?

#-- Waiting for EditorServicesHost to complete execution ---------------------

I am not sure if that is normal of if the editorservices have hung ? The formatting seems to be working so I don't think they have hung, there is just nothing extra in the logs.

One other thing however if I do select a single line of code and then choose Format Selection, then all I see in the status bar is "Formatting PowerShell document …." which also lasts about 2 minutes.

So now if I . . .

1. Press F8 on a line of code 5 times . . . I wait. . .

2. While I am waiting if I do a format selection I see the "Formatting PowerShell document …." . . I wait.

3. After a few minutes, the two both complete at the same time, which I guess is expected.

4. Sometimes (like right now) the format and the F8 work fine/ as I would expect, however the good times only last around another 3 minutes, it starts again then go back to 1) . . . same issue again. I just waited two minutes and it's locked again, I just don't see any new logs anywhere ? only those startup logs ? which I have attached.

If I restart the current session, I see the new editor services startup. . . I see the integrated console has finished loading, I press F8 on the line of code, nothing. it's just the same, I wait. then eventually the command writes out.

One more detail, if I am on the Output "PowerShell extension Log" and I press F8 on the script, it flips be back to the Integrated console/terminal, however there is no output . . . until a minute later, then the results from pressing the F8 returns.

Are there any logs for EditorServices other than what appear to be startup logs?

happy to video screen capture of this or do a screen share. . .

[rkeithhill]

The most helpful logs are under your ~\.vscode\extensions\ms-vscode.powershell-1.7.0\logs dir. Find the sub-dir with the latest date (after repro'ing the problem), zip it up and attach it. The main file we need is the EditorServices.log file in that directory.

[brwilkinson]

@rkeithhill are you okay if I use the Insiders version ? or would you prefer if I provide logs from the standard version?

[rkeithhill]

Either would be fine. But in the case of Insiders the dir will be under ~\.vscode-insiders\....

[brwilkinson]

Thanks @rkeithhill

I restarted the current session to start a fresh set of logs. I have a nice clean repro. . .

The steps I took were:

1. Started the session again PS 6.1 5/19/2018 4:06:29 PM
2. I already had a script open Stop-AzureRMRGDP.ps1
   That script has a sample line of code in it: gps -id $pid
   I did F8 on that line. . . at 5/19/2018 4:06:34 PM (nothing happened)
   I waited a few seconds, then I went to the output tab and made a change in the file
   I can see there it was logged . . .
   vscode-powershell.log 5/19/2018 4:07:31 PM [VERBOSE] - Formatting on type at position
3. Back to the Terminal, nothing output as yet, it's been about 3 minutes.
   I pressed F8 a few more times.
4. I see in the vscode-powershell.log
   5/19/2018 4:10:40 PM [VERBOSE] - No formattable range returned.
   At this time the first output was shown in the Terminal for the first F8 that I did on gps -id $pid
5. There are still around 2 F8's that have not been output as yet.
6. I see in the vscode-powershell.log
   5/19/2018 4:13:13 PM [VERBOSE] - No formattable range returned.
   At this time the output from the 3 F8's that I did earlier were returned.

I hope this is helpful for the timings when you look into the EditorServices.log that is attached.

[brwilkinson]

By the way here is the full output from the session, it appears that I pressed F8 Five times, based on the returned output. The four initial and the one half way down.

#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> gps -id $pid
gps -id $pid
gps -id $pid
gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    109   770.01     524.68     212.92   22496   1 pwsh

gps -id $pid

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.02     430.88   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.91   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.95   22496   1 pwsh

 NPM(K)    PM(M)      WS(M)     CPU(s)      Id  SI ProcessName
 ------    -----      -----     ------      --  -- -----------
    108   527.65     546.03     430.95   22496   1 pwsh

[brwilkinson]

gc $Home\Desktop\1526767589-74dc5124-5067-4b8d-8a55-af9f05b1bd761526761220289\EditorServices.log | sls 'Attempting to execute command' -Context 2,2

2018-05-19 16:06:35 Attempting to execute command(s):

      Import-Module C:\Users\benwilk\.vscode-insiders\extensions\ms-vscode.powershell-1.7.0\modules\PowerShellEditorServices\bin\Core\..\..\Commands\PowerShellEditorServices.Commands.psd1

2018-05-19 16:06:35 Attempting to execute command(s):

      Import-Module PowerShellEditorServices.VSCode

2018-05-19 16:06:36 Attempting to execute command(s):

      D:\OneDrive\Documents\PowerShell\profile.ps1

2018-05-19 16:06:36 Attempting to execute command(s):

      prompt

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 Attempting to execute command(s):

      gps -id $pid

2018-05-19 16:10:40 ttempting to execute command(s):

      gps -id $pid

2018-05-19 16:14:56 Attempting to execute command(s):

      gps -id $pid

[brwilkinson]

Let me know if I repro with get-date would be more helpful?

[brwilkinson]

Also these are my profile settings for the autoformat

        "editor.formatOnSave": false,
        "editor.formatOnType": true,
        "editor.formatOnPaste": false,

I attached another repro with just F8 on get-date

#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> Get-Date
Get-Date
Get-Date
Get-Date
Get-Date

Saturday, May 19, 2018 5:03:52 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM

Saturday, May 19, 2018 5:05:36 PM

5/19/2018 5:02:23 PM [NORMAL] - Language service connected.
5/19/2018 5:02:46 PM [VERBOSE] - Formatting on type at position {"line":32,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:02:47 PM [VERBOSE] - Formatting on type at position {"line":33,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:02:47 PM [VERBOSE] - Formatting on type at position {"line":34,"character":0} - file:///d%3A/OneDrive/Documents/PowerShell/Modules/BRW/Stop-AzureRMRGDP.ps1...
5/19/2018 5:03:52 PM [VERBOSE] - No formattable range returned.
5/19/2018 5:03:52 PM [VERBOSE] - No formattable range returned.
5/19/2018 5:05:36 PM [VERBOSE] - Document formatting finished in 103.588s

[TylerLeonhardt]

Just out of curiosity, if you disable the formatOnType, does the issue still happen?

[brwilkinson]

Hey @tylerl0706 yes tried that.. Still the same, just nothing gets logged, because the format isn't triggered, however the delay is still there. Whatever is blocking stops the formatting as well as the execution. Once that block has completed, both occur/run straight away.

[rkeithhill]

@tylerl0706 yeah, we need threadsafe logging:

  {
      "jsonrpc": "2.0",
      "method": "textDocument/publishDiagnostics",
      "params": {
        "uri": "file:///d%3A/On

    Session state changed --mmand(s):
op-AzureRMRGDP.ps1",
     
    
gnos

        Old state: Ready

    },
    
    
2018-05-19 17:05:36 [VERBOSE        Result: NotFinished
line 61 of C:\projects\powershelleditorservices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageWriter.cs
   }
        },
        "o
 

2018-05-19 17:05:36 [VERBOSE] - Method "ExecuteCnStand" anged" a491 of C171 of C:\projects\powershelleditorservices\src\PowerShellEditorServices\Session\PowerSext.cs
ext.cs
ecution completed successfully.

  {
      "jsonrpc": "2.0",
      "method": "textDocument/publishDiagnostics",
      "params": {
        "uri": "file:///d%3A/On

    Session state changed --mmand(s):
op-AzureRMRGDP.ps1",
     
    
gnos

        Old state: Ready

    },

[TylerLeonhardt]

Oh wow. Well @rjmholt is actively working on this! 😃

[rkeithhill]

@brwilkinson Dang. I can't repro this on my Win 10 PC using PS 6.1 preview 2.

What happens if you create a new, empty .ps1 file in it, place that one line - gps -id $pid - in it and use F8 to execute it. Do you still see the issue?

Also what do these two commands return: Get-Module and (Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke()?

[brwilkinson]

@rkeithhill perhaps try writing and loading a small function?!

I can repro with the following:

new blank script: D:\OneDrive\Foo.ps1 (BTW I also tested outside of onedrive path, this issue still occurs).

get-date (F8 works)

gps (F8 works)

gmo | foreach Name (F8 works)

Microsoft.PowerShell.Management
Microsoft.PowerShell.Security
Microsoft.PowerShell.Utility
posh-git
PowerShellEditorServices.Commands
PowerShellEditorServices.VSCode

(Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke() (F8 works)

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Script     1.16.1     PSScriptAnalyzer                    {Get-ScriptAnalyzerRule, Invoke-Formatter, Invoke-ScriptAnalyzer}

Type in a function foo (breaks, does not execute on F8)

function foo {

    get-date
}

still waiting . . . (still broken)

Original load of the function still waiting + 5 minute later

made a test change to the file, just pressed enter to make / delete a line, nothing logged, since I have all auto formatting disabled.

Still waiting .. . . +7 minutes.

finally loads the function,

foo               

date is returned, not blocked right now.

Sunday, May 20, 2018 12:40:20 PM

This is the full output from the terminal

VERBOSE: Invoking Start-EditorServicesHost
VERBOSE: Start-EditorServicesHost returned Microsoft.PowerShell.EditorServices.Host.EditorServicesHost
VERBOSE: Processing object of type [Hashtable] at depth 0
VERBOSE: Processing object of type [Int32] at depth 1
VERBOSE: Processing object of type [Int32] at depth 1
VERBOSE: Writing session file with contents:
VERBOSE: {"status":"started","debugServicePort":11866,"debugServiceTransport":"Tcp","languageServicePort":12356,"languageServiceTransport":"Tcp"}
VERBOSE: Wrote out session file
VERBOSE:
#-- Waiting for EditorServicesHost to complete execution ---------------------
AZ:\> gmo

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Manifest   3.1.0.0    Microsoft.PowerShell.Management     {Add-Content, Clear-Content, Clear-Item, Clear-ItemProperty...}
Manifest   3.0.0.0    Microsoft.PowerShell.Security       {ConvertFrom-SecureString, ConvertTo-SecureString, Get-Acl, Get-AuthenticodeSignature...}
Manifest   3.1.0.0    Microsoft.PowerShell.Utility        {Add-Member, Add-Type, Clear-Variable, Compare-Object...}
Script     0.7.3      posh-git                            {Add-PoshGitToProfile, Add-SshKey, Enable-GitColors, Expand-GitCommand...}
Script     0.2.0      PowerShellEditorServices.Commands   {ConvertFrom-ScriptExtent, ConvertTo-ScriptExtent, Find-Ast, Get-Token...}
Script     0.2.0      PowerShellEditorServices.VSCode     {Close-VSCodeHtmlContentView, New-VSCodeHtmlContentView, Set-VSCodeHtmlContentView, Show-VSCodeHtmlContentView...}


AZ:\> gmo | foreach Name
Microsoft.PowerShell.Management
Microsoft.PowerShell.Security
Microsoft.PowerShell.Utility
posh-git
PowerShellEditorServices.Commands
PowerShellEditorServices.VSCode
AZ:\> (Get-Runspace -id 4).CreatePipeline("Get-Module PSScriptAnalyzer").Invoke()

ModuleType Version    Name                                ExportedCommands
---------- -------    ----                                ----------------
Script     1.16.1     PSScriptAnalyzer                    {Get-ScriptAnalyzerRule, Invoke-Formatter, Invoke-ScriptAnalyzer}


AZ:\> function foo {

    get-date
}
AZ:\> foo

Sunday, May 20, 2018 12:40:20 PM