Bug in _clean_error_msg()

[TobiKr]

I had a strange issue when executing powershell scripts via this plugin: as soon as I loaded additional powershell modules, the script was executed, but returned error code 1 and the rundeck job was shown as failed.

After debugging of 10 hours via file.write and writing variables and streams in text files ( :-D ) , I found the bug. The method _clean_error_msg() throws an exception, when std_err has content. The initial exception was:
Traceback (most recent call last): File "/var/lib/rundeck/libext/cache/py-winrm-plugin-1.0.7/winrm-exec.py", line 117, in <module> realstderr.write(session._clean_error_msg(sys.stderr.read())) File "/var/lib/rundeck/libext/cache/py-winrm-plugin-1.0.7/winrm_session.py", line 110, in _clean_error_msg return new_msg UnboundLocalError: local variable 'new_msg' referenced before assignment
Content of std_err:
#< CLIXML <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>0</PC><T>Processing</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="1"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>25</PC><T>Processing</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="2"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>50</PC><T>Processing</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="3"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>75</PC><T>Processing</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="4"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>100</PC><T>Processing</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="5"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Loading Active Directory module for Windows PowerShell with default drive 'AD:'</AV><AI>0</AI><Nil /><PI>-1</PI><PC>100</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj><Obj S="progress" RefId="6"><TNRef RefId="0" /><MS><I64 N="SourceId">2</I64><Obj N="Record" RefId="7"><TN RefId="1"><T>Microsoft.Exchange.Configuration.Tasks.ExProgressRecord</T><T>System.Management.Automation.ProgressRecord</T><T>System.Object</T></TN><ToString>parent = -1 id = 0 act = Completed. stat = Completed. cur = pct = -1 sec = -1 type = Completed</ToString><Props><I32 N="ActivityId">0</I32><I32 N="ParentActivityId">-1</I32><S N="Activity">Completed.</S><S N="StatusDescription">Completed.</S><Nil N="CurrentOperation" /><I32 N="PercentComplete">-1</I32><I32 N="SecondsRemaining">-1</I32><Obj N="RecordType" RefId="8"><TN RefId="2"><T>System.Management.Automation.ProgressRecordType</T><T>System.Enum</T><T>System.ValueType</T><T>System.Object</T></TN><ToString>Completed</ToString><I32>1</I32></Obj></Props></Obj></MS></Obj></Objs>

I provisionally fixed the issue with adding the following line in winrm-session.py after line 89:
new_msg = msg
The line before is:
" error message: %s" % (e))
The line after is:
else:

One more comment on this: with the original code, the stacktrace was not visible in any error stream. I am not a python expert and was not able to narrow done, why the error/stacktrace was not shown in the rundeck debug output. The output of the powershell script was interrupted and rundeck and no error message was shown.

[hs-hub-world]

Thanks @TobiKr for your findings. This helped me to at least get it working. Before the job's would not provide any output after there was any timeout from PS side.

But now I am facing another issue. Can you please check/confirm you are experiancing the same on your end:
try to run this Foreach block in a ps1 file

foreach($num in (1..10))
{
write $num
sleep 1
}

my output is below:

It's missing #'s 2,7...

Now, if you run the same below it works find:
foreach($num in (1..10))
{
write "Number $($num)"
sleep 1
}

wondering if it has something to do with the number of data is being streamed back to the session. maybe 1-char is not enough -?

Thanks
HS

[ltamaster]

Hi @TobiKr ,

I added a new release, please let me know if you can test it.

Thanks
Luis

[TobiKr]

Hi @ltamaster
Thank you so much Luis, it works like a charm :-)

Thanks again
Tobi