Solved: Re: VSC 6.2.2 and SnapVault for SMVI 3.0.3 POST_BACKUP finish script with error

MAXIM_KRAMARENKO · ‎2018-07-31

Hello guys,

Could you help me to fix the issue...

First I try to describe the environment: vCenter Server appliience 6.5, VirtualSterage Console 6.2.2 on Windows 2008 r2 + SnapVault for SMVI 3.0.3 (with SV-SMVI.exe /not perl ), FAS 2240-2 with DataONTAP 8.2.5P1 7-mode on Primary and Secondary storage.

SnapVault configured and work fine.

Primary/Source:

m42-stg-2240-2a> snapvault status
Snapvault is ON.
Source                        Destination                                    State          Lag        Status
m42-stg-2240-2a:/vol/bkptest  m42-stg-2240-1a:/vol/nfs_snap_vol_bkp/bkptest  Source         19:05:41   Idle
m42-stg-2240-2a> snap list bkptest
Volume bkptest
working...

  %/used       %/total  date          name
----------  ----------  ------------  --------
  0% ( 0%)    0% ( 0%)  Jul 31 10:00  hourly.0
  0% ( 0%)    0% ( 0%)  Jul 31 09:44  smvi__bkp_kms_vm_recent
  0% ( 0%)    0% ( 0%)  Jul 31 09:01  hourly.1
  0% ( 0%)    0% ( 0%)  Jul 31 08:44  smvi__bkp_kms_vm_20180731084401
  0% ( 0%)    0% ( 0%)  Jul 31 08:01  hourly.2
  0% ( 0%)    0% ( 0%)  Jul 31 07:44  smvi__bkp_kms_vm_20180731074401
  0% ( 0%)    0% ( 0%)  Jul 31 07:00  hourly.3
  0% ( 0%)    0% ( 0%)  Jul 31 06:44  smvi__bkp_kms_vm_20180731064401
  0% ( 0%)    0% ( 0%)  Jul 31 06:00  hourly.4
  0% ( 0%)    0% ( 0%)  Jul 31 05:44  smvi__bkp_kms_vm_20180731054401
  0% ( 0%)    0% ( 0%)  Jul 31 05:00  hourly.5
<...>
  1% ( 0%)    0% ( 0%)  Jul 30 15:00  hourly.18
  1% ( 0%)    0% ( 0%)  Jul 30 15:00  m42-stg-2240-1a(1913975632)_nfs_snap_vol_bkp_bkptest-src.0 (snapvault)
  1% ( 0%)    0% ( 0%)  Jul 30 14:00  hourly.19
  1% ( 0%)    0% ( 0%)  Jul 30 13:00  hourly.20
<...>
m42-stg-2240-2a>

Secondary/Destination:

m42-stg-2240-1a> snapvault status
Snapvault is ON.
Source                        Destination                                    State          Lag        Status
m42-stg-2240-2a:/vol/bkptest  m42-stg-2240-1a:/vol/nfs_snap_vol_bkp/bkptest  Snapvaulted    19:05:19   Idle
m42-stg-2240-1a>
m42-stg-2240-1a> snapvault snap sched
create nfs_snap_vol_bkp smvi__bkp_kms_vm_recent 30@- preserve=default,warn=0
m42-stg-2240-1a>
m42-stg-2240-1a> snap list nfs_snap_vol_bkp
Volume nfs_snap_vol_bkp
working...

  %/used       %/total  date          name
----------  ----------  ------------  --------
  0% ( 0%)    0% ( 0%)  Jul 31 08:00  hourly.0
<...>
  0% ( 0%)    0% ( 0%)  Jul 30 16:00  hourly.2
  0% ( 0%)    0% ( 0%)  Jul 30 15:01  m42-stg-2240-1a(1913975632)_nfs_snap_vol_bkp-base.0 (busy,snapvault)
  3% ( 3%)    0% ( 0%)  Jul 30 12:00  hourly.3
<...>
m42-stg-2240-1a>

If I run the snapvault update, It performed without errors.

I set BackupJob on VSC with script sv-smvi.cmd.

sv-smvi.cmd content is:

#########C:\Program Files\NetApp\Virtual Storage Console\smvi\server\scripts\sv-smvi.cmd###################
"C:\Program Files\NetApp\SV-SMVI\sv-smvi.exe" -verbose -reportdir "C:\Program Files\NetApp\SV-SMVI\report" -debug -report -svip m42-stg-2240-2a -svuser root -svpasswd ***

SnapVault seems ok.

Second, I try to describe the error.

I start the backup job by shceduler or manual and got no errors in the VSC or report file of sv-smvi.

But SnapVault update have not performed yet after backup job.

And I can see in the server.log next errors (C:\Program Files\NetApp\Virtual Storage Console\smvi\server\log\server.log):

2018-07-30 15:45:01,306 [backup:281b49bc2acee147f61ba71f1f6a3acc:] INFO  - Script sv-smvi.cmd is starting in phase POST_BACKUP
2018-07-30 15:45:02,866 [backup:281b49bc2acee147f61ba71f1f6a3acc:] INFO  - Script sv-smvi.cmd completed with output:

