[JBEAP-26114] (8.0.z) [CLUSTERING] Client fail rate degradation in tests with Oracle database

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 8.0 Update 2
Affects Version/s: 8.0.0.GA-CR2
Component/s: Clustering
Labels:
None

Blocked:
False
Blocked Reason:
None
Ready:
False
Affects Testing:

Regression
CDW blocker:
CDW devel_ack:
CDW docs_ack:
CDW pm_ack:
CDW qa_ack:
CDW release:
QE Test Coverage:
+
Target Release:

8.0.z.GA
Git Pull Request:
https://github.com/jbossas/jboss-eap8/pull/272
Intelligence Requested:
Market:

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

This jira is a regression against EAP 8.0.0.CR1 (see comment below);

Scenario: fail-over scenario where we have the usual 4 nodes cluster where each node is configured to store session data into an invalidation-cache backed by an Oracle 19c RAC Database;

This is a quite common scenario where session data is offloaded to some relational database, in facts we test it with all supported databases;

Each node is running on JDK11;
Each node is configured as in the following:

embed-server --server-config=standalone-ha.xml
/subsystem=jgroups/channel=ee:write-attribute(name=stack,value=tcp)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload:add()
data-source add --name=testDS --jndi-name=java:jboss/datasources/testDS --driver-name=oracle-connector.jar --connection-url=jdbc:oracle:thin:@(DESCRIPTION=(LOAD_BALANCE=on)(ADDRESS=(PROTOCOL=TCP)(HOST=oracle-19c-rac-01.mwqe.upshift.rdu2.redhat.com)(PORT=1521))(ADDRESS=(PROTOCOL=TCP)(HOST=oracle-19c-rac-02.mwqe.upshift.rdu2.redhat.com)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=dballo))) --enabled=true --jta=true --use-java-context=true --transaction-isolation=TRANSACTION_READ_COMMITTED --min-pool-size=1 --max-pool-size=5 --pool-prefill=true --user-name=dballo15 --password=dballo15 --prepared-statements-cache-size=32 --share-prepared-statements=true
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc:add(data-source=testDS,fetch-state=false,passivation=false,purge=false,shared=true,dialect=ORACLE){allow-resource-service-restart=true}
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=id-column.name,value=id)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=data-column.name,value=datum)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=timestamp-column.name,value=version)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=id-column.type,value=VARCHAR2(255))
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=timestamp-column.type,value=NUMBER)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=data-column.type,value=BLOB)
/subsystem=infinispan/cache-container=web/invalidation-cache=offload/store=jdbc/table=string:write-attribute(name=prefix, value=i){allow-resource-service-restart=true}
/subsystem=infinispan/cache-container=web:write-attribute(name=default-cache, value=offload)
/subsystem=transactions:write-attribute(name=node-identifier,value=wildfly1)

Here is the overall client fail rate:

EAP 7.4.13: Client fail rate 0.55%
EAP 8.0.0.GA-CR1: Client fail rate 0.629%
EAP 8.0.0.GA-CR2.1: Client fail rate 4.32%

Rado: failures here are caused by https://issues.redhat.com/browse/JBEAP-26114?focusedId=23526646&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-23526646

Please note we always used the very same Database instance and the very same host for all 3 versions;

The outstanding error that we observe in CR2, is "ORA-01555: snapshot too old: rollback segment number with name "" too small":

