Bug #99708 mysql-connector-java 8.0.20 ASSERTION FAILED: Unknown message type: 57 s.close
Submitted: 27 May 14:07 Modified: 18 Jun 13:30
Reporter: Bernd Wahlen Email Updates:
Status: Verified Impact on me:
None 
Category:Connector / J Severity:S1 (Critical)
Version:8.0.20 OS:Ubuntu
Assigned to: CPU Architecture:x86
Tags: connector-java, mxsqlx, session.close

[27 May 14:07] Bernd Wahlen
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);
[29 May 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 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 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 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 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 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 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.