Wednesday, October 7, 2009

Reading Property Files Efficiently In Java and JSP files


Described below is an efficient way of reading configurations from property files in a web application. It uses a class called AppConfigMaster to read all property files available at a directory location specified as a JVM argument. All key value pairs read from the property files are fed into a HashMap object, which is defined as a data member of the AppConfigMaster class. A singleton of this AppConfigMaster is maintained in the JVM so that the properties are read from the file system only once in a JVMs lifecycle.

AppConfigMaster.java

public class AppConfigMaster {

      static Logger logger = Logger.getLogger(NIAppConfigMaster.class);
      private static AppConfigMaster AppConfigMasterObj;
      private Map configPropertiesMap = new HashMap();
      public static String configurationFilesPath = null;

      /**
       * Constructor for the class
       */
      AppConfigMaster() throws SystemException {
            try {
                  /*
                   * Read the path of the folder specified in the JVM argument
                   */
                  configurationFilesPath = System.getProperty("ApplicationConfigPath");
                  navigateConfigDirectory(configurationFilesPath);
            } catch (Exception ex) {
                   //Do Something
            }
      }

      /**
       * Method which returns a singleton instance of this class
       *
       * @return Object
       */
      public synchronized static AppConfigMaster getInstance() {
            if (AppConfigMasterObj == null) {
                  try {
                        AppConfigMasterObj = new AppConfigMaster();
                  } catch (SystemException e) {
                        e.printStackTrace();
                  }
            }
            return AppConfigMasterObj;
      }

      /**
       * Method which navigates through all the sub folders of the root folder to
       * process property files
       *
       * @param path
       *            of the root folder that is specified in JVM Arguments
       * @throws Exception
       */
      private void navigateConfigDirectory(String path) throws NISystemException {

            File configurationDirectiory = new File(path);
            File[] subdirectories = null;

            if ((configurationDirectiory.isDirectory())
                        && (configurationDirectiory.exists())) {
                  subdirectories = configurationDirectiory.listFiles();
                  FilenameFilter propertiesFileFilter = new OnlyExt("properties");
                  int configDirLength = configurationDirectiory.listFiles(propertiesFileFilter).length;
                  for(int i=0;i
                propertiesFileProcessor(configurationDirectiory.listFiles(propertiesFileFilter)[i]);
                 
                  /*
                   * Assuming there are just 2 levels of nesting
                   */
                  for (int i = 0; i < subdirectories.length; i++) {
                        if (subdirectories[i].isDirectory()) {
                              for (int j = 0; j < subdirectories[i].list(propertiesFileFilter).length; j++) {
                                    propertiesFileProcessor(subdirectories[i].listFiles(propertiesFileFilter)[j]);
                              }
                        }
                  }
            }
      }

      /**
       * Class that filter outs all the files found in root folder except the ones
       * with extension "properties"
       */
      class OnlyExt implements FilenameFilter {
            String ext;

            public OnlyExt(String ext) {
                  this.ext = "." + ext;
            }

            public boolean accept(File dir, String name) {
                  return name.endsWith(ext);
            }
      }

      /**
       * Method which reads the property file and populates a hashmap with the key
       * value pairs
       *
       * @param file
       *            the property file to be processed
       */
      private void propertiesFileProcessor(File file) throws SystemException {
            logger.debug("AppConfigMaster :: reading file :: " + file.getAbsolutePath());
            Properties configProprties = new Properties();
            FileInputStream inputstream;
            String key = null;
            String value = null;

            try {
                  inputstream = new FileInputStream(file.getAbsolutePath());
                  configProprties.load(inputstream);
                  Enumeration keys = configProprties.keys();

                  while (keys.hasMoreElements()) {
                        key = (String) keys.nextElement();
                        value = configProprties.getProperty(key.toString());
                        logger.debug("NIAppConfigMaster :: Adding value for key :: " + key);
                        configPropertiesMap.put(key, value);
                  }
            } catch (FileNotFoundException e) {
                  //Do Something
            } catch (IOException e) {
                  //Do Something
            } catch (Exception e) {
                  //Do Something
            }
      }

      /**
       * Method which reads the hashmap
       *
       * @param key
       *            against which value is required
       * @return value against the key that is passed as a parameter
       */
      public String getPropertyforkey(String key) {
            try {
                  if (configPropertiesMap.containsKey(key))
                        return configPropertiesMap.get(key).toString();
                  else
                        //Do Something
            } catch (ClassCastException cex) {
                  //Do Something
            } catch (NullPointerException npex) {
                   //Do Something
            }
            return null;
      }

      /**
       * This method when invoked will reinitialize the hashmap
       *
       * @return
       */
      public String reloadProperties() throws NISystemException {

            String retMessage = null;

            try {
                  navigateConfigDirectory(configurationFilesPath);
                  retMessage = "Reload of properties Successful";
            } catch (SystemException ex) {
                  retMessage = "Reload of properties unsuccessful";
                  //Do Something
            }
            return retMessage;
      }
}

The class is then used in other class files that need to read key values from property file as below:

NIAppConfigMaster.getInstance().getPropertyforkey("artbody.html.imagespanclasss.right");

To use it in JSP files without using scriplets following additional wrapper class and tag file are used:

AppConfigUtil.java

public class AppconfigUtil {
     
      private static final Logger logger = Logger.getLogger(AppconfigUtil.class);
      private String key;
      private String value;
     
