Invoke-NcSsh works, but throws exception in WFA

[DavidSpano]

I need a general purpose WFA Command that will accept a Cluster name and Command as input and run the command on the cluster.

My environment is: WFA Server Windows 2012 R2, WFA 4.2, Clustered ONTAP 9.3P15; PSToolkit 9.7; Putty 0.73

I have written the command using the Invoke-NcSsh cmdlet.  I ran into the issues described in Community Article: "Invoke-NcSsh failing with ONTAP 9.3".  I followed the solution to upgrade the Netapp DataONTAP PSToolkit to 9.7 and install PuTTY v0.7.3.  This got me past the initial problem and the Invoke-NcSsh cmdlet actually runs the command on the cluster.  The only problem is that the cmdlet in the WFA JBOSS container throws an exception at the end of the command processing.

Here is the simplified PS code that shows the problem:

param (
  [parameter(Mandatory=$True, HelpMessage="First Cluster")]
  [string]$Cluster
)

Get-WFALogger -info -message "Running Test Command"

$creds = Get-WfaCredentials -Hostname $Cluster
$result = Invoke-NcSsh -Name $Cluster -Command date -Credential $creds

Get-WFALogger -info -message $("-- " + $result)

Get-WFALogger -info -message "End Test Command"

Output: >>>>>>>>>>>>>>

15:47:29.012 INFO  [SWA Test] ### Command XXX Test' in 'POWER_SHELL' ###
15:47:35.559 INFO  [SWA Test] Running Test Command
15:47:35.574 INFO  [SWA Test] Credentials successfully provided for 'cluster050'
15:47:40.996 INFO  [SWA Test] -- Node      Date                     Time zone
--------- ------------------------ -------------------------
          Fri Jan 10 15:47:41 2020 US/Central
          Fri Jan 10 15:47:41 2020 US/Central
2 entries were displayed.
15:47:41.012 INFO  [XXX Test] End Test Command
15:47:41.074 ERROR  [XXX Test] Failed executing command. Exception:

The command works fine, its just that WFA flags an error; but the Excepton is null.

The only other clue I have found is that an error is posted to the server.log when the command is run:

server.log error >>>>>>>>

2020-01-10 15:47:41,059 ERROR [stderr] (default task-16) [Fatal Error] :1:1: Content is not allowed in prolog.

Any ideas on trouble shooting this error?

[mbeattie]

Hi,

A potenital workaround for you might be to use "Invoke-NcSystemApi" to invoke a CLI command instead of using "Invoke-NcSsh". For example:

Param(
   [Parameter(Mandatory=$True, HelpMessage="The Cluster name or IP Address")]
   [String]$Cluster,
   [Parameter(Mandatory=$True, HelpMessage="The ONTAP CLI to invoke")]
   [String]$Command,
   [Parameter(Mandatory=$False, HelpMessage="If specified the CLI output is logged")]
   [Bool]$VerboseLogging
)
#'------------------------------------------------------------------------------
#'Connect to the Cluster.
#'------------------------------------------------------------------------------
Connect-WFACluster $Cluster
#'------------------------------------------------------------------------------
#'Convert the CLI command to the API to invoke.
#'------------------------------------------------------------------------------
[String]$Command = $Command.Trim();
If($Command.Contains(" ")){
   [Array]$cmd = $Command.Split(" ")
}Else{
   [Array]$cmd = $Command
}
$api = $("<system-cli><args><arg>" + ($cmd -join "</arg><arg>") + "</arg></args></system-cli>")
#'------------------------------------------------------------------------------
#'Invoke the API.
#'------------------------------------------------------------------------------
Try{
   $output = Invoke-NcSystemApi -Request $api -ErrorAction Stop
   Get-WFALogger -Info -Message $("Executed Command`: " + $([String]::Join(" ", $command)))
}Catch{
   Get-WFALogger -Error -Message $("Failed Executed Command`: " + $([String]::Join(" ", $command)) + ". Error " + $_.Exception.Message)
   Throw $("Failed Executing Command`: " + $([String]::Join(" ", $command)))
}
#'------------------------------------------------------------------------------
#'Log the CLI output if required.
#'------------------------------------------------------------------------------
If($VerboseLogging -And $output.results."cli-result-value" -eq 1){
   [Array]$lines = $output.results."cli-output".Trim().Split("`n")
   ForEach($line In $lines){
      Get-WFALogger -Info -Message $line
   }
}
#'------------------------------------------------------------------------------

