Weird problem: Two apparent copies of app started

Fri, 28 Sep 2007 18:15:18 -0700 

Hello All,
I have an application using data source pooling configured in META-INF/context.xml. I set up up the data sources and the classes accessing them in an AppListener. This app works fine on Tomcat 5.5.9 running on Windows and 5.5.25 running on Linux/CentOS 5. I am attempting to bring this app up on a Tomcat 5.5.15 running on a version of Linux/CentOS 4/5 running at an ISP. In this setting, at startup, the app fails in the AppListener, throwing the following exception (in catalina.out): 
[I'll provide more details below.]

   com.strongbrain Error: Name jdbc is not bound in this Context
javax.naming.NameNotFoundException: Name jdbc is not bound in this Context
BUT, then it appears as if Tomcat re-starts the app, and this time the AppListener runs as usual, setting up data sources and the (singleton) classes accessing them correctly (which amounts to storing the datasource 
in a private instance variable accessed by a public method: getConnection().
FINALLY, when a connection to the app is made, the access via getConnection() behaves as if the instance variable holding the datasource had NOT been instantiated, leading me to feel like there are two copies of the app running. 

Ok, here are the details.  The app is named StrongBrain.
First comes a section of the catalina.out log with [POINTs A/B/C] marked for reference: 

[POINT A]
INFO   | jvm 1    | 2007/09/28 18:07:58 | StrongBrain AppListener: ENTER
INFO | jvm 1 | 2007/09/28 18:07:58 | com.strongbrain Error: Name jdbc is not bound in this Context INFO | jvm 1 | 2007/09/28 18:07:58 | javax.naming.NameNotFoundException: Name jdbc is not bound in this Context INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.naming.NamingContext.lookup(NamingContext.java:769) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.naming.NamingContext.lookup(NamingContext.java:152) INFO | jvm 1 | 2007/09/28 18:07:58 | at com.strongbrain.listener.AppListener.contextInitialized(AppListener.java:41) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3729) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardContext.start(StandardContext.java:4183) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardHost.start(StandardHost.java:718) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1013) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:442) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardService.start(StandardService.java:450) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.core.StandardServer.start(StandardServer.java:709) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.startup.Catalina.start(Catalina.java:551) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) INFO | jvm 1 | 2007/09/28 18:07:58 | at java.lang.reflect.Method.invoke(Method.java:585) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:275) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) INFO | jvm 1 | 2007/09/28 18:07:58 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) INFO | jvm 1 | 2007/09/28 18:07:58 | at java.lang.reflect.Method.invoke(Method.java:585) INFO | jvm 1 | 2007/09/28 18:07:58 | at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:159) INFO | jvm 1 | 2007/09/28 18:07:58 | at java.lang.Thread.run(Thread.java:595) 
INFO   | jvm 1    | 2007/09/28 18:07:58 | StrongBrain AppListener: EXIT
INFO | jvm 1 | 2007/09/28 18:08:12 | Sep 28, 2007 6:08:12 PM org.apache.catalina.loader.WebappClassLoader validateJarFile INFO | jvm 1 | 2007/09/28 18:08:12 | INFO: validateJarFile(/opt/tomcat5/webapps/strongbrain/WEB-INF/lib/servlet-api.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offending class: javax/servlet/Servlet.class INFO | jvm 1 | 2007/09/28 18:08:13 | log4j:WARN No appenders could be found for logger (org.apache.commons.digester.Digester.sax). INFO | jvm 1 | 2007/09/28 18:08:13 | log4j:WARN Please initialize the log4j system properly. 

[POINT B]
INFO   | jvm 1    | 2007/09/28 18:08:15 | StrongBrain AppListener: ENTER
INFO | jvm 1 | 2007/09/28 18:08:15 | DAOBaseData: setting [EMAIL PROTECTED] INFO | jvm 1 | 2007/09/28 18:08:15 | DAOBaseUsers: setting [EMAIL PROTECTED] INFO | jvm 1 | 2007/09/28 18:08:20 | Connection[data] allocated: #=1 [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:20 | Connection[data] deallocated: #=0
INFO | jvm 1 | 2007/09/28 18:08:20 | Connection[data] allocated: #=1 [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:20 | Connection[data] deallocated: #=0
INFO   | jvm 1    | 2007/09/28 18:08:22 | JM-constr
INFO   | jvm 1    | 2007/09/28 18:08:22 | JM_mh=smtp.als.com
INFO | jvm 1 | 2007/09/28 18:08:22 | JM: params: [EMAIL PROTECTED] [EMAIL PROTECTED] pw=4214j6ka port=25 lh=66.31.40.155 INFO | jvm 1 | 2007/09/28 18:08:23 | DEBUG: setDebug: JavaMail version 1.4ea 
INFO   | jvm 1    | 2007/09/28 18:08:23 | MediaSenderThread constructor
INFO | jvm 1 | 2007/09/28 18:08:23 | MediaSenderThread constructor finished: [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:23 | Thread=Thread[Thread-1,5,main]
INFO | jvm 1 | 2007/09/28 18:08:23 | StrongBrain AppListener: EmailManager started INFO | jvm 1 | 2007/09/28 18:08:23 | StrongBrain AppListener: WordNetAccess started 
INFO   | jvm 1    | 2007/09/28 18:08:23 | StrongBrain AppListener: EXIT
INFO | jvm 1 | 2007/09/28 18:08:34 | Sep 28, 2007 6:08:34 PM org.apache.catalina.core.StandardHost start 
INFO   | jvm 1    | 2007/09/28 18:08:34 | INFO: XML validation disabled
INFO | jvm 1 | 2007/09/28 18:08:39 | Sep 28, 2007 6:08:39 PM org.apache.catalina.loader.WebappClassLoader validateJarFile INFO | jvm 1 | 2007/09/28 18:08:39 | INFO: validateJarFile(/opt/tomcat5/webapps/strongbrain/WEB-INF/lib/servlet-api.jar) - jar not loaded. See Servlet Spec 2.3, section 9.7.2. Offending class: javax/servlet/Servlet.class INFO | jvm 1 | 2007/09/28 18:08:40 | log4j:WARN No appenders could be found for logger (org.apache.commons.digester.Digester.sax). INFO | jvm 1 | 2007/09/28 18:08:40 | log4j:WARN Please initialize the log4j system properly. 
INFO   | jvm 1    | 2007/09/28 18:08:42 | StrongBrain AppListener: ENTER
INFO | jvm 1 | 2007/09/28 18:08:42 | DAOBaseData: setting [EMAIL PROTECTED] INFO | jvm 1 | 2007/09/28 18:08:42 | DAOBaseUsers: setting [EMAIL PROTECTED] INFO | jvm 1 | 2007/09/28 18:08:43 | Connection[data] allocated: #=1 [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:43 | Connection[data] deallocated: #=0
INFO | jvm 1 | 2007/09/28 18:08:43 | Connection[data] allocated: #=1 [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:43 | Connection[data] deallocated: #=0
INFO   | jvm 1    | 2007/09/28 18:08:45 | JM-constr
INFO   | jvm 1    | 2007/09/28 18:08:45 | JM_mh=smtp.als.com
INFO | jvm 1 | 2007/09/28 18:08:45 | JM: params: [EMAIL PROTECTED] [EMAIL PROTECTED] pw=4214j6ka port=25 lh=66.31.40.155 INFO | jvm 1 | 2007/09/28 18:08:45 | DEBUG: setDebug: JavaMail version 1.4ea 
INFO   | jvm 1    | 2007/09/28 18:08:45 | MediaSenderThread constructor
INFO | jvm 1 | 2007/09/28 18:08:45 | MediaSenderThread constructor finished: [EMAIL PROTECTED] 
INFO   | jvm 1    | 2007/09/28 18:08:45 | Thread=Thread[Thread-2,5,main]
INFO | jvm 1 | 2007/09/28 18:08:45 | StrongBrain AppListener: EmailManager started INFO | jvm 1 | 2007/09/28 18:08:45 | StrongBrain AppListener: WordNetAccess started 
INFO   | jvm 1    | 2007/09/28 18:08:45 | StrongBrain AppListener: EXIT
INFO | jvm 1 | 2007/09/28 18:08:57 | Sep 28, 2007 6:08:57 PM org.apache.coyote.http11.Http11BaseProtocol start INFO | jvm 1 | 2007/09/28 18:08:57 | INFO: Starting Coyote HTTP/1.1 on http-8080 INFO | jvm 1 | 2007/09/28 18:08:59 | Sep 28, 2007 6:08:59 PM org.apache.jk.common.ChannelSocket init INFO | jvm 1 | 2007/09/28 18:08:59 | INFO: JK: ajp13 listening on /0.0.0.0:8009 INFO | jvm 1 | 2007/09/28 18:08:59 | Sep 28, 2007 6:08:59 PM org.apache.jk.server.JkMain start INFO | jvm 1 | 2007/09/28 18:08:59 | INFO: Jk running ID=0 time=0/310 config=null INFO | jvm 1 | 2007/09/28 18:09:00 | Sep 28, 2007 6:09:00 PM org.apache.catalina.storeconfig.StoreLoader load INFO | jvm 1 | 2007/09/28 18:09:00 | INFO: Find registry server-registry.xml at classpath resource INFO | jvm 1 | 2007/09/28 18:09:01 | Sep 28, 2007 6:09:01 PM org.apache.catalina.startup.Catalina start 
INFO   | jvm 1    | 2007/09/28 18:09:01 | INFO: Server startup in 75137 ms

[POINT C]
INFO | jvm 1 | 2007/09/28 18:09:55 | #############BaseAction: [EMAIL PROTECTED] user=null INFO | jvm 1 | 2007/09/28 18:09:55 | Connection[data] allocated: #=1 conn=null
[POINT A] is the first entry to the StrongBrain AppListener, and it's where the exception is thrown I'll include the complete code for the StrongBrain AppListener class at the end of this message, 
but here is the relevant snippet:

       System.out.println("StrongBrain AppListener: ENTER");
       Context initialContext = new InitialContext();
       if(initialContext == null ) {
           throw new Exception("Boom - No Initial Context");
       }
Context envCtx = (Context) initialContext.lookup("java:comp/env"); String key = "jdbc" + "/" + "sb_data"; 
       DataSource ds = (DataSource)envCtx.lookup(key);
       if (ds != null ){
           DAOBaseData.setDataSource(ds);
       }
       key = "jdbc" + "/" + "sb_users";
       ds = (DataSource)envCtx.lookup(key);
       if (ds != null ){
           DAOBaseUsers.setDataSource(ds);
       }

[The code for DAOBaseData.java is also included at the end.]
[POINT B] is where it looks like a second entry is being made, and oddly, the Exception is not thrown. By the log output, it looks as if everything is ok. In particular, it looks like the requests for connections ( Connection[data] allocated: #=1 conn=...) are getting good database connections.
[POINT C] is where the first connection to the webapp is made. There, we don't get a good connection, we get null. I've attached -- at the end of this email -- the full code for DAOBaseData.java, which is where the connection is requested, 
but here is the relevant code snippet from it:

   public Connection getConnection() throws DAOException
{ Connection connection = null; if (datasource!= null) { 
         try {
           connection = datasource.getConnection();
         }
         catch (SQLException e) {
             //TODO: Log this
             String message = e.getMessage();
             System.out.println("DAOBaseUsers: "+message);
             throw new DAOException(message);
         }
       }
       connCount++;
System.out.println("Connection[users] allocated: #="+connCount + " conn="+connection); 
       return connection;
   }
As you can see, the call to getConnection which produced the last line of the log must be in a setting where the instance variable datasource was null. But there are a bunch of calls on getConnection() between [POINT B] and [POINT C] which produced valid connections, and so the value of the datasource variable must have been non-null. Combined with the apparent two entries to the webapp showing in the log, this makes me feel like there are two copies of the application running, that the [POINT B] AppListener calls occur in one copy where the datasource was correctly obtained, and the [POINT C] browser connection call occurs in the other copy of the app, corresponding to the first attempted entry to the AppListener, where the instance variable -- datasource -- has not been instantiated with a data source. 

Here is my file ~META-INF/context.xml:

 <Context debug="5" reloadable="true" crossContext="true">
<Resource name="jdbc/sb_data" auth="Container" type="javax.sql.DataSource" 
            maxActive="100" maxIdle="30" maxWait="10000"
            username="sb_normal" password="********"
            driverClassName="com.mysql.jdbc.Driver"
            url="jdbc:mysql://localhost:3306/sb_data"/>
<Resource name="jdbc/sb_users" auth="Container" type="javax.sql.DataSource" 
            maxActive="100" maxIdle="30" maxWait="10000"
            username="sb_normal" password="********"
            driverClassName="com.mysql.jdbc.Driver"
            url="jdbc:mysql://localhost:3306/sb_users"/>
 </Context>
The last item to note is that I have mysql-connector-java-3.1.14-bin.jar located in ~tomcat5/common/lib in each installation.
I'm at a loss as to what could be going on. Any ideas what I should look for? 

Thanks very much in advance,
Ken Bowen
============ DAOBaseData.java =======[DAOBaseUsers.java is a clone of this]============ 
package com.strongbrain.database;

import java.sql.Connection;
import java.sql.SQLException;

import javax.sql.DataSource;

/**
* Data Access for sb_data (sb_data.xml)
* @author Ken Bowen
*
*/
public class DAOBaseData
{
   private static DataSource datasource;
   private static int connCount = 0;
public static void setDataSource(DataSource ds){ 
System.out.println("DAOBaseData: setting datasource="+ds);
       datasource = ds;
   }
public Connection getConnection() throws DAOException { Connection connection = null; if (datasource!= null) { 
         try {
           connection = datasource.getConnection();
         }
         catch (SQLException e) {
             //TODO: Log this
             String message = e.getMessage();
             System.out.println("DAOBaseData: "+message);
             throw new DAOException(message);
         }
       }
       connCount++;
System.out.println("Connection[data] allocated: #="+connCount + " conn="+connection); 
       return connection;
   }
public void closeConnection(Connection connection) 
       throws SQLException
   {
       connection.close();
       connCount--;
       System.out.println("Connection[data] deallocated: #="+connCount);
   }
/* Management/Admin information */ private static String _standardWEBINFFolder; 
   private static String _dbSpecPath;
   private static String _standardSourceFolder;
public static void setStandardWEBINFFolder(String path){ 
       _standardWEBINFFolder = path;
       _dbSpecPath = _standardWEBINFFolder + "/sb_data.xml";
   }
   public static String getStandardWEBINFFolder(){
       return _standardWEBINFFolder;
   }
   public static String getDbSpecPath(){
       return _dbSpecPath;
   }
public static void setSrcDataFolderPath(String path){ 
       _standardSourceFolder = path;
   }
   public static String getSrcDataFolderPath(){
       return _standardSourceFolder;
   }
}
============== AppListener.java ================================================ 
package com.strongbrain.listener;

import javax.naming.Context;
import javax.naming.InitialContext;
import javax.servlet.ServletContext;
import javax.servlet.ServletContextEvent;
import javax.servlet.ServletContextListener;
import javax.sql.DataSource;

import com.strongbrain.Constants;
import com.strongbrain.actions.BaseAction;
import com.strongbrain.database.AdInfo;
import com.strongbrain.database.DAOBaseData;
import com.strongbrain.database.DAOBaseUsers;
import com.strongbrain.database.TaskIDMap;
import com.strongbrain.email.EmailManager;
import com.strongbrain.reading.StoryInfo;
import com.strongbrain.wordplay.WordNetAccess;

public class AppListener implements ServletContextListener
{

   public void contextInitialized(ServletContextEvent servletContextEvent)
   {
       try {
/* Config config = Config.getInstance(); ServletContext servletContext = cse.getServletContext(); String dbType = servletContext.getInitParameter("dbType"); 
           config.addKeyValue("dbType", dbType);
           */
System.out.println("StrongBrain AppListener: ENTER"); 
           Context initialContext = new InitialContext();
           if(initialContext == null ) {
               throw new Exception("Boom - No Initial Context");
           }
Context envCtx = (Context) initialContext.lookup("java:comp/env"); String key = "jdbc" + "/" + "sb_data"; 
           DataSource ds = (DataSource)envCtx.lookup(key);
           if (ds != null ){
               DAOBaseData.setDataSource(ds);
           }
           key = "jdbc" + "/" + "sb_users";
           ds = (DataSource)envCtx.lookup(key);
           if (ds != null ){
               DAOBaseUsers.setDataSource(ds);
           }
String sbcontextvalue = servletContextEvent.getServletContext().getInitParameter(Constants.SB_CONTEXT); 
           BaseAction.setContext(sbcontextvalue);
           Constants.setContext(sbcontextvalue);
String xmlhttptgt = servletContextEvent.getServletContext().getInitParameter(Constants.XMLHTTP_TGT); 
           BaseAction.setXMLHTTPTarget(xmlhttptgt);
String webappspath = servletContextEvent.getServletContext().getInitParameter(Constants.WEBAPPS_PATH); 
           BaseAction.setWebappsPath(webappspath);
AdInfo.instance(); 
           TaskIDMap.instance();
ServletContext servletContext = servletContextEvent.getServletContext(); String pdfPathHead = (String)servletContext.getInitParameter(Constants.PDF_PATH_HEAD); 
           StoryInfo.setPdfPathHead(pdfPathHead);
String server = (String)servletContext.getInitParameter(Constants.SMTP_SERVER); String fromAddr = (String)servletContext.getInitParameter(Constants.SMTP_FROM_ADDR); String connectPw = (String)servletContext.getInitParameter(Constants.SMTP_CONNECT_PW); String connectPortString = (String)servletContext.getInitParameter(Constants.SMTP_CONNECT_PORT); 
           int connectPort = Integer.valueOf(connectPortString).intValue();
String localHost = (String)servletContext.getInitParameter(Constants.SMTP_LOCALHOST); String authString = (String)servletContext.getInitParameter(Constants.SMTP_AUTH); boolean auth = Boolean.valueOf(authString).booleanValue(); EmailManager emMgr = EmailManager.instance(server, fromAddr, connectPw, connectPort, localHost, auth); 
System.out.println("StrongBrain AppListener: EmailManager started");
String wordnetPropfilePath = (String)servletContext.getInitParameter(Constants.WORDNET_PROPFILE_PATH); 
//            WordNetAccess.setWordnetPropfilePath(wordnetPropfilePath);
System.out.println("StrongBrain AppListener: WordNetAccess started");
         }
         catch (Exception e) {
             //TODO: log this; kill off everything...
            System.out.println("com.strongbrain Error: " + e.getMessage());
            e.printStackTrace(System.out);
         }
System.out.println("StrongBrain AppListener: EXIT"); 
   }

   public void contextDestroyed(ServletContextEvent arg0) {
       // TODO Auto-generated method stub

   }

}




---------------------------------------------------------------------
To start a new topic, e-mail: users@tomcat.apache.org
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]

Reply via email to