Navcontainerhelper: "ClientSession is Uninitialized" when calling Run-TestsInNavContainer

[jwikman]

This is similar to issue #527.

I'm calling Run-TestsInNavContainer from our pipelines, it has been working fine for some time now. But today I started to get "ClientSession is Uninitialized" when calling Run-TestsInNavContainer.

I'm using navcontainerhelper 0.6.4.1 (pipeline updates to latest version)

The target is a BC14 database.
Output when creating container:

Create CI-bld13 from mcr.microsoft.com/businesscentral/sandbox:w1
NavContainerHelper is version 0.6.4.1
Host is Microsoft Windows Server 2019 Standard - ltsc2019
Docker Client Version is 19.03.1
Docker Server Version is 19.03.1
Using image mcr.microsoft.com/businesscentral/sandbox:w1-ltsc2019
Disabling Health Check (always report healthy)
Creating Container CI-bld13
Version: 14.4.35602.0-W1
Style: sandbox
Platform: 14.0.35570.0
Generic Tag: 0.0.9.92
Container OS Version: 10.0.17763.678 (ltsc2019)
Host OS Version: 10.0.17763.720 (ltsc2019)
WARNING: The container operating system matches the host operating system, but the revision is different.
If you encounter issues, you might want to specify -isolation hyperv
Using locale en-US
Using process isolation
Disabling the standard eventlog dump to container log every 2 seconds (use -dumpEventLog to enable)
Using license file ***
Downloading C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\my\license.flf
Files in C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\my:
- AdditionalOutput.ps1
- AdditionalSetup.ps1
- license.flf
- MainLoop.ps1
- updatehosts.ps1
Creating container CI-bld13 from image mcr.microsoft.com/businesscentral/sandbox:w1-ltsc2019
92ecc421f71442c7a2186aefffd5c7663ab6a2c578c0d1c3c9a03da801e067bd
Waiting for container CI-bld13 to be ready
Initializing...
Starting Container
Hostname is CI-bld13
PublicDnsName is CI-bld13
Using NavUserPassword Authentication
Starting Local SQL Server
Starting Internet Information Server
Creating Self Signed Certificate
Self Signed Certificate Thumbprint D8F83C3DA6F06F736305706E9733546F89369884
Modifying Service Tier Config File with Instance Specific Settings
Starting Service Tier
Registering event sources
Creating DotNetCore Web Server Instance
Enabling Financials User Experience
Using license file 'c:\run\my\license.flf'
Import License
Creating http download site
Setting SA Password and enabling SA
Creating *** as SQL User and add to sysadmin
Creating SUPER user
Container IP Address: 172.20.219.63
Container Hostname  : CI-bld13
Container Dns Name  : CI-bld13
Web Client          : http://CI-bld13:8080/NAV/
Dev. Server         : http://CI-bld13
Dev. ServerInstance : NAV

Files:
http://CI-bld13:8080/al-3.0.154634.vsix

Initialization took 53 seconds
Ready for connections!
Reading CustomSettings.config from CI-bld13
Container CI-bld13 successfully created

Error:

Importing Objects from C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\PSTestToolPage.fob (container path)
Objects successfully imported
CommunicationError : An error occurred while sending the request.
ClientSession is Uninitialized
at AwaitState, C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\ClientContext.ps1: line 157
at OpenSession, C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\ClientContext.ps1: line 129
at Initialize, C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\ClientContext.ps1: line 46
at ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\ClientContext.ps1: line 23
at New-ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld13\PsTestTool-3\PsTestFunctions.ps1: line 39
at <ScriptBlock>, <No file>: line 39
##[error]ClientSession is Uninitialized
##[error]At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.
ps1:37 char:13
+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...
+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

##[error]    + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [], RuntimeException

##[error]    + FullyQualifiedErrorId : ClientSession is Uninitialized

##[error] 

##[error]PowerShell exited with code '1'.

I got it on a dev computer a few weeks ago, but then a restart helped. A restart of our build server did not help this time.