      public void setKey(String key) {
            logger.debug("Value for key " + key + " requested");
            this.key = key;
      }
      public String getValue() {
            value = AppConfigMaster.getInstance().getPropertyforkey(key);
            logger.debug("Value of key :: " + key + " is " + value);
            value = (value == null)?"":value;
            return value;
      }
}

/WEB-INF/tags/getProperty.tag

<%@ taglib uri="http://java.sun.com/jsp/jstl/core" prefix="c"%>
<%@ taglib uri="/WEB-INF/struts-bean.tld" prefix="bean"%>
<%@ tag import="com.ni.sto.util.AppconfigUtil"%>
<%@ attribute name="property" required="true"%>
<%@ attribute name="id" required="true"%>

<jsp:useBean id="appconfig" class="com.ni.sto.util.AppconfigUtil">
      <jsp:setProperty name="appconfig" property="key" value="${property}" />
jsp:useBean>
<bean:define id="value" name="appconfig" property="value" />
<%request.setAttribute(id,value);%>

Usage in a JSP file is illustrated below

<%@ taglib uri="http://java.sun.com/jsp/jstl/core" prefix="c"%>
<%@ taglib tagdir="/WEB-INF/tags" prefix="appConfig"%>

<appConfig:getProperty property="publication.name" id="pub_name"/>
<appConfig:getProperty property="times.url" id="times_url"/>





<b><c:out value="${times_url}"/></b> 
<b><c:out value="${times_url}"/></b>

NOTE
To prevent key name conflicts, all key names used in various property files should follow some agreed naming convention. Name space conflicts can cause logical errors otherwise.



Bookmark and Share

Hibernate - Escenic Transaction Filter Integration | Error In Initialization


Issue

When trying to integrate Hibernate with Escenic Transaction Filter I observed the following exceptions, which prevented the Hibernate Session Factory to initialize correctly. Our application has both custom Event handlers and Transaction filters written for implementing certain functionalities. These event handlers and transaction filters in turn use the Hibernate ORM framework for database transactions.

java.lang.ExceptionInInitializerError
        at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.getProxyFactory(CGLIBLazyInitializer.java:117)
        at org.hibernate.proxy.pojo.cglib.CGLIBProxyFactory.postInstantiate(CGLIBProxyFactory.java:43)
        at org.hibernate.tuple.entity.PojoEntityTuplizer.buildProxyFactory(PojoEntityTuplizer.java:162)
        at org.hibernate.tuple.entity.AbstractEntityTuplizer.(AbstractEntityTuplizer.java:135)
        at org.hibernate.tuple.entity.PojoEntityTuplizer.(PojoEntityTuplizer.java:55)
        at org.hibernate.tuple.entity.EntityEntityModeToTuplizerMapping.(EntityEntityModeToTuplizerMapping.java:56)
        at org.hibernate.tuple.entity.EntityMetamodel.(EntityMetamodel.java:295)
        at org.hibernate.persister.entity.AbstractEntityPersister.(AbstractEntityPersister.java:434)
        at org.hibernate.persister.entity.SingleTableEntityPersister.(SingleTableEntityPersister.java:109)
        at org.hibernate.persister.PersisterFactory.createClassPersister(PersisterFactory.java:55)
        at org.hibernate.impl.SessionFactoryImpl.(SessionFactoryImpl.java:226)
        at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1294)
        at com.ni.db.HibernateUtil.(Unknown Source)
        at com.ni.db.sto.SundayTimesDAO.getSession(Unknown Source)
        at com.ni.db.sto.PluckDAO.insertRecord(Unknown Source)
        at com.ni.article.sto.ArticleTransactionFilterImpl.insertRecord(Unknown Source)
        at com.ni.article.sto.ArticleTransactionFilterImpl.handleTransaction(Unknown Source)
        at com.ni.service.EscenicTransactionFilter.doUpdate(Unknown Source)
        at neo.xredsys.api.IOObjectUpdater.applyFiltersTo(IOObjectUpdater.java:3390)
        at neo.xredsys.api.IOObjectUpdater.applyUpdateFiltersTo(IOObjectUpdater.java:3369)
        at neo.xredsys.api.IOObjectUpdater.updateArticle(IOObjectUpdater.java:680)
        at neo.xredsys.api.ArticleTransactionImpl.update(ArticleTransactionImpl.java:62)
        at neo.xredsys.rio.RIOAdapterImpl.update(RIOAdapterImpl.java:625)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at neo.xredsys.rio.RIOSessionImpl$1.invoke(RIOSessionImpl.java:80)
        at $Proxy1.update(Unknown Source)
        at neo.xredsys.rio.RIOSessionImpl$12.run(RIOSessionImpl.java:1518)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAsPrivileged(Subject.java:517)
        at neo.xredsys.rio.RIOSessionImpl.update(RIOSessionImpl.java:1514)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)
        at sun.rmi.transport.Transport$1.run(Transport.java:153)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:149)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.security.AccessControlException: access denied (java.lang.reflect.ReflectPermission suppressAccessChecks)
        at java.security.AccessControlContext.checkPermission(AccessControlContext.java:264)
        at java.security.AccessController.checkPermission(AccessController.java:427)
        at java.lang.SecurityManager.checkPermission(SecurityManager.java:532)
        at java.lang.reflect.AccessibleObject.setAccessible(AccessibleObject.java:107)
        at net.sf.cglib.core.ReflectUtils.getConstructor(ReflectUtils.java:245)
        at net.sf.cglib.core.ReflectUtils.newInstance(ReflectUtils.java:220)
        at net.sf.cglib.core.ReflectUtils.newInstance(ReflectUtils.java:216)
        at net.sf.cglib.core.KeyFactory$Generator.firstInstance(KeyFactory.java:157)
        at net.sf.cglib.core.AbstractClassGenerator.create(AbstractClassGenerator.java:225)
        at net.sf.cglib.core.KeyFactory$Generator.create(KeyFactory.java:145)
        at net.sf.cglib.core.KeyFactory.create(KeyFactory.java:117)
        at net.sf.cglib.core.KeyFactory.create(KeyFactory.java:108)
        at net.sf.cglib.core.KeyFactory.create(KeyFactory.java:104)
        at net.sf.cglib.proxy.Enhancer.(Enhancer.java:69)
        ... 44 more


