TIBCO EMS 5.1.5 ESTATUS = 230 com.tibco.tibems.tibemsd.internal.db.EMSDataStoreException

Alright, the FT setup in the previous article worked, but didn't quite right. After the first successful startup and worked as pair, it never did again the second time.

Kept giving out this error.

2011-04-19 13:47:22.004 Recovering state, please wait.
2011-04-19 13:48:23.313 com.tibco.tibems.tibemsd.internal.db.EMSDataStoreException: failed to open store: IO Error: Socket read timed out
2011-04-19 13:48:23.313         at com.tibco.tibems.tibemsd.internal.db.DataStore._checkValidConnParams(DataStore.java:280)
2011-04-19 13:48:23.313         at com.tibco.tibems.tibemsd.internal.db.DataStore.open(DataStore.java:302)
2011-04-19 13:48:23.313         at com.tibco.tibems.tibemsd.internal.db.CallableDataStore.open(CallableDataStore.java:121)
2011-04-19 13:48:23.313         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2011-04-19 13:48:23.314         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
2011-04-19 13:48:23.314         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-04-19 13:48:23.314         at java.lang.reflect.Method.invoke(Method.java:597)
2011-04-19 13:48:23.314         at com.tibco.tibems.tibemsd.internal.Context.invokeMethodInLine(Context.java:308)
2011-04-19 13:48:23.316 SEVERE ERROR: Unable to open store [$sys.failsafe]: [ ESTATUS = 230, ERRSTR = com.tibco.tibems.tibemsd.internal.db.EMSDataStoreException: failed to open store: IO Error: Socket read timed out ]
2011-04-19 13:48:23.317 com.tibco.tibems.tibemsd.internal.db.EMSDataStoreException: failed to open store: IO Error: Socket read timed out
2011-04-19 13:48:23.317         at com.tibco.tibems.tibemsd.internal.db.DataStore._checkValidConnParams(DataStore.java:280)
2011-04-19 13:48:23.317         at com.tibco.tibems.tibemsd.internal.db.DataStore.open(DataStore.java:302)
2011-04-19 13:48:23.324         at com.tibco.tibems.tibemsd.internal.db.CallableDataStore.open(CallableDataStore.java:121)
2011-04-19 13:48:23.324         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2011-04-19 13:48:23.324         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
2011-04-19 13:48:23.324         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
2011-04-19 13:48:23.325         at java.lang.reflect.Method.invoke(Method.java:597)
2011-04-19 13:48:23.325         at com.tibco.tibems.tibemsd.internal.Context.invokeMethodInLine(Context.java:308)
2011-04-19 13:48:23.325 SEVERE ERROR: Unable to open store [$sys.meta]: [ ESTATUS = 230, ERRSTR = com.tibco.tibems.tibemsd.internal.db.EMSDataStoreException: failed to open store: IO Error: Socket read timed out ]
2011-04-19 13:48:23.327 ERROR: Initialization failed: storage for '$sys.meta' not found.
2011-04-19 13:48:23.327 FATAL: Exception in startup, exiting.

After an hour of investigation, it finally narrowed down to oracle jdbc driver problem.

In TIBCO EMS User's Guide, Chapter 10, the documentation did give some clue about RAC.

"The TIBCO Enterprise Message Service server must connect to the Oracle RAC 10g database using the Oracle JDBC OCI driver and TAF configuration."

Why not give it a try? So I went ahead to try to use OCI rather than the thin driver. And it works!

In summary, 3 things needs to be done.

1) Install the Oracle Instant Client 11.2. (instantclient-basic-linux32-11.2.0.2.0.zip)
2) Install libaio package
3) Update the store-db.conf

1) Install the Oracle Instant Client 11.2.
Download the zip file from Oracle website. Unzip all the contents into the $EMS_HOME/lib folder.

2) Install libaio package

root@tibems01:~# apt-get install libaio1

3) Update the stores-db.conf file.

[$sys.failsafe]
type=dbstore
dbstore_driver_url=jdbc:oracle:oci:emsfs/emsfs@oradb11g01:1521:orcl
dbstore_driver_username=emsfs
dbstore_driver_password=emsfs

