Subject.getPrincipal returning Null sparodically on JBoss 4.

[dfantham]

We have been Jboss 3.2.3 and Postgres 7.4.2 for sometime and have recently been going through an upgrade to Jboss 4.0.3SP1 and Postgres 8.1.2, using Postgres JDBC driver postgresql-8.1-404.jdbc3.jar.

Under the old environment, we have a very solid deployment, with no downtime (other than for regular updates to code) for about 1 year. We have just got through this upgrade and are now getting two or three very strange, and fatal errors.

Below is one of them - We have a custom object that we use extensively throughout the EJB layer on Jboss that performs a lookup to get the current principal with the request being processed. The code has worked flawlessly on Jboss 3.2.3, but now fails sparodically on Jboss 4.0.3SP1 during a user's session. The fail happens as at at the processing of getting Principals from the iterator which is empty

The code we use is as follows:

import javax.security.auth.*;
import javax.naming.*;
import java.security.*;
import org.apache.log4j.Category;
import java.util.*;

public class authInfo
{
public authInfo() { }

private Category log = Category.getInstance(getClass());

private Iterator getPrincipals()
{ //used for getting the user's username and customerID
 log.debug("getPrinciples: Getting Principles from JAAS...");
 Iterator principals = null;
 try {
 InitialContext ic = new InitialContext();
 log.debug("getPrinciples: Got initial context....");
 Subject subj = (javax.security.auth.Subject)
 ic.lookup("java:comp/env/security/subject");
 log.debug("getPrinciples: Got auth subject from context....");
 principals = subj.getPrincipals().iterator();
 } catch (Exception ex)
 {
 log.debug("getPrinciples: Error getting Principles from JAAS: " +
 ex.toString() + " -- hopefully there is details... "+
 ex.getStackTrace());
 }
 return principals;
}

public String getUserId()
{
 log.debug("getUserId: Getting UserId from JAAS...");

 Iterator principals = getPrincipals();
 log.debug("getUserId: Got principals Iterator....");
 String clientIdUserId = null;
 try {
 log.debug("getUserId: Iterating over principals....");
 if (principals.hasNext())
 {
 Principal p = (Principal) principals.next();
 if (log.isDebugEnabled())
 log.debug("getUserId: Principal: " + p.getName());
 clientIdUserId = p.getName();
 } else {
 log.debug("getUserId: Principals has no elements...");
 }
 } catch (Exception e){
 log.error("getUserId: Error Getting user Principle...." + e.toString()
 + " -- hopefully there is details... "+ e.getStackTrace());
 }
 String uid = splitPrincipal(clientIdUserId, 2);
 log.debug("getUserId: Returning userId: " + uid);
 return uid;
}
}

This is the error code that gets thrown by Jboss:

2006-01-18 13:27:12,494 DEBUG [TP-Processor6] [authInfo] getUserId: Getting UserId from JAAS...
2006-01-18 13:27:12,494 DEBUG [TP-Processor6] [authInfo] getPrinciples: Getting Principles from JAAS...
2006-01-18 13:27:12,494 DEBUG [TP-Processor6] [authInfo] getPrinciples: Got initial context....
2006-01-18 13:27:12,495 DEBUG [TP-Processor6] [authInfo] getPrinciples: Got auth subject from context....
2006-01-18 13:27:12,524 DEBUG [TP-Processor6] [authInfo] getPrinciples: Error getting Principles from JAAS: java.lang.NullPointerException -- hopefully there is details... [Ljava.lang.StackTraceElement;@912232
2006-01-18 13:27:12,524 DEBUG [TP-Processor6] [authInfo] getUserId: Got principals Iterator....
2006-01-18 13:27:12,524 DEBUG [TP-Processor6] [authInfo] getUserId: Iterating over principals....
2006-01-18 13:27:12,525 ERROR [TP-Processor6] [authInfo] getUserId: Error Getting user Principle....java.lang.NullPointerException -- hopefully there is details... [Ljava.lang.StackTraceElement;@5c3f7b
2006-01-18 13:27:12,526 INFO [TP-Processor6] [ScheduleSessionBean] ScheduleSessionBean.ejbRemove() called
2006-01-18 13:27:12,527 ERROR [TP-Processor6] [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackException in method: public abstract java.util.ArrayList ScheduleSessionRemote.scheduleExtendValidate(java.lang.String,java.lang.String,java.lang.String,long) throws java.lang.Exception,java.rmi.RemoteException, causedBy:
java.lang.NullPointerException
 at com.edgile.se.component.common.authInfo.splitPrincipal(authInfo.java:17)
 at com.edgile.se.component.common.authInfo.getUserId(authInfo.java:140)
......

[starksm64]

Enable trace level logging of the security layer in conf/log4j.xml:

 <appender name="App1Log" class="org.apache.log4j.FileAppender">
 <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
 <param name="Append" value="false"/>
 <param name="File" value="${jboss.server.home.dir}/log/app1.log"/>
 <layout class="org.apache.log4j.PatternLayout">
 <!-- Add %t to see the thread -->
 <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1},%t] %m%n"/>
 </layout>
 </appender>
...

 <!-- Enable trace level logging -->
 <category name="org.jboss.security">
 <priority value="TRACE" class="org.jboss.logging.XLevel"/>
 </category>

and show the behavior around the null subject.

[dfantham]

Scott,

here is the trace results from the "null" Principal exception. It seems to coincide with the "other" exception I am seeing which relates to getting around transactions failing on EJB and DAO querries against the DB (a Trace of these types of errors is also below (sorry about the length).

Here is the "null" principal exception trace (not we have a short JAASCacheTineout setting to allow for role updates within the system to activated pretty quickly - so the timeout is set to 30 seconds).

18:50:12,437 DEBUG [authInfo,TP-Processor5] getUserId: Getting UserId from JAAS...
18:50:12,437 DEBUG [authInfo,TP-Processor5] getPrinciples: Getting Principles from JAAS...
18:50:12,437 DEBUG [authInfo,TP-Processor5] getPrinciples: Got initial context....
18:50:12,438 DEBUG [authInfo,TP-Processor5] getPrinciples: Got auth subject from context....
18:50:12,438 DEBUG [authInfo,TP-Processor5] getUserId: Got principals Iterator....
18:50:12,438 DEBUG [authInfo,TP-Processor5] getUserId: Iterating over principals....
18:50:12,438 DEBUG [authInfo,TP-Processor5] getUserId: Principal: 20500::infsys
18:50:12,438 DEBUG [authInfo,TP-Processor5] getUserId: Returning customerId: 20500
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] logout
18:50:12,439 TRACE [ClientLoginModule,TP-Processor5] logout
18:50:12,439 TRACE [XMLLoginConfigImpl,TP-Processor5] Begin getAppConfigurationEntry(scheduleExpress), size=9
18:50:12,439 TRACE [XMLLoginConfigImpl,TP-Processor5] End getAppConfigurationEntry(scheduleExpress), authInfo=AppConfigurationEntry[]:
[0]
LoginModule Class: org.jboss.security.auth.spi.DatabaseServerLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:name=rolesQuery, value=select userRoles, 'Roles' from v_roles where principalID=?
name=principalsQuery, value=select password as passwd from v_principals where principalID=?
name=hashAlgorithm, value=MD5
name=dsJndiName, value=java:/PostgresDS
[1]
LoginModule Class: org.jboss.security.ClientLoginModule
ControlFlag: LoginModuleControlFlag: required
Options:
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] initialize, instance=@25704043
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] Password hashing activated: algorithm = MD5, encoding = BASE64, charset = {default}, callback = null, storeCallback = null
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] DatabaseServerLoginModule, dsJndiName=java:/PostgresDS
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] principalsQuery=select password as passwd from v_principals where principalID=?
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] rolesQuery=select userRoles, 'Roles' from v_roles where principalID=?
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] suspendResume=true
18:50:12,439 TRACE [DatabaseServerLoginModule,TP-Processor5] login
18:50:12,440 TRACE [TxConnectionManager,TP-Processor5] No transaction, no need to enlist: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@16efbdc[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175 handles=0 lastUse=1137638952481 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1cafecd context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3ce701 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@bdff2b txSync=null]
18:50:12,445 TRACE [TxConnectionManager,TP-Processor5] connectionClosed called mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175
18:50:12,445 TRACE [TxConnectionManager,TP-Processor5] unregisterConnection: 0 handles left
18:50:12,445 TRACE [TxConnectionManager,TP-Processor5] isManagedConnectionFree=true mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175
18:50:12,445 TRACE [TxConnectionManager,TP-Processor5] delisting org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@16efbdc[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175 handles=0 lastUse=1137638952481 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1cafecd context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3ce701 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@bdff2b txSync=null]
18:50:12,445 TRACE [DatabaseServerLoginModule,TP-Processor5] User '20500::infsys' authenticated, loginOk=true
18:50:12,445 TRACE [ClientLoginModule,TP-Processor5] Begin login
18:50:12,445 TRACE [ClientLoginModule,TP-Processor5] Obtained login: 20500::infsys, credential.class: [C
18:50:12,445 TRACE [ClientLoginModule,TP-Processor5] End login
18:50:12,445 TRACE [DatabaseServerLoginModule,TP-Processor5] commit, loginOk=true
18:50:12,446 TRACE [TxConnectionManager,TP-Processor5] No transaction, no need to enlist: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@16efbdc[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175 handles=0 lastUse=1137639012445 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1cafecd context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3ce701 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@bdff2b txSync=null]
18:50:12,464 TRACE [DatabaseServerLoginModule,TP-Processor5] Assign user to role absenceApprove
18:50:12,464 TRACE [DatabaseServerLoginModule,TP-Processor5] Assign user to role absenceApproveOwn

-------------Lots of Role Assignments - Removed to shorten Msg-------------

18:50:12,468 TRACE [DatabaseServerLoginModule,TP-Processor5] Assign user to role userModify_viewSecurity
18:50:12,468 TRACE [DatabaseServerLoginModule,TP-Processor5] Assign user to role userProfile
18:50:12,468 TRACE [DatabaseServerLoginModule,TP-Processor5] Assign user to role userSysStatus
18:50:12,468 TRACE [TxConnectionManager,TP-Processor5] connectionClosed called mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175
18:50:12,468 TRACE [TxConnectionManager,TP-Processor5] unregisterConnection: 0 handles left
18:50:12,468 TRACE [TxConnectionManager,TP-Processor5] isManagedConnectionFree=true mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175
18:50:12,468 TRACE [TxConnectionManager,TP-Processor5] delisting org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@16efbdc[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@1593175 handles=0 lastUse=1137639012445 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@1cafecd context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@3ce701 xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@bdff2b txSync=null]
18:50:12,469 TRACE [ClientLoginModule,TP-Processor5] commit, subject=Subject:
 Principal: 20500::infsys
 Principal: Roles(members:roleModify,tradeRespond,overtimeCodeModify,trainingClassCreate,specialAssignmentList,overtimeAssignUser,systemMonitor,base,userModify_updateOrgInfo,specialAssignmentViewOwn,specialAssignmentReview,coverageModify,allCustomers,userSysStatus,userModify_viewSecurity,trainingClassList,shiftPatternModify,tradeAvailableList,preApprovedAbsenceRecording,tradeDetail,tradeModify,absenceModify,roleSysStatus,tradeReversal,userModify,scheduleFilter,trainingDetail,groupList,scheduleList,positionProfileSysStatus,trainingViewOwn,tradePendingList,overtimeAvailableList,absenceApproveOwn,coverageExceptionView,coverageDateRules,manualChange,userModify_updateSecurity,userCreate,shiftPatternCreate,groupSysStatus,shiftPatternList,preApprovedTrade,groupModify,absencePendingList,specialAssignmentCancel,positionProfileCreate,userModify_viewOrgInfo,specialAssignmentAssign,userList,absenceReview,positionProfileModify,coverageAddRequirement,roleList,overtimeAssignView,scheduleAdd,roleUsers,scheduleModify,specialAssignmentAssignOwn,trainingClassAssign,positionProfileUserAssign,userModify_updatePrefs,coverageValidate,userProfile,absenceCreate,userAccess,positionProfileUserView,reportList,overtimeAssignOwn,coverageView,scheduleCopy,coveragePublish,specialAssignmentModify,trainingClassAssignCancel,trainingClassDelete,specialAssignmentDelete,overtimeRequestAssign,trainingAssignOwn,overtimeRequestList,tradeCreate,shiftList,absenceDayOfAbsenceRecording,specialAssignmentDetail,trainingReview,shiftModify,overtimeDeleteRequest,absenceDetail,reportSecurity,reports,specialAssignmentRole,specialAssignmentViewAll,tradeApprove,coverageModifyRequirement,schedulePublish,tradeView,positionProfileList,tradeApproveOwn,scheduleCoverage,absenceApprove,userModify_updatePersonal,overtimeVolunteer,scheduleView,trainingViewAll,absenceView,manualChangeView,specialAssignmentCreate,coverageCreate,systemAdmin,groupMembers,absenceReversal,roleCreate,coverageSysStatus,trainingClassModify,overtimeRemoveAssign,overtimeReview,shiftCreate,personalSchedule,userModify_viewPersonal,coverageList,overtimeRequest,tradeAccept,scheduleCreate,groupCreate,inbox,userModify_viewPrefs)

18:50:12,471 DEBUG [authInfo,TP-Processor5] getUserId: Getting CustomerId from JAAS...
18:50:12,472 DEBUG [authInfo,TP-Processor5] getPrinciples: Getting Principles from JAAS...
18:50:12,472 DEBUG [authInfo,TP-Processor5] getPrinciples: Got initial context....
18:50:12,472 DEBUG [authInfo,TP-Processor5] getPrinciples: Got auth subject from context....
18:50:12,473 DEBUG [authInfo,TP-Processor5] getPrinciples: Error getting Principles from JAAS: java.lang.NullPointerException -- hopefully there is details... [Ljava.lang.StackTraceElement;@1b38784
18:50:12,473 DEBUG [authInfo,TP-Processor5] getUserId: Got principals Iterator....
18:50:12,473 DEBUG [authInfo,TP-Processor5] getUserId: Iterating over principals....
18:50:12,476 ERROR [authInfo,TP-Processor5] getUserId: Error Getting customer Principle....java.lang.NullPointerException -- hopefully there is details... [Ljava.lang.StackTraceElement;@186256d
18:50:12,477 INFO [ScheduleSessionBean,TP-Processor5] ScheduleSessionBean.ejbRemove() called
18:50:12,477 ERROR [LogInterceptor,TP-Processor5] TransactionRolledbackException in method: public abstract java.util.ArrayList com.edgile.se.component.schedule.ScheduleSessionRemote.scheduleExtendValidate(java.lang.String,java.lang.String,java.lang.String,long) throws java.lang.Exception,java.rmi.RemoteException, causedBy:
java.lang.NullPointerException
 at com.edgile.se.component.common.authInfo.splitPrincipal(authInfo.java:17)
 at com.edgile.se.component.common.authInfo.getUserId(authInfo.java:113)
 at com.edgile.se.component.schedule.ScheduleSessionBean.customerId(ScheduleSessionBean.java:99)
 at com.edgile.se.component.schedule.ScheduleSessionBean.getSchedules(ScheduleSessionBean.java:827)
 at com.edgile.se.component.schedule.ScheduleSessionBean.scheduleAddShiftValidate(ScheduleSessionBean.java:1406)
 at com.edgile.se.component.schedule.ScheduleSessionBean.scheduleAddShiftPatternValidate(ScheduleSessionBean.java:1674)
 at com.edgile.se.component.schedule.ScheduleSessionBean.scheduleExtendValidate(ScheduleSessionBean.java:1919)
 at sun.reflect.GeneratedMethodAccessor9731.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
 at org.jboss.ejb.plugins.SecurityProxyInterceptor.invoke(SecurityProxyInterceptor.java:175)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
 at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at sun.reflect.GeneratedMethodAccessor4229.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)
 at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155)
 at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104)
 at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179)
 at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165)
 at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46)
 at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55)
 at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97)
 at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86)
 at $Proxy919.scheduleExtendValidate(Unknown Source)
 at com.edgile.se.mvc.schedule.ScheduleCopyAction.execute(ScheduleCopyAction.java:262)
 at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:421)
 at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:226)
 at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
 at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:415)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.cj.trim.trimFilter.doFilter(Unknown Source)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.PerformanceMonitorFilter.doFilter(PerformanceMonitorFilter.java:101)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.AuthFilter.doFilter(AuthFilter.java:207)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
 at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
 at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
 at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
 at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
 at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
 at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
 at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
 at java.lang.Thread.run(Thread.java:595)
