Database connections not closed after idle-timeout in wildfly Datasource

Question

I have an application running under wildfly 8.1 The database connections used in the applications are taken from a Datasource defined in standalone.xml file.

Problem: I don't know why but the Connection from the Pool never goes Idle and are released. Eventually the Pool gets filled will all active Connection and application starts throwing javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/bo/datasource

At the same time when I look at the database, most of the Connections are shown to be idle. (Configuration and result output below)

I have been at this for a week now and have not been able to figure out root cause of this problem. I have also checked all places where a connection is created and have made sure that they are closed afterwards.

What are the other possible places I should be looking into? Or is this a bug (or known issues with Wildfly datasource)?

Wildfly datasource definition:

    <subsystem xmlns="urn:jboss:domain:datasources:2.0">
        <datasources>
            <datasource jndi-name="java:/db/pool" pool-name="DBSource" enabled="true">
                <connection-url>jdbc:postgresql://<IP>:5432/DB</connection-url>
                <driver>postgres</driver>
                <new-connection-sql>select 1</new-connection-sql>
                <pool>
                    <min-pool-size>5</min-pool-size>
                    <max-pool-size>100</max-pool-size>
                </pool>
                <security>
                    <user-name>user</user-name>
                    <password>password</password>
                </security>
                <validation>
                    <check-valid-connection-sql>select 1</check-valid-connection-sql>
                    <background-validation>true</background-validation>
                    <background-validation-millis>60000</background-validation-millis>
                </validation>
                <timeout>
                    <idle-timeout-minutes>30</idle-timeout-minutes>
                </timeout>
                <statement>
                    <track-statements>true</track-statements>
                </statement>
            </datasource>
            <drivers>
                <driver name="h2" module="com.h2database.h2">
                    <xa-datasource-class>org.h2.jdbcx.JdbcDataSource</xa-datasource-class>
                </driver>
                <driver name="postgres" module="org.postgres">
                    <driver-class>org.postgresql.Driver</driver-class>
                </driver>
            </drivers>
        </datasources>
    </subsystem>

Wildfly datasource pool information:

Command:

/subsystem=datasources/data-source=DBSource/statistics=pool:read-resource(recursive=false,proxies=false,include-runtime=true,include-defaults=true) 

Response:

{
    "outcome" => "success",
    "result" => {
        "ActiveCount" => "98",
        "AvailableCount" => "55",
        "AverageBlockingTime" => "1",
        "AverageCreationTime" => "125",
        "AverageGetTime" => "27",
        "BlockingFailureCount" => "0",
        "CreatedCount" => "98",
        "DestroyedCount" => "0",
        "IdleCount" => "3",
        "InUseCount" => "95",
        "MaxCreationTime" => "1382",
        "MaxGetTime" => "1382",
        "MaxUsedCount" => "97",
        "MaxWaitCount" => "0",
        "MaxWaitTime" => "1",
        "TimedOut" => "0",
        "TotalBlockingTime" => "71",
        "TotalCreationTime" => "12340",
        "TotalGetTime" => "12696",
        "WaitCount" => "0"
    },
    "response-headers" => {"process-state" => "reload-required"}
}

PostgreSQL Query Status:

Command:

SELECT datname, pid, usename, waiting, state, (now()-query_start) AS since, (now() - state_change) AS since2, (now() - backend_start) as since3, (now() - xact_start) as since4, query FROM pg_stat_activity ORDER BY datname, state, usename, waiting, query, since, pid; 

Response:

    datname    | pid  |  usename   | waiting |        state        |      since      |      since2      |     since3      |     since4      |                                                                                                                                   
