Run .Net Script activity fails for simple PowerShell script, why?

When the Run .Net Script activity fails, sometimes the error message is not very informational.  Someone showed me the following exception (screenshot  of simplified repro):

The error summary does not say what “this function” is, what “the current host” means, and more importantly which part of the script triggers the unimplemented function so that we can workaround it.  As a software engineer, I want to know whether it is the script’s fault or a bug in the activity, and how to fix it if it’s a bug.

Here we will see how to use windbg to get the stack trace when the exception is raised.

Which process to debug?

Engineers in the product group know that PolicyModule.exe hosts the workflow engine, and that is the starting point.  However this may not seem obvious for outside people.  Fortunately it is easy to figure it out using Process Explorer (https://technet.microsoft.com/en-us/sysinternals/bb896653.aspx, run it from https://live.sysinternals.com/procexp.exe).

In Options menu, click “Difference Highlight Duration”, change the value from 1 second to 5 so we can see it more clearly.  Then start the Runbook Tester, procexp shows the newly created process PolicyModule.exe in green.  After the job is finished, the color of the process turns to red which means the process is terminated.

The session ID (the last column in the screenshot) is 2 which is the current desktop session.  This is good because windbg can automatically attach to it and show up on the desktop.  If the runbook is picked up by the Action Server, PolicyModule.exe will be started in session 0.  In that case, we use a slightly different way to debug, I will write it later.

Setup “Image File Execution Options”

By setting “Image File Execution Options”, the application will be automatically attached to the debugger as soon as it is launched.  This method is typically used when something else is creating the process and manually starting it is not possible.  For more information, refer to Junfeng’s blog at https://blogs.msdn.com/b/junfeng/archive/2004/04/28/121871.aspx and Inside 'Image File Execution Options' debugging.  It is really simple to use.  Assume 32bit windbg is installed at C:\Debuggers32, run C:\Debuggers32\gflags.exe, click “Image File” tab, enter “PolicyModule.exe” (do not use full path), press TAB, select “Debugger” check box, and enter “C:\Debuggers\windbg.exe” (full path of the debugger), then click “OK” button to dismiss the dialog.

Start to Debug

In Runbook Tester, click “Run” to start the runbook.  Windbg will show up immediately.  Now tell windbg to break on CLR exceptions and continue to run:

eax=00000000 ebx=00000000 ecx=60c50000 edx=0008e3b8 esi=fffffffe edi=77953b90
eip=779d0f2b esp=0018fb0c ebp=0018fb38 iopl=0 nv up ei pl zr na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246
ntdll!LdrVerifyImageMatchesChecksum+0x6ce:
779d0f2b cc int 3
0:000> sxe clr
0:000> g

After a while, the CLR exception is caught by windbg.  Let’s see what it is:

(dfc.1250): CLR exception - code e0434f4d (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
*** ERROR: Symbol file could not be found. Defaulted to export symbols for C:\Windows\syswow64\KERNELBASE.dll -
*** ERROR: Symbol file could not be found. Defaulted to export symbols for C:\Windows\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll -
eax=089ff280 ebx=e0434f4d ecx=00000001 edx=00000000 esi=089ff308 edi=003835d8
eip=7692b727 esp=089ff280 ebp=089ff2d0 iopl=0 nv up ei pl nz ac po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000212
KERNELBASE!RaiseException+0x58:
7692b727 c9 leave
0:030> .loadby sos mscorwks
0:030> !sos.PrintException
PDB symbol for mscorwks.dll not loaded
Exception object: 04c14f5c
Exception type: System.Management.Automation.Host.HostException
Message: Cannot invoke this function because the current host does not implement it.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131501
0:030> !sos.CLRStack
OS Thread Id: 0x1250 (30)
ESP EIP
089ff358 7692b727 [HelperMethodFrame: 089ff358]
089ff3fc 6b6e175d System.Management.Automation.Internal.Host.InternalHostRawUserInterface.ThrowNotInteractive()
089ff410 6b6e1665 System.Management.Automation.Internal.Host.InternalHostRawUserInterface.get_ForegroundColor()
089ff444 6d489451 Microsoft.PowerShell.Commands.ConsoleColorCmdlet.get_ForegroundColor()
089ff474 6d4a7207 Microsoft.PowerShell.Commands.WriteHostCommand.PrintObject(System.Object)
089ff4b0 6d4a75f0 Microsoft.PowerShell.Commands.WriteHostCommand.ProcessRecord()
089ff4e0 6b262388 System.Management.Automation.Cmdlet.DoProcessRecord()
089ff4e8 6b2b11a0 System.Management.Automation.CommandProcessor.ProcessRecord()
089ff528 6b29cfe5 System.Management.Automation.CommandProcessorBase.DoExecute()
089ff558 6b2a84cd System.Management.Automation.Internal.PipelineProcessor.Inject(System.Object, Boolean)
089ff574 6b2a3baf System.Management.Automation.Internal.PipelineProcessor.SynchronousExecuteEnumerate(System.Object, System.Collections.Hashtable, Boolean)
089ff5bc 6b2aac03 System.Management.Automation.PipelineNode.Execute(System.Array, System.Management.Automation.Internal.Pipe, System.Collections.ArrayList ByRef, System.Management.Automation.ExecutionContext)
089ff608 6b2aa884 System.Management.Automation.StatementListNode.ExecuteStatement(System.Management.Automation.ParseTreeNode, System.Array, System.Management.Automation.Internal.Pipe, System.Collections.ArrayList ByRef, System.Management.Automation.ExecutionContext)
089ff654 6b2aa79e System.Management.Automation.StatementListNode.Execute(System.Array, System.Management.Automation.Internal.Pipe, System.Collections.ArrayList ByRef, System.Management.Automation.ExecutionContext)
089ff698 6b2aa6b1 System.Management.Automation.ParseTreeNode.Execute(System.Array, System.Management.Automation.Internal.Pipe, System.Management.Automation.ExecutionContext)
089ff6b4 6b2aa4bf System.Management.Automation.ScriptCommandProcessor.ExecuteWithCatch(System.Management.Automation.ParseTreeNode, System.Array)
089ff6f4 6b2a8a79 System.Management.Automation.ScriptCommandProcessor.RunClause(System.Management.Automation.ParseTreeNode, System.Object, System.Object)
089ff740 6b2a861c System.Management.Automation.ScriptCommandProcessor.Complete()
089ff758 6b29d1fe System.Management.Automation.CommandProcessorBase.DoComplete()
089ff78c 6b2a3c2f System.Management.Automation.Internal.PipelineProcessor.SynchronousExecuteEnumerate(System.Object, System.Collections.Hashtable, Boolean)
089ff7d4 6b2a3b12 System.Management.Automation.Internal.PipelineProcessor.SynchronousExecute(System.Array, System.Collections.Hashtable)
089ff7e8 6b29fe09 System.Management.Automation.Runspaces.LocalPipeline.InvokeHelper()
089ff840 6b29f8c7 System.Management.Automation.Runspaces.LocalPipeline.InvokeThreadProc()
089ff890 6c886df6 System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
089ff89c 6c89027f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
089ff8b4 6c886d74 System.Threading.ThreadHelper.ThreadStart()
089ffadc 6e561b4c [GCFrame: 089ffadc]

Obviously, the stack tells us that the exception is caused by WriteHost cmdlet because the InternalHostRawInterface throws an exception while encountering interactive operations. We could stop here, but we want to know what’s being written by WriteHost:

0:030> !sos.CLRStack -a
OS Thread Id: 0x1250 (30)
ESP EIP
089ff358 7692b727 [HelperMethodFrame: 089ff358]
089ff3fc 6b6e175d System.Management.Automation.Internal.Host.InternalHostRawUserInterface.ThrowNotInteractive()
PARAMETERS:
this = <no data>
LOCALS:
<no data>
<no data>

089ff410 6b6e1665 System.Management.Automation.Internal.Host.InternalHostRawUserInterface.get_ForegroundColor()
PARAMETERS:
this = 0x049b014c
LOCALS:
<no data>
0x089ff414 = 0x00000000
0x089ff410 = 0x00000000

089ff444 6d489451 Microsoft.PowerShell.Commands.ConsoleColorCmdlet.get_ForegroundColor()
PARAMETERS:
this = 0x04bdac30
LOCALS:
0x089ff448 = 0x00000000
0x089ff444 = 0x00000000

089ff474 6d4a7207 Microsoft.PowerShell.Commands.WriteHostCommand.PrintObject(System.Object)
PARAMETERS:
this = 0x04bdac30
o = <no data>
LOCALS:
<CLR reg> = 0x04bf7d68
<no data>
<no data>
<no data>
0x089ff478 = 0x00000000
<no data>
<no data>
…

0:030> !sos.do 0x04bf7d68
Name: System.String
MethodTable: 6c8e0ae8
EEClass: 6c69d65c
Size: 20(0x14) bytes
(C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: 3
Fields:
MT Field Offset Type VT Attr Value Name
6c8e2d34 4000096 4 System.Int32 1 instance 2 m_arrayLength
6c8e2d34 4000097 8 System.Int32 1 instance 1 m_stringLength
6c8e17c8 4000098 c System.Char 1 instance 33 m_firstChar
6c8e0ae8 4000099 10 System.String 0 shared static Empty
>> Domain:Value 0033b8a8:04981198 <<
6c8e1718 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 0033b8a8:0498185c <<

In this repro the script being executed is “1 + 2 | Write-Host”, so it is correct that the string passed to WriteHost is “3”.

Workaround

Because the internal host in “Run .Net Script” does not support any host interaction, the workaround is to avoid all such cmdlets, for instance Write-Host, Read-Host, etc.

How to fix it?

Modifying the script which potentially calls into other scripts to workaround this issue may not be straightforward.  How to fix it from Orchestrator’s side?

Typically the first step of executing PowerShell scripts is to create a Runspace using RunspaceFactory.CreateRunspace method (in name space System.Management.Automation.Runspaces).  Creating local runspace is often done by the method CreateRunspace() with the default host and configuration.  Here the default host refers to System.Management.Automation.Internal.Host.InternalHost, and the property UI is InternalHostUserInterface instance.  Implementations of PSHostInterface methods delegate to externalUI of same interface, which is null for default host.  In this case, when host interaction methods are called, HostException is thrown with the message which we see in windbg.

In order to handle host interactions properly and solve this issue, a custom host (interface PSHost) and host interface (interface PSHostUserInterface) need to be implemented.  When the runspace is created, this custom host will be passed to CreateRunspace method.  In other words, the activity should use the methods with PSHost argument in the overload list of RunspaceFactory.CreateRunspace method.

The above analysis can be verified by checking the assembly containing Run .Net Script activity.  From the list of DLL being loaded in windbg, one can see that the code is in RunScriptDomain.dll.  Since it’s managed code, we can get the IL code for RunScriptDomain.PowerShellRunner.run() using ildasm (run from Visual Studio Command Prompt):

.method public hidebysig newslot virtual final
instance void run() cil managed
{
// Code size 60 (0x3c)
.maxstack 2
.locals init (class [System.Management.Automation]System.Management.Automation.Runspaces.Runspace V_0,
class [System.Management.Automation]System.Management.Automation.Runspaces.Pipeline V_1)
IL_0000: call class [System.Management.Automation]System.Management.Automation.Runspaces.Runspace [System.Management.Automation]System.Management.Automation.Runspaces.RunspaceFactory::CreateRunspace()
IL_0005: stloc.0
IL_0006: ldloc.0
IL_0007: callvirt instance void [System.Management.Automation]System.Management.Automation.Runspaces.Runspace::Open()
IL_000c: ldloc.0
IL_000d: callvirt instance class [System.Management.Automation]System.Management.Automation.Runspaces.Pipeline [System.Management.Automation]System.Management.Automation.Runspaces.Runspace::CreatePipeline()
IL_0012: stloc.1
IL_0013: ldloc.1
IL_0014: callvirt instance class [System.Management.Automation]System.Management.Automation.Runspaces.CommandCollection [System.Management.Automation]System.Management.Automation.Runspaces.Pipeline::get_Commands()
IL_0019: ldarg.0
IL_001a: ldfld class RunScriptDomain.Script RunScriptDomain.PowerShellRunner::_script
IL_001f: callvirt instance string RunScriptDomain.Script::get_Contents()
IL_0024: callvirt instance void [System.Management.Automation]System.Management.Automation.Runspaces.CommandCollection::AddScript(string)
IL_0029: ldarg.0
IL_002a: ldloc.1
IL_002b: callvirt instance class [mscorlib]System.Collections.ObjectModel.Collection`1<class [System.Management.Automation]System.Management.Automation.PSObject> [System.Management.Automation]System.Management.Automation.Runspaces.Pipeline::Invoke()
IL_0030: stfld class [mscorlib]System.Collections.ObjectModel.Collection`1<class [System.Management.Automation]System.Management.Automation.PSObject> RunScriptDomain.PowerShellRunner::resultOfRunningCmd
IL_0035: ldloc.0
IL_0036: callvirt instance void [System.Management.Automation]System.Management.Automation.Runspaces.Runspace::Close()
IL_003b: ret
} // end of method PowerShellRunner::run

By the way, if IL code looks unfamiliar to you, take a look at .NET Reflector or open source ILSpy.

If you wonder whether there is a PowerShell integration pack with a richer set of features so no workaround is needed, the answer is yes – a prototype is available, 32-bit and 64-bit runspace without WinRM, persistence and pooling of runspace across process boundary, remoting using WinRM, impersonation are all working.  We are working hard to deliver the best customer experience.