Validation of destroyed connections

[bortx]

Hello. I'm havin a problem using the background validation feature.

On each validation iteration, jboss checks all connections that have been created: the ones that are in the pool at the moment, and the ones that have been destroyed previously. The pool works right, I mean, it never returns a destroyed connection, and the pool has the number of connections I've specified, but I don't know why it tries to validate destroyed connections.

I've implemented the destroy() method so that it closes the connection to the EIS. What actions am I supposed to perform on the destroy() method? May I notify ConnectionEventListener set on some event? I only notify those listeners in the close() method.

Thanks a lot.

Bortx

[weston.price]

The background validation feature only evaluates those connections that are currently in the pool. The destroy operation removes connections from the pool and as a result, they are not subject to validation. Can you give me more info as to why you think it is doing this?

May I notify ConnectionEventListener set on some event?

No, as this is unnecessary. The destroy occurs at the end of the ManagedConnection lifecycle and as such, there is no reason to notify the listener.

[bortx]

I'm maintaining a pool with 5 connections and validations every minute. On creation, I assign them an id for monitoring. Here you can see a test case I've already done:

On startup jboss creates 5 connections (ids 1 to 5), and validates them every minute. In a given moment, the EIS closes all connections, so the validation of all of them fails and jboss destroys them:

18:24:25,314 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:25,314 INFO [TAManagedConnection:249] Validating connection 2
18:24:25,314 INFO [TAManagedConnection:290] I/O ERROR
18:24:25,314 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:24:25,314 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:25,314 WARN [JBossManagedConnectionPool:657]
18:24:25,314 INFO [TAManagedConnection:150] Destroying connection...
18:24:25,314 INFO [TAManagedConnection:160] Connection destroyed
18:24:25,314 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:25,314 INFO [TAManagedConnection:249] Validating connection 3
18:24:25,314 INFO [TAManagedConnection:290] I/O ERROR
18:24:25,314 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:24:25,314 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:25,314 WARN [JBossManagedConnectionPool:657]
18:24:25,314 INFO [TAManagedConnection:150] Destroying connection...
18:24:25,314 INFO [TAManagedConnection:160] Connection destroyed
18:24:25,314 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:25,314 INFO [TAManagedConnection:249] Validating connection 4
18:24:25,314 INFO [TAManagedConnection:290] I/O ERROR
18:24:25,314 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:24:25,314 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:25,314 WARN [JBossManagedConnectionPool:657]
18:24:25,314 INFO [TAManagedConnection:150] Destroying connection...
18:24:25,314 INFO [TAManagedConnection:160] Connection destroyed
18:24:25,314 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:25,314 INFO [TAManagedConnection:249] Validating connection 5
18:24:25,314 INFO [TAManagedConnection:290] I/O ERROR
18:24:25,314 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:24:25,314 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:25,314 WARN [JBossManagedConnectionPool:657]
18:24:25,314 INFO [TAManagedConnection:150] Destroying connection...
18:24:25,314 INFO [TAManagedConnection:160] Connection destroyed
18:24:25,314 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:25,314 INFO [TAManagedConnection:249] Validating connection 1
18:24:25,329 INFO [TAManagedConnection:290] I/O ERROR
18:24:25,329 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:24:25,329 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:25,329 WARN [JBossManagedConnectionPool:657]
18:24:25,329 INFO [TAManagedConnection:150] Destroying connection...
18:24:25,329 INFO [TAManagedConnection:160] Connection destroyed

Inmediately jboss creates 5 new connections (ids 6 to 10) in order to fill the pool:

18:24:25,329 INFO [TAManagedConnection:111] Initiating connection...
18:24:25,329 INFO [TAManagedConnection:118] Connection established
18:24:25,329 INFO [TAManagedConnectionFactory:111] Connection created - number 6
18:24:25,329 INFO [TAManagedConnection:111] Initiating connection...
18:24:25,329 INFO [TAManagedConnection:118] Connection established
18:24:25,329 INFO [TAManagedConnectionFactory:111] Connection created - number 7
18:24:25,329 INFO [TAManagedConnection:111] Initiating connection...
18:24:25,329 INFO [TAManagedConnection:118] Connection established
18:24:25,329 INFO [TAManagedConnectionFactory:111] Connection created - number 8
18:24:25,329 INFO [TAManagedConnection:111] Initiating connection...
18:24:25,329 INFO [TAManagedConnection:118] Connection established
18:24:25,329 INFO [TAManagedConnectionFactory:111] Connection created - number 9
18:24:25,329 INFO [TAManagedConnection:111] Initiating connection...
18:24:25,329 INFO [TAManagedConnection:118] Connection established
18:24:25,329 INFO [TAManagedConnectionFactory:111] Connection created - number 10

30 seconds before, jboss validates the recently created connections:

18:24:55,330 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:55,330 INFO [TAManagedConnection:249] Validating connection 6
18:24:55,345 INFO [TAManagedConnection:275] Connection is valid
18:24:55,345 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:55,345 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:55,345 INFO [TAManagedConnection:249] Validating connection 7
18:24:55,345 INFO [TAManagedConnection:275] Connection is valid
18:24:55,345 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:55,345 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:55,345 INFO [TAManagedConnection:249] Validating connection 8
18:24:55,345 INFO [TAManagedConnection:275] Connection is valid
18:24:55,345 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:55,361 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:55,361 INFO [TAManagedConnection:249] Validating connection 9
18:24:55,361 INFO [TAManagedConnection:275] Connection is valid
18:24:55,361 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:24:55,361 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:24:55,361 INFO [TAManagedConnection:249] Validating connection 10
18:24:55,377 INFO [TAManagedConnection:275] Connection is valid
18:24:55,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED

but 30 seconds before this (and exactly 1 minute before the last unsuccessful validation) jboss validates the destroyed connections (ids 1 to 5):

18:25:25,377 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:25:25,377 INFO [TAManagedConnection:249] Validating connection 2
18:25:25,377 INFO [TAManagedConnection:299] Channel is not connected
18:25:25,377 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:25:25,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:25:25,377 WARN [JBossManagedConnectionPool:657]
18:25:25,377 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:25:25,377 INFO [TAManagedConnection:249] Validating connection 3
18:25:25,377 INFO [TAManagedConnection:299] Channel is not connected
18:25:25,377 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:25:25,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:25:25,377 WARN [JBossManagedConnectionPool:657]
18:25:25,377 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:25:25,377 INFO [TAManagedConnection:249] Validating connection 4
18:25:25,377 INFO [TAManagedConnection:299] Channel is not connected
18:25:25,377 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:25:25,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:25:25,377 WARN [JBossManagedConnectionPool:657]
18:25:25,377 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:25:25,377 INFO [TAManagedConnection:249] Validating connection 5
18:25:25,377 INFO [TAManagedConnection:299] Channel is not connected
18:25:25,377 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:25:25,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:25:25,377 WARN [JBossManagedConnectionPool:657]
18:25:25,377 INFO [TAManagedConnectionFactory:142] VALIDATING CONNECTIONS....
18:25:25,377 INFO [TAManagedConnection:249] Validating connection 1
18:25:25,377 INFO [TAManagedConnection:299] Channel is not connected
18:25:25,377 INFO [TAManagedConnectionFactory:150] Invalid connection found
18:25:25,377 INFO [TAManagedConnectionFactory:154] VALIDATION FINISHED
18:25:25,377 WARN [JBossManagedConnectionPool:657]

As you can see, jboss is constantly validating destroyed connections, the more connections get invalid, the more the problem increases.

[weston.price]

Yep. Looks like a bug. I will take care of it.

[weston.price]

http://jira.jboss.org/jira/browse/JBAS-4170

This has been resolved in 4.2 and 5.0.

[bortx]

Thank you very much!

I've fixed it in my jboss-jca.jar and works perfectly.

Thanks! you rule!