C:\Program Files\NetApp\Virtual Storage Console\smvi\server\scripts>rem "C:\Program Files\NetApp\SV-SMVI\sv-smvi.exe" -verbose -noping -reportdir "C:\Program Files\NetApp\SV-SMVI\report" -debug -report -svip m42-stg-2240-2a -svuser *** -svpasswd ***  

C:\Program Files\NetApp\Virtual Storage Console\smvi\server\scripts>"C:\Program Files\NetApp\SV-SMVI\sv-smvi.exe" -verbose -reportdir "C:\Program Files\NetApp\SV-SMVI\report" -debug -report -svip m42-stg-2240-2a -svuser root -svpasswd *** 
runOpenReport(): LOG REPORT FOR SV-SMVI
runOpenReport(): -----------------------------------------------------
runOpenReport(): SV-SMVI Version: 3.0.3
runOpenReport(): Log Filename: C:\Program Files\NetApp\SV-SMVI\report\SV-SMVI_20180730_154501.log
runOpenReport(): Start Time: Mon Jul 30 15:45:01 2018
runCheckArgs(): Use of -svip overrides IP address(es) in SMVI post-backup output.  Continuing.
runCheckArgs(): Found backup: HOST = '11.4.8.2', VOLUME = 'bkptest', SNAPSHOT = 'smvi__bkp_kms_vm_recent' ...
runCheckArgs(): Use of -svip: Changing HOST = '11.4.8.2' to HOST = 'm42-stg-2240-2a' ...
runCheckArgs(): Preserving SMVI backup with storage controller m42-stg-2240-2a, volume bkptest, snapshot named smvi__bkp_kms_vm_recent ...
runLogin(): Initializing connectivity to storage controller ...
runLogin(): Attempting to ping storage controller m42-stg-2240-2a ...
runLogin(): Ping of storage controller m42-stg-2240-2a successful.
runLogin(): Logging into storage controller m42-stg-2240-2a ...
runLogin(): Setting username and password for storage controller m42-stg-2240-2a ...
runLogin(): Testing login by ONTAP version from storage controller m42-stg-2240-2a ...
runLogin(): ONTAP version: NetApp Release 8.2.5P1 7-Mode: Thu Dec 21 21:09:11 PST 2017
runLogin(): Storage appliance login successful.
runCollectVolumeNameData(): Looking for snapshot smvi__bkp_kms_vm_recent on controller m42-stg-2240-2a ...
runCollectVolumeNameData(): Snapshot smvi__bkp_kms_vm_recent was found in volume bkptest.
runCollectSVData(): Running ZAPI snapvault-primary-relationship-status-list-iter-start on storage controller m42-stg-2240-2a ...
runCollectSVData(): Running ZAPI snapvault-primary-relationship-status-list-iter-next on m42-stg-2240-2a ...
runCollectSVData(): SnapVault relationship found (first) (primary = m42-stg-2240-2a:/vol/bkptest, secondary = m42-stg-2240-1a:/vol/nfs_snap_vol_bkp/bkptest) ...
runCollectSVData(): Running ZAPI snapvault-primary-relationship-status-list-iter-end on m42-stg-2240-2a ...
runLogin(): Initializing connectivity to storage controller ...
runLogin(): Attempting to ping storage controller m42-stg-2240-1a ...
runLogin(): Ping of storage controller m42-stg-2240-1a successful.
runLogin(): Logging into storage controller m42-stg-2240-1a ...
runLogin(): Setting username and password for storage controller m42-stg-2240-1a ...
runLogin(): Testing login by ONTAP version from storage controller m42-stg-2240-1a ...
Can't use string ("") as a subroutine ref while "strict refs" in use at /<C:\Program Files\NetApp\SV-SMVI\sv-smvi.exe>NaServer.pm line 544, <S> line 60.
2018-07-30 15:45:02,866 [backup:281b49bc2acee147f61ba71f1f6a3acc:] ERROR - FLOW-10209: Error logging operation message to database: A truncation error was encountered trying to shrink VARCHAR 'Script sv-smvi.cmd completed with output:

C:\Program Files&' to length 2048.
java.sql.SQLDataException: A truncation error was encountered trying to shrink VARCHAR 'Script sv-smvi.cmd completed with output:

C:\Program Files&' to length 2048.
	at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
	at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
	at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown Source)
	at com.netapp.common.flow.JDBCPersistenceManager.addMessage(JDBCPersistenceManager.java:847)
	at com.netapp.common.flow.OperationLogListener.append(OperationLogListener.java:39)
	at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.netapp.common.util.MulticastProxy.invoke(MulticastProxy.java:49)
	at com.sun.proxy.$Proxy10.append(Unknown Source)
	at com.netapp.common.logging.NALogger.notifyListeners(NALogger.java:98)
	at com.netapp.common.logging.NALogger.log(NALogger.java:149)
	at com.netapp.common.logging.NALogger.log(NALogger.java:175)
	at com.netapp.common.logging.NALogger.info(NALogger.java:228)
	at com.netapp.smvi.task.scripting.ScriptExecutionTask.execute(ScriptExecutionTask.java:151)
	at com.netapp.common.flow.TaskInstanceTemplate.execute(TaskInstanceTemplate.java:325)
	at com.netapp.common.flow.ForLoopTemplate.execute(ForLoopTemplate.java:138)
	at com.netapp.common.flow.Operation.executeCurrentStack(Operation.java:133)
	at com.netapp.common.flow.Operation.execute(Operation.java:59)
	at com.netapp.common.flow.Threadpool$OperationThread.run(Threadpool.java:263)