2023-11-23 10:27:31,202 ERROR [org.infinispan.PERSISTENCE] (SchedulerTopologyChangeListener - 2) ISPN008009: I/O error while unmarshalling from stream: java.io.IOException: ORA-01555: snapshot too old: rollback segment number  with name "" too small
ORA-22924: snapshot too old

	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBlobInputStream.needBytes(OracleBlobInputStream.java:239)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBufferedStream.needBytes(OracleBufferedStream.java:127)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBufferedStream.readInternal(OracleBufferedStream.java:187)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBufferedStream.read(OracleBufferedStream.java:171)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.impl.TagReaderImpl$InputStreamDecoder.isMarkDone(TagReaderImpl.java:1022)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.impl.TagReaderImpl$InputStreamDecoder.isAtEnd(TagReaderImpl.java:1008)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.impl.TagReaderImpl$Decoder.readTag(TagReaderImpl.java:305)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.impl.TagReaderImpl.readTag(TagReaderImpl.java:97)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.WrappedMessage.readMessage(WrappedMessage.java:365)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.WrappedMessage.read(WrappedMessage.java:351)
	at org.infinispan.protostream@4.6.5.Final-redhat-00003//org.infinispan.protostream.ProtobufUtil.fromWrappedStream(ProtobufUtil.java:137)
	at org.infinispan@14.0.17.Final-redhat-00002//org.infinispan.marshall.protostream.impl.AbstractInternalProtoStreamMarshaller.readObject(AbstractInternalProtoStreamMarshaller.java:120)
	at org.infinispan.persistence.jdbc@14.0.17.Final-redhat-00002//org.infinispan.persistence.jdbc.common.JdbcUtil.unmarshall(JdbcUtil.java:68)
	at org.infinispan.persistence.jdbc@14.0.17.Final-redhat-00002//org.infinispan.persistence.jdbc.impl.table.AbstractTableManager.entryFromResultSet(AbstractTableManager.java:630)
	at org.infinispan.persistence.jdbc@14.0.17.Final-redhat-00002//org.infinispan.persistence.jdbc.common.sql.BaseTableOperations$ResultSetEntryIterator.getNext(BaseTableOperations.java:301)
	at org.infinispan.persistence.jdbc@14.0.17.Final-redhat-00002//org.infinispan.persistence.jdbc.common.sql.BaseTableOperations$ResultSetEntryIterator.getNext(BaseTableOperations.java:286)
	at org.infinispan.commons@14.0.17.Final-redhat-00002//org.infinispan.commons.util.AbstractIterator.hasNext(AbstractIterator.java:26)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorSubscription.slowPath(FlowableFromIterable.java:253)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:131)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableDoFinally$DoFinallySubscriber.request(FlowableDoFinally.java:108)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing$UsingSubscriber.request(FlowableUsing.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.request(BasicFuseableSubscriber.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing$UsingSubscriber.request(FlowableUsing.java:153)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.subscriptions.SubscriptionArbiter.setSubscription(SubscriptionArbiter.java:87)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableConcatArray$ConcatArraySubscriber.onSubscribe(FlowableConcatArray.java:72)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing$UsingSubscriber.onSubscribe(FlowableUsing.java:98)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.subscribers.BasicFuseableSubscriber.onSubscribe(BasicFuseableSubscriber.java:67)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing$UsingSubscriber.onSubscribe(FlowableUsing.java:98)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableDoFinally$DoFinallySubscriber.onSubscribe(FlowableDoFinally.java:79)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:69)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableDoFinally.subscribeActual(FlowableDoFinally.java:47)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15959)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing.subscribeActual(FlowableUsing.java:73)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:38)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15959)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableUsing.subscribeActual(FlowableUsing.java:73)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15959)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableConcatArray$ConcatArraySubscriber.onComplete(FlowableConcatArray.java:141)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableConcatArray.subscribeActual(FlowableConcatArray.java:41)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableMap.subscribeActual(FlowableMap.java:36)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableFilter.subscribeActual(FlowableFilter.java:38)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.FlowableOnErrorNext.subscribeActual(FlowableOnErrorNext.java:39)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:16013)
	at io.reactivex.rxjava3.rxjava@3.1.6.redhat-00001//io.reactivex.rxjava3.internal.operators.flowable.BlockingFlowableIterable.iterator(BlockingFlowableIterable.java:42)
	at org.infinispan.commons@14.0.17.Final-redhat-00002//org.infinispan.commons.util.Closeables.iterator(Closeables.java:238)
	at org.infinispan@14.0.17.Final-redhat-00002//org.infinispan.stream.impl.DistributedCacheStream.iterator(DistributedCacheStream.java:370)
	at org.infinispan@14.0.17.Final-redhat-00002//org.infinispan.util.AbstractDelegatingCacheStream.iterator(AbstractDelegatingCacheStream.java:182)
	at org.wildfly.clustering.ee.infinispan@8.0.0.GA-redhat-00010//org.wildfly.clustering.ee.infinispan.scheduler.ScheduleLocalKeysTask.accept(ScheduleLocalKeysTask.java:61)
	at org.wildfly.clustering.ee.infinispan@8.0.0.GA-redhat-00010//org.wildfly.clustering.ee.infinispan.scheduler.ScheduleLocalKeysTask.accept(ScheduleLocalKeysTask.java:42)
	at org.wildfly.clustering.ee.infinispan@8.0.0.GA-redhat-00010//org.wildfly.clustering.ee.infinispan.scheduler.SchedulerTopologyChangeListener.lambda$topologyChanged(SchedulerTopologyChangeListener.java:121)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.wildfly.clustering.context@8.0.0.GA-redhat-00010//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49)
	at org.wildfly.clustering.context@8.0.0.GA-redhat-00010//org.wildfly.clustering.context.ContextualExecutor.run(ContextualExecutor.java:78)
	at java.base/java.lang.Thread.run(Thread.java:834)
	at org.jboss.threads@2.4.0.Final-redhat-00001//org.jboss.threads.JBossThread.run(JBossThread.java:513)