[$sys.meta]
type=dbstore
dbstore_driver_url=jdbc:oracle:oci:emsmeta/emsmeta@oradb11g01:1521:orcl
dbstore_driver_username=emsmeta
dbstore_driver_password=emsmeta

[$sys.nonfailsafe]
  type=file
  file=/home/tibadmin/ems_ft_cfg/datastore/async-msgs.db
  mode=async
  file_crc=disabled

Start the server pair, with log_trace = DEFAULT, +DBSTORE

Primary (active) server (tibems01)

TIBCO Enterprise Message Service.
Copyright 2003-2010 by TIBCO Software Inc.
All rights reserved.

Version 5.1.5 V3 3/29/2010

2011-04-19 15:35:28.828 Process started from '/home/tibadmin/tibco/ems/5.1/bin/tibemsd'.
2011-04-19 15:35:28.829 Process Id: 11175
2011-04-19 15:35:28.829 Hostname: tibems01
2011-04-19 15:35:28.829 Hostname IP address: 172.16.10.10
2011-04-19 15:35:28.829 Detected IP interface: 127.0.0.1 (lo)
2011-04-19 15:35:28.829 Detected IP interface: 172.16.10.10 (eth0)
2011-04-19 15:35:28.829 Detected IP interface: 192.168.50.10 (eth1)
2011-04-19 15:35:28.829 Reading configuration from '/home/tibadmin/ems_ft_cfg/tibemsd-db1.conf'.
2011-04-19 15:35:28.835 Logging into file '/home/tibadmin/ems01.log'
2011-04-19 15:35:28.836 Trying JVM location: /opt/java/jre/lib/i386/server/libjvm.so
2011-04-19 15:35:28.851 Loaded jvm from /opt/java/jre/lib/i386/server/libjvm.so
2011-04-19 15:35:28.851 Added java virtal machine option -Xmx256m
2011-04-19 15:35:28.851 Added java virtal machine option -Djava.class.path=/home/tibadmin/tibco/ems/5.1/bin/tibemsd.jar
2011-04-19 15:35:28.851 Added java virtal machine option -Xrs
2011-04-19 15:35:28.851 Added java virtal machine option -Dems.com.tibco.tibems.tibemsd.internal.version=5.1.5
2011-04-19 15:35:29.024 Java virtual machine started.
2011-04-19 15:35:29.089 Java Version 1.6.0_24
2011-04-19 15:35:29.095 Java server tasks started.
2011-04-19 15:35:29.108 Server name: 'EMS-SERVER'.
2011-04-19 15:35:29.108 Storage Location: '.'.
2011-04-19 15:35:29.108 Routing is disabled.
2011-04-19 15:35:29.108 Authorization is disabled.
2011-04-19 15:35:30.999 Active server 'tcp://tibems02:7222' not found.
2011-04-19 15:35:30.999 Continuing as active server.
2011-04-19 15:35:30.000 Accepting connections on tcp://tibems01:7222.
2011-04-19 15:35:30.000 Recovering state, please wait.
2011-04-19 15:41:45.330 Store '$sys.failsafe' locked by 'EMS-SERVER'
2011-04-19 15:41:45.347 Store '$sys.meta' locked by 'EMS-SERVER'
2011-04-19 15:41:45.347 Store '$sys.meta': Recovering Zone records...
2011-04-19 15:41:45.398 Store '$sys.meta': Recovered <1> Zone records
2011-04-19 15:41:45.398 Store '$sys.meta': Recovering Connection records...
2011-04-19 15:41:45.414 Store '$sys.meta': Recovered <0> Connection records
2011-04-19 15:41:45.415 Recovering transaction records
2011-04-19 15:41:45.415 Store '$sys.meta': Recovering Transaction records...
2011-04-19 15:41:45.427 Store '$sys.meta': Recovered <0> Transaction records
2011-04-19 15:41:45.427 Store '$sys.failsafe': Recovering Transaction records...
2011-04-19 15:41:45.458 Store '$sys.failsafe': Recovered <0> Transaction records
2011-04-19 15:41:45.458 Recovered all transaction records
2011-04-19 15:41:45.458 Store '$sys.meta': Recovering Session records...
2011-04-19 15:41:45.470 Store '$sys.meta': Recovered <0> Session records
2011-04-19 15:41:45.470 Store '$sys.meta': Recovering Consumer records...
2011-04-19 15:41:45.485 Store '$sys.meta': Recovered <0> Consumer records
2011-04-19 15:41:45.486 Store '$sys.meta': Recovering Producer records...
2011-04-19 15:41:45.499 Store '$sys.meta': Recovered <0> Producer records
2011-04-19 15:41:45.499 Store '$sys.meta': Recovering Purge records...
2011-04-19 15:41:45.511 Store '$sys.meta': Recovered <0> Purge records
2011-04-19 15:42:40.661 Recovering valid msg records...
2011-04-19 15:42:40.661 Store '$sys.meta': Recovering Valid records...
2011-04-19 15:43:13.912 Store '$sys.meta': Recovered <0> Valid records
2011-04-19 15:43:13.912 Store '$sys.failsafe': Recovering Valid records...
2011-04-19 15:43:13.982 Store '$sys.failsafe': Recovered <1> Valid records
2011-04-19 15:43:13.982 Recovered all valid msg records
2011-04-19 15:43:13.983 Store '$sys.meta': Recovering Message records...
2011-04-19 15:43:13.985 Store '$sys.failsafe': Recovering Message records...
2011-04-19 15:43:14.252 Store '$sys.failsafe': Recovered <0> Message records
2011-04-19 15:43:14.260 Store '$sys.meta': Recovered <0> Message records
2011-04-19 15:43:14.280 Recovering Ack records
2011-04-19 15:43:14.280 Store '$sys.failsafe': Recovering Ack records...
2011-04-19 15:43:14.302 Store '$sys.failsafe': Recovered <0> Ack records
2011-04-19 15:43:14.302 Recovered all Ack records
2011-04-19 15:43:14.302 Server is active.

