Logical error: wrong JOIN combination

[tavplubix]

https://clickhouse-test-reports.s3.yandex.net/0/d3e604e14b49960ace3209ce360017ea6a498198/fuzzer_debug/report.html#fail1

2021.09.14 10:15:07.985302 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> executeQuery: (from [::1]:42556) SELECT * FROM (SELECT number AS key FROM numbers(5)) AS s1 ANY LEFT JOIN dict_flat AS d USING (key) ORDER BY key ASC
2021.09.14 10:15:07.986203 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Trace> ContextAccess (default): Access granted: CREATE TEMPORARY TABLE ON *.*
2021.09.14 10:15:07.992534 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Trace> ContextAccess (default): Access granted: SELECT(key, a, b, c) ON db_01115.dict_flat
2021.09.14 10:15:07.993204 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2021.09.14 10:15:07.995194 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> HashJoin: Right sample block: d.key UInt64 UInt64(size = 0), a UInt8 UInt8(size = 0), b String String(size = 0), c Float64 Float64(size = 0)
2021.09.14 10:15:07.995332 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> HashJoin: Right keys: [d.key] (required: []), left keys: [key]
2021.09.14 10:15:07.995469 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> HashJoin: Columns to add: [a UInt8 UInt8(size = 0), b String String(size = 0), c Float64 Float64(size = 0)]
2021.09.14 10:15:07.995580 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> HashJoin: Performing join over dict
2021.09.14 10:15:07.997262 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2021.09.14 10:15:07.997548 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2021.09.14 10:15:07.997761 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Debug> JoiningTransform: Before join block: 'key UInt64 UInt64(size = 0)'
2021.09.14 10:15:07.997989 [ 82 ] {02d8dd1d-f6b2-40a2-af5c-20201c8d394c} <Fatal> : Logical error: 'Logical error: wrong JOIN combination'.
2021.09.14 10:15:07.998680 [ 42 ] {} <Trace> BaseDaemon: Received signal 6
2021.09.14 10:15:07.999182 [ 305 ] {} <Fatal> BaseDaemon: ########################################
2021.09.14 10:15:07.999425 [ 305 ] {} <Fatal> BaseDaemon: (version 21.11.1.8072 (official build), build id: A6877D4F1D4FC0652BB01C0312CBE20E11B3B0E1) (from thread 82) (query_id: 02d8dd1d-f6b2-40a2-af5c-20201c8d394c) Received signal Aborted (6)
2021.09.14 10:15:07.999677 [ 305 ] {} <Fatal> BaseDaemon: 
2021.09.14 10:15:07.999991 [ 305 ] {} <Fatal> BaseDaemon: Stack trace: 0x7f14ab4b418b 0x7f14ab493859 0x1311ce58 0x1311cf62 0x1ded6f88 0x1f76072a 0x1f840972 0x1e201438 0x1e1ee3bf 0x1e1ec87c 0x1e54b19d 0x1e54bb5a 0x1e7f76d3 0x1e7f577d 0x1f382f26 0x1f3905e5 0x237bcd59 0x237bd568 0x2390b4f4 0x23907fda 0x23906dbc 0x7f14ab67a609 0x7f14ab590293
2021.09.14 10:15:08.000384 [ 305 ] {} <Fatal> BaseDaemon: 4. raise @ 0x4618b in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.09.14 10:15:08.000571 [ 305 ] {} <Fatal> BaseDaemon: 5. abort @ 0x25859 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.09.14 10:15:08.085767 [ 305 ] {} <Fatal> BaseDaemon: 6. ./obj-x86_64-linux-gnu/../src/Common/Exception.cpp:53: DB::handle_error_code(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int, bool, std::__1::vector<void*, std::__1::allocator<void*> > const&) @ 0x1311ce58 in /workspace/clickhouse
2021.09.14 10:15:08.154196 [ 305 ] {} <Fatal> BaseDaemon: 7. ./obj-x86_64-linux-gnu/../src/Common/Exception.cpp:60: DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int, bool) @ 0x1311cf62 in /workspace/clickhouse
2021.09.14 10:15:09.045559 [ 305 ] {} <Fatal> BaseDaemon: 8. ./obj-x86_64-linux-gnu/../src/Interpreters/HashJoin.cpp:1417: DB::HashJoin::joinBlock(DB::Block&, std::__1::shared_ptr<DB::ExtraBlock>&) @ 0x1ded6f88 in /workspace/clickhouse
2021.09.14 10:15:09.139105 [ 58 ] {} <Debug> system.metric_log (9c85d3b0-3584-4d7c-9c85-d3b035847d7c) (MergerMutator): Merge sorted 3123 rows, containing 302 columns (302 merged, 0 gathered) in 0.701922532 sec., 4449.2089335009405 rows/sec., 10.21 MiB/sec.
2021.09.14 10:15:09.167269 [ 305 ] {} <Fatal> BaseDaemon: 9. ./obj-x86_64-linux-gnu/../src/Processors/Transforms/JoiningTransform.cpp:19: DB::JoiningTransform::transformHeader(DB::Block, std::__1::shared_ptr<DB::IJoin> const&) @ 0x1f76072a in /workspace/clickhouse
2021.09.14 10:15:09.214750 [ 58 ] {} <Trace> system.metric_log (9c85d3b0-3584-4d7c-9c85-d3b035847d7c): Renaming temporary part tmp_merge_202109_1_401_80 to 202109_1_401_80.
2021.09.14 10:15:09.216341 [ 58 ] {} <Trace> system.metric_log (9c85d3b0-3584-4d7c-9c85-d3b035847d7c) (MergerMutator): Merged 6 parts: from 202109_1_396_79 to 202109_401_401_0
2021.09.14 10:15:09.216449 [ 58 ] {} <Debug> MemoryTracker: Peak memory usage: 16.05 MiB.
2021.09.14 10:15:09.333232 [ 305 ] {} <Fatal> BaseDaemon: 10. ./obj-x86_64-linux-gnu/../src/Processors/QueryPlan/JoinStep.cpp:61: DB::FilledJoinStep::FilledJoinStep(DB::DataStream const&, std::__1::shared_ptr<DB::IJoin>, unsigned long) @ 0x1f840972 in /workspace/clickhouse
2021.09.14 10:15:09.757623 [ 130 ] {} <Debug> DiskLocal: Reserving 1.11 MiB on disk `default`, having unreserved 6.20 TiB.
2021.09.14 10:15:09.772892 [ 130 ] {} <Trace> system.text_log (ef78cfae-2169-465b-af78-cfae2169f65b): Renaming temporary part tmp_insert_202109_412_412_0 to 202109_412_412_0.
2021.09.14 10:15:10.000258 [ 264 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 879.80 MiB, peak 1.20 GiB, will set to 941.75 MiB (RSS), difference: 61.95 MiB
2021.09.14 10:15:10.188670 [ 305 ] {} <Fatal> BaseDaemon: 11. ./obj-x86_64-linux-gnu/../contrib/libcxx/include/memory:2068: std::__1::__unique_if<DB::FilledJoinStep>::__unique_single std::__1::make_unique<DB::FilledJoinStep, DB::DataStream const&, std::__1::shared_ptr<DB::IJoin>&, DB::SettingFieldNumber<unsigned long> const&>(DB::DataStream const&, std::__1::shared_ptr<DB::IJoin>&, DB::SettingFieldNumber<unsigned long> const&) @ 0x1e201438 in /workspace/clickhouse
2021.09.14 10:15:10.481490 [ 125 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 8624 entries to flush up to offset 3850130
2021.09.14 10:15:10.509145 [ 125 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 6.20 TiB.
2021.09.14 10:15:10.515837 [ 125 ] {} <Trace> system.asynchronous_metric_log (71da3ecc-524c-49fd-b1da-3ecc524c89fd): Renaming temporary part tmp_insert_202109_444_444_0 to 202109_444_444_0.
2021.09.14 10:15:10.516712 [ 125 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log up to offset 3850130
2021.09.14 10:15:10.855309 [ 305 ] {} <Fatal> BaseDaemon: 12. ./obj-x86_64-linux-gnu/../src/Interpreters/InterpreterSelectQuery.cpp:1148: DB::InterpreterSelectQuery::executeImpl(DB::QueryPlan&, std::__1::shared_ptr<DB::IBlockInputStream> const&, std::__1::optional<DB::Pipe>) @ 0x1e1ee3bf in /workspace/clickhouse
2021.09.14 10:15:11.000252 [ 264 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 941.73 MiB, peak 1.20 GiB, will set to 945.52 MiB (RSS), difference: 3.79 MiB
2021.09.14 10:15:11.009729 [ 127 ] {} <Trace> SystemLog (system.trace_log): Flushing system log, 8 entries to flush up to offset 4555
2021.09.14 10:15:11.017978 [ 127 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 6.20 TiB.
2021.09.14 10:15:11.022507 [ 127 ] {} <Trace> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf): Renaming temporary part tmp_insert_202109_416_416_0 to 202109_416_416_0.
2021.09.14 10:15:11.023036 [ 214 ] {} <Debug> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf) (MergerMutator): Selected 2 parts from 202109_1_411_161 to 202109_412_412_0
2021.09.14 10:15:11.023223 [ 214 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 6.20 TiB.
2021.09.14 10:15:11.023420 [ 127 ] {} <Trace> SystemLog (system.trace_log): Flushed system log up to offset 4555
2021.09.14 10:15:11.023510 [ 55 ] {} <Debug> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf) (MergerMutator): Merging 2 parts: from 202109_1_411_161 to 202109_412_412_0 into Compact
2021.09.14 10:15:11.024092 [ 55 ] {} <Debug> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf) (MergerMutator): Selected MergeAlgorithm: Horizontal
2021.09.14 10:15:11.024621 [ 55 ] {} <Debug> MergeTreeSequentialSource: Reading 2 marks from part 202109_1_411_161, total 4505 rows starting from the beginning of the part
2021.09.14 10:15:11.026090 [ 55 ] {} <Debug> MergeTreeSequentialSource: Reading 2 marks from part 202109_412_412_0, total 12 rows starting from the beginning of the part
2021.09.14 10:15:11.042549 [ 55 ] {} <Debug> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf) (MergerMutator): Merge sorted 4517 rows, containing 10 columns (10 merged, 0 gathered) in 0.019097811 sec., 236519.2534369515 rows/sec., 69.21 MiB/sec.
2021.09.14 10:15:11.061207 [ 55 ] {} <Trace> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf): Renaming temporary part tmp_merge_202109_1_412_162 to 202109_1_412_162.
2021.09.14 10:15:11.061583 [ 55 ] {} <Trace> system.trace_log (16ebf147-ed35-4adf-96eb-f147ed35aadf) (MergerMutator): Merged 2 parts: from 202109_1_411_161 to 202109_412_412_0
2021.09.14 10:15:11.061709 [ 55 ] {} <Debug> MemoryTracker: Peak memory usage: 4.01 MiB.
2021.09.14 10:15:11.505995 [ 305 ] {} <Fatal> BaseDaemon: 13. ./obj-x86_64-linux-gnu/../src/Interpreters/InterpreterSelectQuery.cpp:580: DB::InterpreterSelectQuery::buildQueryPlan(DB::QueryPlan&) @ 0x1e1ec87c in /workspace/clickhouse
2021.09.14 10:15:11.757203 [ 305 ] {} <Fatal> BaseDaemon: 14. ./obj-x86_64-linux-gnu/../src/Interpreters/InterpreterSelectWithUnionQuery.cpp:255: DB::InterpreterSelectWithUnionQuery::buildQueryPlan(DB::QueryPlan&) @ 0x1e54b19d in /workspace/clickhouse
2021.09.14 10:15:12.000308 [ 264 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 945.49 MiB, peak 1.20 GiB, will set to 948.09 MiB (RSS), difference: 2.60 MiB
2021.09.14 10:15:12.010462 [ 305 ] {} <Fatal> BaseDaemon: 15. ./obj-x86_64-linux-gnu/../src/Interpreters/InterpreterSelectWithUnionQuery.cpp:321: DB::InterpreterSelectWithUnionQuery::execute() @ 0x1e54bb5a in /workspace/clickhouse
2021.09.14 10:15:12.151650 [ 274 ] {} <Trace> ExternalDictionariesLoader: Will load the object '49eb2a86-4a97-467b-89eb-2a864a97867b' in background, force = false, loading_id = 15
2021.09.14 10:15:12.151804 [ 274 ] {} <Trace> ExternalDictionariesLoader: Object '49eb2a86-4a97-467b-89eb-2a864a97867b' is neither loaded nor failed, so it will not be reloaded as outdated.
2021.09.14 10:15:12.151918 [ 268 ] {} <Trace> ExternalDictionariesLoader: Start loading object '49eb2a86-4a97-467b-89eb-2a864a97867b'
2021.09.14 10:15:12.154295 [ 268 ] {} <Debug> executeQuery: (internal) SELECT `key`, `a`, `b`, `c` FROM `db_01115`.`t1`;
2021.09.14 10:15:12.156375 [ 268 ] {} <Trace> ContextAccess (default): Access granted: SELECT(key, a, b, c) ON db_01115.t1
2021.09.14 10:15:12.156856 [ 268 ] {} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2021.09.14 10:15:12.158175 [ 268 ] {} <Debug> db_01115.t1 (ee6fd25e-27c0-49b3-ae6f-d25e27c0c9b3) (SelectExecutor): Key condition: unknown
2021.09.14 10:15:12.158417 [ 268 ] {} <Debug> db_01115.t1 (ee6fd25e-27c0-49b3-ae6f-d25e27c0c9b3) (SelectExecutor): Selected 1/1 parts by partition key, 1 parts by primary key, 1/1 marks by primary key, 1 marks to read from 1 ranges
2021.09.14 10:15:12.158794 [ 268 ] {} <Debug> MergeTreeInOrderSelectProcessor: Reading 1 ranges in order from part all_1_1_0, approx. 4 rows starting from 0
2021.09.14 10:15:12.163180 [ 268 ] {} <Trace> ExternalDictionariesLoader: Supposed update time for '49eb2a86-4a97-467b-89eb-2a864a97867b' is 2021-09-14 10:15:16 (loaded, lifetime [1, 10], no errors)
2021.09.14 10:15:12.163295 [ 268 ] {} <Trace> ExternalDictionariesLoader: Next update time for '49eb2a86-4a97-467b-89eb-2a864a97867b' was set to 2021-09-14 10:15:16
2021.09.14 10:15:12.310556 [ 305 ] {} <Fatal> BaseDaemon: 16. ./obj-x86_64-linux-gnu/../src/Interpreters/executeQuery.cpp:601: DB::executeQueryImpl(char const*, char const*, std::__1::shared_ptr<DB::Context>, bool, DB::QueryProcessingStage::Enum, bool, DB::ReadBuffer*) @ 0x1e7f76d3 in /workspace/clickhouse
2021.09.14 10:15:12.621210 [ 305 ] {} <Fatal> BaseDaemon: 17. ./obj-x86_64-linux-gnu/../src/Interpreters/executeQuery.cpp:962: DB::executeQuery(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::shared_ptr<DB::Context>, bool, DB::QueryProcessingStage::Enum, bool) @ 0x1e7f577d in /workspace/clickhouse
2021.09.14 10:15:12.905426 [ 305 ] {} <Fatal> BaseDaemon: 18. ./obj-x86_64-linux-gnu/../src/Server/TCPHandler.cpp:291: DB::TCPHandler::runImpl() @ 0x1f382f26 in /workspace/clickhouse
2021.09.14 10:15:13.000239 [ 264 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 948.09 MiB, peak 1.20 GiB, will set to 966.86 MiB (RSS), difference: 18.77 MiB
2021.09.14 10:15:13.248732 [ 305 ] {} <Fatal> BaseDaemon: 19. ./obj-x86_64-linux-gnu/../src/Server/TCPHandler.cpp:1659: DB::TCPHandler::run() @ 0x1f3905e5 in /workspace/clickhouse
2021.09.14 10:15:13.310149 [ 305 ] {} <Fatal> BaseDaemon: 20. ./obj-x86_64-linux-gnu/../contrib/poco/Net/src/TCPServerConnection.cpp:43: Poco::Net::TCPServerConnection::start() @ 0x237bcd59 in /workspace/clickhouse
2021.09.14 10:15:13.397520 [ 305 ] {} <Fatal> BaseDaemon: 21. ./obj-x86_64-linux-gnu/../contrib/poco/Net/src/TCPServerDispatcher.cpp:115: Poco::Net::TCPServerDispatcher::run() @ 0x237bd568 in /workspace/clickhouse
2021.09.14 10:15:13.485529 [ 305 ] {} <Fatal> BaseDaemon: 22. ./obj-x86_64-linux-gnu/../contrib/poco/Foundation/src/ThreadPool.cpp:199: Poco::PooledThread::run() @ 0x2390b4f4 in /workspace/clickhouse
2021.09.14 10:15:13.573743 [ 305 ] {} <Fatal> BaseDaemon: 23. ./obj-x86_64-linux-gnu/../contrib/poco/Foundation/src/Thread.cpp:56: Poco::(anonymous namespace)::RunnableHolder::run() @ 0x23907fda in /workspace/clickhouse
2021.09.14 10:15:13.618150 [ 123 ] {} <Trace> SystemLog (system.query_log): Flushing system log, 306 entries to flush up to offset 114827
2021.09.14 10:15:13.661840 [ 305 ] {} <Fatal> BaseDaemon: 24. ./obj-x86_64-linux-gnu/../contrib/poco/Foundation/src/Thread_POSIX.cpp:345: Poco::ThreadImpl::runnableEntry(void*) @ 0x23906dbc in /workspace/clickhouse
2021.09.14 10:15:13.662307 [ 305 ] {} <Fatal> BaseDaemon: 25. start_thread @ 0x9609 in /usr/lib/x86_64-linux-gnu/libpthread-2.31.so
2021.09.14 10:15:13.662661 [ 305 ] {} <Fatal> BaseDaemon: 26. clone @ 0x122293 in /usr/lib/x86_64-linux-gnu/libc-2.31.so
2021.09.14 10:15:13.746497 [ 123 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 6.20 TiB.
2021.09.14 10:15:13.770085 [ 123 ] {} <Trace> system.query_log (257f0c47-f610-4a0b-a57f-0c47f6108a0b): Renaming temporary part tmp_insert_202109_402_402_0 to 202109_402_402_0.
2021.09.14 10:15:13.774562 [ 123 ] {} <Trace> SystemLog (system.query_log): Flushed system log up to offset 114827
2021.09.14 10:15:14.000299 [ 264 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 962.58 MiB, peak 1.20 GiB, will set to 973.58 MiB (RSS), difference: 11.00 MiB
2021.09.14 10:15:14.944027 [ 305 ] {} <Fatal> BaseDaemon: Checksum of the binary: 1AE5A96643C00008807F8F5AF068B871, integrity check passed.

cc: @vdimir