Re: SMO for Oracle RAC ( restore error REMOTE-00005: Timeout of .... spawned helper process )

PROMMUNYU · ‎2014-07-23

I cannot test restore smo for oracle rac Envelopment : Oracle 11.2 ,Redhat5.5, SMO v3.3

I can create repo , profile and test full backup success

#[root@PBIDMCDWH02 /]# smo backup restore -profile PBIDMCDWH02 -label F_H_20140723164102ICT -complete -controlfiles -force -verbose

#[ INFO] SMO-13036: Starting operation Backup Restore on host PBIDMCDWH02

#[ INFO] SMO-13046: Operation GUID 8a84d5ea4762baa3014762baa64f0001 starting on Profile PBIDMCDWH02

#[ INFO] SMO-07431: Saving starting state of the database: dmctst2(OPEN).

#[ERROR] REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

#[ERROR] SMO-13032: Cannot perform operation: Backup Restore. Root cause: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

#[ INFO] SMO-07433: Returning the database to its initial state: dmctst2(OPEN).

#[ERROR] REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

#[ERROR] SMO-08002: Error while aborting operation: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

#[ INFO] SMO-13039: Successfully aborted operation: Backup Restore

#[ERROR] SMO-13048: Backup Restore Operation Status: FAILED

#[ INFO] SMO-13049: Elapsed Time: 0:02:11.458

#Operation Id SMO for Oracle RAC ( restore error REMOTE-00005: Timeout of .... spawned helper process ) failed. Error: SMO-13032: Cannot perform operation: Backup Restore. Root cause: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

Thank you in advance for your help.

himanshp · ‎2014-07-24

Hello,

This error could happen when the target database is running in a remote machine..When trying to change the state of the DB it will spawn an remote instance to change the db state…it seems the connection is not happening..

Can you please send the full smo log to investigate this further..

Thanks,

Himanshu

PROMMUNYU · ‎2014-07-28

Hi Himanshu

full log smo server . in this case I disable iptables & selinux on redhat . I can telnet remote host with port 27214 .

2014-07-23 17:18:29,089 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: EXE-00000: Executing shell command:

0:su oracle -p -c "srvctl" "status" "database" "-d" "dmctst"

1:srvctl status database -d dmctst

2014-07-23 17:18:30,125 [Execution Monitor Thread [srvctl status database -d dmctst]] [DEBUG]: EXE-00001: Shell result [0:00:01.036] (Exit Value: 0):

Instance dmctst1 is running on node pbidmcdwh01

Instance dmctst2 is running on node pbidmcdwh02

2014-07-23 17:18:30,126 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Opening connection for JDBC descriptor jdbc:oracle:oci:/@

2014-07-23 17:18:30,674 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: keystore is not initialized

2014-07-23 17:18:30,674 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Keystore path (original): file:/opt/NetApp/smo/properties/keystore

2014-07-23 17:18:30,674 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Keystore path (decoded): /opt/NetApp/smo/properties/keystore

2014-07-23 17:18:30,679 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: No default effective user was found for host: 'PBIDMCDWH02' in the credential cache for user: 'root'

2014-07-23 17:18:30,680 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: No default effective user was found for host: 'PBIDMCDWH01' in the credential cache for user: 'root'

2014-07-23 17:18:30,684 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Host: pbidmcdwh01/10.4.85.105 is using effective user: com.netapp.dlm.api.soap.common.EffectiveUser@6221a86a[PBIDMCDWH01,root,null]

2014-07-23 17:18:31,857 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Authenticating and authorizing user: 'root@PBIDMCDWH01'

