Client session uninitialized when running tests

[tfenster]

PLEASE DO NOT INCLUDE ANY PASSWORDS OR TOKENS IN YOUR ISSUE!!!

Describe the issue
Running tests in a container fails because "Warm-up Client Context" and "Create Client Context" fail

*** Running TestSuite with authentication [NavUserPassword] with User [admin]
*** Run warm-up with page [130455]
*** Warm-up Client Context
CommunicationError : Error reading JObject from JsonReader. Path '', line 0, position 0.
at <ScriptBlock>, <No file>: line 91
at InvokeInteractionAndCatchForm, <No file>: line 266
at OpenForm, <No file>: line 301
at Test-OpenForm, <No file>: line 7
at <ScriptBlock>, <No file>: line 14
at <ScriptBlock>, <No file>: line 1
Current Interaction: Microsoft.Dynamics.Framework.UI.Client.Interactions.OpenFormInteraction
Time spend: 9 seconds
*** Create Client Context
CommunicationError : Response status code does not indicate success: 502 (Bad Gateway).
at <ScriptBlock>, <No file>: line 91
at AwaitState, <No file>: line 220
at OpenSession, <No file>: line 198
at Initialize, <No file>: line 59
at ClientContext, <No file>: line 26
at New-ClientContext, <No file>: line 27
at <ScriptBlock>, <No file>: line 36
at <ScriptBlock>, <No file>: line 1
##[error]Run-Test-Exception: ClientSession State is Uninitialized (Wait time 10 seconds)
*** Get XUnit Test file from [] to [C:\azp\agent\_work\1\s\BC17.AstarInterface\]
##[error]Cannot bind argument to parameter 'Path' because it is null.

Scripts used to create container and cause the issue
We are using bcch for creating images, but not to create the containers, but here are the environment variables and other settings when starting the container

*** Add docker parameter: --env folders=c:\run=https://***.cloudapp.azure.com/automation/0.11/startupfile/package/build
*** Add docker parameter: --env alops-docker-username=admin
*** Add docker parameter: --env alops-docker-password=Passw0rd
*** Add docker parameter: --env customnavsettings=enabletaskscheduler=false
*** Add docker parameter: --env AZURE_DEVOPS_ARTIFACTS=***
*** Add docker parameter: --env AZURE_DEVOPS_PAT64=***
*** Add docker parameter: --volume s:\:c:\azurefileshare
*** Add docker parameter: --isolation=
*** Add docker parameter: --env licenseFile=***
*** Add docker parameter: --env useCustomScriptsFromRepo=
*** Add docker parameter: --env CcOrgName=***
*** Add docker parameter: --env CcProjectId=***
*** Add docker parameter: --env CcRepoId=***
*** Add docker parameter: --env CcBranch=fix-license
*** Add docker parameter: --env AZURE_DEVOPS_EXT_PAT=***
"docker" create --memory 6G --env accept_eula=Y --env accept_outdated=Y --env enableApiServices=Y --env multitenant=Y --restart always --label TFSBuild=BC17.AstarInterface_2353 *** bcinsider/cosmo-bc:sandbox-18.4.27614.0-fr-mt

Full output of scripts
Container start

