0 Replies Latest reply on Apr 29, 2014 8:16 AM by mtarkowski

ERROR - exception occurred during first invocation

mtarkowski Apr 29, 2014 8:16 AM

Hello everyone,

I'm getting the belo random error and I hope someone has an idea what is causing it. The error occurs randomly on multiple servers with a fresh install of JBoss.

Thank you in advance for any suggestions.

=========================================================================

JBoss Bootstrap Environment

JBOSS_HOME: /local/Kony/KonyOneServer/jboss_jms

JAVA: /usr/java/jdk1.6.0_35/bin/java

JAVA_OPTS: -Dprogram.name=run.sh -server -Xms512M -Xmx512M -XX:MaxPermSize=512M -Djava.awt.headless=true -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/local/Kony/KonyOneServer/logs/heapdumps/jms -Dnode.no=1 -Dsechtno=443 -Dmiddleware.home=/local/Kony/KonyOneServer/install -Dnet.spy.log.LoggerImpl=net.spy.memcached.compat.log.Log4JLogger -Dderby.system.home=/local/Kony/KonyOneServer/install/derby/1 -Djboss.service.binding.set=ports-default -Djava.net.preferIPv4Stack=true

CLASSPATH: /local/Kony/KonyOneServer/jboss_jms/bin/run.jar:/usr/java/jdk1.6.0_35/lib/tools.jar

=========================================================================

12:21:38,705 INFO [ServerImpl] Starting JBoss (Microcontainer)...

12:21:38,714 INFO [ServerImpl] Release ID: JBoss [The Oracle] 5.1.0.GA (build: SVNTag=JBoss_5_1_0_GA date=200905221053)

12:21:38,714 INFO [ServerImpl] Bootstrap URL: null

12:21:38,714 INFO [ServerImpl] Home Dir: /local/Kony/KonyOneServer/jboss_jms

12:21:38,714 INFO [ServerImpl] Home URL: file:/local/Kony/KonyOneServer/jboss_jms/

12:21:38,715 INFO [ServerImpl] Library URL: file:/local/Kony/KonyOneServer/jboss_jms/lib/

12:21:38,715 INFO [ServerImpl] Patch URL: null

12:21:38,716 INFO [ServerImpl] Common Base URL: file:/local/Kony/KonyOneServer/jboss_jms/common/

12:21:38,716 INFO [ServerImpl] Common Library URL: file:/local/Kony/KonyOneServer/jboss_jms/common/lib/

12:21:38,716 INFO [ServerImpl] Server Name: default

12:21:38,716 INFO [ServerImpl] Server Base Dir: /local/Kony/KonyOneServer/jboss_jms/server

12:21:38,716 INFO [ServerImpl] Server Base URL: file:/local/Kony/KonyOneServer/jboss_jms/server/

12:21:38,717 INFO [ServerImpl] Server Config URL: file:/local/Kony/KonyOneServer/jboss_jms/server/default/conf/

12:21:38,717 INFO [ServerImpl] Server Home Dir: /local/Kony/KonyOneServer/jboss_jms/server/default

12:21:38,717 INFO [ServerImpl] Server Home URL: file:/local/Kony/KonyOneServer/jboss_jms/server/default/

12:21:38,717 INFO [ServerImpl] Server Data Dir: /local/Kony/KonyOneServer/jboss_jms/server/default/data

12:21:38,718 INFO [ServerImpl] Server Library URL: file:/local/Kony/KonyOneServer/jboss_jms/server/default/lib/

12:21:38,718 INFO [ServerImpl] Server Log Dir: /local/Kony/KonyOneServer/jboss_jms/server/default/log

12:21:38,718 INFO [ServerImpl] Server Native Dir: /local/Kony/KonyOneServer/jboss_jms/server/default/tmp/native

12:21:38,718 INFO [ServerImpl] Server Temp Dir: /local/Kony/KonyOneServer/jboss_jms/server/default/tmp

12:21:38,718 INFO [ServerImpl] Server Temp Deploy Dir: /local/Kony/KonyOneServer/jboss_jms/server/default/tmp/deploy

12:21:39,842 INFO [ServerImpl] Starting Microcontainer, bootstrapURL=file:/local/Kony/KonyOneServer/jboss_jms/server/default/conf/bootstrap.xml

12:21:40,610 INFO [VFSCacheFactory] Initializing VFSCache [org.jboss.virtual.plugins.cache.CombinedVFSCache]