18:50:12,481 ERROR [ScheduleCopyAction,TP-Processor5] javax.transaction.TransactionRolledbackException: null; nested exception is:
 java.lang.NullPointerException
18:50:12,481 INFO [ScheduleCopyAction,TP-Processor5] Leaving ScheduleCopy (268396 mills) scheduleId=df67d43f80f26d05013f54b279b12992...infsys
18:50:12,489 INFO [PerformanceMonitorFilter,TP-Processor5] Remove /app/scheduleCopy.do lock 20500SchAct for userId: infsys
18:50:12,490 INFO [PerformanceMonitorFilter,TP-Processor5] ---------------------------- PERFORMANCE MONITOR --------------------------
18:50:12,490 INFO [PerformanceMonitorFilter,TP-Processor5] Request for: /app/scheduleCopy.do from infsys::20500
18:50:12,490 INFO [PerformanceMonitorFilter,TP-Processor5] Request Started at 01/18/2006 (Wed) 18:45:43 and took 268696 millis
18:50:12,490 INFO [PerformanceMonitorFilter,TP-Processor5] ---------------------------------------------------------------------------

Just below, in another thread, a second exception was also thrown, this one was relating to a failed "Finder exception" on an CMP Entity Bean Finder method.

18:53:47,578 ERROR [RuleDefinition#findByDefinitionId,TP-Processor6] Find failed
org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552])
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:79)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:210)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:128)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCFindEntitiesCommand.execute(JDBCFindEntitiesCommand.java:40)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.findEntities(JDBCStoreManager.java:598)
 at org.jboss.ejb.plugins.CMPPersistenceManager.findEntities(CMPPersistenceManager.java:322)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.findEntities(CachedConnectionInterceptor.java:245)
 at org.jboss.ejb.EntityContainer.findLocal(EntityContainer.java:649)
 at sun.reflect.GeneratedMethodAccessor4228.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.EntityContainer$ContainerInterceptor.invokeHome(EntityContainer.java:1113)
 at org.jboss.ejb.plugins.SecurityProxyInterceptor.invokeHome(SecurityProxyInterceptor.java:150)
 at org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:90)
 at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invokeHome(EntitySynchronizationInterceptor.java:189)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invokeHome(CachedConnectionInterceptor.java:180)
 at org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:90)
 at org.jboss.ejb.plugins.EntityInstanceInterceptor.invokeHome(EntityInstanceInterceptor.java:119)
 at org.jboss.ejb.plugins.EntityLockInterceptor.invokeHome(EntityLockInterceptor.java:61)
 at org.jboss.ejb.plugins.EntityCreationInterceptor.invokeHome(EntityCreationInterceptor.java:28)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invokeHome(CallValidationInterceptor.java:41)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:110)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invokeHome(TxInterceptorCMT.java:146)
 at org.jboss.ejb.plugins.SecurityInterceptor.invokeHome(SecurityInterceptor.java:130)
 at org.jboss.ejb.plugins.LogInterceptor.invokeHome(LogInterceptor.java:121)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invokeHome(ProxyFactoryFinderInterceptor.java:93)
 at org.jboss.ejb.EntityContainer.internalInvokeHome(EntityContainer.java:508)
 at org.jboss.ejb.Container.invoke(Container.java:894)
 at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invokeHome(BaseLocalProxyFactory.java:344)
 at org.jboss.ejb.plugins.local.LocalHomeProxy.invoke(LocalHomeProxy.java:118)
 at $Proxy727.findByDefinitionId(Unknown Source)
 at com.edgile.se.component.customer.CustomerSessionBean.getRuleAndParms(CustomerSessionBean.java:1486)
 at sun.reflect.GeneratedMethodAccessor4455.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
 at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at sun.reflect.GeneratedMethodAccessor4229.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.cj.trim.trimFilter.doFilter(Unknown Source)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.PerformanceMonitorFilter.doFilter(PerformanceMonitorFilter.java:122)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.AuthFilter.doFilter(AuthFilter.java:207)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
 at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
 at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
 at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
 at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
 at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
 at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
 at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
 at java.lang.Thread.run(Thread.java:595)
Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]
 at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:331)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:462)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
 ... 141 more