2014-07-23 17:18:31,857 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: SMO-01107: Executing remote command (Method[authenticateAndAuthorizeUser] on Server[https://pbidmcdwh01:27214/smo_v9/services/SMO] by User[root])

2014-07-23 17:18:32,124 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Session established and user: 'root@PBIDMCDWH01' was successfully authenticated and authorized.

2014-07-23 17:18:32,124 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: User credentials not persisted for root@PBIDMCDWH01

2014-07-23 17:18:32,125 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: SMO-01107: Executing remote command (Method[launchOracleJvm] on Server[https://pbidmcdwh01:27214/smo_v9/services/SMO] by User[root])

2014-07-23 17:18:32,168 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: SMO-01108: Finished executing remote command (Method[launchOracleJvm] on Server[https://pbidmcdwh01:27214/smo_v9/services/SMO] by User[root]): Result:

2014-07-23 17:18:32,172 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:33,178 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:34,183 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:35,188 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:36,194 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:37,199 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:38,205 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

2014-07-23 17:18:39,211 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: Waiting for RemoteObjectFactory to be registered with GUID 7f7ce9baaf6312b9e97ca442b99ea58a ...

.

2014-07-23 17:19:32,487 [RMI TCP Connection(2)-10.4.85.106] [ERROR]: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

2014-07-23 17:19:32,501 [RMI TCP Connection(2)-10.4.85.106] [ERROR]: SMO-13032: Cannot perform operation: Backup Restore. Root cause: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

java.lang.RuntimeException: REMOTE-00005: Timeout of 60.0 seconds trying to connect to spawned helper process.

at com.netapp.common.remote.RemoteObjectFactoryFactory.lookupRemoteObjectFactory(RemoteObjectFactoryFactory.java:186)

at com.netapp.common.remote.RemoteObjectFactoryFactory.createRemoteObjectFactory(RemoteObjectFactoryFactory.java:110)

at com.netapp.oracle.jdbc.OracleConnectionFactory.createOCIJDBCConnectionInNewJvm(OracleConnectionFactory.java:102)

at com.netapp.oracle.jdbc.OracleConnectionFactory.createConnection(OracleConnectionFactory.java:87)

at com.netapp.oracle.jdbc.OracleConnectionFactory.createSoftConnection(OracleConnectionFactory.java:73)

at com.netapp.oracle.database.OracleInstance.getOpenConnection(OracleInstance.java:122)

at com.netapp.oracle.database.RemoteRACOracleDatabaseInstance.getOpenConnection(RemoteRACOracleDatabaseInstance.java:150)

at com.netapp.oracle.database.OracleInstance.getJDBCTemplate(OracleInstance.java:114)

at com.netapp.dlm.services.vdi.DatabaseSession.initializeTargetDatabase(DatabaseSession.java:269)

at com.netapp.dlm.process.operation.AbstractRestoreOperation.doExecute(AbstractRestoreOperation.java:473)

at com.netapp.dlm.process.operation.AbstractRestoreOperation.doExecute(AbstractRestoreOperation.java:117)

at com.netapp.dlm.process.common.OpCycleOperation.execute(OpCycleOperation.java:184)

at com.netapp.dlm.server.RemoteOperationImpl.execute(RemoteOperationImpl.java:63)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)

at sun.rmi.transport.Transport$1.run(Unknown Source)

at java.security.AccessController.doPrivileged(Native Method)

at sun.rmi.transport.Transport.serviceCall(Unknown Source)

at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)

at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)

at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

2014-07-23 17:19:32,525 [RMI TCP Connection(2)-10.4.85.106] [INFO ]: SMO-07433: Returning the database to its initial state: dmctst2(OPEN).

2014-07-23 17:19:32,535 [RMI TCP Connection(2)-10.4.85.106] [DEBUG]: EXE-00000: Executing shell command:

himanshp · ‎2014-07-30

The command is passed to this remote server .. https://pbidmcdwh01:27214/smo_v9/services/SMO]

Can we get the logs from this server to see whether command came to this server..

Just tail this file (on server pbidmcdwh01), tail –f /var/log/smo/server.log and trigger the backup again.. Observe whether any new methods are getting called in that server, if any method is called then there must be smo related logs created in pbidmcdwh01.

Can we get the output of this sequence..

Thanks,

Himanshu