12:21:40,612 INFO [VFSCacheFactory] Using VFSCache [CombinedVFSCache[real-cache: null]]

12:21:40,880 INFO [CopyMechanism] VFS temp dir: /local/Kony/KonyOneServer/jboss_jms/server/default/tmp

12:21:40,881 INFO [ZipEntryContext] VFS force nested jars copy-mode is enabled.

12:21:42,804 INFO [ServerInfo] Java version: 1.6.0_35,Sun Microsystems Inc.

12:21:42,805 INFO [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_35-b10)

12:21:42,805 INFO [ServerInfo] Java VM: Java HotSpot(TM) 64-Bit Server VM 20.10-b01,Sun Microsystems Inc.

12:21:42,805 INFO [ServerInfo] OS-System: Linux 2.6.32-431.11.2.el6.x86_64,amd64

12:21:42,807 INFO [ServerInfo] VM arguments: -Dprogram.name=run.sh -Xms512M -Xmx512M -XX:MaxPermSize=512M -Djava.awt.headless=true -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/local/Kony/KonyOneServer/logs/heapdumps/jms -Dnode.no=1 -Dsechtno=443 -Dmiddleware.home=/local/Kony/KonyOneServer/install -Dnet.spy.log.LoggerImpl=net.spy.memcached.compat.log.Log4JLogger -Dderby.system.home=/local/Kony/KonyOneServer/install/derby/1 -Djboss.service.binding.set=ports-default -Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/local/Kony/KonyOneServer/jboss_jms/lib/endorsed

12:21:42,884 INFO [JMXKernel] Legacy JMX core initialized

12:21:46,225 INFO [ProfileServiceBootstrap] Loading profile: ProfileKey@2d6acad2[domain=default, server=default, name=default]

28 Apr 2014 12:21:49,176 INFO [WebService] Using RMI server codebase: http://10.105.70.31:8083/

28 Apr 2014 12:21:57,398 INFO [NativeServerConfig] JBoss Web Services - Stack Native Core

28 Apr 2014 12:21:57,403 INFO [NativeServerConfig] 3.1.2.GA

28 Apr 2014 12:21:58,040 INFO [AttributeCallbackItem] Owner callback not implemented.

28 Apr 2014 12:21:59,374 INFO [LogNotificationListener] Adding notification listener for logging mbean "jboss.system:service=Logging,type=Log4jService" to server org.jboss.mx.server.MBeanServerImpl@303ec561[ defaultDomain='jboss' ]

28 Apr 2014 12:22:10,886 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@1633572072{vfsfile:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/profileservice-secured.jar/}

28 Apr 2014 12:22:10,890 INFO [Ejb3DependenciesDeployer] Encountered deployment AbstractVFSDeploymentContext@1633572072{vfsfile:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/profileservice-secured.jar/}

28 Apr 2014 12:22:12,365 INFO [JMXConnectorServerService] JMX Connector server: service:jmx:rmi://10.105.70.31/jndi/rmi://10.105.70.31:1090/jmxconnector

28 Apr 2014 12:22:12,632 INFO [MailService] Mail Service bound to java:/Mail

28 Apr 2014 12:22:14,709 WARN [JBossASSecurityMetadataStore] WARNING! POTENTIAL SECURITY RISK. It has been detected that the MessageSucker component which sucks messages from one node to another has not had its password changed from the installation default. Please see the JBoss Messaging user guide for instructions on how to do this.

28 Apr 2014 12:22:14,722 WARN [AnnotationCreator] No ClassLoader provided, using TCCL: org.jboss.managed.api.annotation.ManagementComponent

28 Apr 2014 12:22:14,816 WARN [AnnotationCreator] No ClassLoader provided, using TCCL: org.jboss.managed.api.annotation.ManagementComponent

28 Apr 2014 12:22:14,909 INFO [TransactionManagerService] JBossTS Transaction Service (JTA version - tag:JBOSSTS_4_6_1_GA) - JBoss Inc.

28 Apr 2014 12:22:14,910 INFO [TransactionManagerService] Setting up property manager MBean and JMX layer

28 Apr 2014 12:22:15,185 INFO [TransactionManagerService] Initializing recovery manager

28 Apr 2014 12:22:15,363 INFO [TransactionManagerService] Recovery manager configured