2021-07-05T23:01:49.8895252Z Setting up folders...
2021-07-05T23:01:49.8909895Z Downloading https://ppi-devops.germanywestcentral.cloudapp.azure.com/automation/0.11/startupfile/package/build to c:\run
2021-07-05T23:01:49.8917833Z Extracting file in temp folder
2021-07-05T23:01:49.8925702Z Moving all extracted files to target folder c:\run
2021-07-05T23:01:49.8933471Z Setting up folders took 1 seconds
2021-07-05T23:01:51.1613026Z The command completed successfully.
2021-07-05T23:01:51.1618599Z 
2021-07-05T23:01:51.1628916Z The command completed successfully.
2021-07-05T23:01:51.1634222Z 
2021-07-05T23:01:52.4721980Z ResourceCreated
2021-07-05T23:01:52.4732135Z     Address = http://schemas.xmlsoap.org/ws/2004/08/addressing/role/anonymous
2021-07-05T23:01:52.4741582Z     ReferenceParameters
2021-07-05T23:01:52.4750652Z         ResourceURI = http://schemas.microsoft.com/wbem/wsman/1/config/listener
2021-07-05T23:01:52.4759531Z         SelectorSet
2021-07-05T23:01:52.4773190Z             Selector: Address = *, Transport = HTTPS
2021-07-05T23:01:52.4773652Z 
2021-07-05T23:01:53.8390141Z Auth
2021-07-05T23:01:53.8398822Z     Basic = true
2021-07-05T23:01:53.8406864Z     Kerberos = true
2021-07-05T23:01:53.8414921Z     Negotiate = true
2021-07-05T23:01:53.8423787Z     Certificate = false
2021-07-05T23:01:53.8431439Z     CredSSP = false
2021-07-05T23:01:53.8440783Z     CbtHardeningLevel = Relaxed
2021-07-05T23:01:53.8444336Z 
2021-07-05T23:01:53.8452798Z This seems to be a regular service start
2021-07-05T23:01:53.8460341Z Initializing...
2021-07-05T23:01:53.8467948Z Starting Container
2021-07-05T23:01:53.8476719Z Hostname is 3e33d4b9ea9f
2021-07-05T23:01:53.8484827Z PublicDnsName is 3e33d4b9ea9f
2021-07-05T23:01:53.8492253Z Using NavUserPassword Authentication
2021-07-05T23:01:55.1424524Z Starting Local SQL Server
2021-07-05T23:01:56.4269324Z Starting Internet Information Server
2021-07-05T23:02:01.6177206Z Creating Self Signed Certificate
2021-07-05T23:02:02.9216392Z Self Signed Certificate Thumbprint A6AA82129BC0F5E4EEAB4156317AE86F79F24323
2021-07-05T23:02:02.9226691Z Modifying Service Tier Config File with Instance Specific Settings
2021-07-05T23:02:02.9236586Z Modifying Service Tier Config File with settings from environment variable
2021-07-05T23:02:02.9245283Z Creating enabletaskscheduler and setting it to false
2021-07-05T23:02:04.2358998Z Starting Service Tier
2021-07-05T23:02:18.5000776Z Registering event sources
2021-07-05T23:02:18.5009889Z Creating DotNetCore Web Server Instance
2021-07-05T23:02:53.7051906Z Enabling Financials User Experience
2021-07-05T23:02:53.7062365Z Downloading license file '***'
2021-07-05T23:02:53.7070291Z Import License
2021-07-05T23:03:00.1135875Z Dismounting Tenant
2021-07-05T23:03:00.1144348Z Mounting Tenant
2021-07-05T23:03:00.1153657Z Mounting Database for default on server localhost\SQLEXPRESS with AllowAppDatabaseWrite = False
2021-07-05T23:03:16.6256134Z Sync'ing Tenant
2021-07-05T23:03:16.6264210Z Tenant is Operational
2021-07-05T23:03:16.6271856Z Creating http download site
2021-07-05T23:03:16.6283048Z Setting SA Password and enabling SA
2021-07-05T23:03:16.6291036Z Creating admin as SQL User and add to sysadmin
2021-07-05T23:03:16.6298936Z Creating SUPER user
2021-07-05T23:03:25.5375325Z 
2021-07-05T23:03:25.5384537Z === Additional Setup ===
2021-07-05T23:03:25.5394122Z Import PPI Setup Utils from c:\run\PPIArtifactUtils.psd1
2021-07-05T23:03:25.5403087Z Import Management Utils from C:\Program Files\Microsoft Dynamics NAV\180\Service\Microsoft.Dynamics.Nav.Management.psd1
2021-07-05T23:03:25.5411589Z Import App Management Utils from C:\Program Files\Microsoft Dynamics NAV\180\Service\Microsoft.Dynamics.Nav.Apps.Management.psd1
2021-07-05T23:03:25.5419891Z Import Nav IDE from C:\Program Files (x86)\Microsoft Dynamics NAV\180\RoleTailored Client\Microsoft.Dynamics.Nav.Ide.psm1
2021-07-05T23:03:26.7909872Z Artifacts from AZURE_DEVOPS_ARTIFACTS ...
2021-07-05T23:03:26.7918489Z Artifacts: {"artifacts":{"name":"configuration","url":"C:\\NAVDVD\\ConfigurationPackages\\*EXTENDED.rapidstart"}}
2021-07-05T23:03:26.7926783Z  Artifact(s) found.
2021-07-05T23:03:26.7934899Z     [INFO] Get Artifact from C:\NAVDVD\ConfigurationPackages\*EXTENDED.rapidstart
2021-07-05T23:03:26.7942582Z     [INFO] Get Artifact from C:\NAVDVD\ConfigurationPackages\*EXTENDED.rapidstart
2021-07-05T23:03:26.7950143Z     [INFO] Copy Artifact 'C:\NAVDVD\ConfigurationPackages\*EXTENDED.rapidstart' (configuration v ) to C:\run\my\apps\001...
2021-07-05T23:03:26.7953283Z 
2021-07-05T23:03:26.7956847Z 
2021-07-05T23:03:26.7964306Z     Directory: C:\run\my\apps
2021-07-05T23:03:26.7967694Z 
2021-07-05T23:03:26.7970852Z 
2021-07-05T23:03:26.7978295Z Mode                 LastWriteTime         Length Name                         
2021-07-05T23:03:26.7985507Z ----                 -------------         ------ ----                         
2021-07-05T23:03:26.7992752Z d-----          7/5/2021  11:03 PM                001                          
2021-07-05T23:03:26.8000285Z     [INFO] Downloaded Files (C:\run\my\apps\001):
2021-07-05T23:03:26.8008048Z     [INFO] FullName                                               Length
2021-07-05T23:03:26.8015279Z     [INFO] --------                                               ------
2021-07-05T23:03:26.8022666Z     [INFO] C:\run\my\apps\001\NAV18.4.FR.FRA.EXTENDED.rapidstart 3708874
2021-07-05T23:03:28.0760068Z     [INFO] Donwload Artifacts done.
2021-07-05T23:03:28.0769182Z No FOBs to import.
2021-07-05T23:03:28.0777687Z No Apps to import.
2021-07-05T23:03:28.0785727Z Import 1 RIM packages...
2021-07-05T23:03:28.0794680Z     [INFO] Prepare RIM Artifact Import
2021-07-05T23:03:28.0802690Z RIM [INFO] Import RIM ... Get Companies ...
2021-07-05T23:03:28.0810521Z RIM [INFO] Import RIM ... found 2 companies
2021-07-05T23:03:28.0818463Z RIM [INFO] Import RapidStart files from C:\run\my\apps\001\NAV18.4.FR.FRA.EXTENDED.rapidstart ...
2021-07-05T23:03:28.0826720Z RIM [INFO] Import RIM C:\run\my\apps\001\NAV18.4.FR.FRA.EXTENDED.rapidstart
2021-07-05T23:13:01.3579531Z RIM [INFO] Import RIM ... successful
2021-07-05T23:13:01.3587912Z     [INFO] 
2021-07-05T23:13:01.3596188Z RIM [INFO] Import RIM C:\run\my\apps\001\NAV18.4.FR.FRA.EXTENDED.rapidstart
2021-07-05T23:22:33.5313283Z RIM [INFO] Import RIM ... successful
2021-07-05T23:22:33.5324361Z     [INFO] 
2021-07-05T23:22:33.5333064Z     [INFO] Import RapidStart files done. (Duration: 00:09:32.6565084)
2021-07-05T23:22:33.5340871Z Import RIM packages done. (Duration: 00:19:05.9864798)
2021-07-05T23:22:33.5348420Z No Fonts to import.
2021-07-05T23:22:34.8032229Z Import Artifacts done.
2021-07-05T23:22:34.8040699Z Start Performance Data Collection
2021-07-05T23:22:34.8048923Z Running Perfmon-Collector to create / update Perfmon Data Collector Set BC on 3E33D4B9EA9F
2021-07-05T23:22:34.8057273Z Creating the BC Data Collector Set
2021-07-05T23:22:36.0714082Z Starting the BC Data Collector Set
2021-07-05T23:22:37.3253571Z === Additional Setup Done ===
2021-07-05T23:22:37.3258154Z 
2021-07-05T23:22:38.5818519Z Container IP Address: 172.30.198.86
2021-07-05T23:22:38.5827365Z Container Hostname  : 3e33d4b9ea9f
2021-07-05T23:22:38.5836204Z Container Dns Name  : 3e33d4b9ea9f
2021-07-05T23:22:38.5844826Z Web Client          : https://3e33d4b9ea9f/BC/?tenant=default
2021-07-05T23:22:38.5853514Z Admin Username      : admin
2021-07-05T23:22:38.5861597Z Admin Password      : Fine1191
2021-07-05T23:22:38.5869167Z Dev. Server         : https://3e33d4b9ea9f
2021-07-05T23:22:38.5876458Z Dev. ServerInstance : BC
2021-07-05T23:22:38.5883539Z Dev. Server Tenant  : default
2021-07-05T23:22:38.5886869Z 
2021-07-05T23:22:38.5893829Z Files:
2021-07-05T23:22:38.5901022Z http://3e33d4b9ea9f:8080/ALLanguage.vsix
2021-07-05T23:22:38.5908194Z http://3e33d4b9ea9f:8080/artifacts.log.json
2021-07-05T23:22:38.5915325Z http://3e33d4b9ea9f:8080/certificate.cer
2021-07-05T23:22:38.5918267Z 
2021-07-05T23:22:38.5925667Z WARNING: You are running a container which is 205 days old.
2021-07-05T23:22:38.5932439Z Microsoft recommends that you always run the latest version of our containers.
2021-07-05T23:22:38.5935738Z 
2021-07-05T23:22:38.5942874Z Container Total Physical Memory is 64.0Gb
2021-07-05T23:22:38.5949906Z Container Free Physical Memory is 33.7Gb
2021-07-05T23:22:38.5952806Z 
2021-07-05T23:22:38.5960218Z Initialization took 1245 seconds
2021-07-05T23:22:38.5968176Z Ready for connections!
2021-07-05T23:22:38.5976894Z Starting EventLog Monitor
2021-07-05T23:22:38.5984960Z Monitoring EventSources from EventLog[Application]:
2021-07-05T23:22:38.5992360Z - MicrosoftDynamicsNAVClientClientService
2021-07-05T23:22:38.5999599Z - MicrosoftDynamicsNAVClientWebClient
2021-07-05T23:22:38.6007159Z - MicrosoftDynamicsNavServer$BC
2021-07-05T23:22:38.6014572Z - MSSQL$SQLEXPRESS