Secondary (standby) server (tibems02)

TIBCO Enterprise Message Service.
Copyright 2003-2010 by TIBCO Software Inc.
All rights reserved.

Version 5.1.5 V3 3/29/2010

2011-04-19 15:42:56.457 Process started from '/home/tibadmin/tibco/ems/5.1/bin/tibemsd'.
2011-04-19 15:42:56.457 Process Id: 2466
2011-04-19 15:42:56.457 Hostname: tibems02
2011-04-19 15:42:56.457 Hostname IP address: 172.16.10.11
2011-04-19 15:42:56.457 Detected IP interface: 127.0.0.1 (lo)
2011-04-19 15:42:56.458 Detected IP interface: 172.16.10.11 (eth0)
2011-04-19 15:42:56.458 Detected IP interface: 192.168.50.11 (eth1)
2011-04-19 15:42:56.458 Reading configuration from '/home/tibadmin/ems_ft_cfg/tibemsd-db2.conf'.
2011-04-19 15:42:56.462 Trying JVM location: /opt/java/jre/lib/i386/server/libjvm.so
2011-04-19 15:42:56.480 Loaded jvm from /opt/java/jre/lib/i386/server/libjvm.so
2011-04-19 15:42:56.480 Added java virtal machine option -Xmx256m
2011-04-19 15:42:56.480 Added java virtal machine option -Djava.class.path=/home/tibadmin/tibco/ems/5.1/bin/tibemsd.jar
2011-04-19 15:42:56.480 Added java virtal machine option -Xrs
2011-04-19 15:42:56.480 Added java virtal machine option -Dems.com.tibco.tibems.tibemsd.internal.version=5.1.5
2011-04-19 15:42:56.647 Java virtual machine started.
2011-04-19 15:42:56.702 Java Version 1.6.0_24
2011-04-19 15:42:56.708 Java server tasks started.
2011-04-19 15:42:56.710 Server name: 'EMS-SERVER'.
2011-04-19 15:42:56.710 Storage Location: '.'.
2011-04-19 15:42:56.710 Routing is disabled.
2011-04-19 15:42:56.711 Authorization is disabled.
2011-04-19 15:43:14.416 Accepting connections on tcp://tibems02:7222.
2011-04-19 15:43:14.416 Server is in standby mode for 'tcp://tibems01:7222'.

Cheers...getting ready for my Easter holiday trip.