18:53:47,640 ERROR [CustomerSessionBean,TP-Processor6] javax.ejb.FinderException: Find failed: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552])
18:53:47,641 ERROR [UserMessageSessionBean,TP-Processor6] get rule Inbox Messages failed: java.lang.Exception: javax.ejb.FinderException: Find failed: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552])
18:53:47,641 ERROR [UserMessage#findNewByUserPk,TP-Processor6] Find failed
org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552])
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:79)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:210)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCAbstractQueryCommand.execute(JDBCAbstractQueryCommand.java:128)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCFindEntitiesCommand.execute(JDBCFindEntitiesCommand.java:40)
 at org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreManager.findEntities(JDBCStoreManager.java:598)
 at org.jboss.ejb.plugins.CMPPersistenceManager.findEntities(CMPPersistenceManager.java:322)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.findEntities(CachedConnectionInterceptor.java:245)
 at org.jboss.ejb.EntityContainer.findLocal(EntityContainer.java:649)
 at sun.reflect.GeneratedMethodAccessor4228.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.EntityContainer$ContainerInterceptor.invokeHome(EntityContainer.java:1113)
 at org.jboss.ejb.plugins.SecurityProxyInterceptor.invokeHome(SecurityProxyInterceptor.java:150)
 at org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:90)
 at org.jboss.ejb.plugins.EntitySynchronizationInterceptor.invokeHome(EntitySynchronizationInterceptor.java:189)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invokeHome(CachedConnectionInterceptor.java:180)
 at org.jboss.ejb.plugins.AbstractInterceptor.invokeHome(AbstractInterceptor.java:90)
 at org.jboss.ejb.plugins.EntityInstanceInterceptor.invokeHome(EntityInstanceInterceptor.java:119)
 at org.jboss.ejb.plugins.EntityLockInterceptor.invokeHome(EntityLockInterceptor.java:61)
 at org.jboss.ejb.plugins.EntityCreationInterceptor.invokeHome(EntityCreationInterceptor.java:28)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invokeHome(CallValidationInterceptor.java:41)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:110)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invokeHome(TxInterceptorCMT.java:146)
 at org.jboss.ejb.plugins.SecurityInterceptor.invokeHome(SecurityInterceptor.java:130)
 at org.jboss.ejb.plugins.LogInterceptor.invokeHome(LogInterceptor.java:121)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invokeHome(ProxyFactoryFinderInterceptor.java:93)
 at org.jboss.ejb.EntityContainer.internalInvokeHome(EntityContainer.java:508)
 at org.jboss.ejb.Container.invoke(Container.java:894)
 at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invokeHome(BaseLocalProxyFactory.java:344)
 at org.jboss.ejb.plugins.local.LocalHomeProxy.invoke(LocalHomeProxy.java:118)
 at $Proxy707.findNewByUserPk(Unknown Source)
 at com.edgile.se.component.userMessage.UserMessageSessionBean.getNewMessages(UserMessageSessionBean.java:152)
 at sun.reflect.GeneratedMethodAccessor4669.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.invocation.Invocation.performCall(Invocation.java:345)
 at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:214)
 at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:149)
 at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:154)
 at org.jboss.webservice.server.ServiceEndpointInterceptor.invoke(ServiceEndpointInterceptor.java:54)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:106)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:153)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:624)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at sun.reflect.GeneratedMethodAccessor4229.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:72)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644)
 at org.jboss.invocation.local.LocalInvoker$MBeanServerAction.invoke(LocalInvoker.java:155)
 at org.jboss.invocation.local.LocalInvoker.invoke(LocalInvoker.java:104)
 at org.jboss.invocation.InvokerInterceptor.invokeLocal(InvokerInterceptor.java:179)
 at org.jboss.invocation.InvokerInterceptor.invoke(InvokerInterceptor.java:165)
 at org.jboss.proxy.TransactionInterceptor.invoke(TransactionInterceptor.java:46)
 at org.jboss.proxy.SecurityInterceptor.invoke(SecurityInterceptor.java:55)
 at org.jboss.proxy.ejb.StatelessSessionInterceptor.invoke(StatelessSessionInterceptor.java:97)
