| Bug #99708 | mysql-connector-java 8.0.20 ASSERTION FAILED: Unknown message type: 57 s.close | ||
|---|---|---|---|
| Submitted: | 27 May 2020 14:07 | Modified: | 5 Mar 2021 22:35 |
| Reporter: | Bernd Wahlen | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | Connector / J | Severity: | S1 (Critical) |
| Version: | 8.0.20 | OS: | Ubuntu |
| Assigned to: | CPU Architecture: | x86 | |
| Tags: | connector-java, mxsqlx, session.close | ||
[29 May 2020 12:24]
Filipe Silva
Hi Bernd, I'm unable to reproduce this behavior. I can't run your code and it doesn't provide enough information for me to understand how you are using the connector. Please try to make a self-contained test case showing this issue. In the meantime, you could try again using Connector/J 8.0.20 with compression disabled (`xdevapi.compression=DISABLED`) to see if this may be related to the new compression features. Thanks,
[29 May 2020 13:18]
Bernd Wahlen
I think that helps: xdevapi.compression=DISABLED are there any hidden dependencies, like packages need to be installed on the operation system of the client (zst, zlib, lz4?). Maybe there is something missing because it is minimal docker container? Then error message need to be improved.
[4 Jun 2020 13:16]
Bernd Wahlen
I can reproduce it running the following junit test multiple times:
public class LockingTest {
@Test
public void testConcurrentWrite() throws Exception {
final ObjectMapper mapper = new ObjectMapper();
Session s1 = new SessionFactory().getSession("mysqlx://localhost:33060?user=debian-sys-maint&password=rd9nYWHmbwlQ3inG");
Collection col1 = s1.createSchema("m", true).createCollection("Test", true);
String docId = "4713"; //changeId to something new to produce failure
//doc _id=5 must exist before to lock it
s1.startTransaction();
MessageBoxX mb = new MessageBoxX();
mb.setId(docId);
col1.addOrReplaceOne(docId, mapper.writeValueAsString(mb));
s1.commit();
for (int i = 0; i < 99; i++) { //max 100 connections default, 1 connection for initial create and verify result
final int cc = i;
new Thread(() -> {
try {
boolean success = false;
int retryCount = 0;
do {
success = tryUpdate(docId);
if (!success) {
retryCount++;
long waitFor = getWaitTime(retryCount);
logger.info("thread: " + cc + " retry:" + retryCount + ", wait:" + waitFor);
Thread.sleep(waitFor); //TODO: add warning if wait is >x
}
} while (!success);
} catch (JsonProcessingException | InterruptedException ex) {
logger.error(ex);
}
}).start();
}
Thread.sleep(10000); //wait for all the threads to finish
DbDoc doct = col1.getOne(docId);
s1.close();
MessageBoxX mbr = mapper.readValue(doct.toString(), MessageBoxX.class);
assertEquals(99, mbr.getMessagesRefs().size());
}
private boolean tryUpdate(String idStr) throws JsonProcessingException {
Session s = new SessionFactory().getSession("mysqlx://localhost:33060?user=debian-sys-maint&password=rd9nYWHmbwlQ3inG");
try {
final ObjectMapper mapper = new ObjectMapper();
Collection c = s.createSchema("m", true).createCollection("Test", true);
s.startTransaction();
DbDoc doct = c.find("_id = :id").lockShared(Statement.LockContention.NOWAIT).bind("id", idStr).execute().fetchOne();
MessageBoxX mb = mapper.readValue(doct.toString(), MessageBoxX.class);
mb.addToMessagesRefs(System.nanoTime(), "Thread" + idStr);
c.addOrReplaceOne(idStr, mapper.writeValueAsString(mb));
s.commit();
s.close();
} catch (XProtocolError ex) {
s.rollback();
s.close();
//https://dev.mysql.com/doc/refman/8.0/en/server-error-reference.html
if (CollectionUtil.isOneOf(ex.getErrorCode(), 1213, 1223, 3572)) { //errors corresponds to lock
return false;
}
throw ex;
}
return true;
}
private long getWaitTime(int retryCount) {
return Math.round((10 + (Math.random() * 10)) * retryCount * retryCount);
}
}
[5 Jun 2020 18:57]
Filipe Silva
Hi Bernd, I was hoping you could get us a test case using only Connector/J, without any other 3rd party libraries. I'll try to re-write your test case to see if I can reproduce the behavior you reported. Feel free to share any other tests you may have that could help us identify the problem. Meanwhile, keep using the connector without compression. Regarding your other questions. Connector/J only supports deflate compression by default. Other algorithms (lz4 and zstd) are possible if you configure the driver to use 3rd party libraries to support them, but I recommend you not so explore this feature yet since it will most likely change in the next releases.
[18 Jun 2020 11:39]
Filipe Silva
Hi Bernd, I was able to work with your test case and observe sporadic failures but I don't get the stack trace you posted initially. Can you please share the stack trace you get now so that I can confirm the issue is the same? Thanks,
[18 Jun 2020 11:58]
Bernd Wahlen
You are right, the Stacktrace was from the original code, not from the Testcase, current output is like this: Exception in thread "Thread-4" Exception in thread "Thread-66" com.mysql.cj.exceptions.CJCommunicationsException: Cannot read packet header at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:102) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:79) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:54) at com.mysql.cj.protocol.x.XProtocol.readQueryResult(XProtocol.java:625) at com.mysql.cj.protocol.x.XProtocol.query(XProtocol.java:881) at com.mysql.cj.MysqlxSession.query(MysqlxSession.java:170) at com.mysql.cj.xdevapi.AddStatementImpl.execute(AddStatementImpl.java:93) at com.mysql.cj.xdevapi.AddStatementImpl.execute(AddStatementImpl.java:47) at com.mysql.cj.xdevapi.CollectionImpl.addOrReplaceOne(CollectionImpl.java:222) at com.mysql.cj.xdevapi.CollectionImpl.addOrReplaceOne(CollectionImpl.java:234) at de.k2interactive.qeep.messaging.x.LockingTest.tryUpdate(LockingTest.java:138) at de.k2interactive.qeep.messaging.x.LockingTest.lambda$testConcurrentWrite$1(LockingTest.java:104) at java.base/java.lang.Thread.run(Thread.java:832) Caused by: java.util.zip.ZipException: invalid stored block lengths at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:164) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.x.ConfinedInputStream.read(ConfinedInputStream.java:119) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.readFully(CompressionSplittedInputStream.java:335) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.read(CompressionSplittedInputStream.java:151) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:53) at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:98) ... 12 more Exception in thread "Thread-6" com.mysql.cj.exceptions.CJCommunicationsException: Cannot read packet header at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:102) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:79) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:54) at com.mysql.cj.protocol.x.XProtocol.readQueryResult(XProtocol.java:625) at com.mysql.cj.protocol.x.XProtocol.query(XProtocol.java:881) at com.mysql.cj.MysqlxSession.query(MysqlxSession.java:170) at com.mysql.cj.xdevapi.SessionImpl.rollback(SessionImpl.java:141) at de.k2interactive.qeep.messaging.x.LockingTest.tryUpdate(LockingTest.java:142) at de.k2interactive.qeep.messaging.x.LockingTest.lambda$testConcurrentWrite$1(LockingTest.java:104) at java.base/java.lang.Thread.run(Thread.java:832) Caused by: java.util.zip.ZipException: invalid stored block lengths at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:164) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.x.ConfinedInputStream.read(ConfinedInputStream.java:119) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.readFully(CompressionSplittedInputStream.java:335) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.read(CompressionSplittedInputStream.java:151) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:53) at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:98) ... 9 more com.mysql.cj.exceptions.CJCommunicationsException: Cannot read packet header at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:102) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:79) at com.mysql.cj.protocol.x.SyncMessageReader.readHeader(SyncMessageReader.java:54) at com.mysql.cj.protocol.x.XProtocol.readQueryResult(XProtocol.java:625) at com.mysql.cj.protocol.x.XProtocol.query(XProtocol.java:881) at com.mysql.cj.MysqlxSession.query(MysqlxSession.java:170) at com.mysql.cj.xdevapi.SessionImpl.rollback(SessionImpl.java:141) at de.k2interactive.qeep.messaging.x.LockingTest.tryUpdate(LockingTest.java:142) at de.k2interactive.qeep.messaging.x.LockingTest.lambda$testConcurrentWrite$1(LockingTest.java:104) at java.base/java.lang.Thread.run(Thread.java:832) Caused by: java.util.zip.ZipException: invalid stored block lengths at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:164) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.x.ConfinedInputStream.read(ConfinedInputStream.java:119) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.readFully(CompressionSplittedInputStream.java:335) at com.mysql.cj.protocol.x.CompressionSplittedInputStream.read(CompressionSplittedInputStream.java:151) at java.base/java.io.FilterInputStream.read(FilterInputStream.java:132) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64) at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:53) at com.mysql.cj.protocol.x.SyncMessageReader.readHeaderLocal(SyncMessageReader.java:98) ... 9 more
[18 Jun 2020 13:30]
Filipe Silva
Right, I see that one too. Although in some cases the exception you are seeing is a consequence of another one that you are catching and discarding while executing the `rollback()` in the catch block. The original exception usually has more interesting information. Anyway, as of now I'm setting this bug as verified, but I don't know yet if the problem lies in the connector or in the server, a lot more debugging is needed. Thanks for your help.
[5 Mar 2021 22:35]
Daniel So
Posted by developer: Added the following entry to the C/J 8.0.24 changelog: "Under some specific conditions, when using Deflate as the algorithm for compression of X DevAPI connections, Connector/J threw an AssertionFailedException (ASSERTION FAILED: Unknown message type: 57). It was because when a compressed packet was just a few bytes longer than the size of some internal buffer used by a Java InflaterInputStream, the leftover bytes from the inflate procedure were being discarded by C/J, causing inflation of subsequent packets to fail. With this fix, no data bytes are discarded, and the inflation works as expected."
Description: 27.05.20 14:41:53 ERROR [troller.AbstractRestController: 194] com.mysql.cj.exceptions.AssertionFailedException: ASSERTION FAILED: Unknown message type: 57 (server messages mapping: null) (https-openssl-apr-443-exec-7) com.mysql.cj.exceptions.AssertionFailedException: ASSERTION FAILED: Unknown message type: 57 (server messages mapping: null) at com.mysql.cj.exceptions.AssertionFailedException.shouldNotHappen(AssertionFailedException.java:73) ~[mysql-connector-java-8.0.20.jar:?] at com.mysql.cj.protocol.x.MessageConstants.getMessageClassForType(MessageConstants.java:190) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.protocol.x.SyncMessageReader.readMessage(SyncMessageReader.java:140) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.protocol.x.SyncMessageReader.readMessage(SyncMessageReader.java:132) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.protocol.x.SyncMessageReader.readMessage(SyncMessageReader.java:54) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.protocol.x.XProtocol.readQueryResult(XProtocol.java:626) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.protocol.x.XProtocol.reset(XProtocol.java:983) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.xdevapi.ClientImpl$PooledXProtocol.close(ClientImpl.java:431) ~[mysql-connector-java-8.0.20.jar:8.0.20] at com.mysql.cj.MysqlxSession.quit(MysqlxSession.java:90) ~[mysql-connector-java-8.0.20.jar:?] at com.mysql.cj.xdevapi.SessionImpl.close(SessionImpl.java:217) ~[mysql-connector-java-8.0.20.jar:8.0.20] How to repeat: With the folling code snippet, it works every second time. First time works. Seconds fails, third call works again, fourth attempt fails again. Error see above. I am using docker image library/mysql:8.0.20 for server and running code within docker image: tomcat:9.0.35-jdk14-openjdk-slim-buster. After downgrading mysql connector to 8.0.19 bug disappeared. client = new ClientFactory().getClient(baseUrl, "{\"pooling\":{\"enabled\":true, \"maxSize\":" + maxConnections + ", \"queueTimeout\":" + maxWaitForConnection + ", \"maxIdleTime\":" + maxIdleTime + "} }"); List<ConversationRto> result = new ArrayList<>(); Session s = client.getSession(); try { String boxKey = MessageXUtil.createMessageBoxId(owner); DbDoc boxDoc = mb(s).getOne(boxKey); if (boxDoc != null) { MessageBoxX box = mapper.readValue(boxDoc.toString(), MessageBoxX.class); for (Long msgSortKey : box.getMessagesRefs().descendingKeySet()) { if (msgSortKey < offsetKey && result.size() < limit) { try { String msgBoxMsgRef = box.getMessagesRefs().get(msgSortKey); if (!withHiddenRequests && MessageXUtil.getStatusFromMessageBoxMessageRef(msgBoxMsgRef).isHidden()) { continue; } String msgId = MessageXUtil.convertMessageBoxMessageRefToMessageId(msgBoxMsgRef); DbDoc msgDoc = ms(s).getOne(msgId); if (msgDoc != null) { MessageX msg = mapper.readValue(msgDoc.toString(), MessageX.class); ConversationRto cvRto = new ConversationRto(); cvRto.lastMessage = contentResolver.resolveMessageContent(msg, locale); cvRto.sortKey = msgSortKey; cvRto.totalNew = MessageXUtil.getNewMessageCountInConversationFromMessageBoxMessageRef(msgBoxMsgRef); result.add(cvRto); } } catch (Exception ex) { logger.warn("error converting msg, key: " + msgSortKey + ex, ex); } } } } } catch (Exception ex) { logger.warn("error converting box: " + owner + ex, ex); } closeSession(s);