28 Apr 2014 12:22:15,363 INFO [TransactionManagerService] Binding TransactionManager JNDI Reference

28 Apr 2014 12:22:15,410 INFO [TransactionManagerService] Starting transaction recovery manager

28 Apr 2014 12:22:16,045 INFO [AprLifecycleListener] The Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/jdk1.6.0_35/jre/lib/amd64/server:/usr/java/jdk1.6.0_35/jre/lib/amd64:/usr/java/jdk1.6.0_35/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib

28 Apr 2014 12:22:16,131 INFO [Http11Protocol] Initializing Coyote HTTP/1.1 on http-10.105.70.31-9091

28 Apr 2014 12:22:16,165 INFO [StandardService] Starting service jboss.web

28 Apr 2014 12:22:16,172 INFO [StandardEngine] Starting Servlet Engine: JBoss Web/2.1.3.GA

28 Apr 2014 12:22:16,281 INFO [Catalina] Server startup in 145 ms

28 Apr 2014 12:22:16,327 INFO [TomcatDeployment] deploy, ctxPath=/web-console

28 Apr 2014 12:22:17,453 INFO [TomcatDeployment] deploy, ctxPath=/jbossws

28 Apr 2014 12:22:17,470 INFO [TomcatDeployment] deploy, ctxPath=/invoker

28 Apr 2014 12:22:17,543 INFO [RARDeployment] Required license terms exist, view vfszip:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/jboss-local-jdbc.rar/META-INF/ra.xml

28 Apr 2014 12:22:17,568 INFO [RARDeployment] Required license terms exist, view vfszip:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/jboss-xa-jdbc.rar/META-INF/ra.xml

28 Apr 2014 12:22:17,612 INFO [RARDeployment] Required license terms exist, view vfszip:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/jms-ra.rar/META-INF/ra.xml

28 Apr 2014 12:22:17,646 INFO [RARDeployment] Required license terms exist, view vfszip:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/mail-ra.rar/META-INF/ra.xml

28 Apr 2014 12:22:17,683 INFO [RARDeployment] Required license terms exist, view vfszip:/local/Kony/KonyOneServer/jboss_jms/server/default/deploy/quartz-ra.rar/META-INF/ra.xml

28 Apr 2014 12:22:17,813 INFO [SimpleThreadPool] Job execution threads will use class loader of thread: main

28 Apr 2014 12:22:17,876 INFO [QuartzScheduler] Quartz Scheduler v.1.5.2 created.

28 Apr 2014 12:22:17,878 INFO [RAMJobStore] RAMJobStore initialized.

28 Apr 2014 12:22:17,883 INFO [StdSchedulerFactory] Quartz scheduler 'DefaultQuartzScheduler' initialized from default resource file in Quartz package: 'quartz.properties'

28 Apr 2014 12:22:17,883 INFO [StdSchedulerFactory] Quartz scheduler version: 1.5.2

28 Apr 2014 12:22:17,883 INFO [QuartzScheduler] Scheduler DefaultQuartzScheduler_$_NON_CLUSTERED started.

28 Apr 2014 12:22:17,960 INFO [DerbyDatabase] starting derby jdbc:derby:/local/Kony/KonyOneServer/jboss_jms/server/default/data/derby/default;create=true

28 Apr 2014 12:22:18,934 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' to JNDI name 'java:DefaultDS'

28 Apr 2014 12:22:21,685 INFO [ServerPeer] JBoss Messaging 1.4.3.GA server [0] started

28 Apr 2014 12:22:21,776 WARN [ConnectionFactory] Value of clientLeasePeriod at 0 seems low. Normal values are >= 5000

28 Apr 2014 12:22:21,806 INFO [ConnectionFactory] Connector bisocket://10.105.70.31:4457 has lease disabled

28 Apr 2014 12:22:21,806 INFO [ConnectionFactory] org.jboss.jms.server.connectionfactory.ConnectionFactory@2c16499c started

28 Apr 2014 12:22:21,848 INFO [QueueService] Queue[/queue/DLQ] started, fullSize=200000, pageSize=2000, downCacheSize=2000

28 Apr 2014 12:22:21,849 WARN [ConnectionFactory] Value of clientLeasePeriod at 0 seems low. Normal values are >= 5000

28 Apr 2014 12:22:21,855 INFO [ConnectionFactory] Connector bisocket://10.105.70.31:4457 has lease disabled