I observed that when the Escenic event handler was invoked before the transaction filter in the JVMs lifecycle, the singleton instance of HibernateSessionFactory initialized successfully and subsequent use of this session factory by both the event handler and transaction filter (or any other component in the JVM using the same session factory) worked as expected. However, when the transaction filter was invoked before the even handler the above-mentioned initialization exception was thrown. Once the above exception was thrown, even an invocation of the Event handler failed to initialize the Hibernate session factory successfully making Hibernate framework unusable by any component in the JVM.

Resolution

1. Added the following in the JVM security policy file:
java.policy
grant codeBase "file: /u01/tomcat/shared/lib/cglib-2.1.3.jar" {

        permission java.security.AllPermission;

};

2. Initialized the HibernateSessionFactory using Escenic Initial Context creator.

The following class actually initializes the HibernateSessionFactory:

import org.apache.log4j.Logger;
import org.hibernate.SessionFactory;
import org.hibernate.cfg.Configuration;

import com.myproject.framework.exception.SystemException;

public class HibernateUtil {

      private static final Logger logger = Logger.getLogger(HibernateUtil.class);
      private static final SessionFactory sessionFactory;

      static {
            try {
                  logger.debug("Building hibernate session factory");
                  // Create the SessionFactory from hibernate.cfg.xml
                  sessionFactory = new Configuration().configure().buildSessionFactory();
                  logger.debug("Hibernate session factory built successfully");
            } catch (Throwable e) {
                  throw new SystemException("Initial Hibernate SessionFactory creation failed", e);
            }
      }

      /**
       * Returns the singleton instance of the SessionFactory
       *
       * @return SessionFactory
       */
      public static SessionFactory getSessionFactory() {
            return sessionFactory;
      }
}

This class was invoked during the Escenic initial context creation to initialize the session factory by adding the following entry in Escenic Initial.properties file as below

service.2.0.0-HibernateInit=/com/myproject/HibernateInitializer

and defining a file called HibernateInitializer.properties in [ECE_localconfig]/com/myproject with the following entry:

$class=com.ni.db.HibernateUtil

Note: In non-escenic applications, if a similar problem is encountered, one can try using a start-up filter defined in the web-application deployment descriptor file (web.xml) instead. The idea is to basically initialize the singleton of the HibernateSessionFactory before invocation by the transaction filter

Wednesday, August 19, 2009

Tomcat 5 | Useful Configurations | Performance Tuning

JVM Arguments

argv[4]: -Xmx2560m
Heap Size setting. Min and Max should be set to the same value if you know that your application will mostly operate on the max heap value.
argv[5]: -Xms2560m
argv[13]: -Dsun.rmi.dgc.server.gcInterval=3600000
As there exists a bug in JDK 1.5, this is the recommended setting, http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6200091
argv[14]: -Dsun.rmi.dgc.client.gcInterval=3600000
This is used in combination to the above.
argv[17]: -Dsun.rmi.transport.connectionTimeout=20000
For network failure tuning.
argv[18]: -Dsun.rmi.transport.tcp.handshakeTimeout=20000
For network failure tuning.
argv[19]: -Dsun.rmi.transport.tcp.readTimeout=20000
For network failure tuning.
-XX:+DisableExplicitGC
Do not use. Refer: http://forums.sun.com/thread.jspa?threadID=5369546&tstart=0
argv[20]: -verbose:gc
For debugging
argv[21]: -XX:+UseParNewGC
For debugging
argv[22]: -XX:+PrintGCTimeStamps
For debugging
argv[23]: -XX:+PrintGCDetails
For debugging

Tomcat Settings

Connector Settings

maxThreads="300" minSpareThreads="25" maxSpareThreads="77"
enableLookups="false" redirectPort="8443" acceptCount="256"
connectionTimeout="60000" disableUploadTimeout="true" />
The maxThreads and related settings are based on the corresponding settings on Apache.
Ensure that development mode is set to false in TOMCAT/conf/web.xml [We have not tried this so far. Detailed investigation is in the pipeline]

JDBC Connection Pool Settings (context.xml)

connectionProperties="{ValidateConnection=true,ConnectionWaitTimeout=10}" username="*****" password="*****" validationQuery="select 1 from dual" testOnBorrow="true" poolPreparedStatements="true" maxOpenPreparedStatements="10" initialSize="10" minIdle="10" maxActive="25" maxIdle="20" maxWait="30000" removeAbandonedTimeout="60" removeAbandoned="true" logAbandoned="true"/>

Apache Settings

