[JBoss JIRA] (TEIID-5801) Communications link failure during commit() error message when copying a MySQL table to a DB
10:49 a.m.
[
https://issues.jboss.org/browse/TEIID-5801?page=com.atlassian.jira.plugin...
]
Dmitrii Pogorelov commented on TEIID-5801:
------------------------------------------
[~shawkins] I investigated the remote MySQL DB, checked all timeouts, they had the
following:
{code}
[connect_timeout, 10]
[delayed_insert_timeout, 300]
[innodb_flush_log_at_timeout, 1]
[innodb_lock_wait_timeout, 50]
[innodb_rollback_on_timeout, OFF]
[interactive_timeout, 28800]
[lock_wait_timeout, 31536000]
[net_read_timeout, 30]
[net_write_timeout, 60]
[rpl_stop_slave_timeout, 31536000]
[slave_net_timeout, 3600]
[wait_timeout, 28800]
{code}
I tried to change many timeouts via "set SESSION" command but nothing helped me.
The remote MySQL data source just fails after starting a transaction and committing it
after some time. But I discovered the following behavior, if I run these commands
(lingoda_read_replica is the remote MySQL data source):
{code:sql}
start transaction ;;
SELECT * FROM lingoda_read_replica.transaction limit 100 ;;
--wait for several minutes
commit ;;
{code}
it will fail with the stacktrace:
{code}
2019-08-02 17:39:08,852 WARN
[org.jboss.jca.core.connectionmanager.listener.TxConnectionListener]
(Worker9_QueryProcessorQueue2086) zQviPsbtOB3h IJ000305: Connection error occured:
org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@5aa0db62[state=NORMAL
managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@7e3275d0
connection handles=0 lastReturned=1564760159114 lastValidated=1564760159114
lastCheckedOut=1564760159114 trackByTx=true
pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@4bced85c
mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@160eaa84[pool=lingoda_read_replica]
xaResource=LocalXAResourceImpl@3cb2efe4[connectionListener=5aa0db62
connectionManager=222e8322 warned=false currentXid=null productName=MySQL
productVersion=5.6.34-log jndiName=java:/lingoda_read_replica]
txSync=TransactionSynchronization@1540878037{tx=Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffffc0a8008c:-3ccc1e9e:5d4451f8:bd
status: ActionStatus.COMMITTING >, owner=Local transaction context for provider JBoss
JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]:
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link
failure during commit(). Transaction resolution unknown.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1014)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:988)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:974)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919)
at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1700)
at
org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.commit(LocalManagedConnection.java:96)
at
org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.commit(LocalXAResourceImpl.java:172)
at
com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.commit(XAOnePhaseResource.java:120)
at
com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelOnePhaseCommit(LastResourceRecord.java:172)
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2386)
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1497)
at
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1288)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
at
org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
at
org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commitDirect(TransactionServerImpl.java:386)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commit(TransactionServerImpl.java:459)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.teiid.logging.LogManager$LoggingProxy.invoke(LogManager.java:117)
at com.sun.proxy.$Proxy27.commit(Unknown Source)
at org.teiid.dqp.internal.process.DQPCore$4.call(DQPCore.java:780)
at org.teiid.dqp.internal.process.DQPCore$4.call(DQPCore.java:777)
at org.teiid.dqp.internal.process.DQPCore$8.run(DQPCore.java:845)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:59)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:281)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:113)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:199)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2019-08-02 17:39:08,854 WARN [com.arjuna.ats.jta] (Worker9_QueryProcessorQueue2086)
zQviPsbtOB3h ARJUNA016039: onePhaseCommit on < formatId=131077, gtrid_length=29,
bqual_length=36, tx_uid=0:ffffc0a8008c:-3ccc1e9e:5d4451f8:bd, node_name=1,
branch_uid=0:ffffc0a8008c:-3ccc1e9e:5d4451f8:c1, subordinatenodename=null,
eis_name=java:/lingoda_read_replica >
(LocalXAResourceImpl@3cb2efe4[connectionListener=5aa0db62 connectionManager=222e8322
warned=false currentXid=null productName=MySQL productVersion=5.6.34-log
jndiName=java:/lingoda_read_replica]) failed with exception XAException.XAER_RMFAIL:
org.jboss.jca.core.spi.transaction.local.LocalXAException: IJ001156: Could not commit
local transaction
at
org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.commit(LocalXAResourceImpl.java:177)
at
com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.commit(XAOnePhaseResource.java:120)
at
com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelOnePhaseCommit(LastResourceRecord.java:172)
at com.arjuna.ats.arjuna.coordinator.BasicAction.onePhaseCommit(BasicAction.java:2386)
at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1497)
at
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96)
at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1288)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
at
org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
at
org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commitDirect(TransactionServerImpl.java:386)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commit(TransactionServerImpl.java:459)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.teiid.logging.LogManager$LoggingProxy.invoke(LogManager.java:117)
at com.sun.proxy.$Proxy27.commit(Unknown Source)
at org.teiid.dqp.internal.process.DQPCore$4.call(DQPCore.java:780)
at org.teiid.dqp.internal.process.DQPCore$4.call(DQPCore.java:777)
at org.teiid.dqp.internal.process.DQPCore$8.run(DQPCore.java:845)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:59)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:281)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:113)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:199)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.jca.core.spi.transaction.local.LocalResourceException: Communications
link failure during commit(). Transaction resolution unknown.
at
org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.commit(LocalManagedConnection.java:103)
at
org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.commit(LocalXAResourceImpl.java:172)
... 31 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException:
Communications link failure during commit(). Transaction resolution unknown.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1014)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:988)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:974)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919)
at com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1700)
at
org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.commit(LocalManagedConnection.java:96)
... 32 more
{code}
I started to investigate the bug further and found interesting behavior. The "insert
into .... select *" command will be divided on two commands: select and insert. For
every of these commands Teiid calls DataTierManagerImpl.registerRequest method. At the
moment for remote MySQL and PostgreSQL data sources Teiid calls aqr.setSerial(true); for
both commands (select and insert) and then the "insert into .... select *" fails
(I attached server_1_fail.log, there I added also output of messages related to starting
and finishing transaction). But if I call aqr.setSerial(false); for select command and
aqr.setSerial(true); for insert command then the "insert into .... select *"
doesn't fail, transaction is being committed without errors (I attached
server_2_works.log). Could you tell me, please, why does aqr.setSerial method allow to
avoid transaction errors?
Communications link failure during commit() error message when
copying a MySQL table to a DB
--------------------------------------------------------------------------------------------
Key: TEIID-5801
URL: https://issues.jboss.org/browse/TEIID-5801
Project: Teiid
Issue Type: Quality Risk
Components: Query Engine
Affects Versions: 12.0
Environment: teiid-12.0.0 on WildFly Full 14.0.1.Final (WildFly Core
6.0.2.Final)
Reporter: Dmitrii Pogorelov
Assignee: Steven Hawkins
Priority: Major
Attachments: server_teiid.log
When copying a MySQL table, for example, to PostgreSQL:
{code:sql}
insert into dwh_pg.test_target SELECT * FROM my.test_source ;;
{code}
in the end of the process Teiid throws out the following stacktrace (though rows are
inserted in PostgreSQL successfully, seems that Teiid can't close read transaction for
MySQL):
{code}
2019-08-01 16:48:23,119 WARN
[org.jboss.jca.core.connectionmanager.listener.TxConnectionListener]
(Worker3_QueryProcessorQueue34) TidBkmeGWJN8 IJ000305: Connection error occured:
org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@75284e6d[state=NORMAL
managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5b8d92c7
connection handles=0 lastReturned=1564670796599 lastValidated=1564670796598
lastCheckedOut=1564670796678 trackByTx=true
pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@ae21718
mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@338041b4[pool=lingoda_read_replica]
xaResource=LocalXAResourceImpl@1fcd6b81[connectionListener=75284e6d
connectionManager=20f22ec1 warned=false currentXid=null productName=MySQL
productVersion=5.6.34-log jndiName=java:/lingoda_read_replica]
txSync=TransactionSynchronization@1367866468{tx=Local transaction
(delegate=TransactionImple < ac, BasicAction: 0:ffffc0a8008c:33252ff9:5d42fad3:11
status: ActionStatus.PREPARING >, owner=Local transaction context for provider JBoss
JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]:
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link
failure during commit(). Transaction resolution unknown.
at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at
com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at
com.mysql.jdbc.Util.getInstance(Util.java:386)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1014)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:988)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:974)
at
com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919)
at
com.mysql.jdbc.ConnectionImpl.commit(ConnectionImpl.java:1700)
at
org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.commit(LocalManagedConnection.java:96)
at
org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.commit(LocalXAResourceImpl.java:172)
at
com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.commit(XAOnePhaseResource.java:120)
at
com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelPrepare(LastResourceRecord.java:152)
at
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2664)
at
com.arjuna.ats.arjuna.coordinator.BasicAction.doPrepare(BasicAction.java:2614)
at
com.arjuna.ats.arjuna.coordinator.BasicAction.prepare(BasicAction.java:2157)
at
com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1503)
at
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:96)
at
com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1288)
at
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
at
com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
at
org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
at
org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commitDirect(TransactionServerImpl.java:384)
at
org.teiid.dqp.internal.process.TransactionServerImpl.commit(TransactionServerImpl.java:515)
at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at
java.lang.reflect.Method.invoke(Method.java:498)
at
org.teiid.logging.LogManager$LoggingProxy.invoke(LogManager.java:117)
at
com.sun.proxy.$Proxy25.commit(Unknown Source)
at
org.teiid.dqp.internal.process.RequestWorkItem.processMore(RequestWorkItem.java:514)
at
org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:362)
at
org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:43)
at
org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:285)
at
org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:281)
at
org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:113)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:199)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
I tried to reproduce the problem with local MySQL and PostgreSQL but couldn't. The
problem can be reproduced only when using remote MySQL and PostgreSQL. On my local machine
the error appears with limit more than 200000 rows, on another machines the exception
appeared when setting limit 400000 and more. It seems it's related maybe somehow with
MySQL timeouts or network delays. If I copy the table from remote MySQL to local PostgeSQL
the error doesn't appear, and vice versa, if I copy the table from local MySQL to
remote PostgreSQL the error doesn't appear again. I don't have an access to the
remote MySQL to have a look at its internal options. I also tried to set
net_write_timeout=1800 jdbc property for data source of the remote MySQL,
tcpKeepAlive=true, tried to set ThreadBound MySQL translator property to true value - it
didn't help at all. What do you think, is it possible to avoid the error on Teiid
level?
I also attached a server log with org.teiid.CONNECTOR and org.teiid.PROCESSOR log
outputs.
--
This message was sent by Atlassian Jira
(v7.12.1#712002)
2439
days inactive
2439
days old
0 comments
1 participants
participants (1)
-
Dmitrii Pogorelov (Jira)