---------------+------+------------+---------+---------------------+-----------------+------------------+-----------------+-----------------+-----------------------------------------------------------------------------------------------------------------------------------
 BOIEDUDBV13R1 | 4871 | blueoptima | f       | active              | 00:00:00.176188 | 00:00:00.176179  | 01:37:21.045722 | 00:02:17.212346 | Query-1
 BOIEDUDBV13R1 | 4568 | blueoptima | f       | active              | 00:18:33.035399 | 00:18:33.035395  | 04:25:11.916388 | 00:18:33.473355 | Query-2
 BOIEDUDBV13R1 | 4564 | blueoptima | f       | active              | 00:10:10.599237 | 00:10:10.599232  | 04:25:11.943752 | 00:10:10.915048 | Query-3 
 BOIEDUDBV13R1 | 4498 | blueoptima | f       | active              | 00:03:25.861284 | 00:03:25.86128   | 05:09:51.735583 | 00:03:25.861823 | Query-4 
 BOIEDUDBV13R1 | 4535 | blueoptima | f       | active              | 00:01:16.612227 | 00:01:16.612222  | 04:34:01.668772 | 00:01:16.614149 | Query-5
 BOIEDUDBV13R1 | 4534 | blueoptima | f       | idle                | 00:00:04.72429  | 00:00:04.683504  | 04:35:21.78966  |                 | COMMIT
 BOIEDUDBV13R1 | 4519 | blueoptima | f       | idle                | 00:00:12.950041 | 00:00:12.913566  | 04:50:53.698877 |                 | COMMIT
 BOIEDUDBV13R1 | 4438 | blueoptima | f       | idle                | 00:00:25.82585  | 00:00:25.81036   | 05:34:41.528853 |                 | COMMIT
 BOIEDUDBV13R1 | 4425 | blueoptima | f       | idle                | 00:09:12.999537 | 00:09:12.9731    | 05:41:51.806148 |                 | COMMIT
 BOIEDUDBV13R1 | 4488 | blueoptima | f       | idle                | 00:56:04.709316 | 00:56:04.686439  | 05:14:45.445165 |                 | COMMIT
 BOIEDUDBV13R1 | 4501 | blueoptima | f       | idle                | 00:57:00.615919 | 00:57:00.61589   | 05:06:51.861328 |                 | COMMIT
 BOIEDUDBV13R1 | 4466 | blueoptima | f       | idle                | 04:11:54.8669   | 04:11:54.516947  | 05:25:03.079741 |                 | COMMIT
 BOIEDUDBV13R1 | 4419 | blueoptima | f       | idle                | 04:51:03.786294 | 04:51:03.749462  | 05:41:51.814577 |                 | COMMIT
 BOIEDUDBV13R1 | 4340 | blueoptima | f       | idle                | 04:52:19.772533 | 04:52:19.720537  | 06:31:51.758733 |                 | COMMIT
 BOIEDUDBV13R1 | 4502 | blueoptima | f       | idle                | 04:54:49.892553 | 04:54:49.85151   | 05:06:51.439101 |                 | COMMIT
 BOIEDUDBV13R1 | 4406 | blueoptima | f       | idle                | 05:09:20.675009 | 05:09:20.655038  | 06:00:50.160594 |                 | COMMIT
 BOIEDUDBV13R1 | 4489 | blueoptima | f       | idle                | 05:09:54.785706 | 05:09:54.751723  | 05:14:45.358108 |                 | COMMIT
 BOIEDUDBV13R1 | 4449 | blueoptima | f       | idle                | 05:16:58.881682 | 05:16:58.88074   | 05:26:50.728973 |                 | COMMIT
 BOIEDUDBV13R1 | 4450 | blueoptima | f       | idle                | 05:17:23.727614 | 05:17:23.726158  | 05:25:55.116657 |                 | COMMIT
 BOIEDUDBV13R1 | 4465 | blueoptima | f       | idle                | 05:22:32.475769 | 05:22:32.470301  | 05:25:03.230671 |                 | COMMIT
 BOIEDUDBV13R1 | 4421 | blueoptima | f       | idle                | 05:25:03.596961 | 05:25:03.596942  | 05:41:51.81487  |                 | COMMIT
 BOIEDUDBV13R1 | 4451 | blueoptima | f       | idle                | 05:25:29.373092 | 05:25:29.364467  | 05:25:52.433709 |                 | COMMIT
 BOIEDUDBV13R1 | 4448 | blueoptima | f       | idle                | 05:25:58.729039 | 05:25:58.724453  | 05:26:50.898318 |                 | COMMIT
 BOIEDUDBV13R1 | 4423 | blueoptima | f       | idle                | 05:26:13.2656   | 05:26:13.263502  | 05:41:51.814528 |                 | COMMIT
 BOIEDUDBV13R1 | 4426 | blueoptima | f       | idle                | 05:26:58.773981 | 05:26:58.765174  | 05:41:51.179333 |                 | COMMIT
 BOIEDUDBV13R1 | 4415 | blueoptima | f       | idle                | 05:29:07.123798 | 05:29:07.115682  | 05:47:36.740939 |                 | COMMIT
 BOIEDUDBV13R1 | 4394 | blueoptima | f       | idle                | 05:42:02.02632  | 05:42:01.994772  | 06:05:54.290575 |                 | COMMIT
 BOIEDUDBV13R1 | 4416 | blueoptima | f       | idle                | 05:45:52.799303 | 05:45:52.793004  | 05:47:36.701474 |                 | COMMIT
 BOIEDUDBV13R1 | 4408 | blueoptima | f       | idle                | 05:48:02.635413 | 05:48:02.630767  | 05:54:49.133404 |                 | COMMIT
 BOIEDUDBV13R1 | 4410 | blueoptima | f       | idle                | 05:49:09.631417 | 05:49:09.624039  | 05:49:47.440347 |                 | COMMIT
 BOIEDUDBV13R1 | 4392 | blueoptima | f       | idle                | 05:49:45.136111 | 05:49:45.124627  | 06:05:54.52666  |                 | COMMIT
 BOIEDUDBV13R1 | 4411 | blueoptima | f       | idle                | 05:49:45.208436 | 05:49:45.207393  | 05:49:46.326729 |                 | COMMIT
 BOIEDUDBV13R1 | 4399 | blueoptima | f       | idle                | 05:50:19.476105 | 05:50:19.465746  | 06:04:53.509647 |                 | COMMIT
 BOIEDUDBV13R1 | 4383 | blueoptima | f       | idle                | 05:54:04.625364 | 05:54:04.56991   | 06:09:43.004602 |                 | COMMIT
 BOIEDUDBV13R1 | 4382 | blueoptima | f       | idle                | 05:58:29.615594 | 05:58:29.608542  | 06:09:43.496538 |                 | COMMIT
 BOIEDUDBV13R1 | 4404 | blueoptima | f       | idle                | 06:00:48.381014 | 06:00:48.379175  | 06:00:50.352202 |                 | COMMIT
 BOIEDUDBV13R1 | 4393 | blueoptima | f       | idle                | 06:01:49.740445 | 06:01:49.733278  | 06:05:54.468595 |                 | COMMIT
 BOIEDUDBV13R1 | 4379 | blueoptima | f       | idle                | 06:02:12.00668  | 06:02:12.004878  | 06:11:37.044413 |                 | COMMIT
 BOIEDUDBV13R1 | 4396 | blueoptima | f       | idle                | 06:02:25.216415 | 06:02:25.202565  | 06:05:10.411017 |                 | COMMIT
 BOIEDUDBV13R1 | 4390 | blueoptima | f       | idle                | 06:03:48.651868 | 06:03:48.647211  | 06:06:05.443    |                 | COMMIT
 BOIEDUDBV13R1 | 4375 | blueoptima | f       | idle                | 06:04:51.760968 | 06:04:51.732155  | 06:11:37.545217 |                 | COMMIT
 BOIEDUDBV13R1 | 4353 | blueoptima | f       | idle                | 06:04:53.302492 | 06:04:53.252345  | 06:25:54.61252  |                 | COMMIT
 BOIEDUDBV13R1 | 4372 | blueoptima | f       | idle                | 06:05:08.158286 | 06:05:08.137553  | 06:11:49.797186 |                 | COMMIT
 BOIEDUDBV13R1 | 4397 | blueoptima | f       | idle                | 06:05:08.578854 | 06:05:08.544941  | 06:05:10.298185 |                 | COMMIT
 BOIEDUDBV13R1 | 4377 | blueoptima | f       | idle                | 06:08:34.443118 | 06:08:34.435299  | 06:11:37.432426 |                 | COMMIT
 BOIEDUDBV13R1 | 4378 | blueoptima | f       | idle                | 06:11:35.00451  | 06:11:34.946687  | 06:11:37.293523 |                 | COMMIT
 BOIEDUDBV13R1 | 4354 | blueoptima | f       | idle                | 06:12:01.816625 | 06:12:01.812458  | 06:25:50.247498 |                 | COMMIT
 BOIEDUDBV13R1 | 4344 | blueoptima | f       | idle                | 06:21:56.439509 | 06:21:56.438739  | 06:31:30.8968   |                 | COMMIT
 BOIEDUDBV13R1 | 4350 | blueoptima | f       | idle                | 06:22:20.125071 | 06:22:20.11839   | 06:29:37.465565 |                 | COMMIT
 BOIEDUDBV13R1 | 4343 | blueoptima | f       | idle                | 06:25:59.198819 | 06:25:59.197962  | 06:31:30.901491 |                 | COMMIT
 BOIEDUDBV13R1 | 4351 | blueoptima | f       | idle                | 06:27:23.950853 | 06:27:23.950081  | 06:29:37.456841 |                 | COMMIT
 BOIEDUDBV13R1 | 4348 | blueoptima | f       | idle                | 06:27:36.13192  | 06:27:36.131014  | 06:29:37.513979 |                 | COMMIT
 BOIEDUDBV13R1 | 4349 | blueoptima | f       | idle                | 06:27:42.332901 | 06:27:42.331326  | 06:29:37.491039 |                 | COMMIT
 BOIEDUDBV13R1 | 4352 | blueoptima | f       | idle                | 06:27:54.031819 | 06:27:54.02966   | 06:29:37.265193 |                 | COMMIT
 BOIEDUDBV13R1 | 4341 | blueoptima | f       | idle                | 06:28:14.444963 | 06:28:14.444105  | 06:31:31.858728 |                 | COMMIT
 BOIEDUDBV13R1 | 4337 | blueoptima | f       | idle                | 06:29:20.216685 | 06:29:20.215749  | 06:33:13.450564 |                 | COMMIT
 BOIEDUDBV13R1 | 4346 | blueoptima | f       | idle                | 06:29:28.524638 | 06:29:28.523906  | 06:30:51.904609 |                 | COMMIT
 BOIEDUDBV13R1 | 4342 | blueoptima | f       | idle                | 06:29:58.433751 | 06:29:58.432939  | 06:31:31.204896 |                 | COMMIT
 BOIEDUDBV13R1 | 4345 | blueoptima | f       | idle                | 06:30:28.819691 | 06:30:28.818747  | 06:31:26.849458 |                 | COMMIT
 BOIEDUDBV13R1 | 4355 | blueoptima | f       | idle                | 06:07:48.953452 | 06:07:48.947655  | 06:25:50.216644 |                 | INSERT
 BOIEDUDBV13R1 | 4409 | blueoptima | f       | idle                | 05:49:25.452863 | 05:49:25.435483  | 05:49:49.502884 |                 | INSERT-1
 BOIEDUDBV13R1 | 4424 | blueoptima | f       | idle                | 05:35:44.413808 | 05:35:44.381036  | 05:41:51.814529 |                 | INSERT-2
 BOIEDUDBV13R1 | 4398 | blueoptima | f       | idle                | 05:36:00.621836 | 05:36:00.598047  | 06:04:53.758915 |                 | INSERT-3
 BOIEDUDBV13R1 | 4417 | blueoptima | f       | idle                | 05:46:18.096148 | 05:46:18.07272   | 05:47:36.576677 |                 | INSERT-4
 BOIEDUDBV13R1 | 4395 | blueoptima | f       | idle                | 05:50:44.112353 | 05:50:44.074542  | 06:05:10.557776 |                 | INSERT-5
 BOIEDUDBV13R1 | 4388 | blueoptima | f       | idle                | 06:05:57.843694 | 06:05:57.832724  | 06:06:06.177483 |                 | INSERT-6
 BOIEDUDBV13R1 | 4339 | blueoptima | f       | idle                | 06:17:57.460712 | 06:17:57.459716  | 06:33:12.657432 |                 | INSERT-7
 BOIEDUDBV13R1 | 4487 | blueoptima | f       | idle                | 00:00:15.552081 | 00:00:15.552035  | 05:15:49.047066 |                 | select 1
 BOIEDUDBV13R1 | 4565 | blueoptima | f       | idle                | 00:00:15.553093 | 00:00:15.553037  | 04:25:11.942656 |                 | select 1
 BOIEDUDBV13R1 | 4420 | blueoptima | f       | idle                | 00:00:15.554958 | 00:00:15.55493   | 05:41:51.814789 |                 | select 1
 BOIEDUDBV13R1 | 4402 | blueoptima | f       | idle                | 02:16:15.871078 | 02:16:15.871048  | 06:00:52.663433 |                 | select 1
 BOIEDUDBV13R1 | 4384 | blueoptima | f       | idle                | 05:38:17.430042 | 05:38:17.43002   | 06:09:42.969186 |                 | select 1
 BOIEDUDBV13R1 | 4412 | blueoptima | f       | idle                | 05:46:47.263716 | 05:46:47.263518  | 05:49:45.575215 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4414 | blueoptima | f       | idle                | 05:49:41.773012 | 05:49:41.772712  | 05:49:45.435716 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4405 | blueoptima | f       | idle                | 05:51:32.2168   | 05:51:32.216636  | 06:00:50.160309 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4400 | blueoptima | f       | idle                | 05:52:44.966233 | 05:52:44.965626  | 06:02:28.601245 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4401 | blueoptima | f       | idle                | 06:01:07.430069 | 06:01:07.429643  | 06:02:28.599077 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4389 | blueoptima | f       | idle                | 06:05:52.187161 | 06:05:52.187081  | 06:06:05.801733 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4376 | blueoptima | f       | idle                | 06:06:04.447668 | 06:06:04.447527  | 06:11:37.448819 |                 | SELECT DISTINCT column  FROM table
 BOIEDUDBV13R1 | 4422 | blueoptima | f       | idle                | 04:48:59.446162 | 04:48:59.446103  | 05:41:51.814892 |                 | SELECT
 BOIEDUDBV13R1 | 4385 | blueoptima | f       | idle                | 05:28:13.718473 | 05:28:13.643871  | 06:09:42.799857 |                 | SELECT
 BOIEDUDBV13R1 | 4536 | blueoptima | f       | idle                | 04:29:42.4528   | 04:29:42.429103  | 04:34:01.664679 |                 | SELECT
 BOIEDUDBV13R1 | 4381 | blueoptima | f       | idle                | 06:05:51.131506 | 06:05:51.131429  | 06:11:35.758195 |                 | SELECT
 BOIEDUDBV13R1 | 4338 | blueoptima | f       | idle                | 06:28:31.658157 | 06:28:31.658105  | 06:33:12.953437 |                 | SELECT
 BOIEDUDBV13R1 | 4566 | blueoptima | f       | idle                | 00:00:25.8479   | 00:00:25.835864  | 04:25:11.94033  |                 | UPDATE-1
 BOIEDUDBV13R1 | 4391 | blueoptima | f       | idle                | 03:52:25.755736 | 03:52:25.73571   | 06:06:05.300207 |                 | UPDATE-2
 BOIEDUDBV13R1 | 4512 | blueoptima | f       | idle                | 04:56:03.247543 | 04:56:03.232923  | 04:56:44.188961 |                 | UPDATE-3
 BOIEDUDBV13R1 | 4511 | blueoptima | f       | idle                | 04:56:34.70146  | 04:56:34.691303  | 04:57:00.191291 |                 | UPDATE-4
 BOIEDUDBV13R1 | 4347 | blueoptima | f       | idle                | 05:32:30.754975 | 05:32:30.732481  | 06:29:46.312612 |                 | UPDATE-5
 BOIEDUDBV13R1 | 4439 | blueoptima | f       | idle                | 05:32:55.742867 | 05:32:55.741539  | 05:34:41.519884 |                 | UPDATE-6
 BOIEDUDBV13R1 | 4407 | blueoptima | f       | idle                | 05:37:36.461115 | 05:37:36.451762  | 05:54:49.133383 |                 | UPDATE-7
 BOIEDUDBV13R1 | 4371 | blueoptima | f       | idle                | 05:53:02.986092 | 05:53:02.830753  | 06:11:55.240785 |                 | UPDATE-8
 BOIEDUDBV13R1 | 4403 | blueoptima | f       | idle                | 05:59:57.870442 | 05:59:57.865218  | 06:00:52.646267 |                 | UPDATE-9
 BOIEDUDBV13R1 | 4356 | blueoptima | f       | idle                | 06:09:18.560294 | 06:09:18.559498  | 06:25:50.216061 |                 | UPDATE-10
 BOIEDUDBV13R1 | 4380 | blueoptima | f       | idle                | 06:09:38.951985 | 06:09:38.924395  | 06:11:36.494018 |                 | UPDATE-11
 BOIEDUDBV13R1 | 4863 | postgres   | f       | idle                | 01:21:12.135105 | 01:21:12.052383  | 02:01:39.736693 |                 | select a                                                     
               |      |            |         |                     |                 |                  |                 |                 | ;
 BOIEDUDBV13R1 | 4988 | postgres   | f       | idle                | 00:11:16.272964 | 00:11:16.145621  | 00:13:26.234094 |                 | select b                 
               |      |            |         |                     |                 |                  |                 |                 |
 BOIEDUDBV13R1 | 4437 | blueoptima | f       | idle in transaction | 05:29:11.490837 | 05:29:11.490825  | 05:34:41.52984  | 05:29:11.490949 | select 1
 BOIEDUDBV13R1 | 4413 | blueoptima | f       | idle in transaction | 05:36:47.417173 | 05:36:47.417148  | 05:49:45.5742   | 05:36:47.417257 | select 1
 BOIEDUDBV13R1 | 4567 | blueoptima | f       | idle in transaction | 00:49:38.844059 | 00:49:38.844027  | 04:25:11.936358 | 00:49:40.950629 | Query 
(100 rows)

Answer 1

It turns out that Hibernate was holding connection and not releasing them to the Pool. Irrespective of the fact that we are using thread local context. But after adding <property name="hibernate.connection.release_mode">after_transaction</property> to the hibernate config. The problem got solved.

PS: I still dont understand why we need to define this explicitly and why the auto release_mode would not release the connection once the session is closed.