mod_proxy_http is used instead of mod_proxy_ajp as the connector between Tomcat and Apache as it is more stable. This change sometimes requires ProxyPreserveHost setting to be turned ON to ensure correct configurations.
ProxyPass http://localhost:8080/ retry=0
ProxyPassReverse http://www.thesun.co.uk/
The retry=0 settings is used to resolve an issue on production environment that caused intermittent 503 errors served by Apache. (Refer: http://httpd.apache.org/docs/2.2/mod/mod_proxy.html )
If IPV4 is used in the environment, modify default httpd.conf settings to change the Listener port configurations as indicated below:

0.0.0.0:80 rather than Listen 80

Escenic Content Studio Hang Issue - Version 4.3.3

Problem Statement: ECS Hang

We have a JNLP Based Java Client Application(Escenic Content Studio) which communicates with a Tomcat Servlet Conatiner using RMI. Software stack with versions used is as below:

JVM Version: 1.5.0_14-b03

Server version: Apache Tomcat/5.5.27

OS/uname: SunOS uat5cma52e 5.10 Generic_125101-06 i86pc i386 i86pc

The server application is a web content management system (produced by a company called Escenic) and uses LDAP for its authentication, and Oracle/Apache DBCP for its database connectivity, it also uses RMI to communicate with other nodes for sending events etc.

The problem we are seeing is that after an amount of time(ranging between 20 minutes to 40 hours), the server application appears to hang for the clients connected via RMI, tomcat continues to serve content via HTTP, but after a while (depending on the number of requests) the HTTP threads begin to block, an example of a hung client connection thread is (The RMI connections have been observed to hang at exactly the same point each time the issue has been reproduced). Once hung the threads remain in hung state for as long as 24 hours and don’t recover:

"RMI TCP Connection(1642)-143.252.80.100" daemon prio=10 tid=0x09a972b0 nid=0x872 waiting on condition [0x60916000..0x60917ab8]

at neo.xredsys.auth.JNDIPolicy14.getPermissions(JNDIPolicy14.java:46)

at java.security.Policy.implies(Policy.java:400)

at java.security.ProtectionDomain.implies(ProtectionDomain.java:195)

at java.security.AccessControlContext.checkPermission(AccessControlContext.java:249)

at java.security.AccessController.checkPermission(AccessController.java:427)

at neo.xredsys.api.IOObjectLoader.getArticle(IOObjectLoader.java:306)

at neo.xredsys.api.IOObjectLoader.getObject(IOObjectLoader.java:40)

at neo.xredsys.rio.RIOLockManagerImpl.lockTransaction(RIOLockManagerImpl.java:57)

at neo.xredsys.rio.RIOLockManagerImpl.lockField(RIOLockManagerImpl.java:133)

at neo.xredsys.rio.RIOAdapterImpl.lock(RIOAdapterImpl.java:400)

at neo.xredsys.rio.RIOSessionImpl$3.run(RIOSessionImpl.java:1006)

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

at javax.security.auth.Subject.doAsPrivileged(Subject.java:517)

at neo.xredsys.rio.RIOSessionImpl.lock(RIOSessionImpl.java:1003)

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

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:585)

at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

at sun.rmi.transport.Transport$1.run(Transport.java:153)

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

at sun.rmi.transport.Transport.serviceCall(Transport.java:149)

at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)

at java.lang.Thread.run(Thread.java:595)

The line of code where this is hanging is performing an instanceof operation:

for (int i=0; i <>

Principal tmp = pd.getPrincipals()[i];

if (tmp instanceof ECEPrincipal) {

principal = (ECEPrincipal) tmp;

break;

}

}

The class which is “waiting on condition” has the following inheritance hierarchy:

java.security.Policy

neo.xredsys.auth.JNDIPolicy

neo.xredsys.auth.JNDIPolicy14

The class which is having the instanceof operation performed on it has the following class hierarchy:

java.security.Principal

neo.xredsys.auth.ECEPrincipal

We have an example of the truss output, which shows that the light weight processes are waiting on a condition:

25743/6: lwp_cond_wait(0x08311BA8, 0x08311B90, 0xFAF9BC98, 0) Err#62 ETIME

25743/6: condvar type: USYNC_THREAD

25743/6: mutex type: USYNC_THREAD

25743/6: timeout: 0.010999273 sec

We want to know is “what” the java threads/lwp’s are waiting for, and how to trace through the system; and what exactly is happening when java performs an “instanceof” operation - we believe that it is somehow related to LDAP, as we have had some success in relieving the problem by setting the following 2 properties:

com.sun.jndi.ldap.connect.timeout=5000

com.sun.jndi.ldap.read.timeout=1000


Issue Resolution: ECS Hang

The following exception was being masked in the ECS grey screen and was not visible until we applied the (Grey Screen of Death) GSOD patch:

Caused by: java.lang.LinkageError: neo/xredsys/auth/ECEPrincipal

at neo.xredsys.auth.JNDIPolicy14.getPermissions(JNDIPolicy14.java:46)

at java.security.Policy.implies(Policy.java:400)

at java.security.ProtectionDomain.implies(ProtectionDomain.java:195)

at java.security.AccessControlContext.checkPermission(AccessControlContext.java:249)

at java.security.AccessController.checkPermission(AccessController.java:427)

at neo.xredsys.api.IOObjectLoader.getCatalog(IOObjectLoader.java:1059)

[Stacktrace Truncated]

The error can be simulated ‘at will now’ by accessing the web application named ‘audit’. Since this web application has escenic-io.jar and escenic-common.jar inside its WEB-INF/lib folder, it loads a new instance of class neo.nursery.GlobalBus on access.

Ideally, there should be only on instance of class neo.nursery.GlobalBus in a JVM. The spinning up of a second instance causes a java.lang.LinkageError for the class neo.xredsys.auth.ECEPrincipal when an instanceof operation is invoked by JNDIPolicy14.getPermissions()(Line number 46). The exact same line of code on which we see the RMI TCP Connections hung in the thread dumps throws the Linkage error.

"RMI TCP Connection(1642)-143.252.80.100" daemon prio=10 tid=0x09a972b0 nid=0x872 waiting on condition [0x60916000..0x60917ab8]

at neo.xredsys.auth.JNDIPolicy14.getPermissions(JNDIPolicy14.java:46)

at java.security.Policy.implies(Policy.java:400)

at java.security.ProtectionDomain.implies(ProtectionDomain.java:195)

