ACCESSIBLE connection closed due to Recoverer failure (nothing prevents recoverer from running twice in parallel)

This is really a blocker for us as the problem happens consistently in production.

It looks as though during the recovery process the resource T4CXAConnection@1582e57f is closed twice by bitronix-recovery-thread:

• aimprod88_Other.log.1 - 05 Jan 2010 23:22:53,295
• aimprod88_Other.log.1 - 05 Jan 2010 23:22:53,298

I don't know how this could happen but I have the feeling that you have TWO recovery threads running in parallel.

Could you please try to collect a thread dump and post it here?

This definitely is what I guessed, there are two recovery threads working in parallel.

recovery starts (line #, date):
6636 05 Jan 2010 23:21:24,941
19672 05 Jan 2010 23:22:25,044

recovery ends (line #, date):
22700 05 Jan 2010 23:22:53,345
22703 05 Jan 2010 23:22:53,346

This clearly explains the strange behavior you're getting as the recoverer is working with unshareable (and supposedly unshared!) resources .

As a workaround, you could change the backgroundRecoveryIntervalSeconds config property to run every 10 minutes instead of every minute and see if that helps.

I'll fix that problem for next release.
Thanks for the report.

This bug can happen because neither the XAResourceProducer implementations (PoolingDataSource & PoolingConnectionFactory) nor Recoverer have any safeguard to prevent reentrance.

Those methods should throw an exception if they are reentered:
PoolingDataSource.startRecovery()
PoolingDataSource.endRecovery()
PoolingConnectionFactory.startRecovery()
PoolingConnectionFactory.endRecovery()

This method should log a debug message and return ASAP if it is reentered:
Recoverer.run()

Thanks, Ludovic.

I am still looking into it but am thinking that setting backgroundRecoveryIntervalSeconds to 10 min in an attempt to stagger recovery runs can only take us so far. Perhaps a simple check in the Recoverer.run() method would be a good temporary workaround.

Ben,

Do you think there's a special reason why the recoverer managed to eat its own tail? I had the impression that it just runs a bit longer than 60s once in a while but it could be that it's blocked by a DB lock or whatever else which would indeed void the proposed workaround.

I've built a snapshot version from the 1.3.3 branch containing some code which now prevents the recoverer from being reentered, you can get it from there if you want to try it out: http://dl.dropbox.com/u/3512020/btm-1.3.4-20100107.jar

Please let me know if that helped out.

quick patch which prevents the recoverer from being reentered.

Not sure about the DB locks but it's possible, at least in theory. We do have long running transactions that lock resources. However, by looking at the recovery durations, it looks as though the recovery takes about a minute or so so I am not sure if locking plays any role.
Thanks for the patch, we will test it and let you know how it went.

Emergency patch has been committed to the 1.3.3 branch. I'm waiting for an acknowledge of the reporter that the issue is fixed before applying an improved version of that fix on the trunk.

I have not been able to reproduce the issue since the patch was applied so I am inclined to believe the fix has resolved it.

Thanks for the report, Ben.

I'm now going to port the patch to the trunk.