4 Replies Latest reply on Dec 4, 2006 7:51 AM by lgsw_sam

    Problem with writing JCA adapter

    lgsw_sam

      Hi!
      I am running
      JBoss 4.0.5.GA with ejb3
      Java 1.5.0.09
      and having some problems trying to get my adapter to work.

      I do get connections but after 21min from closing last connection on my test application JBossManagedConnectionPool is trying to destroy 2 timedout connections. That causes IOException because those connections have been closed previously...

      It seems that my connections are created, added to the pool and event listeners are created. And when I call close(), CONNECTION_CLOSED event is raised and connection returned to pool but removeConnectionEventListener() is not called.

      Could this be causing these exeptions?

      If you need specific codes I am happy to post them here. For now I don't know where the problem is and didn't want to put all the codes here.

      Here is my server log from where the server is started and I call TestBean to the point where connections should be closed and IOException occurs.

      
      2006-11-30 13:02:11,001 INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel) [4.0.5.GA (build: CVSTag=Branch_4_0 date=200611270730)] Started in 1m:20s:482ms
       2006-11-30 13:02:56,000 DEBUG [org.jboss.remoting.transport.socket.ServerThread] beginning dorun
       2006-11-30 13:02:56,172 TRACE [org.jboss.tm.TransactionImpl] Created new instance for tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14]
       2006-11-30 13:02:56,172 TRACE [org.jboss.tm.TxManager] began tx: TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14]
       2006-11-30 13:02:56,219 INFO [STDOUT] TestBean.doSomething kutsuttu : jmo
       2006-11-30 13:02:56,219 DEBUG [fi.logiasoftware.jca.adapter.GenericConnectionFactoryImpl] GenericResource getConnection(GenericConnectionRequestInfo)
       2006-11-30 13:02:56,219 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.hashCode()
       2006-11-30 13:02:56,219 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.equals( fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory@4b29cf )
       2006-11-30 13:02:56,219 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] subject: null
       2006-11-30 13:02:56,219 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: registering pool with interval 900000 old interval: 9223372036854775807
       2006-11-30 13:02:56,219 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: about to notify thread: old next: 1164885026219, new next: 1164885026219
       2006-11-30 13:02:56,219 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] ManagedConnection createManagedConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:02:56,234 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] GenericManagedConnection(ManagedConnectionFactory)
       2006-11-30 13:02:56,234 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:02:56,312 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] connect(GenericConnectionRequestInfo)
       2006-11-30 13:02:56,312 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Connecting to FTP server: wbs.software.logia.fi 21
       2006-11-30 13:02:56,437 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] setConnection(AbstractProtocolHandler)
       2006-11-30 13:02:56,437 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] addConnectionEventListener(ConnectionEventListener)
       2006-11-30 13:02:56,437 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying new ManagedConnection: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@b41541[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 handles=0 lastUse=1164884576437 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:02:56,437 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@b41541[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 handles=0 lastUse=1164884576437 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [1/19/20]
       2006-11-30 13:02:56,437 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Object getConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:02:56,453 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] GenericResourceImpl(AbstractProtocolHandler, GenericManagedConnection)
       2006-11-30 13:02:56,453 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Returning XMPPResource=fi.logiasoftware.jca.adapter.GenericResourceImpl@1e5052b
       2006-11-30 13:02:56,453 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] registering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, connection : fi.logiasoftware.jca.adapter.GenericResourceImpl@1e5052b, key: null
       2006-11-30 13:02:56,453 INFO [STDOUT] 1---------TestBean1 ID : 1 user : jmo :
       2006-11-30 13:03:16,452 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] AbstractProtocolHandler getHandler()
       2006-11-30 13:03:16,452 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] AbstractProtocolHandler getHandler()
       2006-11-30 13:03:16,734 INFO [STDOUT] TestBean2.test kutsuttu : sam
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericConnectionFactoryImpl] GenericResource getConnection(GenericConnectionRequestInfo)
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.hashCode()
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.equals( fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory@4b29cf )
       2006-11-30 13:03:16,734 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] subject: null
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] ManagedConnection createManagedConnection(Subject, ConnectionRequestInfo)-----
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] GenericManagedConnection(ManagedConnectionFactory)
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] connect(GenericConnectionRequestInfo)
       2006-11-30 13:03:16,734 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Connecting to FTP server: wbs.software.logia.fi 21
       2006-11-30 13:03:16,749 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] setConnection(AbstractProtocolHandler)
       2006-11-30 13:03:16,749 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] addConnectionEventListener(ConnectionEventListener)
       2006-11-30 13:03:16,749 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying new ManagedConnection: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@18e862c[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d handles=0 lastUse=1164884596749 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:03:16,749 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@18e862c[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d handles=0 lastUse=1164884596749 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [2/18/20]
       2006-11-30 13:03:16,749 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Object getConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:03:16,749 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] GenericResourceImpl(AbstractProtocolHandler, GenericManagedConnection)
       2006-11-30 13:03:16,749 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Returning XMPPResource=fi.logiasoftware.jca.adapter.GenericResourceImpl@1156508
       2006-11-30 13:03:16,749 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] registering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, connection : fi.logiasoftware.jca.adapter.GenericResourceImpl@1156508, key: null
       2006-11-30 13:03:16,749 INFO [STDOUT] 2----------TestBean2 ID : 2 user : sam :
       2006-11-30 13:03:26,749 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] AbstractProtocolHandler getHandler()
       2006-11-30 13:03:26,765 INFO [STDOUT] TestBean4.test kutsuttu : jmo
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericConnectionFactoryImpl] GenericResource getConnection(GenericConnectionRequestInfo)
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.hashCode()
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.equals( fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory@4b29cf )
       2006-11-30 13:03:26,765 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] subject: null
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] ManagedConnection createManagedConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] GenericManagedConnection(ManagedConnectionFactory)
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] connect(GenericConnectionRequestInfo)
       2006-11-30 13:03:26,765 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Connecting to FTP server: wbs.software.logia.fi 21
       2006-11-30 13:03:26,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] setConnection(AbstractProtocolHandler)
       2006-11-30 13:03:26,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] addConnectionEventListener(ConnectionEventListener)
       2006-11-30 13:03:26,780 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying new ManagedConnection: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@1fa8988[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 handles=0 lastUse=1164884606780 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:03:26,780 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@1fa8988[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 handles=0 lastUse=1164884606780 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [3/17/20]
       2006-11-30 13:03:26,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Object getConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:03:26,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] GenericResourceImpl(AbstractProtocolHandler, GenericManagedConnection)
       2006-11-30 13:03:26,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Returning XMPPResource=fi.logiasoftware.jca.adapter.GenericResourceImpl@1044daf
       2006-11-30 13:03:26,780 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] registering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, connection : fi.logiasoftware.jca.adapter.GenericResourceImpl@1044daf, key: null
       2006-11-30 13:03:26,780 INFO [STDOUT] 3-----------Testbean4 ID : 1 user : jmo :
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] AbstractProtocolHandler getHandler()
       2006-11-30 13:03:46,780 INFO [STDOUT] Suljetaan TestBean4 resource
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] close()
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] About to close resource fi.logiasoftware.jca.adapter.GenericResourceImpl@1044daf using mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] close(GenericResourceImpl)
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] Object getAssociatedObject()
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 closing=fi.logiasoftware.jca.adapter.GenericResourceImpl@1044daf impl.associatedObject=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] connectionClosed(ConnectionEvent)
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] notifyConnectionEvent(ConnectionEvent)
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] CONNECTION CLOSED
       2006-11-30 13:03:46,780 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] unregistering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, object: fi.logiasoftware.jca.adapter.GenericResourceImpl@1044daf, key: null
       2006-11-30 13:03:46,780 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] unregisterConnection: 0 handles left
       2006-11-30 13:03:46,780 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@1fa8988[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 handles=0 lastUse=1164884606780 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] invalidate()
       2006-11-30 13:03:46,780 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] setValid(boolean)
       2006-11-30 13:03:46,780 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@1fa8988[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 handles=0 lastUse=1164884626780 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [2/18/20]
       2006-11-30 13:03:46,780 TRACE [org.jboss.tm.TxManager] tx timeout is now: 300s
       2006-11-30 13:04:06,795 INFO [STDOUT] Suljetaan TestBean2 resource
       2006-11-30 13:04:06,795 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] close()
       2006-11-30 13:04:06,795 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] About to close resource fi.logiasoftware.jca.adapter.GenericResourceImpl@1156508 using mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d
       2006-11-30 13:04:06,795 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] close(GenericResourceImpl)
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] Object getAssociatedObject()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d closing=fi.logiasoftware.jca.adapter.GenericResourceImpl@1156508 impl.associatedObject=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] connectionClosed(ConnectionEvent)
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] notifyConnectionEvent(ConnectionEvent)
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] CONNECTION CLOSED
       2006-11-30 13:04:06,811 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] unregistering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, object: fi.logiasoftware.jca.adapter.GenericResourceImpl@1156508, key: null
       2006-11-30 13:04:06,811 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] unregisterConnection: 0 handles left
       2006-11-30 13:04:06,811 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@18e862c[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d handles=0 lastUse=1164884596749 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] invalidate()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] setValid(boolean)
       2006-11-30 13:04:06,811 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@18e862c[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d handles=0 lastUse=1164884646811 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [1/19/20]
       2006-11-30 13:04:06,811 TRACE [org.jboss.tm.TxManager] tx timeout is now: 300s
       2006-11-30 13:04:06,811 INFO [STDOUT] TestBean3.test kutsuttu : jmo
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericConnectionFactoryImpl] GenericResource getConnection(GenericConnectionRequestInfo)
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.hashCode()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] GManagedConnectionFactory.equals( fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory@4b29cf )
       2006-11-30 13:04:06,811 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] subject: null
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] MATCHMANAGEDCONNECTIONS ManagedConnection matchManagedConnections(Set, Subject, ConnectionRequestInfo)
       2006-11-30 13:04:06,811 INFO [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] connections: 1
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] AbstractProtocolHandler getConnection()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] Matching 3 with 2
       2006-11-30 13:04:06,811 INFO [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] Ei match..
       2006-11-30 13:04:06,811 WARN [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Destroying connection that could not be successfully matched: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@18e862c[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d handles=0 lastUse=1164884646811 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] destroy()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] closing fi.logiasoftware.jca.handlers.FTPProtocolHandler@825459 for fi.logiasoftware.jca.adapter.GenericManagedConnection@ab58d
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] disconnect()
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] boolean isConnected()
       2006-11-30 13:04:06,811 INFO [fi.logiasoftware.jca.handlers.FTPProtocolHandler] this.isConnected?? : true
       2006-11-30 13:04:06,811 INFO [STDOUT] Disconnect connected : true
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Disconnecting from FTP server: wbs.software.logia.fi 21
       2006-11-30 13:04:06,811 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] MATCHMANAGEDCONNECTIONS ManagedConnection matchManagedConnections(Set, Subject, ConnectionRequestInfo)
       2006-11-30 13:04:06,826 INFO [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] connections: 1
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] AbstractProtocolHandler getConnection()
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] Matching 3 with 1
       2006-11-30 13:04:06,826 INFO [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] Ei match..
       2006-11-30 13:04:06,826 WARN [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Destroying connection that could not be successfully matched: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@1fa8988[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6 handles=0 lastUse=1164884626780 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] destroy()
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] closing fi.logiasoftware.jca.handlers.FTPProtocolHandler@6fb3d6 for fi.logiasoftware.jca.adapter.GenericManagedConnection@15b44d6
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] disconnect()
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] boolean isConnected()
       2006-11-30 13:04:06,826 INFO [fi.logiasoftware.jca.handlers.FTPProtocolHandler] this.isConnected?? : true
       2006-11-30 13:04:06,826 INFO [STDOUT] Disconnect connected : true
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Disconnecting from FTP server: wbs.software.logia.fi 21
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnectionFactory] ManagedConnection createManagedConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] GenericManagedConnection(ManagedConnectionFactory)
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] connect(GenericConnectionRequestInfo)
       2006-11-30 13:04:06,826 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Connecting to FTP server: wbs.software.logia.fi 21
       2006-11-30 13:04:06,842 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] setConnection(AbstractProtocolHandler)
       2006-11-30 13:04:06,842 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] addConnectionEventListener(ConnectionEventListener)
       2006-11-30 13:04:06,842 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying new ManagedConnection: org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@187a8e0[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc handles=0 lastUse=1164884646842 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:06,842 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@187a8e0[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc handles=0 lastUse=1164884646842 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [2/18/20]
       2006-11-30 13:04:06,842 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Object getConnection(Subject, ConnectionRequestInfo)
       2006-11-30 13:04:06,842 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] GenericResourceImpl(AbstractProtocolHandler, GenericManagedConnection)
       2006-11-30 13:04:06,842 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] Returning XMPPResource=fi.logiasoftware.jca.adapter.GenericResourceImpl@d75cf7
       2006-11-30 13:04:06,842 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] registering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, connection : fi.logiasoftware.jca.adapter.GenericResourceImpl@d75cf7, key: null
       2006-11-30 13:04:06,842 INFO [STDOUT] 4----------TestBean3 ID : 3 user : jmo :
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] AbstractProtocolHandler getHandler()
       2006-11-30 13:04:26,841 INFO [STDOUT] Suljetaan TestBean3 resource
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] close()
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] About to close resource fi.logiasoftware.jca.adapter.GenericResourceImpl@d75cf7 using mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] close(GenericResourceImpl)
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] Object getAssociatedObject()
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc closing=fi.logiasoftware.jca.adapter.GenericResourceImpl@d75cf7 impl.associatedObject=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] connectionClosed(ConnectionEvent)
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] notifyConnectionEvent(ConnectionEvent)
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] CONNECTION CLOSED
       2006-11-30 13:04:26,841 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] unregistering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, object: fi.logiasoftware.jca.adapter.GenericResourceImpl@d75cf7, key: null
       2006-11-30 13:04:26,841 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] unregisterConnection: 0 handles left
       2006-11-30 13:04:26,841 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@187a8e0[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc handles=0 lastUse=1164884646842 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] invalidate()
       2006-11-30 13:04:26,841 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] setValid(boolean)
       2006-11-30 13:04:26,841 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@187a8e0[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc handles=0 lastUse=1164884666841 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [1/19/20]
       2006-11-30 13:04:26,841 TRACE [org.jboss.tm.TxManager] tx timeout is now: 300s
       2006-11-30 13:04:46,856 INFO [STDOUT] Suljetaan TestBean resource
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] close()
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] About to close resource fi.logiasoftware.jca.adapter.GenericResourceImpl@1e5052b using mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] close(GenericResourceImpl)
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] Object getAssociatedObject()
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 closing=fi.logiasoftware.jca.adapter.GenericResourceImpl@1e5052b impl.associatedObject=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] connectionClosed(ConnectionEvent)
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] notifyConnectionEvent(ConnectionEvent)
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] CONNECTION CLOSED
       2006-11-30 13:04:46,856 TRACE [org.jboss.resource.connectionmanager.CachedConnectionManager] unregistering connection from org.jboss.resource.connectionmanager.NoTxConnectionManager@b65a68, object: fi.logiasoftware.jca.adapter.GenericResourceImpl@1e5052b, key: null
       2006-11-30 13:04:46,856 TRACE [org.jboss.resource.connectionmanager.NoTxConnectionManager] unregisterConnection: 0 handles left
       2006-11-30 13:04:46,856 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] putting ManagedConnection back into pool kill=false cl=org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@b41541[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 handles=0 lastUse=1164884576437 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] cleanup()
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] invalidate()
       2006-11-30 13:04:46,856 DEBUG [fi.logiasoftware.jca.adapter.GenericResourceImpl] setValid(boolean)
       2006-11-30 13:04:46,856 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Returning connection to pool org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@b41541[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 handles=0 lastUse=1164884686856 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e] [InUse/Available/Max]: [0/20/20]
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TransactionImpl] Committing, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14], status=STATUS_ACTIVE
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TransactionImpl] Before completion done, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14], status=STATUS_ACTIVE
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TransactionImpl] Zero phase commit TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14]: No resources.
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TransactionImpl] Committed OK, tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14]
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TxManager] commited tx: TransactionImpl:XidImpl[FormatId=257, GlobalId=ws-sam/14, BranchQual=, localId=14]
       2006-11-30 13:04:46,856 TRACE [org.jboss.tm.TxManager] tx timeout is now: 300s
       2006-11-30 13:04:46,935 DEBUG [org.jboss.remoting.transport.socket.ServerThread] begin thread wait
       2006-11-30 13:10:26,348 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000
       2006-11-30 13:17:56,345 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000
       2006-11-30 13:25:26,353 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 450000
       2006-11-30 13:25:26,353 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Destroying timedout connection org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@187a8e0[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc handles=0 lastUse=1164884666841 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] destroy()
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] closing fi.logiasoftware.jca.handlers.FTPProtocolHandler@d79c75 for fi.logiasoftware.jca.adapter.GenericManagedConnection@1602bbc
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] disconnect()
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] boolean isConnected()
       2006-11-30 13:25:26,353 INFO [fi.logiasoftware.jca.handlers.FTPProtocolHandler] this.isConnected?? : true
       2006-11-30 13:25:26,353 INFO [STDOUT] Disconnect connected : true
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Disconnecting from FTP server: wbs.software.logia.fi 21
       2006-11-30 13:25:26,353 WARN [fi.logiasoftware.jca.handlers.FTPProtocolHandler] IOException while disconnecting from FTP server: wbs.software.logia.fi 21 Reason : Software caused connection abort: recv failed
       2006-11-30 13:25:26,353 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Destroying timedout connection org.jboss.resource.connectionmanager.NoTxConnectionManager$NoTxConnectionEventListener@b41541[state=NORMAL mc=fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2 handles=0 lastUse=1164884686856 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$OnePool@18faa02 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@e26d2e]
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] destroy()
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.adapter.GenericManagedConnection] closing fi.logiasoftware.jca.handlers.FTPProtocolHandler@160e8a2 for fi.logiasoftware.jca.adapter.GenericManagedConnection@df88d2
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] disconnect()
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] boolean isConnected()
       2006-11-30 13:25:26,353 INFO [fi.logiasoftware.jca.handlers.FTPProtocolHandler] this.isConnected?? : true
       2006-11-30 13:25:26,353 INFO [STDOUT] Disconnect connected : true
       2006-11-30 13:25:26,353 DEBUG [fi.logiasoftware.jca.handlers.FTPProtocolHandler] Disconnecting from FTP server: wbs.software.logia.fi 21
       2006-11-30 13:25:26,353 WARN [fi.logiasoftware.jca.handlers.FTPProtocolHandler] IOException while disconnecting from FTP server: wbs.software.logia.fi 21 Reason : Software caused connection abort: recv failed
      
      
      


      Thanks!

      Br,
      Sami Männistö



        • 1. Re: Problem with writing JCA adapter
          weston.price

          Hmmm...what are you doing in your cleanup() method in your adapter? What this looks like is a timeout in your FTP connection. As a result, the underlying socket has already been closed and is causing the problem.

          • 2. Re: Problem with writing JCA adapter
            lgsw_sam

            Hi Weston!

            I also noticed that my matchManagedConnections(Set connections, Subject subject, ConnectionRequestInfo info)
            connections.size() is always 1..
            I have checked that I do get connections.

            Here is my cleanup and destroy methods.

            
            private AbstractProtocolHandler handler;
             private Vector <Object> handles;
            
             // Goes throu every item in handles and sets value of valid to false
             public void cleanup() throws ResourceException {
             synchronized (this) {
             for (Iterator it = handles.iterator(); it.hasNext(); )
             {
             Invalidatable i = (Invalidatable)it.next();
             i.invalidate();
             }
             handles = new Vector();
             attributes = new HashMap();
             }
             }
            
             public void invalidate() {
             setValid(false);
             }
            
             // Sets value of closing to true and if there is handler then disconnects its connection.
             public void destroy() throws ResourceException {
             synchronized (this) {
             this.closing = true;
             if (handler != null) {
             try {
             handler.disconnect();
             } catch (ProtocolHandlerException e) {
             e.printStackTrace();
             }
             }
             }
             }
            


            • 3. Re: Problem with writing JCA adapter
              weston.price

              Correct. The match managed connection method will always receive 1 connection, this is by design. Again, this is a some sort of socket level issue with a timeout from what I can tell.

              • 4. Re: Problem with writing JCA adapter
                lgsw_sam

                Hi Weston!
                It seem that this problem was caused because FTP server had already cut the connection and throwed exception when disconnecting failed... I changed my disconnect method so it doesn't throw exception just catceh it and writes it to log.

                Thanks for your help!

                Br,
                Sami Männistö