1

SPE: 4.5.0.0

Sitecore: 8.2u3

I designed a script to remotely publish a series of item paths. Each path is iterated across each publishing target database. The net result is 8 individual remote publish operations, each with a unique jobId.

Script

When executed from Azure DevOps, the following script appears to execute properly, but when viewing the logs, it actually throws an exception and publishing does not occur (it also executes in a second or two, which is incorrect, should be around 2 minutes in my test). I've removed the publishing portion of the script as the behavior is the same with or without it:

$sitecoreUrl = "https://authoring{0}{1}.{2}" -f "$(dev4_envName)", "$(envColor)", "$(rootHostName)"

$session = $null
$session = New-ScriptSession -Username "$(pubUserName)" -Password "$(srvscpubnprd)" -ConnectionUri "$sitecoreUrl"
if ($session -ne $null) {
    write-host "Connected to Sitecore server $sitecoreUrl"
} else {
    write-error "Login failed to Sitecore server $sitecoreUrl for user $(pubUserName)."
}

$targetDatabaseNames = @("web","preview")
$itemPaths = @("master:\sitecore\layout", "master:\sitecore\commerce", "master:\sitecore\templates\customer", "master:\sitecore\content\customer")

foreach($targetDatabaseName in $targetDatabaseNames){

    foreach($itemPath in $itemPaths){

        $data = @{targetDatabaseName=$targetDatabaseName;itemPath=$itemPath}
        $jobId = $null
        Write-Output "*** 1"

        $jobId = Invoke-RemoteScript -Session $session -ScriptBlock {
            Write-Log "In job"
        } -AsJob

        $result = Wait-RemoteScriptSession -Session $session -Id $jobId -Delay 5 -Verbose
        Write-Output "*** 2"
    }
}
Write-Output "Done with all jobs"

Stop-ScriptSession -Session $session

SPE Exception/Logs

The logs are interesting. SPE logs the "primary" session as executing a variety of operations and then abruptly disposes of the session just before the calls I need are executed. It then appears to open up a new session (though none was instantiated) and tries to execute remote commands only to be faced with the exception. Also notice that "In job" is never output.

7148 16:31:44 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  Executing PsSitecoreItemProvider5.Start(providerInfo='Sitecore')
7232 16:31:45 INFO  Executing PsSitecoreItemProvider5.Start(providerInfo='Sitecore')
7148 16:31:45 INFO  Executing a script in ScriptSession ''.
7148 16:31:45 INFO  The script execution in ScriptSession '' completed in 2 ms.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 22 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 4 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7232 16:31:45 INFO  Executing PsSitecoreItemProvider5.Start(providerInfo='Sitecore')
7148 16:31:45 INFO  Executing PsSitecoreItemProvider5.Start(providerInfo='Sitecore')
7148 16:31:45 INFO  Executing a script in ScriptSession ''.
7148 16:31:45 INFO  The script execution in ScriptSession '' completed in 3 ms.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 22 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 3 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Script executed in session a658eb45-f825-436c-b247-ebb5046d4c88 through remoting by user: 'customerad\srv_sc_pub_nprd'
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 1 ms.
7148 16:31:45 INFO  Executing a script in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88'.
7148 16:31:45 INFO  The script execution in ScriptSession '$scriptSession$|a658eb45-f825-436c-b247-ebb5046d4c88' completed in 0 ms.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' calling the Remoting Automation service.
7148 16:31:45 INFO  User 'customerad\srv_sc_pub_nprd' successfully logged in to the Remoting Automation service.
7148 16:31:45 INFO  Session 'a658eb45-f825-436c-b247-ebb5046d4c88' disposed by user: 'customerAD\srv_sc_pub_nprd'
ManagedPoolThread #7 16:31:46 INFO  Executing a script in ScriptSession '$scriptSession$|63c3755e-debc-4e10-98bb-524d211c4f9a'.
ManagedPoolThread #7 16:31:46 ERROR Error while performing timed 'script execution in ScriptSession '$scriptSession$|63c3755e-debc-4e10-98bb-524d211c4f9a'' operation within 1 ms. Exception logged at operation origin point.
ManagedPoolThread #9 16:31:46 INFO  Executing a script in ScriptSession '$scriptSession$|901ab9fc-10ca-4217-9122-d08e6384e9e9'.
ManagedPoolThread #9 16:31:46 ERROR Error while performing timed 'script execution in ScriptSession '$scriptSession$|901ab9fc-10ca-4217-9122-d08e6384e9e9'' operation within 0 ms. Exception logged at operation origin point.
ManagedPoolThread #7 16:31:46 ERROR Error while executing PowerShell Extensions script.
Exception: System.Management.Automation.Runspaces.InvalidRunspaceStateException
Message: Cannot perform operation because the runspace is not in the 'Opened' state. Current state of runspace is 'Closed'.
Source: System.Management.Automation
   at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.Invoke(IEnumerable input, PSInvocationSettings settings)
   at Cognifide.PowerShell.Core.Host.ScriptSession.ExecuteCommand(Boolean stringOutput, Boolean marshallResults)
   at Cognifide.PowerShell.Core.Host.ScriptSession.<>c__DisplayClass141_0.<ExecuteScriptPart>b__0()
   at Cognifide.PowerShell.Core.Utility.SpeTimer.Measure[T](String message, Func`1 action)
   at Cognifide.PowerShell.Core.Host.ScriptSession.ExecuteScriptPart(String script, Boolean stringOutput, Boolean internalScript, Boolean marshalResults)
   at Cognifide.PowerShell.Commandlets.ScriptSessions.StartScriptSessionCommand.RunJob(ScriptSession session, String command)

ManagedPoolThread #11 16:31:46 INFO  Executing a script in ScriptSession '$scriptSession$|0e7c0ee8-a0a5-4b3b-86e0-4b2529fa320d'.
ManagedPoolThread #11 16:31:46 ERROR Error while performing timed 'script execution in ScriptSession '$scriptSession$|0e7c0ee8-a0a5-4b3b-86e0-4b2529fa320d'' operation within 0 ms. Exception logged at operation origin point.
ManagedPoolThread #11 16:31:46 ERROR Error while executing PowerShell Extensions script.
Exception: System.Management.Automation.Runspaces.InvalidRunspaceStateException
Message: Cannot perform operation because the runspace is not in the 'Opened' state. Current state of runspace is 'Closed'.
Source: System.Management.Automation
   at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
   at System.Management.Automation.PowerShell.Invoke(IEnumerable input, PSInvocationSettings settings)
   at Cognifide.PowerShell.Core.Host.ScriptSession.ExecuteCommand(Boolean stringOutput, Boolean marshallResults)
   at Cognifide.PowerShell.Core.Host.ScriptSession.<>c__DisplayClass141_0.<ExecuteScriptPart>b__0()
   at Cognifide.PowerShell.Core.Utility.SpeTimer.Measure[T](String message, Func`1 action)
   at Cognifide.PowerShell.Core.Host.ScriptSession.ExecuteScriptPart(String script, Boolean stringOutput, Boolean internalScript, Boolean marshalResults)
   at Cognifide.PowerShell.Commandlets.ScriptSessions.StartScriptSessionCommand.RunJob(ScriptSession session, String command)