Caused by: java.sql.SQLException: ORA-01555: snapshot too old: rollback segment number  with name "" too small
ORA-22924: snapshot too old

	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:509)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:456)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:451)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4C8TTILob.processError(T4C8TTILob.java:838)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:553)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:269)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4C8TTILob.read(T4C8TTILob.java:159)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.T4CConnection.getBytes(T4CConnection.java:3647)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBlob.getBytes(OracleBlob.java:382)
	at deployment.oracle-connector.jar//oracle.jdbc.driver.OracleBlobInputStream.needBytes(OracleBlobInputStream.java:220)
	... 66 more

it is emitted on nodes 2 and 3 right after node1 has been shut down:

2023-11-23 10:27:26,003 INFO  [org.jboss.as] (MSC service thread 1-5) WFLYSRV0050: JBoss EAP 8.0.0.GA (WildFly Core 21.0.4.Final-redhat-00001) stopped in 1342ms

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

server-logs.zip
28.10 MB
2023/11/23 2:28 PM

is cloned by

WFLY-18785 Client fail rate degradation in tests with Oracle database: IJ000453: Unable to get managed connection for ... + StoreUnavailableException

Closed

is incorporated by

JBEAP-26770 (8.0.z) Upgrade EAP codebase to 8.0.3.GA-redhat-SNAPSHOT in EAP 8.0 Update 2

Closed

is related to

JBEAP-26112 (8.0.z) [CLUSTERING]: java.io.InvalidClassException with ORACLE Data store

Closed

Michaela Osmerova added a comment - 2024/08/19 1:59 PM

As all verified issues should change to closed status, closing them with the bulk update.

Michaela Osmerova added a comment - 2024/08/19 1:59 PM As all verified issues should change to closed status, closing them with the bulk update.

Paul Ferraro added a comment - 2023/11/29 5:44 PM

Given the result in the comment above, I'm lowing the priority of this.

Paul Ferraro added a comment - 2023/11/29 5:44 PM Given the result in the comment above, I'm lowing the priority of this.

Radoslav Husar added a comment - 2023/11/24 12:54 PM

Just an update, the proposed fix is the https://github.com/jbossas/jboss-eap8/pull/269 which reverts workaround for JBEAP-25812. This solves all the connection pooling issues to the database, but QE runs are still hitting java.io.IOException: ORA-01555: snapshot too old: rollback segment number with name "" too small in their lab with one instance from DBAllocator but when using dockerized free version, there is are no isssues.

Radoslav Husar added a comment - 2023/11/24 12:54 PM Just an update, the proposed fix is the https://github.com/jbossas/jboss-eap8/pull/269 which reverts workaround for JBEAP-25812 . This solves all the connection pooling issues to the database, but QE runs are still hitting java.io.IOException: ORA-01555: snapshot too old: rollback segment number with name "" too small in their lab with one instance from DBAllocator but when using dockerized free version, there is are no isssues.

Tommaso Borgato added a comment - 2023/11/23 2:31 PM - edited

rhn-engineering-rhusar I added fail-over to the description;
You are right and the job name might not be correct;
Serial is always off (stale) by one because as soon as the serial is detected to be wrong, the session is reset;
It might be related to some DB issue but, nevertheless, it only shows with CR2 (main issue being the increased client fail rate, not any specific error that might or might not be the cause or part of the cause);

Tommaso Borgato added a comment - 2023/11/23 2:31 PM - edited rhn-engineering-rhusar I added fail-over to the description; You are right and the job name might not be correct; Serial is always off (stale) by one because as soon as the serial is detected to be wrong, the session is reset; It might be related to some DB issue but, nevertheless, it only shows with CR2 (main issue being the increased client fail rate, not any specific error that might or might not be the cause or part of the cause);