Hope that helps

/Matt

[DavidSpano]

Matt,  Thank you for the suggested solution.  I have deployed the code into a WFA command to test.  It seems to run fine, except that the output from the command is either not returned or not logged.  Below is the output I see, even though I set "VerboseLogging" to true:

10:19:45.261 INFO  [Execute cDOT Command] ### Command 'Execute cDOT Command' in 'POWER_SHELL' ###
10:19:51.763 INFO  [Execute cDOT Command] Using cached cluster connection
10:19:53.008 INFO  [Execute cDOT Command] Executed Command: date
10:19:53.055 INFO  [Execute cDOT Command] Command completed, took 7794 milliseconds

[DavidSpano]

Matt,

Running a second test to actually modify a volume on the cluster seems to show that the command is not executing even though the Invoke-NcSystemApi does not return a failure.  Using a test volume, I list the current snapshots:

sdcdclr050::> volume snapshot show -vserver dsvmnas04 -volume dev_appz
                                                                 ---Blocks---
Vserver  Volume   Snapshot                                  Size Total% Used%
-------- -------- ------------------------------------- -------- ------ -----
dsvmnas04
         dev_appz
                  daily.2020-01-07_0010                    672KB     0%   40%
                  daily.2020-01-08_0010                    572KB     0%   36%
                  daily.2020-01-09_0010                    504KB     0%   33%
                  daily.2020-01-10_0010                    364KB     0%   26%
                  daily.2020-01-11_0010                    644KB     0%   39%
                  daily.2020-01-12_0010                    456KB     0%   31%
                  hourly.2020-01-12_0800                   108KB     0%   10%
                  hourly.2020-01-12_1200                   472KB     0%   32%
                  hourly.2020-01-12_1600                   108KB     0%   10%
                  hourly.2020-01-12_2000                   108KB     0%   10%
                  daily.2020-01-13_0010                    416KB     0%   29%
                  hourly.2020-01-13_0400                   108KB     0%   10%
                  hourly.2020-01-13_0800                   100KB     0%    9%
13 entries were displayed.

I then run the command with the following Inputs:

When I list the snapshots on the volume again, I don't see a new snapshot named "testsnap".

When I check the Audit log, I don't find any logging of the API command.

https://xxxxxxx050/spi/xxxxxx050-01/etc/log/

[mbeattie]

Hi David,

I've tweaked the code and tested it.

Param(
   [Parameter(Mandatory=$True, HelpMessage="The Cluster name or IP Address")]
   [String]$Cluster,
   [Parameter(Mandatory=$True, HelpMessage="The ONTAP CLI to invoke")]
   [String]$Command,
   [Parameter(Mandatory=$False, HelpMessage="The ONTAP CLI privilege")]
   [ValidateSet("admin","advanced","diag")]
   [String]$Privilege,
   [Parameter(Mandatory=$False, HelpMessage="If specified the CLI output is logged")]
   [Bool]$VerboseLogging
)
#'------------------------------------------------------------------------------
#'Connect to the Cluster.
#'------------------------------------------------------------------------------
Connect-WFACluster $Cluster
#'------------------------------------------------------------------------------
#'Convert the CLI command to the API to invoke.
#'------------------------------------------------------------------------------
[String]$Command = $Command.Trim();
If($Command.Contains(" ")){
   [Array]$cmd = $Command.Split(" ")
}Else{
   [Array]$cmd = $Command
}
If($Privilege){
   $cmd[0] = $("set $Privilege`;" + $cmd[0])
}
$api = $("<system-cli><args><arg>" + ($cmd -join "</arg><arg>") + "</arg></args></system-cli>")
#'------------------------------------------------------------------------------
#'Invoke the API.
#'------------------------------------------------------------------------------
Try{
   $output = Invoke-NcSystemApi -Request $api -ErrorAction Stop
   Get-WFALogger -Info -Message $("Executed Command`: " + $([String]::Join(" ", $command)))
}Catch{
   Get-WFALogger -Error -Message $("Failed Executed Command`: " + $([String]::Join(" ", $command)) + ". Error " + $_.Exception.Message)
   Throw $("Failed Executing Command`: " + $([String]::Join(" ", $command)))
}
#'------------------------------------------------------------------------------
#'Log the CLI output if required.
#'------------------------------------------------------------------------------
If($VerboseLogging -And $output.results."cli-result-value" -eq 1){
   [Array]$lines = $output.results."cli-output".Trim().Split("`n")
   ForEach($line In $lines){
      If(-Not([String]::IsNullOrEmpty($line))){
         Get-WFALogger -Info -Message $line
      }
   }
}
#'------------------------------------------------------------------------------

