rollbacked transaction is lost from pool. WFLY-18253?

[Tom Eicher]

Hello,

in a production application with millions of database transactions a day,

on wildfly 26.1.3,

using an AbstractMultiTenantConnectionProvider to have multiple tenants,

on rare occasions we get an error in the EJB layer, actually we throw an IllegalStateException ourselved, and this propagates up to a

ERROR [org.jboss.as.ejb3.invocation] (default task-1) WFLYEJB0034: Jakarta Enterprise Beans Invocation failed on component xxxDAO for method public xxx xxxDAO.findByName(java.lang.String): javax.ejb.EJBTransactionRolledbackException: Query for retrieving values of xxx returned more than the single expected result!

that is very fine an expected/intended. However, subsequent calls to the same method now return a

WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-1) SQL Error: 0, SQLState: null
ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-1) IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK
ERROR [org.jboss.as.ejb3.invocation] (default task-1) WFLYEJB0034: Jakarta Enterprise Beans Invocation failed on component xxxDAO for method public xxx xxxDAO.findByName(java.lang.String): javax.ejb.EJBTransactionRolledbackException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection

I see this stack as the root cause (the setSchema is in my MultiTenantConnectionProvider)

Caused by: java.sql.SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK
at org.jboss.jca.adapters.jdbc.WrapperDataSource.checkTransactionActive(WrapperDataSource.java:272)
at org.jboss.jca.adapters.jdbc.WrappedConnection.checkTransactionActive(WrappedConnection.java:2005)
at org.jboss.jca.adapters.jdbc.WrappedConnection.checkStatus(WrappedConnection.java:2020)
at org.jboss.jca.adapters.jdbc.WrappedConnection.checkTransaction(WrappedConnection.java:1994)
at org.jboss.jca.adapters.jdbc.WrappedConnection.setSchema(WrappedConnection.java:1781)
at xxxlMultiTenantConnectionProvider.getConnection(xxxTenantConnectionProvider.java:64)

and I could live with all that, but this connection now remains broken and is never returned to the pool, so over time, as this happens now and then, my pool is being depleted until I need to restart the appserver.

The stack looks very similar to

https://issues.redhat.com/browse/WFLY-18253

and I would say I didn't have this issue in other wildfly version before.

Do you think it is related?

As we can't upgrade to jakarta for some time, is there anything I can do to remedy the situation?

Like do something special in the AbstractMultiTenantConnectionProvider.releaseConnection()?

Or some connection settings?

Ideas and Opinions appreciated,

Cheers Tom.

[Scott Marlow]

Which class is holding onto the broken connection and why?  Does your MultiTenantConnectionProvider class normally get called to close the connection when errors do not occur?  Is it the MultiTenantConnectionProvider.releaseAnyConnection(Connection) that is called normally to release the connection?

Or is it the WildFly connection pool management that normally returns the MultiTenantConnectionProvider obtained connection to the connection pool?

If you can simulate the failure on your local machine, you might enable TRACE logging as mentioned in the troubleshooting section https://docs.wildfly.org/31/Developer_Guide.html#troubleshooting.  For this situation, you could enable TRACE LOGGING via:

<logger category="org.jboss.jca">
<level name="TRACE"/>
</logger>

<logger category="org.jboss.jpa">
<level name="TRACE"/>
</logger>

The org.jboss.jpa tracing might just show the persistence calls which just better shows the application flow.  The org.jboss.jca tracing should show more details about the connection handling. 

Also see instructions 1-4 in my comment on issue https://issues.redhat.com/browse/WFLY-19082?focusedId=24400493&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-24400493 that talks about setting additional trace out for connections which may also show more info that is relevant.

Scott

--
You received this message because you are subscribed to the Google Groups "WildFly" group.
To unsubscribe from this group and stop receiving emails from it, send an email to wildfly+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/wildfly/54c2d0c9-a9ff-4446-83a2-5521408fb8fen%40googlegroups.com.

[Tom Eicher]

Hello, ok, so the situation is:

probably due to WFLY-19082, a setSchema inside my AbstractMultiTenantConnectionProvider.getConnection() nowadays might throw a SQLException.

Former code (working since JBoss 7.2.0 ;-) did not account for an Exception to occur inside getConnection(), and thus failed to return the connection to the pool (just exiting getConnection() by exception).

So using this workaround I can remedy the connection leak:

@Override
public Connection getConnection(String identifier) throws SQLException {
String[] tenantCrowd = splitTenantToken(identifier);
Connection c = super.getConnection(tenantCrowd[0]);
        try {
            c.setSchema(tenantCrowd[1]); 
        } catch (Exception sqle) {
            if (c!=null) {
            log.warn("broken connection encountered in getConnection("+identifier+") - releasing manually. "+sqle);
            releaseConnection(tenantCrowd[0], c);
            throw sqle;
            }
        }
return c;
}

Behaviour is a bit different than before, because since we can't pass on the (already-marked-for-rollback) tx, subsequent calls within the same TX now throw a 

GenericJDBCException: Unable to acquire JDBC Connection

but this can't be helped probably, and the main thing is not to have a connection leak here.

