Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id BC785200D4B for ; Mon, 27 Nov 2017 15:35:21 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id BAE78160C13; Mon, 27 Nov 2017 14:35:21 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id DAED7160C02 for ; Mon, 27 Nov 2017 15:35:20 +0100 (CET) Received: (qmail 42996 invoked by uid 500); 27 Nov 2017 14:35:20 -0000 Mailing-List: contact user-help@cayenne.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cayenne.apache.org Delivered-To: mailing list user@cayenne.apache.org Received: (qmail 42985 invoked by uid 99); 27 Nov 2017 14:35:19 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd2-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 27 Nov 2017 14:35:19 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd2-us-west.apache.org (ASF Mail Server at spamd2-us-west.apache.org) with ESMTP id ECB8A1A0EE0 for ; Mon, 27 Nov 2017 14:35:18 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd2-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 0.3 X-Spam-Level: X-Spam-Status: No, score=0.3 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, RCVD_IN_DNSWL_LOW=-0.7] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd2-us-west.apache.org [10.40.0.9]) (amavisd-new, port 10024) with ESMTP id k2KN3IU7KydI for ; Mon, 27 Nov 2017 14:35:16 +0000 (UTC) Received: from mail-03.1984.is (mail-03.1984.is [93.95.224.70]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTPS id 678B65F1B3 for ; Mon, 27 Nov 2017 14:35:15 +0000 (UTC) Received: from localhost by mail-03.1984.is with esmtpsa (TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eJKV6-0006En-Li for user@cayenne.apache.org; Mon, 27 Nov 2017 14:35:12 +0000 From: Hugi Thordarson Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: quoted-printable Mime-Version: 1.0 (Mac OS X Mail 11.1 \(3445.4.7\)) Subject: =?utf-8?Q?Re=3A_Exception/Transaction_problems_when_performing_DB?= =?utf-8?Q?-access_in_a_thread_inside_a_CommitLogListener_=E2=80=94_but_on?= =?utf-8?Q?ly_if_using_a_3rd_party_Connection_Pool?= Date: Mon, 27 Nov 2017 14:35:14 +0000 References: <764E2B71-433C-42E1-A720-53857DB388EF@karlmenn.is> To: user@cayenne.apache.org In-Reply-To: Message-Id: X-Mailer: Apple Mail (2.3445.4.7) archived-at: Mon, 27 Nov 2017 14:35:21 -0000 Hi Nikita, Thanks for replying. I just found out that for this specific case, = CommitLogFilter has a nice little method called = "excludeFromTransaction()" that handles exactly this case, i.e. makes = onPostCommit do it's work inside it's own transaction. (boy, do I ever = wish I knew this earlier) But thanks for the code example, quite interesting and might be useful = in a later situation! Cheers, - hugi > On 27 Nov 2017, at 14:20, Nikita Timofeev = wrote: >=20 > Hi, >=20 > The problem seems in InheritableThreadLocal that stores current > transaction [1]. When you start new Thread from the one that already > have bound transaction it will grab that transaction. In your case > this leads to exception as transaction already committed (exactly as > error say). > Probably we should rethink this behavior. > Right now this logic is not configurable as it is completely static, > so it can't be easily changed. >=20 > However you can try to manually start new transaction with a code > similar to one found in DefaultTransactionManager [2]. >=20 > Following method fixes your demo project: >=20 > static T runInNewTransaction(TransactionalOperation operation) = { > TransactionFactory factory =3D > serverRuntime().getInjector().getInstance(TransactionFactory.class); >=20 > Transaction tx =3D factory.createTransaction(); > Transaction oldTransaction =3D = BaseTransaction.getThreadTransaction(); >=20 > BaseTransaction.bindThreadTransaction(tx); > try { > T result =3D operation.perform(); > tx.commit(); > return result; > } catch (CayenneRuntimeException ex) { > tx.setRollbackOnly(); > throw ex; > } catch (Exception ex) { > tx.setRollbackOnly(); > throw new CayenneRuntimeException(ex); > } finally { > BaseTransaction.bindThreadTransaction(oldTransaction); >=20 > if (tx.isRollbackOnly()) { > try { > tx.rollback(); > } catch (Exception e) { > //e.printStackTrace(); > } > } > } > } >=20 > ... >=20 > @Override > public void onPostCommit( ObjectContext originatingContext, ChangeMap > changes ) { > new Thread( () -> > runInNewTransaction(() -> { > serverRuntime().newContext().select( new > SelectQuery<>( "Person" ) ); > return null; > }), "afterUpdateThread" ).start(); > } >=20 >=20 > [1] = https://github.com/apache/cayenne/blob/bd1b109a943307a83078399c7a4d6aa5363= 1a065/cayenne-server/src/main/java/org/apache/cayenne/tx/BaseTransaction.j= ava#L41 > [2] = https://github.com/apache/cayenne/blob/bd1b109a943307a83078399c7a4d6aa5363= 1a065/cayenne-server/src/main/java/org/apache/cayenne/tx/DefaultTransactio= nManager.java#L55 >=20 > On Sat, Nov 25, 2017 at 7:11 PM, Hugi Thordarson = wrote: >> Hi all. >> I've been fighting a bug that's been a pain to replicate. Here's a = small self-contained project that demonstrates the issue: >>=20 >> https://github.com/hugith/concurrencytest-simple/ >>=20 >> Just run Main.java to see it happen: >>=20 >> = https://github.com/hugith/concurrencytest-simple/blob/master/src/main/java= /concurrencytest/Main.java >>=20 >> The subject basically says it all: If I touch the DB in a Thread = inside a CommitLogListener AND am using a connection pool, it will fail = with the Exception/trace shown below. But the real kicker: This only = happens if I'm using a 3rd party connection pool (I've tried both = HikariCP and c3p0 so I assume it's generic). If I just have Cayenne = handle the DB connection for me, everything works fine. >>=20 >> I've been attempting to figure out what the issue is but I'm somewhat = at a loss. Any ideas what might be happening? >>=20 >> Cheers, >> - hugi >>=20 >> ---------------------------------- >>=20 >> java.lang.IllegalStateException: Transaction must have = 'STATUS_ACTIVE' to add a connection. Current status: STATUS_COMMITTED >> at = org.apache.cayenne.tx.BaseTransaction.connectionAdded(BaseTransaction.java= :246) >> at = org.apache.cayenne.tx.CayenneTransaction.connectionAdded(CayenneTransactio= n.java:49) >> at = org.apache.cayenne.tx.BaseTransaction.addConnection(BaseTransaction.java:2= 31) >> at = org.apache.cayenne.tx.BaseTransaction.getOrCreateConnection(BaseTransactio= n.java:203) >> at = org.apache.cayenne.access.DataNode$TransactionDataSource.getConnection(Dat= aNode.java:446) >> at = org.apache.cayenne.access.DataNode.performQueries(DataNode.java:273) >> at = org.apache.cayenne.access.DataDomainQueryAction.runQuery(DataDomainQueryAc= tion.java:471) >> at = org.apache.cayenne.access.DataDomainQueryAction.access$000(DataDomainQuery= Action.java:72) >> at = org.apache.cayenne.access.DataDomainQueryAction$2.perform(DataDomainQueryA= ction.java:446) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:87) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:51) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:40) >> at = org.apache.cayenne.access.DataDomainQueryAction.runQueryInTransaction(Data= DomainQueryAction.java:443) >> at = org.apache.cayenne.access.DataDomainQueryAction.execute(DataDomainQueryAct= ion.java:122) >> at = org.apache.cayenne.access.DataDomain.onQueryNoFilters(DataDomain.java:564)= >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.commitlog.CommitLogFilter.onQuery(CommitLogFilter.java:= 61) >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.tx.TransactionFilter.onQuery(TransactionFilter.java:49)= >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.access.DataDomain.onQuery(DataDomain.java:556) >> at = org.apache.cayenne.util.ObjectContextQueryAction.runQuery(ObjectContextQue= ryAction.java:406) >> at = org.apache.cayenne.util.ObjectContextQueryAction.executePostCache(ObjectCo= ntextQueryAction.java:107) >> at = org.apache.cayenne.util.ObjectContextQueryAction.execute(ObjectContextQuer= yAction.java:94) >> at = org.apache.cayenne.access.DataContext.onQuery(DataContext.java:965) >> at = org.apache.cayenne.access.DataContext.performQuery(DataContext.java:954) >> at org.apache.cayenne.BaseContext.select(BaseContext.java:307) >> at = org.apache.cayenne.query.FluentSelect.select(FluentSelect.java:157) >> at = concurrencytest.Main$AfterUpdateListener.lambda$0(Main.java:61) >> at java.lang.Thread.run(Thread.java:748) >> Exception in thread "afterUpdateThread" = org.apache.cayenne.CayenneRuntimeException: [v.4.1.M1 Oct 06 2017 = 09:23:31] Global exception. >> at = org.apache.cayenne.access.DataDomainQueryAction.nextGlobalException(DataDo= mainQueryAction.java:619) >> at = org.apache.cayenne.access.DataNode.performQueries(DataNode.java:282) >> at = org.apache.cayenne.access.DataDomainQueryAction.runQuery(DataDomainQueryAc= tion.java:471) >> at = org.apache.cayenne.access.DataDomainQueryAction.access$000(DataDomainQuery= Action.java:72) >> at = org.apache.cayenne.access.DataDomainQueryAction$2.perform(DataDomainQueryA= ction.java:446) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:87) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:51) >> at = org.apache.cayenne.tx.DefaultTransactionManager.performInTransaction(Defau= ltTransactionManager.java:40) >> at = org.apache.cayenne.access.DataDomainQueryAction.runQueryInTransaction(Data= DomainQueryAction.java:443) >> at = org.apache.cayenne.access.DataDomainQueryAction.execute(DataDomainQueryAct= ion.java:122) >> at = org.apache.cayenne.access.DataDomain.onQueryNoFilters(DataDomain.java:564)= >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.commitlog.CommitLogFilter.onQuery(CommitLogFilter.java:= 61) >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.tx.TransactionFilter.onQuery(TransactionFilter.java:49)= >> at = org.apache.cayenne.access.DataDomain$DataDomainQueryFilterChain.onQuery(Da= taDomain.java:748) >> at = org.apache.cayenne.access.DataDomain.onQuery(DataDomain.java:556) >> at = org.apache.cayenne.util.ObjectContextQueryAction.runQuery(ObjectContextQue= ryAction.java:406) >> at = org.apache.cayenne.util.ObjectContextQueryAction.executePostCache(ObjectCo= ntextQueryAction.java:107) >> at = org.apache.cayenne.util.ObjectContextQueryAction.execute(ObjectContextQuer= yAction.java:94) >> at = org.apache.cayenne.access.DataContext.onQuery(DataContext.java:965) >> at = org.apache.cayenne.access.DataContext.performQuery(DataContext.java:954) >> at org.apache.cayenne.BaseContext.select(BaseContext.java:307) >> at = org.apache.cayenne.query.FluentSelect.select(FluentSelect.java:157) >> at = concurrencytest.Main$AfterUpdateListener.lambda$0(Main.java:61) >> at java.lang.Thread.run(Thread.java:748) >> Caused by: java.lang.IllegalStateException: Transaction must have = 'STATUS_ACTIVE' to add a connection. Current status: STATUS_COMMITTED >> at = org.apache.cayenne.tx.BaseTransaction.connectionAdded(BaseTransaction.java= :246) >> at = org.apache.cayenne.tx.CayenneTransaction.connectionAdded(CayenneTransactio= n.java:49) >> at = org.apache.cayenne.tx.BaseTransaction.addConnection(BaseTransaction.java:2= 31) >> at = org.apache.cayenne.tx.BaseTransaction.getOrCreateConnection(BaseTransactio= n.java:203) >> at = org.apache.cayenne.access.DataNode$TransactionDataSource.getConnection(Dat= aNode.java:446) >> at = org.apache.cayenne.access.DataNode.performQueries(DataNode.java:273) >> ... 24 more >>=20 >=20 >=20 >=20 > --=20 > Best regards, > Nikita Timofeev