4 Replies Latest reply on Dec 4, 2006 7:51 AM by Sami Männistö

    Problem with writing JCA adapter

    Sami Männistö Newbie

      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 M. Price Master

          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
            Sami Männistö Newbie

            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 M. Price Master

              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
                Sami Männistö Newbie

                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ö