Any second thoughts? 

Cheers Tom.

[Scott Marlow]

On Fri, Apr 5, 2024 at 9:43 AM 'Tom Eicher' via WildFly <wil...@googlegroups.com> wrote:

Hello, ok, so the situation is:

probably due to WFLY-19082, a setSchema inside my AbstractMultiTenantConnectionProvider.getConnection() nowadays might throw a SQLException.

Interesting as I was just looking a bit more at https://issues.redhat.com/browse/WFLY-19082.  My comment from today on WFLY-19082 suggests two possible ways to work around the "IJ000152: Trying to return an unknown connection".

If you are getting the  "IJ000152: Trying to return an unknown connection" failure, could you please call sqle.printStackTrace() and add a comment to WFLY-19082 with the printed exception and mention this forum thread.

Thanks,

Scott

Former code (working since JBoss 7.2.0 ;-) did not account for an Exception to occur inside getConnection(), and thus failed to return the connection to the pool (just exiting getConnection() by exception).

So using this workaround I can remedy the connection leak:

@Override
public Connection getConnection(String identifier) throws SQLException {
String[] tenantCrowd = splitTenantToken(identifier);
Connection c = super.getConnection(tenantCrowd[0]);
        try {
            c.setSchema(tenantCrowd[1]); 
        } catch (Exception sqle) {
            if (c!=null) {
            log.warn("broken connection encountered in getConnection("+identifier+") - releasing manually. "+sqle);
            releaseConnection(tenantCrowd[0], c);
            throw sqle;
            }
        }
return c;
}

Behaviour is a bit different than before, because since we can't pass on the (already-marked-for-rollback) tx, subsequent calls within the same TX now throw a 

GenericJDBCException: Unable to acquire JDBC Connection

but this can't be helped probably, and the main thing is not to have a connection leak here.

Any second thoughts? 

Cheers Tom.

--

You received this message because you are subscribed to the Google Groups "WildFly" group.
To unsubscribe from this group and stop receiving emails from it, send an email to wildfly+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/wildfly/c1171da1-6225-4e33-b667-7a7dbebd21den%40googlegroups.com.

[Tom Eicher (von unterwegs)]

No i got

IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK

Still imterested?

Tom.

---

Von:

Scott Marlow <sma...@redhat.com>

Gesendet: 5. April 2024 19:55:45 MESZ
An:

Tom Eicher <teich...@googlemail.com>

CC:

WildFly <wil...@googlegroups.com>

Betreff:

Re: rollbacked transaction is lost from pool. WFLY-18253?

--
Gesendet vom Mobiltelefon - Bitte Tippfehler, fehlende Umlaute und Kürze gegebenenfalls zu entschuldigen.

[Scott Marlow]

On 4/5/24 15:04, Tom Eicher (von unterwegs) wrote:

No i got

IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK

Still imterested?

My interest in WFLY-19082 would only be if you also got the "IJ000152: Trying to return an unknown connection" failure as a cause for why c.setSchema(tenantCrowd[1]) fails sometimes.  The reason being to understand that better.  I think the interesting think to understand is as to why the Active JTA transaction was marked to rollback.

The "IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK" error is thrown to force the request being processed to fail early/immediately with an error instead of continuing to run possibly for a long time.  Is there a previous server.log error logged from the same thread as the one that gets the "IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK" error?

Scott

To view this discussion on the web visit https://groups.google.com/d/msgid/wildfly/1E5672D6-187A-4573-8273-31EDB6F9BA30%40teicher.net.

[Tom Eicher (von unterwegs)]

Sorry no IJ000152 here.

Tx is marked rollback only because I throw an Exception from EJB layer deliberately.

The (new) problem is just that I now cannot call setSchema on such a tx (which doesnt make sense IMHO - why should this be forbidden now...).

Cheers tom.

---

Von:

Scott Marlow <sma...@redhat.com>

Gesendet: 5. April 2024 21:29:34 MESZ
An:

"Tom Eicher (von unterwegs)" <ro...@teicher.net>, WildFly <wil...@googlegroups.com>

[Scott Marlow]

On 4/5/24 16:43, Tom Eicher (von unterwegs) wrote:

Sorry no IJ000152 here.

Tx is marked rollback only because I throw an Exception from EJB layer deliberately.

The (new) problem is just that I now cannot call setSchema on such a tx (which doesnt make sense IMHO - why should this be forbidden now...).

https://github.com/ironjacamar/ironjacamar/blob/9c7bda20b5c3a05acbc396db6db4e5e6eb4aec31/adapters/src/main/java/org/jboss/jca/adapters/jdbc/WrapperDataSource.java#L270 has the check if the JTA transaction has been marked as rollback only that throws an exception to fail early (e.g. throw an exception to halt the current application work in current thread).  In earlier versions, we didn't have that check so the JTA transaction marked for rollback-only could go on running for a long time. 

Another workaround (in your code) could be to check if there is an active JTA transaction and don't call setSchema() if there is an active JTA transaction that has been marked for rollback-only. 

Scott

To view this discussion on the web visit https://groups.google.com/d/msgid/wildfly/C0229037-D0E3-418B-86C0-2D7083293F98%40teicher.net.

