Windows Eventlog Error after successful sv-smvi operation

[brauntvr2swiss]

Hi All

I have the following "little" Problem (is a cosmetic not a functional Issue) with VSC 4.1 and sv-smvi 3.0.3.

Environment:

Windows 2008 R2 SP1

VSC 4.1

vcenter Server 5.1

sv-smvi 3.0.3

- VSC Backup Job runs without errors.

- sv-smvi script runs witout Errors:

LOG REPORT FOR SV-SMVI

-----------------------------------------------------

[21:01:06] SV-SMVI Version: 3.0.3

[21:01:06] Log Filename: C:\Temp\Reports\SV-SMVI_20121126_210106.log

[21:01:06] Start Time: Mon Nov 26 21:01:06 2012

[21:01:06] Using -svschednames, only taking SnapVault snapshots on specific schedule names ...

[21:01:06] Saving SnapVault schedule name sv_smvi ...

[21:01:06] Use of -svip overrides IP address(es) in SMVI post-backup output.  Continuing.

[21:01:06] Found backup: HOST = 'IP Adress', VOLUME = 'DataVol', SNAPSHOT = 'smvi__VMware Daily_recent' ...

[21:01:06] Use of -svip: Changing HOST = 'IP Adress' to HOST = 'Override IP Adress' ...

[21:01:06] Preserving SMVI backup with storage controller Override IP Adress, volume DataVol, snapshot named smvi__VMware Daily_recent ...

[21:01:06] Found backup: HOST = 'IP Adress', VOLUME = 'OsVol, SNAPSHOT = 'smvi__VMware Daily_recent' ...

[21:01:06] Use of -svip: Changing HOST = 'IP Adress' to HOST = 'Override IP Adress' ...

[21:01:06] Preserving SMVI backup with storage controller Override IP Adress, volume OsVol, snapshot named smvi__VMware Daily_recent ...

[21:01:06] Initializing connectivity to storage controller ...

[21:01:06] Attempting to ping storage controller Override IP Adress ...

[21:01:06] Ping of storage controller Override IP Adress successful.

[21:01:06] Logging into storage controller Override IP Adress ...

[21:01:06] Setting username and password for storage controller Override IP Adress ...

[21:01:06] Testing login by ONTAP version from storage controller Override IP Adress ...

[21:01:06] ONTAP version: NetApp Release 8.0.2P6 7-Mode: Fri Jan 27 14:48:08 PST 2012

[21:01:06] Storage appliance login successful.

[21:01:06] Looking for snapshot smvi__VMware Daily_recent on controller Override IP Adress ...

[21:01:06] Snapshot smvi__VMware Daily_recent was found in volume OsVol.

[21:01:07] Looking for snapshot smvi__VMware Daily_recent on controller Override IP Adress ...

[21:01:07] Snapshot smvi__VMware Daily_recent was found in volume DataVol.

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-start on storage controller Override IP Adress ...

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-next on Override IP Adress ...

[21:01:07] SnapVault relationship found (first) (primary = Filer:/vol/OsVol/qtree_os, secondary = nearstore:/vol/backup/os) ...

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-end on Override IP Adress ...

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-start on storage controller Override IP Adress ...

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-next on Override IP Adress ...

[21:01:07] SnapVault relationship found (first) (primary = Filer:/vol/DataVol/qtree_data, secondary = nearstore:/vol/backup/data) ...

[21:01:07] Running ZAPI snapvault-primary-relationship-status-list-iter-end on Override IP Adress ...

[21:01:07] Initializing connectivity to storage controller ...

[21:01:07] Attempting to ping storage controller nearstore ...

[21:01:07] Ping of storage controller nearstore successful.

[21:01:07] Logging into storage controller nearstore ...

[21:01:07] Setting username and password for storage controller nearstore ...

[21:01:07] Testing login by ONTAP version from storage controller nearstore ...

[21:01:07] ONTAP version: NetApp Release 8.0.2P6 7-Mode: Fri Jan 27 14:46:25 PST 2012

[21:01:07] Storage appliance login successful.

[21:01:07] Running ZAPI snapvault-secondary-initiate-incremental-transfer on storage controller nearstore, snapshot smvi__VMware Daily_recent, secondary path /vol/backup/os ...

[21:01:09] SnapVault incremental transfer started successfully.

[21:01:09] Running ZAPI snapvault-secondary-initiate-incremental-transfer on storage controller nearstore, snapshot smvi__VMware Daily_recent, secondary path /vol/backup/data ...

[21:01:10] SnapVault incremental transfer started successfully.

[21:01:10] Running ZAPI snapvault-secondary-get-relationship-status on storage controller nearstore, path /vol/backup/os ...

