Как исправить «SQLRecoverableException: Closed Connection» в Java

Мы работаем над электронной коммерцией, построенной с помощью инфраструктуры Hybris, и в настоящее время у нас есть проблема с подключением к базе данных (я полагаю), и мы не знаем, как ее решить. Это происходит только в производственной среде и только на серверах, которые использует ESB (всего 2 сервера из 40).

В основном, иногда (1-3 раза в день) мы обнаруживаем сеансы, ожидающие какого-то незанятого сеанса (сообщение SEL*NET от клиента). Мы можем только вручную убить держателя, чтобы освободить эти сессии.

Все серверы используют один и тот же код приложения, и основное различие между серверами ESB и Frontend заключается в вызываемых контроллерах и количестве запросов.

ESB-сервер: 10 запросов в минуту. Фронтенд-сервер: 300 запросов в минуту.

В журнале приложений я нашел много ошибок Closed Connection на этих двух серверах, и я думаю, что это связано с нашей проблемой, но на самом деле я не знаю, почему. В access.log у меня есть этот запрос:

[26/Mar/2019:09:04:39 +0100] "GET /blockorder?orderCode=XXXX&access_token=XXXX HTTP/1.1" 400 122 "-" "AHC/1.0"

а в console.log у меня так:

hybrisHTTP8 2019-03-26 09:04:39,184 ERROR [[10.125.31.2] ] () [de.hybris.platform.jdbcwrapper.ConnectionImpl] error resetting AutoCommit
java.sql.SQLRecoverableException: Closed Connection
        at oracle.jdbc.driver.PhysicalConnection.setAutoCommit(PhysicalConnection.java:3763)
        at de.hybris.platform.jdbcwrapper.ConnectionImpl.doSetAutoCommit(ConnectionImpl.java:431)
        at de.hybris.platform.jdbcwrapper.ConnectionImpl.restoreAutoCommit(ConnectionImpl.java:185)
        at de.hybris.platform.jdbcwrapper.ConnectionImpl.unsetTxBound(ConnectionImpl.java:175)
        at de.hybris.platform.tx.Transaction.unsetTxBoundConnection(Transaction.java:920)
        at de.hybris.platform.tx.Transaction.clearTxBoundConnectionAndNotify(Transaction.java:897)
        at de.hybris.platform.tx.Transaction.clearTxBoundConnectionAndNotifyRollback(Transaction.java:887)
        at de.hybris.platform.tx.Transaction.rollbackOuter(Transaction.java:1084)
        at de.hybris.platform.tx.Transaction.rollback(Transaction.java:1028)
        at de.hybris.platform.tx.Transaction.commit(Transaction.java:690)
        at de.hybris.platform.tx.Transaction.finishExecute(Transaction.java:1218)
        at de.hybris.platform.tx.Transaction.execute(Transaction.java:1205)
        at de.hybris.platform.tx.Transaction.execute(Transaction.java:1160)
        at de.hybris.platform.jalo.Item.setAllAttributes(Item.java:2082)
        at de.hybris.platform.jalo.Item.setAllAttributes(Item.java:2057)
        at de.hybris.platform.servicelayer.internal.converter.impl.ItemModelConverter.storeAttributes(ItemModelConverter.java:1503)
        at de.hybris.platform.servicelayer.internal.converter.impl.ItemModelConverter.save(ItemModelConverter.java:730)
        at de.hybris.platform.servicelayer.internal.model.impl.wrapper.ModelWrapper.save(ModelWrapper.java:336)
        at de.hybris.platform.servicelayer.internal.model.impl.ResolvingModelPersister.saveOthers(ResolvingModelPersister.java:64)
        at de.hybris.platform.servicelayer.internal.model.impl.ResolvingModelPersister.persist(ResolvingModelPersister.java:49)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.saveViaJalo(DefaultModelService.java:1059)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.doJaloPersistence(DefaultModelService.java:648)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.persistWrappers(DefaultModelService.java:1002)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.performPersistenceOperations(DefaultModelService.java:626)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.saveAllInternal(DefaultModelService.java:620)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.saveAll(DefaultModelService.java:600)
        at de.hybris.platform.servicelayer.internal.model.impl.DefaultModelService.save(DefaultModelService.java:548)
        at com.test.fulfilment.process.impl.DefaultOrderProcessService.requestForcedOrderCancellation(DefaultOrderProcessService.java:131)
        at com.test.application.order.facades.impl.DefaultOrderFacade.forcedOrderCancel(DefaultOrderFacade.java:62)
        at com.test.application.controllers.OrderController.blockOrder(OrderController.java:520)

Конфигурация нашего пула следующая:

{
    "maxIdle": 90,
    "minIdle": 2,
    "maxActive": 90,
    "maxWait": 10000,
    "whenExhaustedAction": 1,
    "testOnBorrow": true,
    "testOnReturn": true,
    "testWhileIdle": true,
    "timeBetweenEvictionRunsMillis": 10000,
    "numTestsPerEvictionRun": 100,
    "minEvictableIdleTimeMillis": 300000,
    "softMinEvictableIdleTimeMillis": -1,
    "lifo": true
}

