Re: sc4.1 errors with vibe and ssl handshake

FLORIAN_MEIER · ‎2013-11-29

hello everybody

we updated to sc4.1. now we have some really strange errors in our backup! we backup about 50 different configs in a night. (everytime vibe plugin)

sometimes we get this error when sc ist starting with the first backup:

Application Discovery ##########

[2013-11-28 22:25:01,581] ERROR: SCF-00028: Auto Discovery for plug-in [vibe] failed with error [javax.ws.rs.client.ClientException: javax.net.ssl.SSLHandshakeException: SSLHandshakeException invoking https://IPADRESS:PORT/SnapCreator/operations/version: Remote host closed connection during handshake] and exit code [-1], Exiting!

after that, about 10 backup jobs working without errors i get this error on 11 backupjob again:

Application Discovery ##########

[2013-11-28 22:44:15,541] ERROR: SCF-00028: Auto Discovery for plug-in [vibe] failed with error [javax.ws.rs.client.ClientException: javax.net.ssl.SSLHandshakeException: SSLHandshakeException invoking https://IPADRESS:PORT/SnapCreator/operations/version: Remote host closed connection during handshake] and exit code [-1], Exiting!

after that, sc4.1 makes about 30 backups without any problems. then i get this error again:

Application Discovery ##########

[2013-11-28 23:40:01,527] ERROR: SCF-00028: Auto Discovery for plug-in [vibe] failed with error [javax.ws.rs.client.ClientException: javax.net.ssl.SSLHandshakeException: SSLHandshakeException invoking https://IPADRESS:PORT/SnapCreator/operations/version: Remote host closed connection during handshake] and exit code [-1], Exiting!

Please help me! we're used before the upgrade to 4.1 50 different agents on the virtual center server. now we are using one agent for all. its really better for us, because we save about 1gb ram with the new sc4.1 agent.

regards flo

FLORIAN_MEIER · ‎2013-11-29

really interesting is, that in the first one on 22:25:01 the backup is not starting!

but one 22:44:08 and on 23:40:01 i get this error after the hole backup job in the end of the log file. so sc4.1 take the hole backup from this job but in the end he gives out this sslhandshake error.

....... the hole backup job is correctly running...

########## Running Snapshot copy Create on Secondary ctrl03 ##########

[2013-11-28 22:44:07,326] INFO: STORAGE-02007: Creating Snapshot copy [customerbackup40.backup-SV_daily_20131128223400] on volume [sv_sas_customerbackup40]

[2013-11-28 22:44:07,326] INFO: STORAGE-02008: Snapshot copy [customerbackup40.backup-SV_daily_20131128223400] on volume [sv_sas_customerbackup40] created successfully

[2013-11-28 22:44:08,280] INFO: STORAGE-02007: Creating Snapshot copy [customerbackup40.backup-SV_daily_20131128223400] on volume [sv_sata_customerbackup40]

[2013-11-28 22:44:08,280] INFO: STORAGE-02008: Snapshot copy [customerbackup40.backup-SV_daily_20131128223400] on volume [sv_sata_customerbackup40] created successfully

########## Post Data Transfer commands ##########

[2013-11-28 22:44:08,298] INFO: No commands defined

[2013-11-28 22:44:08,298] INFO: Post Data Transfer commands finished successfully

########## Post Ntap commands ##########

[2013-11-28 22:44:08,300] INFO: No Post Ntap commands defined

[2013-11-28 22:44:08,300] INFO: Post Ntap commands finished successfully

########## ARCHIVE COMMANDS ##########

[2013-11-28 22:44:08,307] INFO: Archive commands are not defined

########## Running Snapshot copy Delete on Primary ##########

[2013-11-28 22:44:09,201] INFO: STORAGE-02013: Removing Snapshot copy [customerbackup40.backup-daily_20131113233400] on volume [sata_customerbackup40]

[2013-11-28 22:44:09,201] INFO: STORAGE-02014: Removing Snapshot copy [customerbackup40.backup-daily_20131113233400] on volume [sata_customerbackup40] finished successfully.

[2013-11-28 22:44:11,398] INFO: STORAGE-02013: Removing Snapshot copy [customerbackup40.backup-daily_20131113233400] on volume [sas_customerbackup40]

[2013-11-28 22:44:11,398] INFO: STORAGE-02014: Removing Snapshot copy [customerbackup40.backup-daily_20131113233400] on volume [sas_customerbackup40] finished successfully.

########## Running Snapshot copy Delete on Secondary ##########

########## Running Snapshot copy Delete on Secondary ctrl03 ##########

[2013-11-28 22:44:13,307] INFO: STORAGE-02013: Removing Snapshot copy [customerbackup40.backup-SV_daily_20131025223400] on volume [sv_sas_customerbackup40]

[2013-11-28 22:44:13,307] INFO: STORAGE-02014: Removing Snapshot copy [customerbackup40.backup-SV_daily_20131025223400] on volume [sv_sas_customerbackup40] finished successfully.

[2013-11-28 22:44:15,463] INFO: STORAGE-02013: Removing Snapshot copy [customerbackup40.backup-SV_daily_20131025223400] on volume [sv_sata_customerbackup40]

[2013-11-28 22:44:15,463] INFO: STORAGE-02014: Removing Snapshot copy [customerbackup40.backup-SV_daily_20131025223400] on volume [sv_sata_customerbackup40] finished successfully.

########## Application cleanup ##########

[2013-11-28 22:44:15,541] ERROR: SCF-00074: Cleanup for plug-in [vibe] failed with error [javax.ws.rs.client.ClientException: javax.net.ssl.SSLHandshakeException: SSLHandshakeException invoking https://192.168.244:2:9090/SnapCreator/operations/version: Remote host closed connection during handshake] and exit code [-1], Exiting!

########## Agent Workflow Finalization ##########

[2013-11-28 22:44:15,545] INFO: Agent Workflow Finalization started

[2013-11-28 22:44:19,773] INFO: [192.168.244:2:9090 (4.1.0.1)] Finalized workflow with id 74

[2013-11-28 22:44:19,773] INFO: Agent Workflow Finalization finished successfully

########## Snap Creator Community Release 4.1.0c failed ##########

[2013-11-28 22:44:19,785] INFO: Pre Exit commands are not defined. Skipping !

[2013-11-28 22:44:19,794] INFO: Sending Trap message to external system /usr/bin/php5 /var/www/scripts/customers/general-error.php daily customerbackup40

[2013-11-28 22:44:19,897] INFO: stdout:done

..and in the end i get this error..

Clemens_Siebler · ‎2013-11-29

Which Java version are your currently using? I'd assume both Agent and Server run on Linux, correct?

If you are currently use JRE 1.7.0 Update x, I'd suggest giving JRE 1.6.0 Update 45 a try.

Regards,

Clemens

FLORIAN_MEIER · ‎2013-11-29

hi keith. thank you for response. the agents running on windows server 2008 r2 with the newest 64bit java version (7 update 45)

sc server is running on linux, but thank you for hint. i checked the java version and this is an older one. i update the java on the same version.

give you feedback tomorrow when backup runned.

Clemens_Siebler · ‎2013-11-29

Hey Florian, I'm not Keith

Ok, I would appreciate if you could retry with 1.6.0_45 on both Windows and Linux. Let me know if that fixed it. I am also investigating what the issue with 1.7.0_45 is.

Thanks,

Clemens

FLORIAN_MEIER · ‎2013-11-29

sorry for the name confusion. clemens i will downgrade all the systems to 1.6.0_45 and try it again.

you get feedback tomorrow.

thank you

FLORIAN_MEIER · ‎2013-11-30

hello

ok we fixed this specific error with java 1.6.0_45! but i have a new error!

the server stopped all backups after 23:01:52. about 30 jobs are not running because they planned after 23:01:52.

could be this a memory issue with the server? because it looks like, the server is not sending any commands to the agent..

on server log i get this error in backup jobs:

[2013-11-30 02:02:51,613] ERROR: SCF-00074: Cleanup for plug-in [vibe] failed with error [java.net.SocketTimeoutException: SocketTimeoutException invoking http://ipaddress/SnapCreator/Daemon/Agent: Read timed out] and exit code [-1], Exiting!

on 23:01:52 snap creator agent only show this in the log:

23:01:52.075 [pool-2-thread-2] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.ExecutorImpl DEBUG - stdoutLogger running=true

23:01:52.075 [pool-2-thread-2] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.ExecutorImpl DEBUG - stderrLogger running=true

23:01:52.204 [Thread-212] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=133, p=vibe - 2013-11-29 23:01:52 (pid=6760) - Listing incoming requests from plugins/wrapper/in

23:01:52.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:52 (pid=1648) - Writing results to plugins/wrapper/out/141+vibe+1385762440974+unquiesce

23:01:52.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:52 (pid=1648) - Result: SC_MSG#INFO#Fri Nov 29 23:00:44 2013#Checking if VIBE pre-requisites already run (function: unquiesce) ....

23:01:52.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:52 (pid=1648) - Listing incoming requests from plugins/wrapper/in

23:01:52.666 [Thread-240] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=140, p=vibe - 2013-11-29 23:01:52 (pid=8640) - Listing incoming requests from plugins/wrapper/in

23:01:52.823 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-29 23:01:52 (pid=6676) - Listing incoming requests from plugins/wrapper/in

23:01:52.878 [Thread-287] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=145, p=vibe - 2013-11-29 23:01:52 (pid=8020) - Listing incoming requests from plugins/wrapper/in

23:01:52.888 [Thread-285] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=144, p=vibe - 2013-11-29 23:01:52 (pid=7020) - Listing incoming requests from plugins/wrapper/in

23:01:53.204 [Thread-212] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=133, p=vibe - 2013-11-29 23:01:53 (pid=6760) - Listing incoming requests from plugins/wrapper/in

23:01:53.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:53 (pid=1648) - Listing incoming requests from plugins/wrapper/in

23:01:53.666 [Thread-240] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=140, p=vibe - 2013-11-29 23:01:53 (pid=8640) - Listing incoming requests from plugins/wrapper/in

23:01:53.823 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-29 23:01:53 (pid=6676) - Listing incoming requests from plugins/wrapper/in

23:01:53.878 [Thread-287] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=145, p=vibe - 2013-11-29 23:01:53 (pid=8020) - Listing incoming requests from plugins/wrapper/in

23:01:53.888 [Thread-285] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=144, p=vibe - 2013-11-29 23:01:53 (pid=7020) - Listing incoming requests from plugins/wrapper/in

23:01:54.204 [Thread-212] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=133, p=vibe - 2013-11-29 23:01:54 (pid=6760) - Listing incoming requests from plugins/wrapper/in

23:01:54.577 [pool-2-thread-2] com.netapp.snapcreator.agent.nextgen.operationmanager.OperationManagerImpl DEBUG - updateOperationStatus() - Removed lock [customer_1054_backup_1054_vibe_unquiesce] for opId=02d48cde-d0f1-49ad-ba9b-8dd8e9226c62

23:01:54.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:54 (pid=1648) - Listing incoming requests from plugins/wrapper/in

23:01:54.666 [Thread-240] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=140, p=vibe - 2013-11-29 23:01:54 (pid=8640) - Listing incoming requests from plugins/wrapper/in

23:01:54.823 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-29 23:01:54 (pid=6676) - Listing incoming requests from plugins/wrapper/in

23:01:54.878 [Thread-287] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=145, p=vibe - 2013-11-29 23:01:54 (pid=8020) - Listing incoming requests from plugins/wrapper/in

23:01:54.888 [Thread-285] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=144, p=vibe - 2013-11-29 23:01:54 (pid=7020) - Listing incoming requests from plugins/wrapper/in

23:01:55.204 [Thread-212] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=133, p=vibe - 2013-11-29 23:01:55 (pid=6760) - Listing incoming requests from plugins/wrapper/in

23:01:55.652 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-29 23:01:55 (pid=1648) - Listing incoming requests from plugins/wrapper/in

23:01:55.666 [Thread-240] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=140, p=vibe - 2013-11-29 23:01:55 (pid=8640) - Listing incoming requests from plugins/wrapper/in

23:01:55.729 [Watchdog] com.netapp.snapcreator.agent.nextgen.watchdog.WatchdogImpl DEBUG - removeDoneWatchables() - removing WatchableImpl [stopTime=1385766040960, startTime=1385762440960, operationId=02d48cde-d0f1-49ad-ba9b-8dd8e9226c62, operationName=unquiesce]

23:01:55.823 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-29 23:01:55 (pid=6676) - Listing incoming requests from plugins/wrapper/in

23:01:55.878 [Thread-287] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=145, p=vibe - 2013-11-29 23:01:55 (pid=8020) - Listing incoming requests from plugins/wrapper/in

23:01:55.888 [Thread-285] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=144, p=vibe - 2013-11-29 23:01:55 (pid=7020) - Listing incoming requests from plugins/wrapper/in

... same text ..

00:01:33.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:33 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:33.554 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-30 00:01:33 (pid=6676) - Listing incoming requests from plugins/wrapper/in

00:01:34.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:34 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:34.554 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-30 00:01:34 (pid=6676) - Listing incoming requests from plugins/wrapper/in

00:01:35.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:35 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:35.554 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-30 00:01:35 (pid=6676) - Will shutdown now. Reason: Could not find any new incoming requests in the last 3600 seconds at wrapper.pl line 256.

00:01:35.554 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe -

00:01:35.554 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - 2013-11-30 00:01:35 (pid=6676) - Done

00:01:35.664 [Thread-283] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=143, p=vibe - Finished

00:01:35.664 [Thread-284] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stderr, wid=143, p=vibe - Finished

00:01:36.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:36 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:37.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:37 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:38.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:38 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:39.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:39 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:40.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:40 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:41.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:41 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:42.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:42 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:43.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:43 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:44.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:44 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:45.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:45 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:46.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:46 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:47.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:47 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:48.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:48 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:49.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:49 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:50.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:50 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:51.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:51 (pid=1648) - Listing incoming requests from plugins/wrapper/in

00:01:52.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:52 (pid=1648) - Will shutdown now. Reason: Could not find any new incoming requests in the last 3600 seconds at wrapper.pl line 256.

00:01:52.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe -

00:01:52.348 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - 2013-11-30 00:01:52 (pid=1648) - Done

00:01:52.472 [Thread-246] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stdout, wid=141, p=vibe - Finished

00:01:52.473 [Thread-247] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger DEBUG - run() - type=stderr, wid=141, p=vibe - Finished

thank you

FLORIAN_MEIER · ‎2013-11-30

in the scAgent/logs/plugins/unkown i found the follow lines:

[2013-11-29T22:56:58,688+0100] INFO [qtp1924003262-19] org.eclipse.jetty.server.AsyncHttpConnection - EndPoint making no progress: 100 SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=true {AsyncHttpConnection@ac4b67b,g=HttpGenerator{s=4,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=16,c=0},r=1} AsyncHttpConnection@ac4b67b,g=HttpGenerator{s=4,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=16,c=0},r=1

[2013-11-29T22:56:58,706+0100] WARN [qtp1924003262-181] org.eclipse.jetty.server.AsyncHttpConnection - Closing EndPoint making no progress: 200 SSL NEED_UNWRAP i/o/u=0/0/0 ishut=false oshut=true {AsyncHttpConnection@ac4b67b,g=HttpGenerator{s=4,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=16,c=0},r=1} AsyncHttpConnection@ac4b67b,g=HttpGenerator{s=4,h=-1,b=-1,c=-1},p=HttpParser{s=7,l=16,c=0},r=1

[2013-11-30T08:53:31,287+0100] WARN [qtp1924003262-292] org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor - Error serializing the response, please check the server logs, response class : OperationStatus.

is it possible to change ssl connection to normal http? because i think this is not very stable...

FLORIAN_MEIER · ‎2013-11-30

some other guys have also excact the same problem with jetty:

http://markmail.org/message/5vzeidowgwvl2gsc#query:+page:1+mid:5vzeidowgwvl2gsc+state:results

maybe sc4.1 is unstable, i dont know. please clear me up. if you are not sure how to resolve this error i will downgrade all my sc installations to sc4.0p1 because i need a running backup!

FLORIAN_MEIER · ‎2013-11-30

I updated now the cpus of my vcenter server where the agent is installed, because i saw that the cpu is on very high load at the backup time (80-100%). i gave now more cpu ressources to the machine. i will provide feedback tomorrow. hope i can handle this issue now with this changes.

Clemens_Siebler · ‎2013-12-02

Hi Florian,

thanks for giving JRE 1.6 a try, thanks for the feedback. I'm looking in the other issue and will update you as soon as I have news.

Clemens

FLORIAN_MEIER · ‎2013-12-02

hi guys

the other issue that i posted is now fixed. it was because i had to low cpu ressources on the vcenter server.

thank you for help!

FLORIAN_MEIER · ‎2013-12-02

hi guys

for the last two days, the backup was running without problem. now we have again a big issue!

today only about 1 jobs are running correctly. all other jobs stopped with error.

it looks like, snapcreator 4.1 is very unstable. please help us. thats a big problem for us!

we get new errors:

the first backup was running without problems, then the second backup gets this error:

########## Agent Workflow Finalization ##########

[2013-12-02 22:31:26,838] INFO: Agent Workflow Finalization started

[2013-12-02 23:31:27,012] WARN: SCF-00080: Agent finalization for workflow failed with warning [javax.ws.rs.client.ClientException: .Problem with writing the request message, class : class com.netapp.snapcreator.agent.nextgen.common.data.Request, ContentType : application/json.]. Continuing.

########## Snap Creator Community Release 4.1.0c finished successfully ##########

the third backup get this error:

[2013-12-02 23:31:27,221] INFO: Performing cleanup on : vibe

[2013-12-02 23:31:27,422] ERROR: SCF-00074: Cleanup for plug-in [vibe] failed with error [org.codehaus.jackson.map.exc.UnrecognizedPropertyException: Unrecognized field "discoveredGroups" (Class com.netapp.snapcreator.agent.nextgen.common.result.Result), not marked as ignorable

at [Source: sun.net.www.protocol.http.HttpURLConnection$HttpInputStream@f42f38e; line: 1, column: 343] (through reference chain: com.netapp.snapcreator.agent.nextgen.common.result.Result["discoveredGroups"])] and exit code [-1], Exiting!

########## Agent Workflow Finalization ##########

[2013-12-02 23:31:27,428] INFO: Agent Workflow Finalization started

and after that, every other job cancled with this error:

########## Application cleanup ##########

[2013-12-03 02:42:21,073] ERROR: SCF-00074: Cleanup for plug-in [vibe] failed with error [java.net.SocketTimeoutException: SocketTimeoutException invoking http://172.30.1.57:9000/SnapCreator/Daemon/Agent: Read timed out] and exit code [-1], Exiting!

########## Agent Workflow Finalization ##########

[2013-12-03 02:42:21,078] INFO: Agent Workflow Finalization started

[2013-12-03 05:42:21,340] WARN: SCF-00080: Agent finalization for workflow failed with warning [java.net.SocketTimeoutException: SocketTimeoutException invoking http://172.30.1.57:9000/SnapCreator/Daemon/Agent: Read timed out]. Continuing.

########## Snap Creator Community Release 4.1.0c failed ##########

FLORIAN_MEIER · ‎2013-12-02

on the agents side, we get the same error like before..

[2013-12-02T22:32:25,417+0100] DEBUG [pool-2-thread-7] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.ExecutorImpl - stderrLogger running=true

[2013-12-02T22:32:25,507+0100] DEBUG [Thread-1243] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=321, p=vibe - 2013-12-02 22:32:25 (pid=7492) - Listing incoming requests from plugins/wrapper/in

[2013-12-02T22:32:25,747+0100] DEBUG [Thread-1237] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=318, p=vibe - 2013-12-02 22:32:25 (pid=7536) - Listing incoming requests from plugins/wrapper/in

[2013-12-02T22:32:25,927+0100] DEBUG [Thread-1189] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=316, p=vibe - 2013-12-02 22:32:25 (pid=3340) - Listing incoming requests from plugins/wrapper/in

[2013-12-02T22:32:26,052+0100] DEBUG [Thread-1239] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=319, p=vibe - 2013-12-02 22:32:26 (pid=7000) - Writing results to plugins/wrapper/out/319+vibe+1386019805409+quiesce

[2013-12-02T22:32:26,052+0100] DEBUG [Thread-1239] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=319, p=vibe - 2013-12-02 22:32:26 (pid=7000) - Result: SC_MSG#INFO#Mon Dec 2 22:30:08 2013#Checking if VIBE pre-requisites already run (function: quiesce) ....

[2013-12-02T22:32:26,052+0100] DEBUG [Thread-1239] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=319, p=vibe - 2013-12-02 22:32:26 (pid=7000) - Listing incoming requests from plugins/wrapper/in

this goes on and on and on..

for about 1 hour.. (thats also the limit of agents timeout)

then he stops with this mesage:

[2013-12-02T23:31:15,992+0100] DEBUG [Thread-1237] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=318, p=vibe - 2013-12-02 23:31:15 (pid=7536) - Will shutdown now. Reason: Could not find any new incoming requests in the last 3600 seconds at wrapper.pl line 256.

[2013-12-02T23:31:15,992+0100] DEBUG [Thread-1237] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=318, p=vibe -

[2013-12-02T23:31:15,992+0100] DEBUG [Thread-1237] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=318, p=vibe - 2013-12-02 23:31:15 (pid=7536) - Done

[2013-12-02T23:31:16,100+0100] DEBUG [Thread-1237] com.netapp.snapcreator.agent.nextgen.plugin.legacyservice.StreamLogger - run() - type=stdout, wid=318, p=vibe - Finished

FLORIAN_MEIER · ‎2013-12-03

i also saw, that some wrappers are running in the morning. i think the wrappers should be closed after the backup is finishd, right?

Clemens_Siebler · ‎2013-12-03

Hi Florian,

would you be so kind to reach out to me via email and provide me with the agent.log?

Thanks,

Clemens

FLORIAN_MEIER · ‎2013-12-03

of course! if you want we can also do a webex or somethink like this.

i send you the agent.log now

ktenzer · ‎2013-12-03

Hi Florian,

Yes send clemens email with logs and then we will setup a webex. I will join as well. We need to understand these issues. We appreciate your time and help!

Regards,

keith

FLORIAN_MEIER · ‎2013-12-03

i have sent the logs. thank you

Clemens_Siebler · ‎2013-12-04

Quick update: The fix for the initial issue will be in the GA release of 4.1.