I see that the error is thrown from AppHandlingClientContext.ps1. Could it be a timing issue, so that the 100 ms timeout is not enough?

Just let me know if you need more info

[freddydk]

Could you try to add -debugMode to the run-tests - to see if that prints out additional information?

[jwikman]

Ok, I'll update my pipelines to test this. I'll try to bind that parameter to the System.Debug variabel in yaml, would be nice if that worked...

I'll be back.

[freddydk]

If possible, maybe you could get the event log from the container (Get-NavContainerEventLog) if this error occurs?

[jwikman]

The pipeline is cleaning up in the end, removing containers and all.

But I'll check out what I can find, maybe I always should collect event logs etc if pipeline fails, and publish as an artifact for that build, making it easier to trouble shoot strange behaviors. Failing tests is the easy ones to solve.

[jwikman]

The debugMode does not help here. The flag is not set yet when the error occur.
$clientContext.DebugMode = $debugMode is called after [ClientContext]::new(..) in AppHandlingPsTestFunctions.ps1

Maybe the debugMode should have been added to the constructors of ClientContext instead, otherwise it's hard to get this help if initialization fails.

Below is a detailed log of this task, but it's nothing new really :(

2019-09-13T12:20:06.0902711Z ##[section]Starting: Run Tests
2019-09-13T12:20:06.1074781Z ==============================================================================
2019-09-13T12:20:06.1074940Z Task         : PowerShell
2019-09-13T12:20:06.1075064Z Description  : Run a PowerShell script on Linux, macOS, or Windows
2019-09-13T12:20:06.1075316Z Version      : 2.151.2
2019-09-13T12:20:06.1075426Z Author       : Microsoft Corporation
2019-09-13T12:20:06.1075564Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/powershell
2019-09-13T12:20:06.1075719Z ==============================================================================
2019-09-13T12:20:06.9200607Z ##[debug]VstsTaskSdk 0.11.0 commit 7ff27a3e0bdd6f7b06690ae5f5b63cb84d0f23f4
2019-09-13T12:20:07.0568392Z ##[debug]Entering C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1.
2019-09-13T12:20:07.0638737Z ##[debug]Loading resource strings from: C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\task.json
2019-09-13T12:20:07.0842833Z ##[debug]Loaded 11 strings.
2019-09-13T12:20:07.0878278Z ##[debug]SYSTEM_CULTURE: 'en-US'
2019-09-13T12:20:07.0897808Z ##[debug]Loading resource strings from: C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\Strings\resources.resjson\en-US\resources.resjson
2019-09-13T12:20:07.1106746Z ##[debug]Loaded 11 strings.
2019-09-13T12:20:07.1287144Z ##[debug]INPUT_ERRORACTIONPREFERENCE: 'stop'
2019-09-13T12:20:07.1315410Z ##[debug]INPUT_FAILONSTDERR: 'false'
2019-09-13T12:20:07.1346772Z ##[debug] Converted to bool: False
2019-09-13T12:20:07.1365923Z ##[debug]INPUT_IGNORELASTEXITCODE: 'false'
2019-09-13T12:20:07.1382408Z ##[debug] Converted to bool: False
2019-09-13T12:20:07.1403355Z ##[debug]INPUT_PWSH: 'false'
2019-09-13T12:20:07.1418413Z ##[debug] Converted to bool: False
2019-09-13T12:20:07.1437919Z ##[debug]INPUT_WORKINGDIRECTORY: 'C:\Agent_AS011_01\_work\4\s'
2019-09-13T12:20:07.1539711Z ##[debug]Asserting container path exists: 'C:\Agent_AS011_01\_work\4\s'
2019-09-13T12:20:07.1562337Z ##[debug]INPUT_TARGETTYPE: 'filePath'
2019-09-13T12:20:07.1591852Z ##[debug]INPUT_FILEPATH: 'C:\Agent_AS011_01\_work\4\NAB%20DevOps%20Tools\PowerShell\Run-Tests.ps1'
2019-09-13T12:20:07.1608622Z ##[debug]Asserting leaf path exists: 'C:\Agent_AS011_01\_work\4\NAB%20DevOps%20Tools\PowerShell\Run-Tests.ps1'
2019-09-13T12:20:07.1642931Z ##[debug]INPUT_ARGUMENTS: '-credential ([PSCredential]::new("***", (ConvertTo-SecureString -String "***" -AsPlainText -Force))) -TestResultsFile (Join-Path "C:\Agent_AS011_01\_work\4\s" "TestResults.xml") -testsuite "QWEPR" -containerNameSuffix "12" -debugMode:$True'
2019-09-13T12:20:07.1676428Z Generating script.
2019-09-13T12:20:07.1720816Z Formatted command: . 'C:\Agent_AS011_01\_work\4\NAB%20DevOps%20Tools\PowerShell\Run-Tests.ps1' -credential ([PSCredential]::new("***", (ConvertTo-SecureString -String "***" -AsPlainText -Force))) -TestResultsFile (Join-Path "C:\Agent_AS011_01\_work\4\s" "TestResults.xml") -testsuite "QWEPR" -containerNameSuffix "12" -debugMode:$True
2019-09-13T12:20:07.1824777Z ##[debug]AGENT_VERSION: '2.155.1'
2019-09-13T12:20:07.1889836Z ##[debug]AGENT_TEMPDIRECTORY: 'C:\Agent_AS011_01\_work\_temp'
2019-09-13T12:20:07.1905434Z ##[debug]Asserting container path exists: 'C:\Agent_AS011_01\_work\_temp'
2019-09-13T12:20:07.2236683Z ##[debug]Asserting leaf path exists: 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe'
2019-09-13T12:20:07.2251271Z ========================== Starting Command Output ===========================
2019-09-13T12:20:07.2391649Z ##[debug]Entering Invoke-VstsTool.
2019-09-13T12:20:07.2526089Z ##[debug] Arguments: '-NoLogo -NoProfile -NonInteractive -ExecutionPolicy Unrestricted -Command ". 'C:\Agent_AS011_01\_work\_temp\9df10ab4-429d-4631-a018-036473339cb3.ps1'"'
2019-09-13T12:20:07.2539449Z ##[debug] FileName: 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe'
2019-09-13T12:20:07.2554685Z ##[debug] WorkingDirectory: 'C:\Agent_AS011_01\_work\4\s'
2019-09-13T12:20:07.2600007Z ##[command]"C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe" -NoLogo -NoProfile -NonInteractive -ExecutionPolicy Unrestricted -Command ". 'C:\Agent_AS011_01\_work\_temp\9df10ab4-429d-4631-a018-036473339cb3.ps1'"
2019-09-13T12:20:13.0316437Z Importing Objects from C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\PSTestToolPage.fob (container path)
2019-09-13T12:20:24.0333717Z Objects successfully imported
2019-09-13T12:20:26.9454089Z CommunicationError : An error occurred while sending the request.
2019-09-13T12:20:27.0074631Z ClientSession is Uninitialized
2019-09-13T12:20:27.0097264Z at AwaitState, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 157
2019-09-13T12:20:27.0099667Z at OpenSession, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 129
2019-09-13T12:20:27.0102183Z at Initialize, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 46
2019-09-13T12:20:27.0104563Z at ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 23
2019-09-13T12:20:27.0107167Z at New-ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\PsTestFunctions.ps1: line 39
2019-09-13T12:20:27.0109545Z at <ScriptBlock>, <No file>: line 39
2019-09-13T12:20:27.2106673Z ##[debug]Error record:
2019-09-13T12:20:27.3118844Z ##[debug]powershell.exe : ClientSession is Uninitialized
2019-09-13T12:20:27.3130435Z ##[debug]At line:1 char:1
2019-09-13T12:20:27.3143559Z ##[debug]+ & 'C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe' --% -No ...
2019-09-13T12:20:27.3152541Z ##[debug]+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2019-09-13T12:20:27.3163346Z ##[debug]    + CategoryInfo          : NotSpecified: (ClientSession is Uninitialized:String) [], RemoteException
2019-09-13T12:20:27.3174130Z ##[debug]    + FullyQualifiedErrorId : NativeCommandError
2019-09-13T12:20:27.3184615Z ##[debug] 
2019-09-13T12:20:27.3200436Z ##[debug]Script stack trace:
2019-09-13T12:20:27.3231106Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3241703Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.3252406Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.3262907Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3273885Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.3284508Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.3295345Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3311058Z ##[debug]Exception:
2019-09-13T12:20:27.3344513Z ##[debug]System.Management.Automation.RemoteException: ClientSession is Uninitialized
2019-09-13T12:20:27.3591593Z ##[error]ClientSession is Uninitialized
2019-09-13T12:20:27.3598551Z ##[debug]Processed: ##vso[task.logissue type=error]ClientSession is Uninitialized
2019-09-13T12:20:27.3598880Z ##[debug]Error record:
2019-09-13T12:20:27.3620218Z ##[debug]At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.
2019-09-13T12:20:27.3627306Z ##[debug]ps1:37 char:13
2019-09-13T12:20:27.3634964Z ##[debug]+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...
2019-09-13T12:20:27.3642626Z ##[debug]
2019-09-13T12:20:27.3655568Z ##[debug]Script stack trace:
2019-09-13T12:20:27.3666986Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3674775Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.3682453Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.3690072Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3697686Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.3705291Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.3712901Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3724837Z ##[debug]Exception:
2019-09-13T12:20:27.3737184Z ##[debug]System.Management.Automation.RemoteException: At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.
2019-09-13T12:20:27.3745340Z ##[debug]ps1:37 char:13
2019-09-13T12:20:27.3753294Z ##[debug]+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...
2019-09-13T12:20:27.3761142Z ##[debug]
2019-09-13T12:20:27.3773379Z ##[error]At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.
ps1:37 char:13
+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...

