Commit events are not broadcast because no JMS Transport is available

During weblogic server domain creation,if you have enabled RDBMS Security Store and you see these errors during Weblogic Server (10.3.4) startup,

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.> 

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.> 

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.> 

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.> 

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.> 

<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.>

...here is the reason why.

The error messages are caused by the server's inability to locate the p13n.security.RDBMSSecurityStoreTopic from the JNDI tree during startup. Contrary to some believe that this can be solved by configuring the "Delivery Failure" parameters such as "Redelivery Delay Override" and "Redelivery Limit" of the Topic, this is really not the case of delivery failure. According to the Oracle Weblogic documentations,

"WebLogic Server security services are always initialized before server resources, applications, and startup classes are deployed. ..."

(Well, the part "because no JMS Transport is available" is not very helpful though it is true that the transport is not yet established at that the time the error occurs. The server assumes that if the resource is registered in the JNDI, then it is deemed to be available).

Provided here a section of the debug trace obtain during server startup, which shows that the JNDILookup has failed to find 'p13n' entry

####<Jul 31, 2012 7:27:14 PM GMT+10:00> <Debug> <JNDIResolution> <appsvr02> <AdminServer> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1343726834241> <BEA-000000> <--- failed to find p13n>

####<Jul 31, 2012 7:27:14 PM GMT+10:00> <Debug> <WorkContext> <> <> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <> <1343726834244> <BEA-000000> <get(weblogic.diagnostics.DiagnosticContext)>

####<Jul 31, 2012 7:27:14 PM GMT+10:00> <Debug> <WorkContext> <> <> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <> <1343726834244> <BEA-000000> <get(weblogic.diagnostics.DiagnosticContext)>

####<Jul 31, 2012 7:27:14 PM GMT+10:00> <Error> <Security> <appsvr02> <AdminServer> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1343726834244> <BEA-000000> <Commit events are not broadcast because no JMS Transport is available. Remote L2 caches will be out of sync.>

And only at a later time the p13n sub node was created in the JNDI tree.

####<Jul 31, 2012 7:27:15 PM GMT+10:00> <Debug> <JNDIResolution> <appsvr02> <AdminServer> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1343726835596> <BEA-000000> <--- failed to find p13n>

####<Jul 31, 2012 7:27:15 PM GMT+10:00> <Debug> <WorkContext> <> <> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <> <1343726835597> <BEA-000000> <get(weblogic.diagnostics.DiagnosticContext)>

####<Jul 31, 2012 7:27:15 PM GMT+10:00> <Debug> <WorkContext> <> <> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <> <> <> <1343726835597> <BEA-000000> <get(weblogic.diagnostics.DiagnosticContext)>

####<Jul 31, 2012 7:27:15 PM GMT+10:00> <Debug> <JNDIResolution> <appsvr02> <AdminServer> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1343726835597> <BEA-000000> <--- created sub node p13n weblogic.jndi.internal.ServerNamingNode@1f253d6>

About a second later at 1343726835597, the p13n sub node was created in the JNDI tree.

I can't see there is any way to get around this non-issue and the conclusion is that it is safe to ignore the error message because the security service will retry until the JMS resource is established. Even if we try to use an external JNDI service provider (which is not recommended by Oracle), we still need to map the local and the foreign entries but the local entries will not be available after the security services are initialized. AFAIK, there is no 'best-practise' that can remove this startup error because the JNDI tree is simply not populated with the JMS resource reference at the time of security service initialization. Please correct me if I am wrong. Happy to hear from your experience.

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.

svc: failed to register lockdv1 RPC service (errno 97). lockd: cannot monitor

Alright, you have searched the internet in and out, up and down, plough through the forums and read all the available man pages on earth regarding NFS and still did not find answer you longed for, because they are not directly available/described/discussed whatever it might be. Well, this might help you.

Good thing about linux is that it keeps you at your toes.

When mounting a NFS directory, you might see this error in your /var/log/messages trace.

Apr  1 09:10:45 orasoa1 kernel: [  895.012894] svc: failed to register lockdv1 RPC service (errno 97).
Apr  1 09:25:31 orasoa1 kernel: [ 1778.601154] svc: failed to register lockdv1 RPC service (errno 97).

Or when acquiring a file lock either by some applications, Oracle SOA Admin Server for example, or when simply trying to manually acquire an exclusive lock of a file on NFS.

$flock lockfile -c 'vi dosomeactivities'

You might see these errors.

Apr  1 09:25:57 orasoa1 kernel: [ 1804.313073] lockd: cannot monitor 192.168.50.100
Apr  1 09:33:59 orasoa1 kernel: [ 2285.828349] lockd: cannot monitor 192.168.50.100
Apr  1 09:36:39 orasoa1 kernel: [ 2444.869671] lockd: cannot monitor 192.168.50.100

where "192.168.50.100" is the NAS server IP address (the 'openfiler1' host).

It is probably because you don't have a DNS for your host names or simply because you haven't updated your /etc/hosts file to include the name of your NAS server.

Try this if you had similar problem, I hope it saves your precious time.

On your client host(s), stick this line into your /etc/hosts file(s)

#vi /etc/hosts

nas_server_ip_addr nas_sever_hostname #example 192.168.50.100    openfiler1
nas_client_ip_addr nas_client_hostname     #example 172.16.20.50      orasoa1

Cheers,