| Bug #115182 | Contribution: [fix] QueryTimeout does not take effect in certain scenarios. | ||
|---|---|---|---|
| Submitted: | 31 May 2024 2:57 | Modified: | 18 Sep 2024 11:49 |
| Reporter: | OCA Admin (OCA) | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | Connector / J | Severity: | S3 (Non-critical) |
| Version: | 8.0 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | Contribution | ||
[31 May 2024 2:57]
OCA Admin
[31 May 2024 2:57]
OCA Admin
Contribution submitted via Github - [fix] QueryTimeout does not take effect in certain scenarios. (*) Contribution by Nan Chiu (Github qnnn, mysql-connector-j/pull/107#issuecomment-2139365272): I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: git_patch_1877468149.txt (text/plain), 1.27 KiB.
[31 May 2024 5:09]
MySQL Verification Team
Hello Nan Chiu, Thank you for the report and contribution. regards, Umesh
[18 Sep 2024 11:49]
Filipe Silva
Posted by developer: This contribution couldn't be accepted because it leads to additional problems caused by a conflict between the internal cancellation timer (the process that stops statement executions when they exceed their timeout) and the socket timeout this change implies. Also, the patch, as it was proposed, doesn't work—it's missing null checks. Finally, it is not clearly explained what problem this patch is supposed to fix. Please reopen the bug, provide all details about the alleged issues, a fully working test case and revise the patch itself, in case you're interested in proceeding with it. Thank you.
[18 Sep 2024 16:13]
Nan Chiu
I apologize for the error due to the lack of null value checks, and sorry for providing insufficient information. This issue may be difficult to capture in unit tests. The queryTimeout failure occurs in scenarios where the client is unaware that the socket has actually become invalid (you can reproduce this issue by closing the network adapter on the MySQL server side after the socket has been established).
When this issue occurs, the queryTimeout setting is ineffective because the queryTimeout value was not set on the socket. The corresponding stack trace is as follows:
"http-nio-8080-exec-10" #99 [80724] daemon prio=5 os_prio=0 cpu=0.00ms elapsed=569.80s tid=0x0000027b5e37c4f0 nid=80724 runnable [0x000000af409fb000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Net.poll(java.base@21.0.2/Native Method)
at sun.nio.ch.NioSocketImpl.park(java.base@21.0.2/NioSocketImpl.java:191)
at sun.nio.ch.NioSocketImpl.timedRead(java.base@21.0.2/NioSocketImpl.java:280)
at sun.nio.ch.NioSocketImpl.implRead(java.base@21.0.2/NioSocketImpl.java:304)
at sun.nio.ch.NioSocketImpl.read(java.base@21.0.2/NioSocketImpl.java:346)
at sun.nio.ch.NioSocketImpl$1.read(java.base@21.0.2/NioSocketImpl.java:796)
at java.net.Socket$SocketInputStream.read(java.base@21.0.2/Socket.java:1099)
at sun.security.ssl.SSLSocketInputRecord.read(java.base@21.0.2/SSLSocketInputRecord.java:489)
at sun.security.ssl.SSLSocketInputRecord.readHeader(java.base@21.0.2/SSLSocketInputRecord.java:483)
at sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(java.base@21.0.2/SSLSocketInputRecord.java:70)
at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base@21.0.2/SSLSocketImpl.java:1461)
at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@21.0.2/SSLSocketImpl.java:1066)
at java.io.FilterInputStream.read(java.base@21.0.2/FilterInputStream.java:119)
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:576)
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:762)
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:701)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1052)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:998)
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:655)
at com.mysql.cj.jdbc.StatementImpl.executeQuery(StatementImpl.java:1168)
At the same time, when this issue occurs, a null pointer exception may be thrown because the CancelQueryTask has already been executed. The corresponding stack trace is as follows:
java.lang.NullPointerException: Cannot invoke "com.mysql.cj.NativeSession.getCancelTimer()" because "this.session" is null
at com.mysql.cj.AbstractQuery.stopQueryTimer(AbstractQuery.java:228) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.StatementImpl.stopQueryTimer(StatementImpl.java:643) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.StatementImpl.executeQuery(StatementImpl.java:1182) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.alibaba.druid.filter.FilterChainImpl.statement_executeQuery(FilterChainImpl.java:2882) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterAdapter.statement_executeQuery(FilterAdapter.java:2513) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterEventAdapter.statement_executeQuery(FilterEventAdapter.java:296) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.statement_executeQuery(FilterChainImpl.java:2879) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.proxy.jdbc.StatementProxyImpl.executeQuery(StatementProxyImpl.java:217) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.pool.DruidPooledStatement.executeQuery(DruidPooledStatement.java:300) ~[druid-1.2.22.jar:na]
at org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:452) ~[spring-jdbc-5.3.25.jar:5.3.25]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:381) ~[spring-jdbc-5.3.25.jar:5.3.25]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:465) ~[spring-jdbc-5.3.25.jar:5.3.25]
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:475) ~[spring-jdbc-5.3.25.jar:5.3.25]
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:508) ~[spring-jdbc-5.3.25.jar:5.3.25]
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:515) ~[spring-jdbc-5.3.25.jar:5.3.25]
This issue can be reproduced by triggering a scenario where the client is unaware of the socket's failure during runtime (such as by closing the network adapter on the MySQL server side). If there is anything else needed to reproduce this issue, please @ me.
[20 Sep 2024 10:55]
Nan Chiu
I am currently a bit confused. My intention was to end the current SQL execution when the queryTimeout is reached, but now there is another scenario where the queryTimeout is reached and it does not return (which is unrelated to the current issue).
This is another issue I encountered. I locked a certain row, triggering its execution timeout, while I configured queryTimeoutKillsConnection=true. At this point, CancelQueryTask will wait for StatementImpl#executeQuery because it has locked the Connection, resulting in the query not ending within the queryTimeout period. Is this also a problem?
Corresponding stack trace:
"http-nio-8080-exec-1" #68 [16020] daemon prio=5 os_prio=0 cpu=0.00ms elapsed=57.14s tid=0x00000214f0a45870 nid=16020 runnable [0x000000ca9fdfb000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Net.poll(java.base@21.0.2/Native Method)
at sun.nio.ch.NioSocketImpl.park(java.base@21.0.2/NioSocketImpl.java:191)
at sun.nio.ch.NioSocketImpl.timedRead(java.base@21.0.2/NioSocketImpl.java:280)
at sun.nio.ch.NioSocketImpl.implRead(java.base@21.0.2/NioSocketImpl.java:304)
at sun.nio.ch.NioSocketImpl.read(java.base@21.0.2/NioSocketImpl.java:346)
at sun.nio.ch.NioSocketImpl$1.read(java.base@21.0.2/NioSocketImpl.java:796)
at java.net.Socket$SocketInputStream.read(java.base@21.0.2/Socket.java:1099)
at java.net.Socket$SocketInputStream.read(java.base@21.0.2/Socket.java:1093)
at sun.security.ssl.SSLSocketInputRecord.deplete(java.base@21.0.2/SSLSocketInputRecord.java:509)
at sun.security.ssl.SSLSocketImpl$AppInputStream.readLockedDeplete(java.base@21.0.2/SSLSocketImpl.java:1216)
at sun.security.ssl.SSLSocketImpl$AppInputStream.deplete(java.base@21.0.2/SSLSocketImpl.java:1191)
at sun.security.ssl.SSLSocketImpl.bruteForceCloseInput(java.base@21.0.2/SSLSocketImpl.java:808)
at sun.security.ssl.SSLSocketImpl.duplexCloseOutput(java.base@21.0.2/SSLSocketImpl.java:664)
at sun.security.ssl.SSLSocketImpl.close(java.base@21.0.2/SSLSocketImpl.java:584)
at com.mysql.cj.protocol.NetworkResources.forceClose(NetworkResources.java:94)
at com.mysql.cj.protocol.AbstractSocketConnection.forceClose(AbstractSocketConnection.java:104)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:88)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:576)
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:762)
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:701)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1052)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:998)
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:655)
at com.mysql.cj.jdbc.StatementImpl.executeQuery(StatementImpl.java:1168)
- **locked <0x00000006050c7530> (a com.mysql.cj.jdbc.ConnectionImpl)** ———— : )
om.alibaba.druid.filter.FilterChainImpl.statement_executeQuery(FilterChainImpl.java:2882)
at com.alibaba.druid.filter.FilterAdapter.statement_executeQuery(FilterAdapter.java:2513)
at com.alibaba.druid.filter.FilterEventAdapter.statement_executeQuery(FilterEventAdapter.java:296)
at com.alibaba.druid.filter.FilterChainImpl.statement_executeQuery(FilterChainImpl.java:2879)
at com.alibaba.druid.proxy.jdbc.StatementProxyImpl.executeQuery(StatementProxyImpl.java:217)
at com.alibaba.druid.pool.DruidPooledStatement.executeQuery(DruidPooledStatement.java:300)
at org.springframework.jdbc.core.JdbcTemplate$1QueryStatementCallback.doInStatement(JdbcTemplate.java:452)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:381)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:465)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:475)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:508)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:515)
CancelQueryTask stack trace:
"Thread-2" #88 [11228] daemon prio=5 os_prio=0 cpu=0.00ms elapsed=26.32s tid=0x00000214f186c2f0 nid=11228 waiting for monitor entry [0x000000ca9e1fe000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mysql.cj.jdbc.ConnectionImpl.getAutoCommit(ConnectionImpl.java:1089)
- waiting to lock <0x00000006050c7530> (a com.mysql.cj.jdbc.ConnectionImpl) ———— : )
om.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1665)
at com.mysql.cj.jdbc.ConnectionImpl.cleanup(ConnectionImpl.java:611)
at com.mysql.cj.jdbc.ConnectionImpl.handleCleanup(ConnectionImpl.java:2657)
at com.mysql.cj.NativeSession.invokeCleanupListeners(NativeSession.java:808)
at com.mysql.cj.CancelQueryTaskImpl$1.run(CancelQueryTaskImpl.java:85)