2019-09-13T12:20:27.3774279Z ##[debug]Processed: ##vso[task.logissue type=error]At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.%0D%0Aps1:37 char:13%0D%0A+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...%0D%0A
2019-09-13T12:20:27.3785468Z ##[debug]Error record:
2019-09-13T12:20:27.3848898Z ##[debug]+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2019-09-13T12:20:27.3857937Z ##[debug]
2019-09-13T12:20:27.3870971Z ##[debug]Script stack trace:
2019-09-13T12:20:27.3883649Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3892077Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.3900309Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.3908434Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3916619Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.3924941Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.3933168Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.3946189Z ##[debug]Exception:
2019-09-13T12:20:27.3959778Z ##[debug]System.Management.Automation.RemoteException: +             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2019-09-13T12:20:27.3968475Z ##[debug]
2019-09-13T12:20:27.3980880Z ##[error]+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2019-09-13T12:20:27.3981757Z ##[debug]Processed: ##vso[task.logissue type=error]+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~%0D%0A
2019-09-13T12:20:27.3994091Z ##[debug]Error record:
2019-09-13T12:20:27.4108270Z ##[debug]    + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [], RuntimeException
2019-09-13T12:20:27.4118147Z ##[debug]
2019-09-13T12:20:27.4133507Z ##[debug]Script stack trace:
2019-09-13T12:20:27.4147871Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4157955Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.4167874Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.4177639Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4187948Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.4197496Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.4207370Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4221882Z ##[debug]Exception:
2019-09-13T12:20:27.4236773Z ##[debug]System.Management.Automation.RemoteException:     + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [], RuntimeException
2019-09-13T12:20:27.4246499Z ##[debug]
2019-09-13T12:20:27.4260500Z ##[error]    + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [], RuntimeException