Caused by: java.sql.SQLException: A truncation error was encountered trying to shrink VARCHAR 'Script sv-smvi.cmd completed with output:

C:\Program Files&' to length 2048.
	at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
	at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
	... 26 more
Caused by: ERROR 22001: A truncation error was encountered trying to shrink VARCHAR 'Script sv-smvi.cmd completed with output:

C:\Program Files&' to length 2048.
	at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
	at org.apache.derby.iapi.types.SQLChar.hasNonBlankChars(Unknown Source)
	at org.apache.derby.iapi.types.SQLVarchar.normalize(Unknown Source)
	at org.apache.derby.iapi.types.SQLVarchar.normalize(Unknown Source)
	at org.apache.derby.iapi.types.DataTypeDescriptor.normalize(Unknown Source)
	at org.apache.derby.impl.sql.execute.NormalizeResultSet.normalizeColumn(Unknown Source)
	at org.apache.derby.impl.sql.execute.NormalizeResultSet.normalizeRow(Unknown Source)
	at org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore(Unknown Source)
	at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(Unknown Source)
	at org.apache.derby.impl.sql.execute.InsertResultSet.open(Unknown Source)
	at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
	at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
	... 20 more
2018-07-30 15:45:02,866 [backup:281b49bc2acee147f61ba71f1f6a3acc:] INFO  - Script sv-smvi.cmd failed with code 255 in phase POST_BACKUP

You can find the full log in attachment.

I think that root case is

Can't use string ("") as a subroutine ref while "strict refs" in use at /<C:\Program Files\NetApp\SV-SMVI\sv-smvi.exe>NaServer.pm line 544, <S> line 60.

Could you help me make SnapVault update after backupJob.

Thank you very much.

MAXIM_KRAMARENKO · ‎2018-08-01

Yahooo!!!

Problem has already resolved!

Difference between system is in options httpd.admin.enable on (on primary) and off (on secondary).

I set both to httpd.admin.enable on and sv-smvi.cmd finished without errors!!!

View solution in original post

MAXIM_KRAMARENKO · ‎2018-08-01

I have tried make some troubleshooting step.

I try to parse the source sv-smvi.pl and as I can see from the log, function runLogin stops under Login process to Secondary (m42-stg-2240-1a) filer between the next lines:

	# instead of getting system information, get the licenses from the storage controller
	logMsg( $LOG_INFO, "Testing login by ONTAP version from storage controller $server ..." );
	$results = $zapiServer->invoke( 'system-get-version' );
	if ( $results->results_status() eq "failed" ) {
		logMsg( $LOG_ERROR, "ZAPI connection to $server failed: " . $results->results_reason() );
		runExit( $ERR_NOSACONNECTION );
	}
	logMsg( $LOG_INFO, "ONTAP version: " . $results->child_get_string( 'version' ) );

Because "Testing login by ONTAP version from storage controller" is present and "ONTAP version:" OR "ZAPI connection to $server failed:" are not present.

I hoped, that problem is in the system-get-version API.

Then I have tried to download SDK and use apitest PowerShell utility. But apitest connect to both filers without errors:

PS C:\Program Files\NetApp\netapp-manageability-sdk-9.4\src\sample\Data_ONTAP\DotNet\PowerShell> .\apitest.ps1 m42-stg-2240-2a  root  *** system-get-version
<results status='passed'>
        <version>NetApp Release 8.2.5P1 7-Mode: Thu Dec 21 21:09:11 PST 2017</version>
        <is-clustered>false</is-clustered>
</results>

PS C:\Program Files\NetApp\netapp-manageability-sdk-9.4\src\sample\Data_ONTAP\DotNet\PowerShell> .\apitest.ps1 m42-stg-2240-1a  root  *** system-get-version
<results status='passed'>
        <version>NetApp Release 8.2.5P1 7-Mode: Thu Dec 21 21:09:11 PST 2017</version>
        <is-clustered>false</is-clustered>
</results>

What can I do more?

MAXIM_KRAMARENKO · ‎2018-08-01

Yahooo!!!

Problem has already resolved!

Difference between system is in options httpd.admin.enable on (on primary) and off (on secondary).

I set both to httpd.admin.enable on and sv-smvi.cmd finished without errors!!!

VSC 6.2.2 and SnapVault for SMVI 3.0.3 POST_BACKUP finish script with error

powershell script

SMVI script error

Scripting a SMVI VSC Job to run

powershell script

StorageGrid certificate renewal -Need the final push to finish this