WIP Enhance Start-EditorServices.ps1 for better logging and fix bugs #1198

rkeithhill · 2018-02-15T06:27:51Z

The first commit, fixes a few bugs with the original Test-PortAvailability function. The second commit. try a different approach to looking for ports in use - see https://stackoverflow.com/questions/570098/in-c-how-to-check-if-a-tcp-port-is-available.

BTW I had to remove the signature to test this and there's no point putting it back because it would be invalid. Seems like we should not commit scripts that are signed but instead, sign them just before publishing.

Here is a sample of Start-EditorServices.log contents:

**********************
Windows PowerShell transcript start
Start time: 20180214232028
Username: KEITH-YOGA2\Keith
RunAs User: KEITH-YOGA2\Keith
Configuration Name: 
Machine: KEITH-YOGA2 (Microsoft Windows NT 10.0.16299.0)
Host Application: C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive -ExecutionPolicy Bypass -Command & 'C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\scripts\Start-EditorServices.ps1' -EditorServicesVersion '1.5.1' -HostName 'Visual Studio Code Host' -HostProfileId 'Microsoft.VSCode' -HostVersion '1.5.1' -AdditionalModules @('PowerShellEditorServices.VSCode') -BundledModulesPath 'C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\module' -EnableConsoleRepl -LogLevel 'Verbose' -LogPath 'C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\logs\1518675624-someValue.sessionId\EditorServices.log' -SessionDetailsPath 'C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\sessions\PSES-VSCode-4788-759658' -FeatureFlags @()
Process ID: 6228
PSVersion: 5.1.16299.248
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.16299.248
BuildVersion: 10.0.16299.248
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\Users\Keith\GitHub\rkeithhill\vscode-powershell\logs\1518675624-someValue.sessionId\Start-EditorServices.log
VERBOSE: 
#-- Updated PSModulePath to: -------------------------------------------------
VERBOSE: C:\Users\Keith\Documents\WindowsPowerShell\Modules
VERBOSE: C:\Program Files\WindowsPowerShell\Modules
VERBOSE: C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\
VERBOSE: C:\Program Files\Microsoft Message Analyzer\PowerShell\
VERBOSE: C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\module
VERBOSE: 
#-- Check required modules available -----------------------------------------
VERBOSE: Testing module availability PowerShellGet
VERBOSE: Populating RepositorySourceLocation property for module PowerShellGet.
VERBOSE: Loading module from path 'C:\Users\Keith\Documents\WindowsPowerShell\Modules\PowerShellGet\1.6.0\PSModule.psm1'.
VERBOSE: Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\PowerShellGet\1.0.0.1\PSModule.psm1'.
VERBOSE: PowerShellGet  found
VERBOSE: Testing module availability PowerShellEditorServices 1.5.1
VERBOSE: Loading module from path 'C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\module\PowerShellEditorServices\PowerShellEditorServices.psm1'.
VERBOSE: PowerShellEditorServices 1.5.1 found
VERBOSE: 
#-- Start up PowerShellEditorServices ----------------------------------------
VERBOSE: Importing PowerShellEditorServices
VERBOSE: Loading module from path 'C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\module\PowerShellEditorServices\PowerShellEditorServices.psd1'.
VERBOSE: Loading module from path 'C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\module\PowerShellEditorServices\PowerShellEditorServices.psm1'.
VERBOSE: Exporting function 'Start-EditorServicesHost'.
VERBOSE: Exporting function 'Compress-LogDir'.
VERBOSE: Exporting function 'Get-PowerShellEditorServicesVersion'.
VERBOSE: Importing function 'Compress-LogDir'.
VERBOSE: Importing function 'Get-PowerShellEditorServicesVersion'.
VERBOSE: Importing function 'Start-EditorServicesHost'.
VERBOSE: Ports in use in range 10000-30000:
VERBOSE: 12325,15059
VERBOSE: Searching for available socket port for the language service
VERBOSE: Checking port: 12777, attempts remaining 10 --------------------
VERBOSE: Port: 12777 is available
VERBOSE: Searching for available socket port for the debug service
VERBOSE: Checking port: 24342, attempts remaining 10 --------------------
VERBOSE: Port: 24342 is available
PowerShell Integrated Console
VERBOSE: Invoking Start-EditorServicesHost
VERBOSE: Start-EditorServicesHost returned Microsoft.PowerShell.EditorServices.Host.EditorServicesHost
VERBOSE: Writing session file with contents:
VERBOSE: {"debugServicePort":24342,"status":"started","channel":"tcp","languageServicePort":12777}
VERBOSE: Wrote out session file
VERBOSE: 
#-- Waiting for EditorServicesHost to complete execution ---------------------

