The problem is that completion request can takes too much time,
especially with S3 storage, and because of this it fails sometimes after
client writes "Bye.", like here [1]:
2023-03-07 22:20:22 send: sending "\u0004" to { exp7 }
2023-03-07 22:20:22 Bye.
2023-03-07 22:20:22 [?2004lexpect: timed out
[1]: https://s3.amazonaws.com/clickhouse-test-reports/47295/946dff2d04e7f7af8d3541ed7de11f195b521b6c/stateless_tests__release__s3_storage__[2/2].html
And from server logs:
2023.03.07 22:19:21.885151 [ 41723 ] {00cb66fe-d01f-40ca-a6ef-b7dbd9f69d9e} <Trace> ContextAccess (default): Access granted: CREATE DATABASE ON test_4xqrwzwv.*
...
2023.03.07 22:19:22.286606 [ 5806 ] {} <Debug> TCPHandler: Connected ClickHouse client version 23.3.0, revision: 54461, database: test_4xqrwzwv, user: default.
2023.03.07 22:19:22.287361 [ 5806 ] {1493527c-8b85-4080-be82-a1c78829a104} <Debug> executeQuery: (from [::1]:40978) SELECT DISTINCT arrayJoin(extractAll(name, '[\\w_]{2,}')) AS res FROM (SELECT * FROM viewIfPermitted(SELECT name FROM system.functions ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.table_engines ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.formats ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.table_functions ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.data_type_families ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.merge_tree_settings ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.settings ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT cluster FROM system.clusters ELSE null('cluster String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT macro FROM system.macros ELSE null('macro String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT policy_name FROM system.storage_policies ELSE null('policy_name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT concat(func.name, comb.name) AS x FROM system.functions AS func CROSS JOIN system.aggregate_function_combinators AS comb WHERE is_aggregate ELSE null('x String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT name FROM system.databases LIMIT 10000 ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT DISTINCT name FROM system.tables LIMIT 10000 ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT DISTINCT name FROM system.dictionaries LIMIT 10000 ELSE null('name String')) UNION ALL SELECT * FROM viewIfPermitted(SELECT DISTINCT name FROM system.columns LIMIT 10000 ELSE null('name String'))) WHERE notEmpty(res) (stage: Complete)
...
2023.03.07 22:20:22.316230 [ 58563 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=DROP+DATABASE+IF+EXISTS+test_4xqrwzwv&database=system&connect_timeout=539&receive_timeout=539&send_timeout=539&http_connection_timeout=539&http_receive_timeout=539&http_send_timeout=539&log_comment=01300_client_save_history_when_terminated_long.expect
...
2023.03.07 22:20:45.575830 [ 5806 ] {1493527c-8b85-4080-be82-a1c78829a104} <Warning> TCPHandler: Client has gone away.
2023.03.07 22:20:45.575843 [ 5806 ] {1493527c-8b85-4080-be82-a1c78829a104} <Debug> TCPHandler: Processed in 83.289128886 sec.
So query for autocomplete takes 83 seconds!
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
CI reports [1]:
2023.03.14 00:29:07.031349 [ 166170 ] {110f8654-7d7d-4b47-b6b0-3ce83414a80f} <Error> ReadWriteBufferFromHTTP: HTTP request to `http://127.0.0.1:9018/columns_info?use_connection_pooling=1&version=1&connection_string=DSN%3D%7BClickHouse%20DSN%20%28ANSI%29%7D&schema=test_15&table=t&external_table_functions_use_nulls=1` failed at try 1/1 with bytes read: 0/unknown. Error: DB::HTTPException: Received error from remote server /columns_info?use_connection_pooling=1&version=1&connection_string=DSN%3D%7BClickHouse%20DSN%20%28ANSI%29%7D&schema=test_15&table=t&external_table_functions_use_nulls=1. HTTP status code: 500 Internal Server Error, body: Error getting columns from ODBC 'Code: 49. DB::Exception: Columns definition was not returned. (LOGICAL_ERROR) (version 23.2.4.12 (official build))'
[1]: https://s3.amazonaws.com/clickhouse-test-reports/47541/3d247b8635da44bccfdeb5fcd53be7130b8d0a32/upgrade_check__msan_.html
Here the problem is that system.columns has cached value for number of
total table to iterate, and so it can skip something.
But anyway, this should be LOGICAL_ERROR, since ODBC bridge does two
queries:
- to system.tables and
- to system.columns
And if between this two queries the table will be removed, them there
will be no columns
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
