MySQL compatibility: command \x16 is not implemented

[slvrtrn]

When connecting Tableau to ClickHouse via MySQL interface, the following error is raised:

Code: 48. DB::Exception: Command \x16; is not implemented. (NOT_IMPLEMENTED) (version 23.6.1.518 (official build))

How to reproduce

• Which ClickHouse server version to use: latest head (23.6.1.518)
• Which interface to use, if matters: MySQL

Error message and/or stacktrace

2023.06.16 18:44:57.889906 [ 45 ] {} <Debug> MySQLHandler: Authentication for user default succeeded.
2023.06.16 18:44:57.889921 [ 45 ] {} <Debug> MYSQL-Session: f9042e6d-73b6-4e37-8955-0d66e881371c Creating session context with user_id: 94309d50-4f52-5250-31bd-74fecac179db
2023.06.16 18:44:57.890075 [ 45 ] {} <Trace> ContextAccess (default): Settings: readonly=0, allow_ddl=true, allow_introspection_functions=false
2023.06.16 18:44:57.890123 [ 45 ] {} <Trace> ContextAccess (default): List of all grants: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, UNDROP TABLE, TRUNCATE, OPTIMIZE, BACKUP, KILL QUERY, KILL TRANSACTION, MOVE PARTITION BETWEEN SHARDS, ACCESS MANAGEMENT, SYSTEM, dictGet, displaySecretsInShowAndSelect, INTROSPECTION, SOURCES, CLUSTER ON *.* WITH GRANT OPTION
2023.06.16 18:44:57.890152 [ 45 ] {} <Trace> ContextAccess (default): List of all grants including implicit: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, UNDROP TABLE, TRUNCATE, OPTIMIZE, BACKUP, KILL QUERY, KILL TRANSACTION, MOVE PARTITION BETWEEN SHARDS, ACCESS MANAGEMENT, SYSTEM, dictGet, displaySecretsInShowAndSelect, INTROSPECTION, SOURCES, CLUSTER ON *.* WITH GRANT OPTION
2023.06.16 18:44:57.890201 [ 45 ] {} <Trace> ContextAccess (default): Settings: readonly=0, allow_ddl=true, allow_introspection_functions=false
2023.06.16 18:44:57.890217 [ 45 ] {} <Trace> ContextAccess (default): List of all grants: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, UNDROP TABLE, TRUNCATE, OPTIMIZE, BACKUP, KILL QUERY, KILL TRANSACTION, MOVE PARTITION BETWEEN SHARDS, ACCESS MANAGEMENT, SYSTEM, dictGet, displaySecretsInShowAndSelect, INTROSPECTION, SOURCES, CLUSTER ON *.* WITH GRANT OPTION
2023.06.16 18:44:57.890233 [ 45 ] {} <Trace> ContextAccess (default): List of all grants including implicit: GRANT SHOW, SELECT, INSERT, ALTER, CREATE, DROP, UNDROP TABLE, TRUNCATE, OPTIMIZE, BACKUP, KILL QUERY, KILL TRANSACTION, MOVE PARTITION BETWEEN SHARDS, ACCESS MANAGEMENT, SYSTEM, dictGet, displaySecretsInShowAndSelect, INTROSPECTION, SOURCES, CLUSTER ON *.* WITH GRANT OPTION
2023.06.16 18:44:57.932017 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 0.
2023.06.16 18:44:57.973862 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 0.
2023.06.16 18:44:58.015656 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 0.
2023.06.16 18:44:58.015778 [ 45 ] {} <Debug> MYSQL-Session: f9042e6d-73b6-4e37-8955-0d66e881371c Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.06.16 18:44:58.015945 [ 45 ] {mysql:0:b52bbd39-c7e1-48f8-9d22-0d6f7d8882f0} <Debug> executeQuery: Query span trace_id for opentelemetry log: 00000000-0000-0000-0000-000000000000
2023.06.16 18:44:58.016092 [ 45 ] {mysql:0:b52bbd39-c7e1-48f8-9d22-0d6f7d8882f0} <Debug> executeQuery: (from 34.246.62.141:48070) SET SQL_AUTO_IS_NULL = 0 (stage: Complete)
2023.06.16 18:44:58.016352 [ 45 ] {mysql:0:b52bbd39-c7e1-48f8-9d22-0d6f7d8882f0} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.
2023.06.16 18:44:58.060260 [ 45 ] {} <Debug> MySQLHandler: Received command: 22. Connection id: 0.
2023.06.16 18:44:58.060656 [ 45 ] {} <Error> MySQLHandler: MySQLHandler: Cannot read packet: : Code: 48. DB::Exception: Command  is not implemented. (NOT_IMPLEMENTED), Stack trace (when copying this message, always include the lines below):

0. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000e37ca35 in /usr/bin/clickhouse
1. ? @ 0x000000000e586a30 in /usr/bin/clickhouse
2. DB::MySQLHandler::run() @ 0x0000000014d06ab7 in /usr/bin/clickhouse
3. Poco::Net::TCPServerConnection::start() @ 0x0000000017cb0574 in /usr/bin/clickhouse
4. Poco::Net::TCPServerDispatcher::run() @ 0x0000000017cb1791 in /usr/bin/clickhouse
5. Poco::PooledThread::run() @ 0x0000000017e2e547 in /usr/bin/clickhouse
6. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000017e2bf7c in /usr/bin/clickhouse
7. ? @ 0x00007f090944f609 in ?
8. clone @ 0x00007f0909374133 in ?
 (version 23.6.1.518 (official build))
2023.06.16 18:44:58.103488 [ 45 ] {} <Debug> MySQLHandler: Received command: 1. Connection id: 0.
2023.06.16 18:44:58.919658 [ 45 ] {} <Trace> MySQLHandlerFactory: MySQL connection. Id: 1. Address: 34.246.62.141:42171
2023.06.16 18:44:58.919876 [ 45 ] {} <Trace> MySQLHandler: Sent handshake
2023.06.16 18:44:58.961150 [ 45 ] {} <Trace> MySQLHandler: payload size: 91
2023.06.16 18:44:58.961244 [ 45 ] {} <Trace> MySQLHandler: Capabilities: 431923853, max_packet_size: 1073741824, character_set: 255, user: default, auth_response length: 20, database: default, auth_plugin_name: mysql_native_password
2023.06.16 18:44:58.961376 [ 45 ] {} <Debug> MYSQL-Session: 191b7671-5e3e-4a84-a3af-67bb0eaabdbc Authenticating user 'default' from 34.246.62.141:42171
2023.06.16 18:44:58.961414 [ 45 ] {} <Debug> MYSQL-Session: 191b7671-5e3e-4a84-a3af-67bb0eaabdbc Authenticated with global context as user 94309d50-4f52-5250-31bd-74fecac179db
2023.06.16 18:44:58.961427 [ 45 ] {} <Debug> MySQLHandler: Authentication for user default succeeded.
2023.06.16 18:44:58.961442 [ 45 ] {} <Debug> MYSQL-Session: 191b7671-5e3e-4a84-a3af-67bb0eaabdbc Creating session context with user_id: 94309d50-4f52-5250-31bd-74fecac179db
2023.06.16 18:44:59.002641 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 1.
2023.06.16 18:44:59.043873 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 1.
2023.06.16 18:44:59.085114 [ 45 ] {} <Debug> MySQLHandler: Received command: 3. Connection id: 1.
2023.06.16 18:44:59.085229 [ 45 ] {} <Debug> MYSQL-Session: 191b7671-5e3e-4a84-a3af-67bb0eaabdbc Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.06.16 18:44:59.085341 [ 45 ] {mysql:1:b25fa4f1-1a22-4eed-8956-1a746dde0e27} <Debug> executeQuery: Query span trace_id for opentelemetry log: 00000000-0000-0000-0000-000000000000
2023.06.16 18:44:59.085457 [ 45 ] {mysql:1:b25fa4f1-1a22-4eed-8956-1a746dde0e27} <Debug> executeQuery: (from 34.246.62.141:42171) SET SQL_AUTO_IS_NULL = 0 (stage: Complete)
2023.06.16 18:44:59.085695 [ 45 ] {mysql:1:b25fa4f1-1a22-4eed-8956-1a746dde0e27} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.
2023.06.16 18:44:59.129101 [ 45 ] {} <Debug> MySQLHandler: Received command: 22. Connection id: 1.
2023.06.16 18:44:59.129286 [ 45 ] {} <Error> MySQLHandler: MySQLHandler: Cannot read packet: : Code: 48. DB::Exception: Command  is not implemented. (NOT_IMPLEMENTED), Stack trace (when copying this message, always include the lines below):

0. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000e37ca35 in /usr/bin/clickhouse
1. ? @ 0x000000000e586a30 in /usr/bin/clickhouse
2. DB::MySQLHandler::run() @ 0x0000000014d06ab7 in /usr/bin/clickhouse
3. Poco::Net::TCPServerConnection::start() @ 0x0000000017cb0574 in /usr/bin/clickhouse
4. Poco::Net::TCPServerDispatcher::run() @ 0x0000000017cb1791 in /usr/bin/clickhouse
5. Poco::PooledThread::run() @ 0x0000000017e2e547 in /usr/bin/clickhouse
6. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000017e2bf7c in /usr/bin/clickhouse
7. ? @ 0x00007f090944f609 in ?
8. clone @ 0x00007f0909374133 in ?
 (version 23.6.1.518 (official build))
2023.06.16 18:44:59.171703 [ 45 ] {} <Debug> MySQLHandler: Received command: 1. Connection id: 1.
2023.06.16 18:45:01.249571 [ 96 ] {} <Debug> DNSResolver: Updating DNS cache
2023.06.16 18:45:01.249652 [ 96 ] {} <Debug> DNSResolver: Updated DNS cache
2023.06.16 18:45:01.260270 [ 286 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 4 entries to flush up to offset 4
2023.06.16 18:45:01.261644 [ 286 ] {} <Debug> SystemLog (system.query_log): Will use existing table system.query_log for QueryLog
2023.06.16 18:45:01.265807 [ 286 ] {} <Trace> system.query_log (3da47ab5-5f3d-4bdc-b81d-bc6b8bd7e41d): Trying to reserve 1.00 MiB using storage policy from min volume index 0
2023.06.16 18:45:01.265877 [ 286 ] {} <Trace> DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 16.68 GiB.
2023.06.16 18:45:01.271013 [ 286 ] {} <Trace> MergedBlockOutputStream: filled checksums 20230616_1_1_0 (state Temporary)
2023.06.16 18:45:01.271594 [ 286 ] {} <Trace> system.query_log (3da47ab5-5f3d-4bdc-b81d-bc6b8bd7e41d): Renaming temporary part tmp_insert_20230616_1_1_0 to 20230616_4_4_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
2023.06.16 18:45:01.272024 [ 286 ] {} <Trace> SystemLog (system.query_log): Flushed system log up to offset 4

[alexey-milovidov]

Could you please help check out - what's the command \x16?

[slvrtrn]

I guess \x16 is coming from logs (see an extra space):

Command  is not implemented

prior to that, there is the following line

2023.06.16 18:44:58.060260 [ 45 ] {} <Debug> MySQLHandler: Received command: 22. Connection id: 0.

I tried to research how MySQL protocol works and stumbled upon this https://dev.mysql.com/doc/dev/mysql-server/latest/page_protocol_command_phase.html

it refers to https://dev.mysql.com/doc/dev/mysql-server/latest/my__command_8h_source.html

22 seems to be COM_STMT_PREPARE if I understand it correctly.

[alexey-milovidov]

Understood. It is about prepared statements. We will need to add support for them.

[vgcrld]

I am seeing this issue in v 23.12.1.9

2023.12.11 17:26:45.360105 [ 34020 ] {mysql:1:ae099acc-a46b-4abe-9aa2-0ac9934cff69} <Debug> executeQuery: (from [::ffff:3.219.176.18]:9755, user: mysql_user) SET SQL_AUTO_IS_NULL = 0 (stage: Complete)
2023.12.11 17:26:45.360763 [ 34020 ] {mysql:1:ae099acc-a46b-4abe-9aa2-0ac9934cff69} <Error> executeQuery: Code: 115. DB::Exception: Setting SQL_AUTO_IS_NULL is neither a builtin setting nor started with the prefix '
                custom_
                SQL_
        ' registered for user-defined settings. (UNKNOWN_SETTING) (version 23.12.1.9 (official build)) (from [::ffff:3.219.176.18]:9755) (in query: SET SQL_AUTO_IS_NULL = 0), Stack trace (when copying this message, always include the lines below):

0. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000c4fd017 in /home/ec2-user/ch/clickhouse
1. DB::Exception::Exception<String, String>(int, FormatStringHelperImpl<std::type_identity<String>::type, std::type_identity<String>::type>, String&&, String&&) @ 0x00000000071c6b28 in /home/ec2-user/ch/clickhouse
2. DB::AccessControl::CustomSettingsPrefixes::checkSettingNameIsAllowed(std::basic_string_view<char, std::char_traits<char>>) const @ 0x000000000fe2878f in /home/ec2-user/ch/clickhouse
3. DB::SettingsConstraints::checkImpl(DB::Settings const&, DB::SettingChange&, DB::SettingsConstraints::ReactionOnViolation, DB::SettingSource) const @ 0x000000000ff2037d in /home/ec2-user/ch/clickhouse
4. DB::Context::checkSettingsConstraints(DB::SettingsChanges const&, DB::SettingSource) const @ 0x0000000010656db3 in /home/ec2-user/ch/clickhouse
5. DB::InterpreterSetQuery::execute() @ 0x0000000010fad6c8 in /home/ec2-user/ch/clickhouse
6. DB::executeQueryImpl(char const*, char const*, std::shared_ptr<DB::Context>, DB::QueryFlags, DB::QueryProcessingStage::Enum, DB::ReadBuffer*) @ 0x000000001132db82 in /home/ec2-user/ch/clickhouse
7. DB::executeQuery(DB::ReadBuffer&, DB::WriteBuffer&, bool, std::shared_ptr<DB::Context>, std::function<void (DB::QueryResultDetails const&)>, DB::QueryFlags, std::optional<DB::FormatSettings> const&, std::function<void (DB::IOutputFormat&)>) @ 0x000000001132fda1 in /home/ec2-user/ch/clickhouse
8. DB::MySQLHandler::comQuery(DB::ReadBuffer&, bool) @ 0x0000000012204cf0 in /home/ec2-user/ch/clickhouse
9. DB::MySQLHandler::run() @ 0x00000000121ff70e in /home/ec2-user/ch/clickhouse
10. Poco::Net::TCPServerConnection::start() @ 0x0000000014c6fc52 in /home/ec2-user/ch/clickhouse
11. Poco::Net::TCPServerDispatcher::run() @ 0x0000000014c70a51 in /home/ec2-user/ch/clickhouse
12. Poco::PooledThread::run() @ 0x0000000014d678e7 in /home/ec2-user/ch/clickhouse
13. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000014d65edc in /home/ec2-user/ch/clickhouse
14. ? @ 0x00007fb086e9f7f2 in ?
15. ? @ 0x00007fb086e3f450 in ?

I added this to conf.d/config.xml:

<clickhouse>
        <custom_settings_prefixes>
                <prefix>custom_</prefix>
                <prefix>SQL_</prefix>
        </custom_settings_prefixes>
</clickhouse>

Is the syntax wrong? This is from Tableau cloud to ch running in aws.
The message appears to indicate it would check for prefix SQL_ but then it doesn't?
Thoughts?

[slvrtrn]

@vgcrld, could you try this instead:

<clickhouse>
        <custom_settings_prefixes>
                <prefix>SQL_,custom_</prefix>
        </custom_settings_prefixes>
</clickhouse>

[vgcrld]

I tried that and the same issue:

2023.12.14 12:41:32.523438 [ 136549 ] {} <Error> MySQLHandler: MySQLHandler: Cannot read packet: : Code: 115. DB::Exception: Setting SQL_AUTO_IS_NULL is neither a builtin setting nor started
 with the prefix '                                                                             
                SQL_' or 'custom_                                                              
        ' registered for user-defined settings. (UNKNOWN_SETTING), Stack trace (when copying this message, always include the lines below):                                                                                                                                                  
0. DB::Exception::Exception(DB::Exception::MessageMasked&&, int, bool) @ 0x000000000c4fd017 in /home/ec2-user/ch/clickhouse
1. DB::Exception::Exception<String, String>(int, FormatStringHelperImpl<std::type_identity<String>::type, std::type_identity<String>::type>, String&&, String&&) @ 0x00000000071c6b28 in /home
/ec2-user/ch/clickhouse                                                                                                                                                                       2. DB::AccessControl::CustomSettingsPrefixes::checkSettingNameIsAllowed(std::basic_string_view<char, std::char_traits<char>>) const @ 0x000000000fe2878f in /home/ec2-user/ch/clickhouse
3. DB::SettingsConstraints::checkImpl(DB::Settings const&, DB::SettingChange&, DB::SettingsConstraints::ReactionOnViolation, DB::SettingSource) const @ 0x000000000ff2037d in /home/ec2-user/ch/clickhouse                                                                                   
4. DB::Context::checkSettingsConstraints(DB::SettingsChanges const&, DB::SettingSource) const @ 0x0000000010656db3 in /home/ec2-user/ch/clickhouse
5. DB::InterpreterSetQuery::execute() @ 0x0000000010fad6c8 in /home/ec2-user/ch/clickhouse
6. DB::executeQueryImpl(char const*, char const*, std::shared_ptr<DB::Context>, DB::QueryFlags, DB::QueryProcessingStage::Enum, DB::ReadBuffer*) @ 0x000000001132db82 in /home/ec2-user/ch/clickhouse                                                                                        
7. DB::executeQuery(DB::ReadBuffer&, DB::WriteBuffer&, bool, std::shared_ptr<DB::Context>, std::function<void (DB::QueryResultDetails const&)>, DB::QueryFlags, std::optional<DB::FormatSettin
gs> const&, std::function<void (DB::IOutputFormat&)>) @ 0x000000001132fda1 in /home/ec2-user/ch/clickhouse
8. DB::MySQLHandler::comQuery(DB::ReadBuffer&, bool) @ 0x0000000012204cf0 in /home/ec2-user/ch/clickhouse                                                                                     9. DB::MySQLHandler::run() @ 0x00000000121ff70e in /home/ec2-user/ch/clickhouse
10. Poco::Net::TCPServerConnection::start() @ 0x0000000014c6fc52 in /home/ec2-user/ch/clickhouse
11. Poco::Net::TCPServerDispatcher::run() @ 0x0000000014c70a51 in /home/ec2-user/ch/clickhouse
12. Poco::PooledThread::run() @ 0x0000000014d678e7 in /home/ec2-user/ch/clickhouse                                                                                                            13. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000014d65edc in /home/ec2-user/ch/clickhouse 
14. ? @ 0x00007f8e5389f7f2 in ?                                                                
15. ? @ 0x00007f8e5383f450 in ?                                                                
 (version 23.12.1.9 (official build))                                                                 

[slvrtrn]

@vgcrld, the right syntax actually is:

<clickhouse>
  <custom_settings_prefixes>SQL_,custom_</custom_settings_prefixes>
</clickhouse>

[vgcrld]

That was it. Thanks!