at java.security.AccessControlContext.checkPermission(AccessControlContext.java:249)

at java.security.AccessController.checkPermission(AccessController.java:427)

at neo.xredsys.api.IOObjectLoader.getArticle(IOObjectLoader.java:306)

at neo.xredsys.api.IOObjectLoader.getObject(IOObjectLoader.java:40)

at neo.xredsys.rio.RIOLockManagerImpl.lockTransaction(RIOLockManagerImpl.java:57)

at neo.xredsys.rio.RIOLockManagerImpl.lockField(RIOLockManagerImpl.java:133)

at neo.xredsys.rio.RIOAdapterImpl.lock(RIOAdapterImpl.java:400)

at neo.xredsys.rio.RIOSessionImpl$3.run(RIOSessionImpl.java:1006)

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

at javax.security.auth.Subject.doAsPrivileged(Subject.java:517)

at neo.xredsys.rio.RIOSessionImpl.lock(RIOSessionImpl.java:1003)

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

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:585)

at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)

at sun.rmi.transport.Transport$1.run(Transport.java:153)

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

at sun.rmi.transport.Transport.serviceCall(Transport.java:149)

at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)

at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)

at java.lang.Thread.run(Thread.java:595)

The above has been confirmed by reading JVM heap dumps before and after invoking audit web application in the Tomcat container. There are two instances of neo.nursery.GlobalBus after accessing the audit web application (which should not be there) as opposed to one instance until audit web application is not accessed.

Why is this not seen in Websphere (WAS 6.0.2)?

Websphere has a different class loading mechanism than Tomcat. In Websphere, a web application always delegates the loading of a class to the Parent class loader first. On the other hand, In Tomcat, a web application tries to load a class from the WebApp class loader before delegating the request to the Parent classloader. Thus, in Websphere, presence of the jar files in audit web application has no impact.

Why is this not seen on other Titles/Escenic publications?

Sun Online is the only other title that is using the audit web application. Times Online uses auditing functionality as well but the code is bundled in the main publication web application instead of a separate web application (WAR). News of the World does not audit web application.

Open Questions

  1. Why do we not see any logs corresponding to the LinkageError in the server logs? We could not see this error until we applied the GSOD patch.
  2. Why does a class loaded by a web application class loader (audit web application in our case) effect other web applications deployed on the Tomcat container? Is this a Tomcat class loader ‘leak’ bug?

Wednesday, June 24, 2009

Grinder Installation and Setup

What is Grinder?

The Grinder is a JavaTM load testing framework that makes it easy to run a distributed test using many load injector machines. It is freely available under a BSD-style open-source license

Refer: http://grinder.sourceforge.net/index.html for more details

Installation and Setup

[This example assumes that you are installing grinder in the directory /u01/grinder/grinder-3.2 referred to as GRINDER_HOME on a Solaris environment]

1. Download Grinder version 3.2
wget http://kent.dl.sourceforge.net/sourceforge/grinder/grinder-3.2.zip

2. Unzip grinder-3.2.zip to GRINDER_HOME, where GRINDER_HOME in this example referes t

/u01/grinder/grinder-3.2

3. Create additional utility directories as follows:

mkdir /u01/grinder/grinder-3.2/bin
mkdir /u01/grinder/grinder-3.2/grinder-agent [This basically houses the default load test script called grinder.py and grinder.properties, the configuration file the defines properties required by the Grinder engine]
mkdir /u01/grinder/grinder-3.2/scripts [Custom load testing scripts can be kept here]
mkdir /u01/app/grinder/grinder-3.2/cachedir [Reference from grinder.properties]
mkdir /u01/grinder/grinder-3.2/logs [Reference from grinder.properties]

4. Create the following files in /u01/grinder/grinder-3.2/bin
  • setGrinderEnv.sh
#!/usr/bin/ksh
GRINDERPATH=/u01/grinder/grinder-3.2
GRINDERPROPERTIES=/u01/grinder/grinder-3.2/grinder-agent/grinder.properties
CLASSPATH=$GRINDERPATH/lib/grinder.jar:$GRINDERPATH/lib/jython.jar:$CLASSPATH
JAVA_HOME=/usr/jdk/jdk1.5.0_14
PATH=$JAVA_HOME/bin:$PATH
export CLASSPATH PATH GRINDERPROPERTIES
  • startConsole.sh
#!/usr/bin/ksh
#. (path to setGrinderEnv.sh)/setGrinderEnv.sh
. ./setGrinderEnv.sh
java -cp $CLASSPATH net.grinder.Console &

  • startAgent.sh
#!/usr/bin/ksh
#. (path to setGrinderEnv.sh)/setGrinderEnv.sh
. ./setGrinderEnv.sh
java -cp $CLASSPATH net.grinder.Grinder $GRINDERPROPERTIES
  • startProxy.sh
#!/usr/bin/ksh
#. (path to setGrinderEnv.sh)/setGrinderEnv.sh
. ./setGrinderEnv.sh
java -cp $CLASSPATH net.grinder.TCPProxy -console -http > grinder.py

5. Create grinder.properties in /u01/grinder/grinder-3.2/grinder-agent as follows

#########################################################################################
# Properties understood by the Grinder Engine
#########################################################################################

#########################################################################################
# The number of worker processes the agent should start.
# Example: grinder.processes=1
#########################################################################################
grinder.processes=1

#########################################################################################
# The number of worker threads that each worker process spawns.
# Example:grinder.threads=1
#########################################################################################
grinder.threads=1

#########################################################################################
# The number of runs of the test script each thread performs.
# 0 means "run forever", and should be used when you are using the console to control
# your test runs.
# Example: grinder.runs=0
#########################################################################################
grinder.runs=0