28 Apr 2014 12:22:21,855 INFO [ConnectionFactory] org.jboss.jms.server.connectionfactory.ConnectionFactory@a50243d started

28 Apr 2014 12:22:21,859 WARN [ConnectionFactory] Value of clientLeasePeriod at 0 seems low. Normal values are >= 5000

28 Apr 2014 12:22:21,860 INFO [ConnectionFactoryJNDIMapper] supportsFailover attribute is true on connection factory: jboss.messaging.connectionfactory:service=ClusteredConnectionFactory but post office is non clustered. So connection factory will *not* support failover

28 Apr 2014 12:22:21,860 INFO [ConnectionFactoryJNDIMapper] supportsLoadBalancing attribute is true on connection factory: jboss.messaging.connectionfactory:service=ClusteredConnectionFactory but post office is non clustered. So connection factory will *not* support load balancing

28 Apr 2014 12:22:21,861 INFO [ConnectionFactory] Connector bisocket://10.105.70.31:4457 has lease disabled

28 Apr 2014 12:22:21,862 INFO [ConnectionFactory] org.jboss.jms.server.connectionfactory.ConnectionFactory@4bb8e77c started

28 Apr 2014 12:22:21,866 INFO [QueueService] Queue[/queue/ExpiryQueue] started, fullSize=200000, pageSize=2000, downCacheSize=2000

28 Apr 2014 12:22:21,873 INFO [TopicService] Topic[/topic/KonyLogTopic] started, fullSize=200000, pageSize=2000, downCacheSize=2000

28 Apr 2014 12:22:21,968 INFO [ConnectionFactoryBindingService] Bound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' to JNDI name 'java:JmsXA'

28 Apr 2014 12:22:22,323 INFO [JBossASKernel] Created KernelDeployment for: profileservice-secured.jar

28 Apr 2014 12:22:22,325 INFO [JBossASKernel] installing bean: jboss.j2ee:jar=profileservice-secured.jar,name=SecureProfileService,service=EJB3

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] with dependencies:

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] and demands:

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] jndi:SecureManagementView/remote-org.jboss.deployers.spi.management.ManagementView

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] jboss.ejb:service=EJBTimerService

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] and supplies:

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] Class:org.jboss.profileservice.spi.ProfileService

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] jndi:SecureProfileService/remote

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] jndi:SecureProfileService/remote-org.jboss.profileservice.spi.ProfileService

28 Apr 2014 12:22:22,326 INFO [JBossASKernel] Added bean(jboss.j2ee:jar=profileservice-secured.jar,name=SecureProfileService,service=EJB3) to KernelDeployment of: profileservice-secured.jar

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] installing bean: jboss.j2ee:jar=profileservice-secured.jar,name=SecureDeploymentManager,service=EJB3

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] with dependencies:

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] and demands:

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] jboss.ejb:service=EJBTimerService

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] and supplies:

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] jndi:SecureDeploymentManager/remote-org.jboss.deployers.spi.management.deploy.DeploymentManager

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] Class:org.jboss.deployers.spi.management.deploy.DeploymentManager

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] jndi:SecureDeploymentManager/remote

28 Apr 2014 12:22:22,327 INFO [JBossASKernel] Added bean(jboss.j2ee:jar=profileservice-secured.jar,name=SecureDeploymentManager,service=EJB3) to KernelDeployment of: profileservice-secured.jar

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] installing bean: jboss.j2ee:jar=profileservice-secured.jar,name=SecureManagementView,service=EJB3

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] with dependencies:

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] and demands:

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] jboss.ejb:service=EJBTimerService

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] and supplies:

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] jndi:SecureManagementView/remote-org.jboss.deployers.spi.management.ManagementView

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] Class:org.jboss.deployers.spi.management.ManagementView

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] jndi:SecureManagementView/remote

28 Apr 2014 12:22:22,328 INFO [JBossASKernel] Added bean(jboss.j2ee:jar=profileservice-secured.jar,name=SecureManagementView,service=EJB3) to KernelDeployment of: profileservice-secured.jar

28 Apr 2014 12:22:22,341 INFO [EJB3EndpointDeployer] Deploy AbstractBeanMetaData@70f88a49{name=jboss.j2ee:jar=profileservice-secured.jar,name=SecureProfileService,service=EJB3_endpoint bean=org.jboss.ejb3.endpoint.deployers.impl.EndpointImpl properties=[container] constructor=null autowireCandidate=true}