Log for running of the tests:

VERBOSE: Loading module from path 'C:\Run\DevOps\BCAppTest\bin\Microsoft.Dynamics.Framework.UI.Client.dll'.
*** Import NewtonSoft JSON [C:\Program Files\Microsoft Dynamics NAV\180\Service\Newtonsoft.Json.dll]
*** Import Modules in Docker Session: class_ClientContext
*** Test Context Url: https://3e33d4b9ea9f/BC/cs?tenant=default
*** Setup BC Credentials in Docker
*** Resolve Docker Credentials
*** Set TCP Keep-Alive
*** Start TestSuite
*** Running TestSuite with authentication [NavUserPassword] with User [admin]
*** Run warm-up with page [130455]
*** Warm-up Client Context
CommunicationError : Error reading JObject from JsonReader. Path '', line 0, position 0.
at <ScriptBlock>, <No file>: line 91
at InvokeInteractionAndCatchForm, <No file>: line 266
at OpenForm, <No file>: line 301
at Test-OpenForm, <No file>: line 7
at <ScriptBlock>, <No file>: line 14
at <ScriptBlock>, <No file>: line 1
Current Interaction: Microsoft.Dynamics.Framework.UI.Client.Interactions.OpenFormInteraction
Time spend: 9 seconds
*** Create Client Context
CommunicationError : Response status code does not indicate success: 502 (Bad Gateway).
at <ScriptBlock>, <No file>: line 91
at AwaitState, <No file>: line 220
at OpenSession, <No file>: line 198
at Initialize, <No file>: line 59
at ClientContext, <No file>: line 26
at New-ClientContext, <No file>: line 27
at <ScriptBlock>, <No file>: line 36
at <ScriptBlock>, <No file>: line 1
##[error]Run-Test-Exception: ClientSession State is Uninitialized (Wait time 10 seconds)
*** Get XUnit Test file from [] to [C:\azp\agent\_work\1\s\BC17.AstarInterface\]
##[error]Cannot bind argument to parameter 'Path' because it is null.
Finishing: ALOps Run TestSuite

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context