at org.jboss.proxy.ClientContainer.invoke(ClientContainer.java:86)
 at $Proxy913.getNewMessages(Unknown Source)
 at com.edgile.se.mvc.userMessage.InboxMessageCheckAction.execute(InboxMessageCheckAction.java:42)
 at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:421)
 at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:226)
 at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
 at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:397)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:697)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.cj.trim.trimFilter.doFilter(Unknown Source)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.PerformanceMonitorFilter.doFilter(PerformanceMonitorFilter.java:122)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at com.edgile.se.mvc.filter.AuthFilter.doFilter(AuthFilter.java:207)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
 at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
 at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
 at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
 at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
 at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
 at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
 at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
 at java.lang.Thread.run(Thread.java:595)
Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]
 at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:331)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:462)
 at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
 at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
 ... 105 more
18:53:47,648 ERROR [UserMessageSessionBean,TP-Processor6] javax.ejb.FinderException: Find failed: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=demo.scheduleexpress.com/9552, BranchQual=, localId=9552])

[starksm64]

There are no TRACE level messages from the SecurityAssociation here so I can't see what is going on between the ClientLoginModule and the point where the subject principals are accessed.

[dfantham]

I am not sure what the do then??? The output you see is exactly what is thrown, so I am now at a loss to explain.

A couple of observations from our testing here that may help (or not!):

1. We are using JDK 1.5.0_06 from Sun. We backed this back to 1.4.2_06 (Jrockit From Bea) and tested again. All of our "Finder" based exceptions went away (See the stack track from the finder exceptions is the first post). I have not idea why backing down the JVM would cause that.

2. With the old JVM in place (1.4.2_06) I then tried changing the JAASCacheTimeout settings from the current setting of 30 to 300 seconds. Most of the getPrincipal null pointers also seemed to disappear also.

So Why would the JAAS cached timeout affect/cause NullPointers?

and, why would change the JVM back to an older version cause all of the finder exceptions to go away?

None of this makes sence unless I am missing something simple in our config/deployment.

[starksm64]

The finder exceptions are noise in terms of the Subject issue so seperate it out. Until you can get trace level messages from the SecurityAssociation class I can't help with this issue. You are sure this is a 4.0.3SP1 release and not 4.0.3?