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.