• does it happen all the time?
  So far it looks like we only get this for nextMinor

• did it use to work?
  Yes

[freddydk]

When did this start to fail?

Where does this output come from:

VERBOSE: Loading module from path 'C:\Run\DevOps\BCAppTest\bin\Microsoft.Dynamics.Framework.UI.Client.dll'.
*** Import NewtonSoft JSON [C:\Program Files\Microsoft Dynamics NAV\180\Service\Newtonsoft.Json.dll]
*** Import Modules in Docker Session: class_ClientContext
*** Test Context Url: https://3e33d4b9ea9f/BC/cs?tenant=default
*** Setup BC Credentials in Docker
*** Resolve Docker Credentials
*** Set TCP Keep-Alive
*** Start TestSuite
*** Running TestSuite with authentication [NavUserPassword] with User [admin]
*** Run warm-up with page [130455]
*** Warm-up Client Context

What are you using to run the tests?

There should not be anything special with next minor, all my pipelines works normally
https://github.com/BusinessCentralApps/HelloWorld/actions

[tfenster]

When did this start to fail?

• We have a failing one on sandbox-18.3.27287.0-us-mt
• We have a working one on sandbox-18.4.27591.0-us-mt
• We have a failing one on sandbox-18.4.27591.0-us-mt

Same machine, same setup, same code. Basically I am looking for any ideas how we can find out what the problem is?

Where does this output come from:

VERBOSE: Loading module from path 'C:\Run\DevOps\BCAppTest\bin\Microsoft.Dynamics.Framework.UI.Client.dll'.
*** Import NewtonSoft JSON [C:\Program Files\Microsoft Dynamics NAV\180\Service\Newtonsoft.Json.dll]
*** Import Modules in Docker Session: class_ClientContext
*** Test Context Url: https://3e33d4b9ea9f/BC/cs?tenant=default
*** Setup BC Credentials in Docker
*** Resolve Docker Credentials
*** Set TCP Keep-Alive
*** Start TestSuite
*** Running TestSuite with authentication [NavUserPassword] with User [admin]
*** Run warm-up with page [130455]
*** Warm-up Client Context

This is a pipeline using ALOps

What are you using to run the tests?

Not sure if I understand the question, but we are using ALOps in an Azure pipeline here

[freddydk]

My assumption is that this is an ALOps problem.
My pipelines are using Run-TestsInBcContainer, and that seems to work just fine.
I don't know if ALOps is using the same function or they have a different test execution mechanism.

[tfenster]

It was caused by Rapidstart imports or at least we could solve it removing the import