Наша конфигурация tomcat:

tomcat.generaloptions.JDBC=-Doracle.jdbc.ReadTimeout=60000
tomcat.generaloptions.TIMEOUT=-Dsun.net.client.defaultConnectTimeout\=60000 -Dsun.net.client.defaultReadTimeout\=60000
tomcat.ajp.acceptCount=100
tomcat.ajp.maxThreads=400
tomcat.maxthreads=400
tomcat.minsparethreads=50
tomcat.maxidletime=10000
tomcat.connectiontimeout=120000
tomcat.acceptcount=100

Мы попытались удалить oracle.jdbc.ReadTimeout, но в результате мы начали видеть Closed Connections на других серверах.

Код, вызывающий эту ошибку, довольно прост (и работает в 95% случаев):

    @Override
    public boolean requestForcedOrderCancellation(final OrderModel order) {
        Transaction.current().begin();
        try {
            modelService.lock(order.getPk());
            modelService.refresh(order);
            order.setForcedCancelled(true);
            modelService.save(order);
            Transaction.current().commit();
            return true;
        catch (Exception e) {
            LOG.error(e.getMessage(), e);
            Transaction.current().rollback();
            return false;
        }
    }

Мы пробовали также без явной блокировки, и проблема точно такая же. Похоже, что соединение уже закрыто, и мы не можем откатить (или зафиксировать) транзакции, которые все еще ожидают в БД.

Я ожидаю избежать этой блокировки и этих ошибок закрытого соединения.


person Vincenzo    schedule 02.04.2019    source источник


Ответы (2)


Ваш пул соединений, вероятно, уже исправляет это для вас. Попробуйте увеличить ведение журнала, чтобы увидеть, так ли это.

Справочная информация: базы данных ненавидят долгоживущие соединения, потому что они могут лишить их доступа к сети. Поэтому они имеют тенденцию закрывать соединение через некоторое время. Другим виновником являются брандмауэры, которые имеют тенденцию удалять неактивные соединения из своих таблиц. Пулы соединений знают, как справиться с этим, проверяя соединения (все эти параметры test* в вашей конфигурации выше).

Иногда вам нужно сообщить вашему пулу, как проверить соединение. Проверьте документацию. Для Oracle хорошим тестом является select 1 from dual.

Я думаю, что ваша настоящая проблема — это застрявшие сеансы. Узнайте, чего они ждут, просмотрев дамп потока Java, который можно создать с помощью инструмента jstack, входящего в состав Java SDK.

person Aaron Digulla    schedule 02.04.2019
comment
Привет, спасибо за ваш ответ, я не получил блокировки с помощью jstack, просто нашел какой-то поток, ожидающий в java.net.SocketInputStream.socketRead0. Чего я не понимаю, так это почему в некоторые дни он работает без проблем, а в некоторые дни он работает хорошо для первых 50-100 запросов, после чего он начинает показывать закрытое соединение (также без ожидания тайм-аута 90 с) - person Vincenzo; 09.04.2019
comment
Вы уверены, что конфигурация вашего пула действительно используется? Я не вижу классов пула в трассировке стека. - person Aaron Digulla; 09.04.2019

Мы обнаружили, что проблема возникла из-за необработанного исключения/ошибки в транзакционном коде.

Сервер ответил с ошибкой, и Hybris не отменил транзакцию, которая все еще открыта. Тот же поток повторно используется через некоторое время (возможно, через несколько дней), а старая транзакция все еще открыта.

Когда этот поврежденный поток используется для блокировки некоторых строк в базе данных, даже если мы фиксируем транзакцию в коде, она не фиксируется в базе данных, потому что внутри Hybris есть счетчик транзакций для обработки внутренних транзакций (возможно, используется в вызываемых методах). Транзакция фиксируется/откатывается в БД только тогда, когда мы используем метод фиксации/отката, а счетчик транзакций равен 1.

Request1:
    Transaction.begin() // Hybris Counter = 1
    doSomething() // This throws Exception, Application Exit, Hybris Counter is still 1
    try {
        Transaction.commit()
    } catch (Exception e) {
        Transaction.rollback();
    }

Request2 on same thread:
    Transaction.begin() // Hybris Counter now is 2
    doSomething() // Works OK, Hybris Counter is still 2
    try {       
        Transaction.commit() // HybrisCounter -= 1
        // Transaction is not commited to DB because Hybris counter now is 1
    } catch (Exception e) {
        Transaction.rollback();
    }

Request3 on same thread:
    Transaction.begin() // Hybris Counter now is 2
    lockRow() 
    // Row is locked for the whole transaction (the same opened in R1)
    // Everything is OK
    try {       
        Transaction.commit() // HybrisCounter -= 1
        // Transaction is not commited to DB because Hybris counter now is 1
        // Row is still locked
        // Next requests to the same row will wait lock forever
    } catch (Exception e) {
        Transaction.rollback();
    }
person Vincenzo    schedule 27.02.2020