28 Apr 2014 12:22:22,341 INFO [EJB3EndpointDeployer] Deploy AbstractBeanMetaData@6130dd8e{name=jboss.j2ee:jar=profileservice-secured.jar,name=SecureDeploymentManager,service=EJB3_endpoint bean=org.jboss.ejb3.endpoint.deployers.impl.EndpointImpl properties=[container] constructor=null autowireCandidate=true}

28 Apr 2014 12:22:22,345 INFO [EJB3EndpointDeployer] Deploy AbstractBeanMetaData@32af84d3{name=jboss.j2ee:jar=profileservice-secured.jar,name=SecureManagementView,service=EJB3_endpoint bean=org.jboss.ejb3.endpoint.deployers.impl.EndpointImpl properties=[container] constructor=null autowireCandidate=true}

28 Apr 2014 12:22:22,707 INFO [SessionSpecContainer] Starting jboss.j2ee:jar=profileservice-secured.jar,name=SecureDeploymentManager,service=EJB3

28 Apr 2014 12:22:22,718 INFO [EJBContainer] STARTED EJB: org.jboss.profileservice.ejb.SecureDeploymentManager ejbName: SecureDeploymentManager

28 Apr 2014 12:22:22,768 INFO [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

SecureDeploymentManager/remote - EJB3.x Default Remote Business Interface

SecureDeploymentManager/remote-org.jboss.deployers.spi.management.deploy.DeploymentManager - EJB3.x Remote Business Interface

28 Apr 2014 12:22:22,899 INFO [SessionSpecContainer] Starting jboss.j2ee:jar=profileservice-secured.jar,name=SecureManagementView,service=EJB3

28 Apr 2014 12:22:22,900 INFO [EJBContainer] STARTED EJB: org.jboss.profileservice.ejb.SecureManagementView ejbName: SecureManagementView

28 Apr 2014 12:22:22,914 INFO [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

SecureManagementView/remote - EJB3.x Default Remote Business Interface

SecureManagementView/remote-org.jboss.deployers.spi.management.ManagementView - EJB3.x Remote Business Interface

28 Apr 2014 12:22:22,983 INFO [SessionSpecContainer] Starting jboss.j2ee:jar=profileservice-secured.jar,name=SecureProfileService,service=EJB3

28 Apr 2014 12:22:22,984 INFO [EJBContainer] STARTED EJB: org.jboss.profileservice.ejb.SecureProfileServiceBean ejbName: SecureProfileService

28 Apr 2014 12:22:23,020 INFO [JndiSessionRegistrarBase] Binding the following Entries in Global JNDI:

SecureProfileService/remote - EJB3.x Default Remote Business Interface

SecureProfileService/remote-org.jboss.profileservice.spi.ProfileService - EJB3.x Remote Business Interface

28 Apr 2014 12:22:23,210 INFO [TomcatDeployment] deploy, ctxPath=/admin-console

28 Apr 2014 12:22:23,342 INFO [config] Initializing Mojarra (1.2_12-b01-FCS) for context '/admin-console'

28 Apr 2014 12:22:26,660 INFO [TomcatDeployment] deploy, ctxPath=/

28 Apr 2014 12:22:26,744 INFO [TomcatDeployment] deploy, ctxPath=/jmx-console

28 Apr 2014 12:22:27,019 INFO [Http11Protocol] Starting Coyote HTTP/1.1 on http-10.105.70.31-9091

28 Apr 2014 12:22:27,055 INFO [ServerImpl] JBoss (Microcontainer) [5.1.0.GA (build: SVNTag=JBoss_5_1_0_GA date=200905221053)] Started in 48s:334ms

29 Apr 2014 06:30:55,768 ERROR [ServerThread] WorkerThread#0[10.105.70.31:47989] exception occurred during first invocation

java.net.SocketTimeoutException: Read timed out

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.read(SocketInputStream.java:129)

at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)

at java.io.BufferedInputStream.read(BufferedInputStream.java:237)

at java.io.FilterInputStream.read(FilterInputStream.java:66)

at org.jboss.remoting.transport.socket.ServerThread.readVersion(ServerThread.java:1038)

at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:673)

at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:524)

at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:232)

29 Apr 2014 06:33:02,129 ERROR [ServerThread] WorkerThread#0[10.105.70.31:48119] exception occurred during first invocation