EG: Create a volume snapshot via a CLI:

11:30:14.845 INFO  [invoke_system_api] ### Command 'invoke_system_api' in 'POWER_SHELL' ###
11:30:27.471 INFO  [invoke_system_api] Get-WfaCredentials -Host cluster1
11:30:27.502 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
11:30:27.533 INFO  [invoke_system_api] Connect-Controller -Type CLUSTER -Name cluster1 -Credential System.Management.Automation.PSCredential -Vserver  -SSLversion TLSv1
11:30:27.580 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
11:30:27.643 INFO  [invoke_system_api] Connect-NcController (with credentials) -Name cluster1 -Timeout 60000 -ErrorAction Stop -Port 443 -SSLVersion TLSv1
11:30:29.518 INFO  [invoke_system_api] Connected to cluster node
11:30:31.549 INFO  [invoke_system_api] Executed Command: volume snapshot create -vserver vserver1 -volume volume1 -snapshot snapshot3
11:30:31.611 INFO  [invoke_system_api] Command completed, took 16766 milliseconds

Display the volume snapshots using CLI:

11:31:38.837 INFO  [invoke_system_api] ### Command 'invoke_system_api' in 'POWER_SHELL' ###
11:31:52.134 INFO  [invoke_system_api] Get-WfaCredentials -Host cluster1
11:31:52.166 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
11:31:52.197 INFO  [invoke_system_api] Connect-Controller -Type CLUSTER -Name cluster1 -Credential System.Management.Automation.PSCredential -Vserver  -SSLversion TLSv1
11:31:52.259 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
11:31:52.306 INFO  [invoke_system_api] Connect-NcController (with credentials) -Name cluster1 -Timeout 60000 -ErrorAction Stop -Port 443 -SSLVersion TLSv1
11:31:54.619 INFO  [invoke_system_api] Connected to cluster node
11:31:54.884 INFO  [invoke_system_api] Executed Command: volume snapshot show -vserver vserver1 -volume volume1
11:31:54.916 INFO  [invoke_system_api] ---Blocks---
11:31:54.931 INFO  [invoke_system_api] Vserver  Volume   Snapshot                                  Size Total% Used%
11:31:54.963 INFO  [invoke_system_api] -------- -------- ------------------------------------- -------- ------ -----
11:31:54.994 INFO  [invoke_system_api] vserver1 volume1
11:31:55.009 INFO  [invoke_system_api]                   weekly.2020-01-05_0015                   548KB     0%   46%
11:31:55.041 INFO  [invoke_system_api]                   weekly.2020-01-12_0015                   652KB     0%   50%
11:31:55.056 INFO  [invoke_system_api]                   daily.2020-01-13_0010                    548KB     0%   46%
11:31:55.088 INFO  [invoke_system_api]                   daily.2020-01-14_0010                    524KB     0%   45%
11:31:55.103 INFO  [invoke_system_api]                   hourly.2020-01-14_0605                   156KB     0%   19%
11:31:55.134 INFO  [invoke_system_api]                   hourly.2020-01-14_0705                   384KB     0%   37%
11:31:55.150 INFO  [invoke_system_api]                   hourly.2020-01-14_0805                   156KB     0%   19%
11:31:55.197 INFO  [invoke_system_api]                   hourly.2020-01-14_0905                   376KB     0%   37%
11:31:55.213 INFO  [invoke_system_api]                   hourly.2020-01-14_1005                   156KB     0%   19%
11:31:55.244 INFO  [invoke_system_api]                   hourly.2020-01-14_1105                   364KB     0%   36%
11:31:55.259 INFO  [invoke_system_api]                   snapshot1                                140KB     0%   18%
11:31:55.291 INFO  [invoke_system_api]                   snapshot2                                140KB     0%   18%
11:31:55.322 INFO  [invoke_system_api]                   snapshot3                                136KB     0%   17%
11:31:55.338 INFO  [invoke_system_api] 13 entries were displayed.
11:31:55.416 INFO  [invoke_system_api] Command completed, took 16579 milliseconds

The command is logged in: https://<%cluster_name%>/spi/<%node_name%>/etc/log/mlog/auditlog.log