Radoslav Husar added a comment - 2023/11/23 1:40 PM - edited

Looking at the logs, this is the culprit of failures:

2023-11-23 08:49:33,526 ERROR [org.infinispan.PERSISTENCE] (SchedulerTopologyChangeListener - 3) ISPN008009: I/O error while unmarshalling from stream: java.io.IOException: ORA-01555: snapshot too old: rollback segment number  with name "" too small
...
2023-11-23 08:55:44,325 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (non-blocking-thread--p8-t11) ISPN000136: Error executing command GetAllCommand on Cache 'cbnc.ear.a.war', writing keys []: org.infinispan.persistence.spi.PersistenceException: jakarta.resource.ResourceException: IJ000453: Unable to get managed connection for java:jbo
ss/datasources/testDS
2023-11-23 08:55:44,341 ERROR [io.undertow.servlet.request] (default task-271) UT015005: Error invoking method requestInitialized on listener class org.jboss.weld.module.web.servlet.WeldInitialListener: org.infinispan.persistence.spi.PersistenceException: jakarta.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/
testDS
....
2023-11-23 08:56:14,159 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (default task-729) ISPN000136: Error executing command GetKeyValueCommand on Cache 'cbnc.ear.a.war', writing keys []: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable
2023-11-23 08:56:14,159 ERROR [io.undertow.servlet.request] (default task-729) UT015005: Error invoking method requestInitialized on listener class org.jboss.weld.module.web.servlet.WeldInitialListener: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable
2023-11-23 08:56:14,159 ERROR [io.undertow.request] (default task-729) UT005023: Exception handling request to /clusterbench/session: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable

Moreover, after the "failover" the node refuses the start because the previous process has not exited as I was hinting at above

2023-11-23 09:01:04,819 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC000001: Failed to start service org.wildfly.undertow.listener.ajp: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.ajp: Address already in use /10.19.96.122:8009
2023-11-23 09:01:04,819 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-4) MSC000001: Failed to start service org.wildfly.undertow.listener.default: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.default: Address already in use /10.19.96.122:8080
2023-11-23 09:01:05,017 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-3) MSC000001: Failed to start service org.wildfly.undertow.listener.https: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.https: Address already in use /10.19.96.122:8443

Radoslav Husar added a comment - 2023/11/23 1:40 PM - edited Looking at the logs, this is the culprit of failures: 2023-11-23 08:49:33,526 ERROR [org.infinispan.PERSISTENCE] (SchedulerTopologyChangeListener - 3) ISPN008009: I/O error while unmarshalling from stream: java.io.IOException: ORA-01555: snapshot too old: rollback segment number with name "" too small ... 2023-11-23 08:55:44,325 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (non-blocking-thread--p8-t11) ISPN000136: Error executing command GetAllCommand on Cache 'cbnc.ear.a.war', writing keys []: org.infinispan.persistence.spi.PersistenceException: jakarta.resource.ResourceException: IJ000453: Unable to get managed connection for java:jbo ss/datasources/testDS 2023-11-23 08:55:44,341 ERROR [io.undertow.servlet.request] (default task-271) UT015005: Error invoking method requestInitialized on listener class org.jboss.weld.module.web.servlet.WeldInitialListener: org.infinispan.persistence.spi.PersistenceException: jakarta.resource.ResourceException: IJ000453: Unable to get managed connection for java:jboss/datasources/ testDS .... 2023-11-23 08:56:14,159 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (default task-729) ISPN000136: Error executing command GetKeyValueCommand on Cache 'cbnc.ear.a.war', writing keys []: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable 2023-11-23 08:56:14,159 ERROR [io.undertow.servlet.request] (default task-729) UT015005: Error invoking method requestInitialized on listener class org.jboss.weld.module.web.servlet.WeldInitialListener: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable 2023-11-23 08:56:14,159 ERROR [io.undertow.request] (default task-729) UT005023: Exception handling request to /clusterbench/session: org.infinispan.persistence.spi.StoreUnavailableException: Store org.jboss.as.clustering.infinispan.persistence.jdbc.JDBCStore@8b213d4 is unavailable Moreover, after the "failover" the node refuses the start because the previous process has not exited as I was hinting at above 2023-11-23 09:01:04,819 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC000001: Failed to start service org.wildfly.undertow.listener.ajp: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.ajp: Address already in use /10.19.96.122:8009 2023-11-23 09:01:04,819 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-4) MSC000001: Failed to start service org.wildfly.undertow.listener.default: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.default: Address already in use /10.19.96.122:8080 2023-11-23 09:01:05,017 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-3) MSC000001: Failed to start service org.wildfly.undertow.listener.https: org.jboss.msc.service.StartException in service org.wildfly.undertow.listener.https: Address already in use /10.19.96.122:8443