#########################################################################################
# If set, the agent will ramp up the number of worker processes, starting the number
# specified every grinder.processesIncrementInterval milliseconds. The upper limit is
# set by grinder.processes. Do not set this property id you want to start all worker
# processes together.
# Example: grinder.processIncrement=1
#########################################################################################
#grinder.processIncrement=

#########################################################################################
# Used in conjunction with grinder.processIncrement, this property sets the interval in
# milliseconds at which the agent starts new worker processes.
#grinder.processIncrementInterval
#########################################################################################
#grinder.processIncrementInterval=60000

#########################################################################################
# Used in conjunction with grinder.processIncrement, this property sets the initial
# number of worker processes to start.
#########################################################################################
#grinder.initialProcesses=1

#########################################################################################
# The maximum length of time in milliseconds that each worker process should run for.
# grinder.duration can be specified in conjunction with grinder.runs, in which case the
# worker processes will terminate if either the duration time or the number of runs is
# exceeded.
# Don't define this property to make grinder run forever. A manul break can be used in
# this case (via Grinder console) to terminate the run
#########################################################################################
#grinder.duration=

#########################################################################################
# The file name of the Jython script to run
# This is not mandatory to specify. If not specified the script to run can be chosed via
# the grinder console.
#########################################################################################
#grinder.script=

#########################################################################################
# Use an alternate JVM for worker processes. Defaults to java so you do not need to
# specify this if your PATH is sensible.
#########################################################################################
#grinder.jvm=

#########################################################################################
# Use to adjust the classpath used for the worker process JVMs. Anything specified
# here will be prepended to the classpath used to start the Grinder processes.
#########################################################################################
#grinder.jvm.classpath=

#########################################################################################
# Additional arguments to worker process JVMs.
#########################################################################################
# The following JVM argument is set due to a bug in the version of Jython being used.
# This error causes error during startup as below:
# *sys-package-mgr*: can't create package cache dir,
# '/u01/grinder/grinder-3.2/lib/jython.jar/cachedir/packages'
grinder.jvm.arguments=-Dpython.cachedir=/u01/app/grinder/grinder-3.2/cachedir

#########################################################################################
# Directory to write log files to. Created if it doesn't already exist.
#########################################################################################
grinder.logDirectory=/u01/grinder/grinder-3.2/logs

#########################################################################################
# The number of archived logs from previous runs that should be kept.
#########################################################################################
grinder.numberOfOldLogs=100

#########################################################################################
# Override the "host" string used in log filenames and logs.
#########################################################################################
grinder.hostID=localhost

#########################################################################################
# The IP address or host name that the agent and worker processes use to contact the
# console. [All the network interfaces of the local machine.]
#########################################################################################
grinder.consoleHost=127.0.0.1

#########################################################################################
# The IP port that the agent and worker processes use to contact the console.
#########################################################################################
grinder.consolePort=6372

#########################################################################################
# Set to false to set the agent and worker processes not to use the console.
#########################################################################################
grinder.useConsole=true

#########################################################################################
# The period (in ms) at which each process sends updates to the console. This also
# controls the frequency at which the data files are flushed.
#########################################################################################
grinder.reportToConsole.interval=500

#########################################################################################
# The maximum time in milliseconds that each thread waits before starting. Unlike the
# sleep times specified in scripts, this is varied according to a flat random
# distribution. The actual sleep time will be a random value between 0 and the specified
# value. Affected by grinder.sleepTimeFactor, but not grinder.sleepTimeVariation.
#########################################################################################
grinder.initialSleepTime=0

#########################################################################################
# Apply a factor to all the sleep times you've specified, either through a property
# of in a script. Setting this to 0.1 would run the script ten times as fast.
#########################################################################################
grinder.sleepTimeFactor=1

#########################################################################################
# The Grinder varies the sleep times specified in scripts according to a Normal
# distribution. This property specifies a fractional range within which nearly
# all (99.75%) of the times will lie. E.g., if the sleep time is specified as 1000 and
# the sleepTimeVariation is set to 0.1, then 99.75% of the actual sleep times will be
# between 900 and 1100 milliseconds.
#########################################################################################
grinder.sleepTimeVariation=0.1

#########################################################################################
# Set to false to disable the logging of output and error steams for worker processes.
# You might want to use this to reduce the overhead of running a client thread.
#########################################################################################
grinder.logProcessStreams=true

#########################################################################################
# Set to false to disable reporting of timing information to the console; other
# statistics are still reported.
#########################################################################################
grinder.reportTimesToConsole=true

#########################################################################################
# If set to true, the agent process spawns engines in threads rather than processes,
# using special class loaders to isolate the engines. This allows the engine to be
# easily run in a debugger. This is primarily a tool for debugging The Grinder engine,
# but it might also be useful to advanced users. GrinderStone uses this property to allow
# interactive debugging.
#########################################################################################
grinder.debug.singleprocess=false

#########################################################################################
# For advanced use only. Specifies a comma separated list of names of classes that
# should be shared between the worker engines when grinder.debug.singleprocess is true.
# Class names can end with a * wildcard. See bug 2314157 for more details.
#########################################################################################
#grinder.debug.singleprocess.sharedclasses=

#########################################################################################
# If set to true, System.nanoTime() is used for measuring time instead of
# System.currentTimeMills(). The Grinder will still report times in milliseconds.
# The precision of these methods depends on the JVM implementation and the operating
# system. Setting to true requires J2SE 5 or later.
#########################################################################################
grinder.useNanoTime=false


Note:- The key: grinder.jvm.arguments=-Dpython.cachedir=/u01/app/grinder/grinder-3.2/cachedir is specified in grinder.properties to take care of errors in the version of Jython being used by default with Grinder.