Note: I've tested this on WFA5 using an ONTAP 9.6 simulator. The WFA user cached credentials used to connect to the cluster has the admin role.

/Matt

[DavidSpano]

Matt,

I plugged in your new code into the test command and I am still getting the same failure as described above.  It must be due to my configuration being different.

My environment is: WFA Server Windows 2012 R2, WFA 4.2, Clustered ONTAP 9.3P15; PSToolkit 9.7; Putty 0.73

Weeks back, I looked into upgrading our environment to WFA5.0.1, but we have a lot of 7Mode systems that only support TLS1.0.  It turns out that WFA5.0.1 no longer supports TLS1.0.  For this reason, I cannot upgrade to WFA5 at this time.

Is there anyway you could test on WFA 4.2?

Either way, thanks for your help.

[mbeattie]

Hi David,

I do have WFA4.2 running on WIN2K12R2 in my lab and tested it for you. It works:

09:41:40.862 INFO  [invoke_system_api] ### Command 'invoke_system_api' in 'POWER_SHELL' ###
09:42:05.691 INFO  [invoke_system_api] Get-WfaCredentials -Host cluster1
09:42:05.722 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
09:42:05.847 INFO  [invoke_system_api] Connect-Controller -Type CLUSTER -Name cluster1 -Credential System.Management.Automation.PSCredential -Vserver  -SSLversion TLSv1
09:42:05.894 INFO  [invoke_system_api] Credentials successfully provided for 'cluster1'
09:42:06.003 INFO  [invoke_system_api] Connect-NcController (with credentials) -Name cluster1 -Timeout 60000 -ErrorAction Stop -Port 443 -SSLVersion TLSv1
09:42:09.972 INFO  [invoke_system_api] Connected to cluster node
09:42:10.550 INFO  [invoke_system_api] Executed Command: snapshot show -volume volume1 -vserver vserver1
09:42:10.597 INFO  [invoke_system_api] ---Blocks---
09:42:10.613 INFO  [invoke_system_api] Vserver  Volume   Snapshot                                  Size Total% Used%
09:42:10.675 INFO  [invoke_system_api] -------- -------- ------------------------------------- -------- ------ -----
09:42:10.691 INFO  [invoke_system_api] vserver1 volume1
09:42:10.706 INFO  [invoke_system_api]                   weekly.2020-01-05_0015                   548KB     0%   49%
09:42:10.722 INFO  [invoke_system_api]                   weekly.2020-01-12_0015                   652KB     0%   54%
09:42:10.816 INFO  [invoke_system_api]                   daily.2020-01-14_0010                    580KB     0%   51%
09:42:10.831 INFO  [invoke_system_api]                   snapshot1                                140KB     0%   20%
09:42:10.863 INFO  [invoke_system_api]                   snapshot2                                140KB     0%   20%
09:42:10.878 INFO  [invoke_system_api]                   snapshot3                                524KB     0%   48%
09:42:10.925 INFO  [invoke_system_api]                   daily.2020-01-15_0010                    508KB     0%   47%
09:42:10.941 INFO  [invoke_system_api]                   hourly.2020-01-15_0405                   156KB     0%   22%
09:42:10.987 INFO  [invoke_system_api]                   hourly.2020-01-15_0505                   440KB     0%   44%
09:42:11.003 INFO  [invoke_system_api]                   hourly.2020-01-15_0605                   156KB     0%   22%
09:42:11.066 INFO  [invoke_system_api]                   hourly.2020-01-15_0705                   384KB     0%   41%
09:42:11.081 INFO  [invoke_system_api]                   hourly.2020-01-15_0805                   156KB     0%   22%
09:42:11.113 INFO  [invoke_system_api]                   hourly.2020-01-15_0905                   364KB     0%   39%
09:42:11.206 INFO  [invoke_system_api] 13 entries were displayed.
09:42:11.269 INFO  [invoke_system_api] Command completed, took 10407 milliseconds

The difference would be the version of ONTAP perhaps (i doubt that is the issue). I am using the default cluster admin user in the WFA credentials for an ONTAP 9.6 simulator so it's running within a user that has the admin role.

1. Have you configured any delegated access that might be restricting it from working?
2. Have you considered alternatives. EG: https://docs.ansible.com/ansible/latest/modules/na_ontap_command_module.html 
3. Does the following code work externally to WFA?