[Tom Eicher]

Well, previously transaction marked as read-only could go
on running, and performing read operations and doing stuff,
just not commit the result at the end.

This is desireable for e.g. an import job, that wants
to process all data (rows) and report a summary at the end.

Example: I need to import 1000 data rows, and 500 and 700
are bad. Previously, I got 998 good operations and 2 bad,
now I get 499 good and 501 bad.

And in the case of a AbstractMultiTenantConnectionProvider,
I cannot omit the call to setSchema, or the TX might read
data from the wrong Schema, i.e. wrong Tenant.
(The BigMac appearing the the BurgerKing sales, if you know
what I mean ;-)

I was under the impression, from WFLY-18253,
that from WF30 that would would again?

[Scott Marlow]

Tom,

Thanks for raising this discussion and your concern which likely is also shared by others who have not reached out. 

On 4/6/24 06:55, Tom Eicher wrote:

Well, previously transaction marked as read-only could go
on running, and performing read operations and doing stuff,
just not commit the result at the end.

This is desireable for e.g. an import job, that wants
to process all data (rows) and report a summary at the end.

I understand and wonder if a new (datasource?) FAIL_ON_ROLLBACK configuration setting would help that would default to true but could be overridden to be false to get back the old behavior.

Example: I need to import 1000 data rows, and 500 and 700
are bad. Previously, I got 998 good operations and 2 bad,
now I get 499 good and 501 bad.

And in the case of a AbstractMultiTenantConnectionProvider,
I cannot omit the call to setSchema, or the TX might read
data from the wrong Schema, i.e. wrong Tenant.
(The BigMac appearing the the BurgerKing sales, if you know
what I mean ;-)

I get it ;-)

I was under the impression, from WFLY-18253,
that from WF30 that would would again?

The (https://issues.redhat.com/browse/JBJCA-1473)  https://github.com/ironjacamar/ironjacamar/pull/775 change does not change setSchema.

[Tom Eicher GMail]

Thanks Scott,

>> Well, previously transaction marked as read-only could go
>> on running, and performing read operations and doing stuff,
>> just not commit the result at the end.
>>
>> This is desireable for e.g. an import job, that wants
>> to process all data (rows) and report a summary at the end.
>
> I understand and wonder if a new (datasource?) FAIL_ON_ROLLBACK
> configuration setting would help that would default to true but could be
> overridden to be false to get back the old behavior.

Well, I personally have no love for the new behavior at all ;-)
but of course a switch somewhere would be better than nothing.

IMHO a fail-early makes no sense for non-write operations.

That would be all set*ters in Connection (setSchema, setNetworkTimeout,
...) maybe except setSavePoint(...) and setReadOnly() ?

>> I was under the impression, from WFLY-18253,
>> that from WF30 that would would again?
> The (https://issues.redhat.com/browse/JBJCA-1473)
> https://github.com/ironjacamar/ironjacamar/pull/775 change does not
> change setSchema.

What a pity.

So we need a new issue here?

Thanks Cheers Tom.

[Scott Marlow]

On Mon, Apr 8, 2024 at 11:45 AM 'Tom Eicher GMail' via WildFly <wil...@googlegroups.com> wrote:

Thanks Scott,

>> Well, previously transaction marked as read-only could go
>> on running, and performing read operations and doing stuff,
>> just not commit the result at the end.
>>
>> This is desireable for e.g. an import job, that wants
>> to process all data (rows) and report a summary at the end.
>
> I understand and wonder if a new (datasource?) FAIL_ON_ROLLBACK
> configuration setting would help that would default to true but could be
> overridden to be false to get back the old behavior.

Well, I personally have no love for the new behavior at all ;-)
but of course a switch somewhere would be better than nothing.

Thanks again for bringing attention to your use case.  I think it would also bring in compatibility with the previous behavior.  If you would like the FAIL_ON_ROLLBACK configuration setting, please open a https://issues.redhat.com/browse/JBJCA issue to request that and mention the issue on this thread.

 

IMHO a fail-early makes no sense for non-write operations.

That would be all set*ters in Connection (setSchema, setNetworkTimeout,
...) maybe except setSavePoint(...) and setReadOnly() ?

>> I was under the impression, from WFLY-18253,
>> that from WF30 that would would again?
> The (https://issues.redhat.com/browse/JBJCA-1473)
> https://github.com/ironjacamar/ironjacamar/pull/775 change does not
> change setSchema.

It looks like JBJCA-1473 was for addressing a more specific change.

 

What a pity.

So we need a new issue here?

Yes, please do open a new issue for making the change that you think would work better. 

Scott

 

Thanks Cheers Tom.

--
You received this message because you are subscribed to the Google Groups "WildFly" group.
To unsubscribe from this group and stop receiving emails from it, send an email to wildfly+u...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/wildfly/3a867445-380e-43f3-bf60-5be60239d4b8%40googlemail.com.

[Tom Eicher]

So, finally, I filed this:

https://issues.redhat.com/browse/JBJCA-1491

[Tom Eicher]

It didn't meet much interest, though :-(