Azure DevOps Output

For completeness, the output as seen from Azure DevOps is included below. Subtract 5 hours from times below (UTC to EST) to compare logs above.

2019-12-23T21:31:18.7404453Z Connected to Sitecore server https://authoringdev4.customernp.ca
2019-12-23T21:31:18.8463342Z *** 1
2019-12-23T21:31:43.2363551Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:43.4202624Z VERBOSE: Polling job 13e0e7c5-58f1-4199-a546-34727df5b388. Status : Available.
2019-12-23T21:31:43.4207025Z VERBOSE: Finished polling job 13e0e7c5-58f1-4199-a546-34727df5b388.
2019-12-23T21:31:43.4258703Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:43.5139509Z *** 2
2019-12-23T21:31:43.5146853Z *** 1
2019-12-23T21:31:43.6053178Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:43.6749800Z VERBOSE: Polling job 9851c51d-876c-4593-aa89-471e11fdb97a. Status : Available.
2019-12-23T21:31:43.6795108Z VERBOSE: Finished polling job 9851c51d-876c-4593-aa89-471e11fdb97a.
2019-12-23T21:31:43.6814448Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:43.7514117Z *** 2
2019-12-23T21:31:43.7515727Z *** 1
2019-12-23T21:31:43.8452467Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:43.9154585Z VERBOSE: Polling job 99ea6635-f255-4e20-a45a-fc117ef66eb0. Status : Available.
2019-12-23T21:31:43.9165068Z VERBOSE: Finished polling job 99ea6635-f255-4e20-a45a-fc117ef66eb0.
2019-12-23T21:31:43.9209215Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.0044643Z *** 2
2019-12-23T21:31:44.0051697Z *** 1
2019-12-23T21:31:44.1003524Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.1681733Z VERBOSE: Polling job 63c3755e-debc-4e10-98bb-524d211c4f9a. Status : Available.
2019-12-23T21:31:44.1702237Z VERBOSE: Finished polling job 63c3755e-debc-4e10-98bb-524d211c4f9a.
2019-12-23T21:31:44.1738289Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.2541223Z *** 2
2019-12-23T21:31:44.2550038Z *** 1
2019-12-23T21:31:44.4000368Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.4408993Z VERBOSE: Polling job dbddffe2-b3d5-4483-b942-c325b985c02b. Status : Available.
2019-12-23T21:31:44.4477276Z VERBOSE: Finished polling job dbddffe2-b3d5-4483-b942-c325b985c02b.
2019-12-23T21:31:44.4479932Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.5108768Z *** 2
2019-12-23T21:31:44.5111599Z *** 1
2019-12-23T21:31:44.8341160Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.9104120Z VERBOSE: Polling job 288cbd6a-0ea4-4f21-90a3-00641701d074. Status : Available.
2019-12-23T21:31:44.9105840Z VERBOSE: Finished polling job 288cbd6a-0ea4-4f21-90a3-00641701d074.
2019-12-23T21:31:44.9120042Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:44.9816581Z *** 2
2019-12-23T21:31:44.9822107Z *** 1
2019-12-23T21:31:45.0780101Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:45.1492860Z VERBOSE: Polling job 901ab9fc-10ca-4217-9122-d08e6384e9e9. Status : Available.
2019-12-23T21:31:45.1494770Z VERBOSE: Finished polling job 901ab9fc-10ca-4217-9122-d08e6384e9e9.
2019-12-23T21:31:45.1527634Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:45.2174971Z *** 2
2019-12-23T21:31:45.2176732Z *** 1
2019-12-23T21:31:45.3115325Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:45.3774818Z VERBOSE: Polling job 0e7c0ee8-a0a5-4b3b-86e0-4b2529fa320d. Status : Available.
2019-12-23T21:31:45.3783204Z VERBOSE: Finished polling job 0e7c0ee8-a0a5-4b3b-86e0-4b2529fa320d.
2019-12-23T21:31:45.3827872Z VERBOSE: Checking the Runspace for the variable id.
2019-12-23T21:31:45.4459073Z *** 2
2019-12-23T21:31:45.4461440Z Done with all jobs