2019-09-13T12:20:27.4261668Z ##[debug]Processed: ##vso[task.logissue type=error]    + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [%5D, RuntimeException%0D%0A
2019-09-13T12:20:27.4274822Z ##[debug]Error record:
2019-09-13T12:20:27.4362284Z ##[debug]    + FullyQualifiedErrorId : ClientSession is Uninitialized
2019-09-13T12:20:27.4371868Z ##[debug]
2019-09-13T12:20:27.4385814Z ##[debug]Script stack trace:
2019-09-13T12:20:27.4400005Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4409738Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.4419485Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.4429009Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4438610Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.4448227Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.4457792Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4471970Z ##[debug]Exception:
2019-09-13T12:20:27.4486062Z ##[debug]System.Management.Automation.RemoteException:     + FullyQualifiedErrorId : ClientSession is Uninitialized
2019-09-13T12:20:27.4495652Z ##[debug]
2019-09-13T12:20:27.4509162Z ##[error]    + FullyQualifiedErrorId : ClientSession is Uninitialized

2019-09-13T12:20:27.4509978Z ##[debug]Processed: ##vso[task.logissue type=error]    + FullyQualifiedErrorId : ClientSession is Uninitialized%0D%0A
2019-09-13T12:20:27.4523580Z ##[debug]Error record:
2019-09-13T12:20:27.4604360Z ##[debug] 
2019-09-13T12:20:27.4612644Z ##[debug]
2019-09-13T12:20:27.4625238Z ##[debug]Script stack trace:
2019-09-13T12:20:27.4637971Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4646631Z ##[debug]at Invoke-Tool, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\ps_modules\VstsTaskSdk\ToolFunctions.ps1: line 107
2019-09-13T12:20:27.4654956Z ##[debug]at <ScriptBlock>, C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1: line 98
2019-09-13T12:20:27.4662980Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4671216Z ##[debug]at <ScriptBlock>, <No file>: line 22
2019-09-13T12:20:27.4679325Z ##[debug]at <ScriptBlock>, <No file>: line 18
2019-09-13T12:20:27.4687428Z ##[debug]at <ScriptBlock>, <No file>: line 1
2019-09-13T12:20:27.4699655Z ##[debug]Exception:
2019-09-13T12:20:27.4712024Z ##[debug]System.Management.Automation.RemoteException:  
2019-09-13T12:20:27.4720201Z ##[debug]
2019-09-13T12:20:27.4731812Z ##[error] 