rkeithhill · 2018-02-15T16:26:56Z

Well, shoot. The NetworkInformation classes I tested with on PS Core (on Windows) doesn't work on Linux (WSL). That's a bummer because when I tested ports I knew were in use (via tcpview, netstat), the old Test-PortAvailability function showed them as available.

Try this. Open VSCode and then a PS1 file, note the lang/debug ports the session is using in the log file. Now try this (substitute in your port #):

$port = 29991
$ipAddress = [System.Net.Dns]::GetHostEntryAsync("localhost").Result.AddressList[0];
try { $tcp = New-Object System.Net.Sockets.TcpListener @($ipAddress, $port); $tcp.Start(); $tcp.Stop() } catch [System.Net.Sockets.SocketException] { $_ }

Even though that port is in use by an instance of PSES, it shows as available. :-(

rkeithhill · 2018-02-15T16:35:19Z

Hmm, if I retrieve the IP address like so, the above code works better:

$ipAddress = [System.Net.IPAddress]::Parse("127.0.0.1")

This gives an ipv4 address:

AddressFamily      : InterNetwork
ScopeId            :
IsIPv6Multicast    : False
IsIPv6LinkLocal    : False
IsIPv6SiteLocal    : False
IsIPv6Teredo       : False
IsIPv4MappedToIPv6 : False
Address            : 16777343
IPAddressToString  : 127.0.0.1

It seems that by using GetHostEntryAsync, I'm getting back an ipv6 address:

AddressFamily      : InterNetworkV6
ScopeId            : 0
IsIPv6Multicast    : False
IsIPv6LinkLocal    : False
IsIPv6SiteLocal    : False
IsIPv6Teredo       : False
IsIPv4MappedToIPv6 : False
Address            :
IPAddressToString  : ::1

I wonder if we should test both IP address types?

TylerLeonhardt · 2018-02-15T19:54:58Z

I noticed that you can do:

$ipAddress = [System.Net.IPAddress]::Parse("127.0.0.1")
ipAddress.MapToIPv6() # or .MapToIPv4

but I haven't figured out how to get the ports just yet

Modify Test-PortAvailability to check each address (ipv4 and ipv6) in AddressList for localhost.

rkeithhill · 2018-02-16T03:39:01Z

OK, I think this is ready for a serious review. I'd like to get this into 1.6.0 to see if we can get some info to track down why PSES isn't starting up for some folks. I would appreciate someone testing this on macOS.

TylerLeonhardt · 2018-02-16T03:40:22Z

Any particular test steps or would you like me to just start/stop vscode a bunch of times?

rkeithhill · 2018-02-16T03:44:31Z

The tcp port range is so broad - 10000 to 30000 that it is unlikely that you'll run into ports in use. Could you start one VSCode session - note one of the ports in use (in the log file). Then temporarily hack the $minPortNumber / $maxPortNumber values in the Start-EditorServices.ps1 file (just under params decl) to a range of say 4 around the port number you know to be in use. Then run the extension in the debug host (with log level set to Verbose) and watch the PSIC window as it starts up. I'd like to see that it finds the port known to be in use to be, well, in use. And then attempt another port. Thanks.

rkeithhill · 2018-02-19T01:59:45Z

I wonder if these tests are going to fail until a new signature is applied to this script file?

TylerLeonhardt · 2018-02-19T04:01:38Z

Hmmm I'm not sure that's the case here. I'm seeing this issue across AppVeyor and Travis:

https://travis-ci.org/PowerShell/vscode-powershell/jobs/342931436#L666

TylerLeonhardt · 2018-02-19T04:03:46Z

If that is the case, could we fix the Travis and AppVeyor definitions to be ok with a miss matched signature?

If we merge this in, every build will fail (if the mismatched sig is the issue), right?

rkeithhill · 2018-02-19T04:48:46Z

I'm not sure. This is the first time I've touched this file but that build failure seems more related to a node/npm issue. Hmm...

TylerLeonhardt · 2018-02-20T04:01:05Z

I've restarted them. Let's see what happens. It's also possible that one of our dependencies broke us.

If these fail, I want to trigger a build of master which should pass.

TylerLeonhardt · 2018-02-20T04:04:46Z

Looks like Travis and AppVeyor had one too many that night and have recovered :)

TylerLeonhardt

Just had a couple of questions.

TylerLeonhardt · 2018-02-20T04:11:25Z

scripts/Start-EditorServices.ps1

+        $portsInUse[$port] = 1
+
+        Log "Checking port: $port, attempts remaining $triesRemaining --------------------"
+        if ($true -eq (Test-PortAvailability -PortNumber $port)) {


Is the $true -eq ... needed? I would think Test-PortAvailability is truthy enough.

Or rather, it looks like it returns a boolean, no?

I think I'll put that back the way it was. The reasoning here is if someone tweaks the function and has it output more values the condition should handle that. Turns out that $true -eq '','' is still true but '','' -eq $true is false. We want the latter in this case.

That's an interesting gotcha 😅

TylerLeonhardt · 2018-02-20T04:18:52Z

scripts/Start-EditorServices.ps1


    try {
        if ($isPS5orLater) {
-            $ipAddress = [System.Net.Dns]::GetHostEntryAsync("localhost").Result.AddressList[0];
+            $ipAddresses = [System.Net.Dns]::GetHostEntryAsync("localhost").Result.AddressList


Did you decide against testing ipv4 via

$ipAddress = [System.Net.IPAddress]::Parse("127.0.0.1")

The above returns both the ipv6 and ipv4 addresses. Note that I'm not limiting the value to the first index and below we iterate the values. IOW the port has to be open on both ipv6 and ipv4 before we will use it.

Ah. I see! Thanks!

TylerLeonhardt · 2018-02-20T04:20:59Z

Forgive me, as I reviewed this on my phone while waiting for a flight back to Seattle :)

TylerLeonhardt

LGTM :)

daviwil

Thanks a lot for doing this, it'll be really helpful in diagnosing startup issues! I'd like to eventually move the port checking code to C# because this script is growing too large, but it's totally worthwhile to improve this for now.

daviwil · 2018-02-20T17:13:01Z

scripts/Start-EditorServices.ps1

+$minPortNumber = 10000
+$maxPortNumber = 30000
+
+if ($LogLevel -ne "Normal") {


There are "lesser" log levels than Normal (though honestly they're kinda pointless), so maybe you should check for Verbose and Diagnostic specifically? Or maybe just Diagnostic? Can definitely change this in a separate PR so that the release isn't held up.

Doh! I thought that Normal was the lowest level. I can change it. What do you think? Maybe use Diagnostics to trigger this - particularly considering this will spew yellow verbose text in the PSIC during startup when Start-EditorServices logging is enabled.

Yeah, I think "Diagnostic" is the right level to enable the logging since we'd only use that level in cases where things have really gone sideways :)

I'll change this tonight. BTW how do we handle the fact that this file had an Authenticode signature which I had to remove because my changes invalidated it?

@tylerl0706 needs to sign the script again when he ships the update. In the past I wasn't checking in the authenticode part, but as time went on it seemed easier to just check it in since the script doesn't change that often between releases.

On the VSCode side, Diagnostics isn't one of the logging options although I suppose we could add it:

Thoughts? Diagnostics is available on the PSES side. I'm inclined to leave the script set to trigger on Verbose and consider changing this in a future release. This makes sense from the perspective that right now we're having issues on some machines with startup. Hopefully we get the issues ferreted out and fixed and then we can dial the output back down to happen only with Diagnostics log level.

daviwil · 2018-02-21T04:07:51Z

Diagnostic should be there in the VS Code setting, someone added that for 1.5.1. I'm OK with Verbose until next release if it isn't doable though.

rkeithhill · 2018-02-21T04:10:15Z

It's not there but I'm working on adding it right now.

daviwil · 2018-02-21T04:12:41Z

Weird, could have sworn it was there but it's not!

rkeithhill · 2018-02-21T04:20:28Z

OK, I've about got this licked. Just need to do a bit of testing. Expect update in 15 mins or so.

rkeithhill · 2018-02-21T04:24:08Z

This will be nicer:

rkeithhill · 2018-02-21T04:26:53Z

And now we get DIAGNOSTIC log output in the PSES log file.

2/20/2018 9:25:00 PM [DIAGNOSTIC] - Method "ReadMessage" at line 114 of C:\Users\Keith\GitHub\rkeithhill\PowerShellEditorServices\src\PowerShellEditorServices.Protocol\MessageProtocol\MessageReader.cs

Set Start-EditorServices to log only for Diagnostic log level. Add string enum support for log level so in UserSettings you get a list.

rkeithhill · 2018-02-21T04:43:41Z

@daviwil Can you review the last commit that adds the Diagnostic log level - 913d9f7

daviwil · 2018-02-22T01:21:47Z

Changes look great to me!

rkeithhill added 2 commits February 14, 2018 18:43

Initial stab at logging PSES startup script

ec08740

Try different approach to find ports in use

b25e1ab

rkeithhill requested review from daviwil and TylerLeonhardt February 15, 2018 06:27

Revert back to Test-PortAvailability due to missing .NET Core features

8a9bcc7

Modify Test-PortAvailability to check each address (ipv4 and ipv6) in AddressList for localhost.

Add blank line between func defs

d700d70

TylerLeonhardt reviewed Feb 20, 2018

View reviewed changes

Revert bool condition check, $true on RHS

46cbf51

TylerLeonhardt approved these changes Feb 20, 2018

View reviewed changes

daviwil approved these changes Feb 20, 2018

View reviewed changes

Add support for Diagnostic log level

913d9f7

Set Start-EditorServices to log only for Diagnostic log level. Add string enum support for log level so in UserSettings you get a list.

rkeithhill merged commit b1b23e7 into master Feb 21, 2018

rkeithhill deleted the rkeithhill/log-pses-startup branch February 21, 2018 17:17

WIP Enhance Start-EditorServices.ps1 for better logging and fix bugs #1198

WIP Enhance Start-EditorServices.ps1 for better logging and fix bugs #1198

Conversation

rkeithhill commented Feb 15, 2018

rkeithhill commented Feb 15, 2018 • edited Loading

rkeithhill commented Feb 15, 2018 • edited Loading

TylerLeonhardt commented Feb 15, 2018

rkeithhill commented Feb 16, 2018

TylerLeonhardt commented Feb 16, 2018

rkeithhill commented Feb 16, 2018 • edited Loading

rkeithhill commented Feb 19, 2018

TylerLeonhardt commented Feb 19, 2018

TylerLeonhardt commented Feb 19, 2018

rkeithhill commented Feb 19, 2018

TylerLeonhardt commented Feb 20, 2018

TylerLeonhardt commented Feb 20, 2018

TylerLeonhardt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TylerLeonhardt commented Feb 20, 2018

TylerLeonhardt left a comment

Choose a reason for hiding this comment

daviwil left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rkeithhill Feb 21, 2018 • edited Loading

Choose a reason for hiding this comment

daviwil commented Feb 21, 2018

rkeithhill commented Feb 21, 2018

daviwil commented Feb 21, 2018

rkeithhill commented Feb 21, 2018

rkeithhill commented Feb 21, 2018

rkeithhill commented Feb 21, 2018

rkeithhill commented Feb 21, 2018

daviwil commented Feb 22, 2018

rkeithhill commented Feb 15, 2018 •

edited

Loading

rkeithhill commented Feb 15, 2018 •

edited

Loading

rkeithhill commented Feb 16, 2018 •

edited

Loading

rkeithhill Feb 21, 2018 •

edited

Loading