I've reran this script dozens of times at this point and possibly the strangest part is that on some runs some of the publish operations are executed flawlessly. Again, in my example there are 8 total operations and I've seen 3 execute properly and 5 fail. In that example, the first 5 failed, then the last 3 succeeded.

Lastly, the same script has been run successfully without the use of job polling. However, leveraging the script without polling will (and has) result(ed) in timeout exceptions.

  • I wonder if you should use a unique session object for each call to Invoke-RemoteScript. – Michael West Dec 23 '19 at 21:55
  • I tried that in several previous test and the results were similar. I’m leaning on it being a version issue or something along those lines. – jrap Dec 23 '19 at 21:56
  • Further findings: Appears to be an Azure DevOps-ism. The script works properly when executed directly from the server (IaaS). Same behavior is seen in Azure DevOps regardless of Inline or File-based execution. – jrap Jan 2 at 20:53
1

The primary hurdle was Azure DevOps. While I was using the native PowerShell command in my Release, it did not recreate the same execution cycle I witnessed when running the script directly on the VM.

The solution was to create an additional runspace and to sleep prior to the execution of the status check Wait-RemoteScriptSession of SPE.

The trimmed-down script is below:

# new runspace creation
$Runspace = [runspacefactory]::CreateRunspace()
$PowerShell = [powershell]::Create()
$PowerShell.runspace = $Runspace
$Runspace.Open()

# set variables to be consumed by new runspace
$Runspace.SessionStateProxy.SetVariable("myVariable", "$(myVariable)") # $(X) notation pulls from Azure DevOps variables

[void]$PowerShell.AddScript({
    # read variables like normal (as set above), i.e. $myVariable
    # this is where $username, $password and $sitecoreUrl would come from

    $session = New-ScriptSession -Username $userName -Password $password -ConnectionUri $sitecoreUrl
    if ($session -ne $null) {
        Write-Output "Connected to Sitecore server $sitecoreUrl"
    } else {
        Write-Error "Login failed to Sitecore server $sitecoreUrl"
    }

    $list = @("item1","item2")

    # in my case, I triggered multiple loops/remote scripting sessions
    foreach($item in $list){

        $jobId = Invoke-RemoteScript -Session $session -ScriptBlock {

            # do stuff here related to $item

            # this is key
            Start-Sleep -s 10
        } -AsJob

        # this is key
        Start-Sleep -s 10
        Wait-RemoteScriptSession -Session $session -Id $jobId -Delay 5 -Verbose
    }

    Stop-ScriptSession -Session $session
})

# execute the above script in a new runspace
$AsyncObject = $PowerShell.BeginInvoke()

# polling to check for status and apply a max runtime

$Runspace.Close()    
$PowerShell.EndInvoke($AsyncObject)
$PowerShell.Dispose()

The polling I introduced, as commented in the above script is below. It logs a warning to the release in Azure DevOps as, in my case, it isn't critical if it fails:

$maxSeconds = 900 # 15 minutes
$start = $(get-date)

while($AsyncObject.IsCompleted -eq $false){
    Write-Output "Complete?" $AsyncObject.IsCompleted
    $currentTime = $(get-date)
    $span = new-timespan $start $currentTime
    if($span.Seconds -gt $maxSeconds){
        Write-Host  "##vso[task.LogIssue type=warning;]Maximum time expired for the task. Perform operation manually."
        $Runspace.Close()
        $PowerShell.Dispose()
        exit
    }
    Start-Sleep -s 10
}

Write-Output "Complete?" $AsyncObject.IsCompleted
| improve this answer | |
  • It's not just an Azure DevOps thing, I'm observing the exact same behavior from a Jenkins pipeline powershell step. The issue is intermittent. Adding the sleep before checking on the job status seemed to help but it still happens sometimes. I'm considering some sort of Retry loop instead of the additional Runspace wrapper. – Paul Martin May 21 at 13:29

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.