If the above mentioned JVM argument is not supplied you might get the following error:
[*sys-package-mgr*: can't create package cache dir, '/u01/grinder/grinder-3.2/lib/jython.jar/cachedir/packages']

Refer: http://grinder.sourceforge.net/g3/scripts.html for details.

5. Create a minimal test script named grinder.py in the directory /u01/grinder/grinder-3.2/grinder-agent to ensure that the grinder agent starts sucessfully before any scripts have been distributed from the console machine. (This step is mandatory in most cases)

################################################
# A minimal script that ensures the agent will start before any
# scripts have been distributed from the console machine.
#
# This script shows the recommended style for scripts, with a
# TestRunner class. The script is executed just once by each worker
# process and defines the TestRunner class. The Grinder creates an
# instance of TestRunner for each worker thread, and repeatedly calls
# the instance for each run of that thread.

from net.grinder.script.Grinder import grinder
from net.grinder.script import Test

# A shorter alias for the grinder.logger.output() method.
log = grinder.logger.output

# Create a Test with a test number and a description. The test will be
# automatically registered with The Grinder console if you are using
# it.
test1 = Test(1, "Log method")

# Wrap the log() method with our Test and call the result logWrapper.
# Calls to logWrapper() will be recorded and forwarded on to the real
# log() method.
logWrapper = test1.wrap(log)

# A TestRunner instance is created for each thread. It can be used to
# store thread-specific data.
class TestRunner:

# This method is called for every run.
def __call__(self):
logWrapper("Hello World")

You may want to comment out the line logWrapper("Hello World") above to prevernt the grinder logs from being unnecessarily filled up.

NOTE
Target host must allow X11 forwarding -so that grinder console can run. Although you can ignore this if you do not plan to use grinder console.

To enable X11 forwarding on a solaris environment:

vi /etc/ssh/sshd_config

# make sure the following properties are set:
AllowTcpForwarding yes

# X11 tunneling options
X11Forwarding yes
X11DisplayOffset 10
X11UseLocalhost no # this is required because of the IPV6 Solaris problem

svcadm disable /network/ssh
svcadm enable /network/ssh

Tuesday, June 23, 2009

Setting-up Full Text Search on the Escenic Schema

A set of scripts provided by Escenic are used to setup full text search on the Escenic Schema. These scripts are required to enable text search via Escenic Content Studio (ECS)

Common problems faced while setting up and executing the Escenic provided scripts are described below.

Problem 1
Executing the following script to setup required indexing jobs

alter session set nls_language=american;
VARIABLE jobno number;
exec DBMS_JOB.SUBMIT(:jobno,'STO_ECE_SI1.ctx_ddl.sync_index(''STO_ECE_SI1.XML_INDEX'');',SYSDATE, 'SYSDATE + 1/1440');
exec DBMS_JOB.SUBMIT(:jobno,'STO_ECE_SI1.ctx_ddl.sync_index(''STO_ECE_SI1.XMLENTITY_CONTENT'');',SYSDATE, 'SYSDATE + 1/1440');
exec DBMS_JOB.SUBMIT(:jobno,'CTX_DDL.OPTIMIZE_INDEX(''STO_ECE_SI1.XML_INDEX'',CTX_DDL.OPTLEVEL_FAST);',SYSDATE, 'trunc(sysdate+1)+2/24');
exec DBMS_JOB.SUBMIT(:jobno,'CTX_DDL.OPTIMIZE_INDEX(''STO_ECE_SI1.XMLENTITY_CONTENT'',CTX_DDL.OPTLEVEL_FAST);',SYSDATE, 'trunc(sysdate+1)+2/24');


Results in the following error

Error starting at line 3 in command:
exec DBMS_JOB.SUBMIT(:jobno,'STO_ECE_SI1.ctx_ddl.sync_index(''STO_ECE_SI1.XML_INDEX'');',SYSDATE, 'SYSDATE + 1/1440');
Error report:
ORA-06550: line 1, column 93:
PLS-00201: identifier 'STO_ECE_SI1.CTX_DDL' must be declared
ORA-06550: line 1, column 93:
PL/SQL: Statement ignored
ORA-06512: at "SYS.DBMS_JOB", line 79
ORA-06512: at "SYS.DBMS_JOB", line 136
ORA-06512: at line 1
06550. 00000 - "line %s, column %s:\n%s"
*Cause: Usually a PL/SQL compilation error.
*Action:

Explanation

The scripts(provided by Escenic) specify [Escenic_Schema_User].ctx_ddl which does not exists.

Resolution

Simply remove the [Escenic_Schema_User] prefix and run the scripts to setup indexing jobs. Verification that the jobs are setup correctly can be done by executing the following scripts:

  • select job, what from user_jobs;
Sample Output
Job What
13 CTX_DDL.OPTIMIZE_INDEX('XML_INDEX',CTX_DDL.OPTLEVEL_FAST);
14 CTX_DDL.OPTIMIZE_INDEX('XMLENTITY_CONTENT', CTX_DDL.OPTLEVEL_FAST);
21 ctxsys.ctx_ddl.sync_index('XMLENTITY_CONTENT');
22 ctxsys.ctx_ddl.sync_index('XML_INDEX');

  • select job, last_sec, last_date, next_sec, next_date,failures, broken from user_jobs;
Sample Output
Job LAST_SEC LAST_DATE NEXT_SEC NEXT_DATE FAILURES BROKEN
13 02:00:00 23-JUN-09 02:00:00 24-JUN-09 0 N
14 02:00:01 23-JUN-09 02:00:00 24-JUN-09 0 N
21 10:03:04 23-JUN-09 13:03:00 23-JUN-09 0 N
22 10:00:04 23-JUN-09 13:00:00 23-JUN-09 0 N


Problem 2
Executing the following script

alter session set nls_language=american;
BEGIN
ctx_ddl.create_section_group('sto_ece_si1.IO_ARTICLE','AUTO_SECTION_GROUP');
END;
/

Results in the following error

alter session set succeeded.

Error starting at line 2 in command:

BEGIN
ctx_ddl.create_section_group('sto_ece_si1.IO_ARTICLE','AUTO_SECTION_GROUP');
END;
Error report:
ORA-06550: line 2, column 1:
PLS-00201: identifier 'CTX_DDL' must be declared
ORA-06550: line 2, column 1:
PL/SQL: Statement ignored
06550. 00000 - "line %s, column %s:\n%s"
*Cause: Usually a PL/SQL compilation error.
*Action:

Explanation

The CTXSYS user needs to grant the CTXAPP role to the user running the script. A DBA can do this and this is normally done while installaing the DB.

Resolution

This was reported to the DBA and after he resolved the permission issues, the script ran successfully.

Tuesday, June 9, 2009

Escenic Content Studio - 4.3.5

Issue in saving images in ECS version 4.3.5


Problem Statement

Attempt to save an image throws the following exception in both the server logs and the ECS error log pop-up


2009-06-09 14:02:59,503 ERROR [RMI TCP Connection(12)-10.194.138.185] (neo.dbaccess.GenericDataConnector) Error in database operation. Invalidating resource: null java.lang.reflect.UndeclaredThrowableException at $Proxy1.executeUpdate(Unknown Source) at neo.dbaccess.OracleUtil.insertEmptyClob(OracleUtil.java:20) at neo.xredsys.content.entity.EntityManager$InsertXMLEntityAction.execute(EntityManager.java:709) at neo.xredsys.content.entity.EntityManager.insertXMLEntity(EntityManager.java:748) at neo.xredsys.content.entity.EntityManager$InsertEntityAction.execute(EntityManager.java:1094) at neo.xredsys.content.entity.EntityManager.insertReferenceEntity(EntityManager.java:1137) at neo.xredsys.content.multimedia.MultimediaManager$InsertMultimediaObjectAction.execute(MultimediaManager.java:372) at neo.xredsys.content.ContentManager$TransactionOperationWrapper.execute(ContentManager.java:145) at neo.dbaccess.GenericDataConnector.doTransaction(GenericDataConnector.java:139) at neo.xredsys.content.ContentManager.doDatabaseAction(ContentManager.java:169) at neo.xredsys.content.ContentManager.doTransaction(ContentManager.java:194) at neo.xredsys.content.multimedia.MultimediaManager.insertMultimediaObject(MultimediaManager.java:471) at neo.xredsys.api.IOObjectUpdater.createImage(IOObjectUpdater.java:2853) at neo.xredsys.api.IOObjectUpdater.createMultimedia(IOObjectUpdater.java:2580) at neo.xredsys.api.IOObjectUpdater.createMultimedia(IOObjectUpdater.java:2555) at neo.xredsys.api.ImageTransactionImpl.create(ImageTransactionImpl.java:161) at neo.xredsys.rio.RIOAdapterImpl.create(RIOAdapterImpl.java:901) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at neo.xredsys.rio.RIOSessionImpl$1.invoke(RIOSessionImpl.java:80) at $Proxy2.create(Unknown Source) at neo.xredsys.rio.RIOSessionImpl$9.run(RIOSessionImpl.java:1385) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAsPrivileged(Subject.java:517) at neo.xredsys.rio.RIOSessionImpl.create(RIOSessionImpl.java:1382) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294) at sun.rmi.transport.Transport$1.run(Transport.java:153) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:149) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707) at java.lang.Thread.run(Thread.java:595) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at neo.dbaccess.DebugPreparedStatement.invoke(DebugPreparedStatement.java:35) ... 38 more Caused by: java.sql.SQLException: ORA-29861: domain index is marked LOADING/FAILED/UNUSABLE at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112) at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331) at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:288) at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:743) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216) at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:955) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1168) at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3316) at oracle.jdbc.driver.OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3400) at org.apache.tomcat.dbcp.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:102) ... 43 more