2019-09-13T12:20:27.4732469Z ##[debug]Processed: ##vso[task.logissue type=error] %0D%0A
2019-09-13T12:20:27.4744490Z ##[debug]Exit code: 1
2019-09-13T12:20:27.4771339Z ##[debug]Leaving Invoke-VstsTool.
2019-09-13T12:20:27.4818911Z ##[error]PowerShell exited with code '1'.
2019-09-13T12:20:27.4819791Z ##[debug]Processed: ##vso[task.logissue type=error]PowerShell exited with code '1'.
2019-09-13T12:20:27.4892542Z ##[debug]Processed: ##vso[task.complete result=Failed]Error detected
2019-09-13T12:20:27.4905468Z ##[debug]Leaving C:\Agent_AS011_01\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.151.2\powershell.ps1.
2019-09-13T12:20:27.5285149Z ##[section]Finishing: Run Tests

I'll proceed to see if I can export some logs if the pipeline fails

[jwikman]

Now I exported the Application and System logs if the pipeline fails.
This is what I get, but it didn't give me any more clues about what's wrong: ErrorLogs_1.0.668.zip

Anything more I can fetch from the container to help us solve this?

At least I got my pipelines improved with this :-)

[jwikman]

Now I commented out the cleanup in my pipeline, leaving the container as-is after failing pipeline build.
I just discovered that it is the call to Get-TestsFromNavContainer that fails, not Run-TestsInNavContainer. But I don't think that changes much.

Anyway, now I got a container that throws this error on every call to Get-TestsFromNavContainer.

Any suggestions on what to do further investigate in this? I'll try to modify the constructors of ClientContext to include debug-mode, maybe that will show something more...

[jwikman]

Now I finally made at least some progress. From the InnerException of the CommunicationError Exception I get this:

CommunicationError : An error occurred while sending the request.
CommunicationError InnerException : System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.Net.WebException: Unable to connect to the remote server ---> System.Net.Sockets.SocketException: No connection could be made because the target machine actively refused it 127.0.0.1:80
   at System.Net.Sockets.Socket.InternalEndConnect(IAsyncResult asyncResult)
   at System.Net.Sockets.Socket.EndConnect(IAsyncResult asyncResult)
   at System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.EndGetRequestStream(IAsyncResult asyncResult, TransportContext& context)
   at System.Net.Http.HttpClientHandler.GetRequestStreamCallback(IAsyncResult ar)
   --- End of inner exception stack trace ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Dynamics.Framework.UI.Client.JsonHttpClient.<>c__DisplayClass9_0.<EndOpenSession>b__0() in s:\repo\src\Platform\Client\ClientService\Prod.Client.ClientService.Client\Service\ServiceClients\JsonHttpClient\JsonHttpClient.cs:line 158
   at Microsoft.Dynamics.Framework.UI.Client.JsonHttpClient.ConvertExceptions[T](Func`1 action) in s:\repo\src\Platform\Client\ClientService\Prod.Client.ClientService.Client\Service\ServiceClients\JsonHttpClient\JsonHttpClient.cs:line 181
ClientSession is Uninitialized
at AwaitState, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 160
at OpenSession, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 132
at Initialize, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 46
at ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\ClientContext.ps1: line 23
at New-ClientContext, C:\ProgramData\NavContainerHelper\Extensions\CI-bld12\PsTestTool-3\PsTestFunctions.ps1: line 39
at <ScriptBlock>, <No file>: line 39
ClientSession is Uninitialized
At C:\Program Files\WindowsPowerShell\Modules\navcontainerhelper\0.6.4.1\ContainerHandling\Invoke-ScriptInNavContainer.ps1:37 char:13
+             Invoke-Command -Session $session -ScriptBlock $scriptbloc ...
+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : OperationStopped: (ClientSession is Uninitialized:String) [], RuntimeException
    + FullyQualifiedErrorId : ClientSession is Uninitialized

The interesting part is No connection could be made because the target machine actively refused it 127.0.0.1:80
So it tries to connect to localhost port 80. But Why? The only references I find to port 80 in navcontainerhelper is related to traefik, which I'm not using. (At least I'm not aware of using that)

When running docker container ls I see that it uses ports 80/tcp, 443/tcp, 1433/tcp, 7045-7049/tcp, 8080/tcp
What is port 80 used for in my container?
Why is the ClientContext trying to connect to 127.0.0.1:80?

Btw, I created PR #619 to help troubleshoot similar errors in the future.

[freddydk]

The connection to the WebClient comes from inside the container and it tries to connect to localhost to avoid leaving the container. Can you connect to the Web Client from the outside with a browser?
Does it help to run IISRESET inside the container?

[jwikman]

I think I just found out what was causing this...
Of course I couldn't connect to the web client from the outside...
I added the webclientport parameter to my script, but mistakenly set the default port to 8080 instead of 80. So when not specifying the port it tried to create the web client on the same port as the file share site and that messes up everything, embarrassing...

Would you accept a PR that adds the default port numbers to the port number parameters of the New-NavContainer function? At least the parameters WebClientPort and FileSharePort ports. Then I could also check that those ports does not collide, resulting in this mess.... If any of the other ports would collide I believe that the NST would fail instead.

Anyway, this issue is closed now...

[freddydk]

PR is welcome, if it can help other people not encounter similar problem.
Thanks.

[jwikman]

btw, have you managed to get the debugMode to work?
When I tested that switch I had two problems:

1. It was set too late, so it was not set when I got my issue
2. After I added it to the constructor instead, to solve point 1 above, I didn't get it to work anyway. It seemed as if it was not reachable in the action context where it was used... Even if $this.debugMode was set, it always returned nothing when called inside the event action

[freddydk]

In some cases I got output from debugmode (especially when the clientsession error stems from a dialog popping up in the session). I will check if I can make it better for connection issues

[jwikman]

another issue was that the GetAllForms() always failed for me, since $this.clientSession.OpenedForms was null.

[freddydk]

Yeah, I didn't take into consideration that the session wasn't initialized.
I did add this as a parameter because it was risky:-)