[21:01:10] Relationship for path /vol/backup/os is still running ...

[21:01:10] Running ZAPI snapvault-secondary-get-relationship-status on storage controller nearstore, path /vol/backup/data ...

[21:01:10] Relationship for path /vol/backup/data is still running ...

[21:01:10] More relationships need to be updated, sleeping for 30 seconds ...

[21:01:40] Running ZAPI snapvault-secondary-get-relationship-status on storage controller nearstore, path /vol/backup/os ...

[21:01:41] Relationship for path /vol/backup/os is idle, removing from the list to check.

[21:01:41] Running ZAPI snapvault-secondary-get-relationship-status on storage controller nearstore, path /vol/backup/data ...

[21:01:41] Relationship for path /vol/backup/data is idle, removing from the list to check.

[21:01:41] All relationships updated.

[21:01:41] Duplicate SnapVault secondary controller/volume found (nearstore:/vol//vol/backup), removing duplicate from list.

[21:01:41] SnapVault secondary snapshot(s) to be taken on nearstore:/vol/backup/os.

[21:01:41] Creating a SnapVault secondary snapshot for volume /vol/backup using schedule sv_smvi ...

[21:01:41] SnapVault secondary snapshot created successfully.

[21:01:41] A total of 2 SnapVault relationship update(s) and 1 SnapVault snapshot creation(s) successful.

[21:01:41] Command completed successfully.

[21:01:41] End Time: Mon Nov 26 21:01:41 2012

-----------------------------------------------------

Exiting with return code:0

- But in the Eventlog from Windows I have an Error everytime sv-smvi is running as a Part of the VSC Backup:

390716018 [backup4 1d4f1e1fbe753ae60afbaf02e7f12cb4] ERROR com.netapp.common.flow.JDBCPersistenceManager - 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:845)    at com.netapp.common.flow.OperationLogListener.append(OperationLogListener.java:38)    at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)    at java.lang.reflect.Method.invoke(Unknown Source)    at com.netapp.common.util.MulticastProxy.invoke(MulticastProxy.java:49)    at $Proxy8.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:324)    at com.netapp.common.flow.ForLoopTemplate.execute(ForLoopTemplate.java:136)    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:254)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 moreCaused 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

Has someone the same Issue or/and a solution for this?

TIA

Thomas

[rmatt]

Can you please provide your command line (cmd script) and path to the script?  Most people don't override using -svip so I'm curious as to what the mapping is intended to be (the IP address appears to be text not a real IP address).

--Matt

[brauntvr2swiss]

Hi Matt

First Thanks for your response...

You are right the value of svip is a text. This is becaue i wan't publish Names or IPs from the customer in a public  Forum :-)...

This behavior I see at 2 Custer Site with VSC 4.1 and sv.smvi 3.0.3..

Script:

"C:\Program Files\NetApp\Virtual Storage Console\smvi\svsmvi\sv-smvi.exe" -svip 10.5.9.89 -svuser vscadmin -svcryptpasswd 53616c7465645f5fcf897643fa6fe4a76acaa1c188176b6b06cc174b90e620a3 -verbose -report -reportdir C:\Temp\SV-SMVI_reports\sv-smvi_STV0001

Path:

C:\Program Files\NetApp\Virtual Storage Console\smvi\server\scripts

We have to use svip. We have try to use the parameter -dnslist, but this doesn't, because we use IP Adresses and not DNS Names for mounting ESX Datastores.

The other thing to say again ist, that this Problem has no functional impact. Is only a consmetic Issue, but the Windows Admins doesn't like Warnings in the Event Log :-)...

regards

Thomas

[rmatt · Accepted solution]

I suspect the issue then is related to VSC, not to SV-SMVI.  SV-SMVI is based on Perl, where you would see messages that indicate Perl syntax or error constructs.  Seeing Java error conditions is likely the issue -- I suspect if you get rid of -verbose it may eliminate the issue, as something in the VSC logger could be complaining that the log output from SV-SMVI is too big to insert as VARCHAR output for VSC's (SMVI's) logs.  Can you give that a spin?

Thanks again,

--Matt

P.S.  Good to know I'm not insane with the IP address string.

[brauntvr2swiss]

Hi Matt

I think the same (Its not a smvi issue).

the idea with "remove -verbose" switch is a good idea. I need only verbose, when I have a problem for deeper diagnostic.

I will reopen my Case at Netapp. When I have a statement from Netapp,You will hear from me..

Thanks for your help

Thomas

[brauntvr2swiss]

Hi Matt

I have tested without -verbose and the error in the Windows Event log goes away.

Thanks for this hint

Thomas