Resolution

The issue was caused because one of the domain indices was not created successfully while setting up the Escenic schema. Domain indices are created as part of settinup up Full text searcgh on the Escenic schema.

The following domain indices are created as part of enabling full text search:
  • XMLENTITY_CONTENT
  • XML_INDEX
The issue was resolved by simply dropping the 2 domain indices and recreating them. Following scripts were executed to achieve this:

--Dropping indexes
drop index XML_INDEX force;
drop index XMLENTITY_CONTENT force;


--Recreating indexes
alter session set nls_language=american;
create index STO_ECE_BLD1.XML_INDEX on STO_ECE_BLD1.XMLArticle(content) indextype is ctxsys.context parameters('SECTION GROUP STO_ECE_BLD1.IO_ARTICLE storage STO_ECE_BLD1.ECE_STORAGE1M lexer STO_ECE_BLD1.ece_text_lexer stoplist STO_ECE_BLD1.ECE_STOP MEMORY 12M');


alter session set nls_language=american;
create index STO_ECE_BLD1.XMLENTITY_CONTENT on STO_ECE_BLD1.XMLEntity(content) indextype is ctxsys.context parameters('storage STO_ECE_BLD1.ECE_STORAGE1M lexer STO_ECE_BLD1.ece_text_lexer stoplist STO_ECE_BLD1.ECE_STOP MEMORY 12M');