Param(
   [Parameter(Mandatory=$True, HelpMessage="The Cluster name or IP Address")]
   [String]$Cluster,
   [Parameter(Mandatory=$True, HelpMessage="The ONTAP CLI to invoke")]
   [String]$Command,
   [Parameter(Mandatory=$False, HelpMessage="The ONTAP CLI privilege")]
   [ValidateSet("admin","advanced","diag")]
   [String]$Privilege,
   [Parameter(Mandatory=$False, HelpMessage="If specified the CLI output is logged")]
   [Bool]$VerboseLogging,
   [Parameter(Mandatory=$True, HelpMessage="The Credentials to connect to the cluster")]
   [System.Management.Automation.PSCredential]$Credentials
)
#'------------------------------------------------------------------------------
#'Import the DataONTAP PSTK.
#'------------------------------------------------------------------------------
[String]$moduleName = "DataONTAP"
Try{
   Import-Module -Name $moduleName -ErrorAction Stop
   Write-Host "Imported Module ""$moduleName"""
}Catch{
   Write-Warning -Message $("Failed importing module ""$moduleName"". Error " + $_.Exception.Message)
   Break;
}
#'------------------------------------------------------------------------------
#'Connect to the Cluster.
#'------------------------------------------------------------------------------
Try{
   Connect-NcController -Name $Cluster -HTTPS -Credential $Credentials -ErrorAction Stop | Out-Null
   Write-Host "Connect to cluster ""$Cluster"""
}Catch{
   Write-Warning -Message $("Failed connecting to cluster ""$Cluster"". Error " + $_.Exception.Message)
   Break;
}
#'------------------------------------------------------------------------------
#'Convert the CLI command to the API to invoke.
#'------------------------------------------------------------------------------
[String]$Command = $Command.Trim();
If($Command.Contains(" ")){
   [Array]$cmd = $Command.Split(" ")
}Else{
   [Array]$cmd = $Command
}
If($Privilege){
   $cmd[0] = $("set $Privilege`;" + $cmd[0])
}
$api = $("<system-cli><args><arg>" + ($cmd -join "</arg><arg>") + "</arg></args></system-cli>")
#'------------------------------------------------------------------------------
#'Invoke the API.
#'------------------------------------------------------------------------------
Try{
   $output = Invoke-NcSystemApi -Request $api -ErrorAction Stop
   Write-Host $("Executed Command`: " + $([String]::Join(" ", $command)))
}Catch{
   Write-Warning -Message $("Failed Executed Command`: " + $([String]::Join(" ", $command)) + ". Error " + $_.Exception.Message)
   Break;
}
#'------------------------------------------------------------------------------
#'Log the CLI output if required.
#'------------------------------------------------------------------------------
If($VerboseLogging -And $output.results."cli-result-value" -eq 1){
   [Array]$lines = $output.results."cli-output".Trim().Split("`n")
   ForEach($line In $lines){
      If(-Not([String]::IsNullOrEmpty($line))){
         Write-Host $line
      }
   }
}
#'------------------------------------------------------------------------------

Example Output:

PS D:\Scripts\PowerShell\Projects\InvokeSystemApi> $Credentials = Get-Credential -Credential admin
PS D:\Scripts\PowerShell\Projects\InvokeSystemApi> .\InvokeSystemApi.ps1 -Cluster cluster1 -Command "snapshot show -volume volume1 -vserver vserver1" -VerboseLogging $True -Credentials $credentials
Imported Module "DataONTAP"
Connect to cluster "cluster1"
Executed Command: snapshot show -volume volume1 -vserver vserver1
---Blocks---
Vserver  Volume   Snapshot                                  Size Total% Used%
-------- -------- ------------------------------------- -------- ------ -----
vserver1 volume1
                  weekly.2020-01-05_0015                   548KB     0%   46%
                  weekly.2020-01-12_0015                   652KB     0%   50%
                  daily.2020-01-14_0010                    580KB     0%   47%
                  snapshot1                                140KB     0%   18%
                  snapshot2                                140KB     0%   18%
                  snapshot3                                524KB     0%   45%
                  daily.2020-01-15_0010                    512KB     0%   44%
                  hourly.2020-01-15_0505                   440KB     0%   40%
                  hourly.2020-01-15_0605                   156KB     0%   19%
                  hourly.2020-01-15_0705                   384KB     0%   37%
                  hourly.2020-01-15_0805                   156KB     0%   19%
                  hourly.2020-01-15_0905                   372KB     0%   36%
                  hourly.2020-01-15_1005                   148KB     0%   19%
13 entries were displayed.

/Matt