Radoslav Husar added a comment - 2023/11/23 1:31 PM - edited

This is odd, the job names are 'repl' but the configured cache in the description is invalidation cache...

Did a brief grep on the logs from the CR2.1 job - there is 4x 500 and 637x 200 but serial is off (stale) by one.

The job artefacts at https://jenkins.eapqe.psi.redhat.com/job/eap-8.x-clustering-db-session-shutdown-repl-oracle-RAC/163/artifact/report/wildfly/ are missing node 1 logs...

Radoslav Husar added a comment - 2023/11/23 1:31 PM - edited This is odd, the job names are 'repl' but the configured cache in the description is invalidation cache... Did a brief grep on the logs from the CR2.1 job - there is 4x 500 and 637x 200 but serial is off (stale) by one. The job artefacts at https://jenkins.eapqe.psi.redhat.com/job/eap-8.x-clustering-db-session-shutdown-repl-oracle-RAC/163/artifact/report/wildfly/ are missing node 1 logs...

Radoslav Husar added a comment - 2023/11/23 12:03 PM - edited

It would be ideal to mention what constitutes as a failure and what those actual failures are (wrong serial, 500, 503, etc?).

Also, ideally mention that this is a 'failover' scenario as that's not mentioned anywhere in the description (since that might not be clear to everyone).

Is this only affecting shutdown scenarios or others as well?

Is this using clean shutdown (i.e. with a timeout) and does the test verify that the shutdown actually completely completed (i.e. the process exited)?

Radoslav Husar added a comment - 2023/11/23 12:03 PM - edited It would be ideal to mention what constitutes as a failure and what those actual failures are (wrong serial, 500, 503, etc?). Also, ideally mention that this is a 'failover' scenario as that's not mentioned anywhere in the description (since that might not be clear to everyone). Is this only affecting shutdown scenarios or others as well? Is this using clean shutdown (i.e. with a timeout) and does the test verify that the shutdown actually completely completed (i.e. the process exited)?

Details

Description

Attachments

Attachments

Issue Links

Easy Agile Planning Poker

Activity

Collapse comment: Michaela Osmerova added a comment - 2024/08/19 1:59 PM

Expand comment: Michaela Osmerova added a comment - 2024/08/19 1:59 PM

Collapse comment: Paul Ferraro added a comment - 2023/11/29 5:44 PM

Expand comment: Paul Ferraro added a comment - 2023/11/29 5:44 PM

Collapse comment: Radoslav Husar added a comment - 2023/11/24 12:54 PM

Expand comment: Radoslav Husar added a comment - 2023/11/24 12:54 PM

Collapse comment: Tommaso Borgato added a comment - 2023/11/23 2:31 PM, Edited by Tommaso Borgato - 2023/11/23 2:32 PM

Expand comment: Tommaso Borgato added a comment - 2023/11/23 2:31 PM, Edited by Tommaso Borgato - 2023/11/23 2:32 PM

Collapse comment: Radoslav Husar added a comment - 2023/11/23 1:40 PM, Edited by Radoslav Husar - 2023/11/24 12:56 PM

Expand comment: Radoslav Husar added a comment - 2023/11/23 1:40 PM, Edited by Radoslav Husar - 2023/11/24 12:56 PM

Collapse comment: Radoslav Husar added a comment - 2023/11/23 1:31 PM, Edited by Radoslav Husar - 2023/11/23 1:33 PM

Expand comment: Radoslav Husar added a comment - 2023/11/23 1:31 PM, Edited by Radoslav Husar - 2023/11/23 1:33 PM

Collapse comment: Radoslav Husar added a comment - 2023/11/23 12:03 PM, Edited by Radoslav Husar - 2023/11/23 12:04 PM

Expand comment: Radoslav Husar added a comment - 2023/11/23 12:03 PM, Edited by Radoslav Husar - 2023/11/23 12:04 PM

People

Dates