Data Backup and Recovery

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

MAXIM_KRAMARENKO

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.

 

 

1 ACCEPTED SOLUTION

MAXIM_KRAMARENKO

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

2 REPLIES 2

MAXIM_KRAMARENKO

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

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?

 

Announcements
NetApp on Discord Image

We're on Discord, are you?

Live Chat, Watch Parties, and More!

Explore Banner

Meet Explore, NetApp’s digital sales platform

Engage digitally throughout the sales process, from product discovery to configuration, and handle all your post-purchase needs.

NetApp Insights to Action
I2A Banner
Public