Clickhouse: Poco::Exception. Code: 1000, e.code() = 0

[eagle1981]

Using docker clickhouse-server:latest

After upgrade - we have many error-log entries such as:

2019.01.14 02:24:10.831297 [ 17 ] {} graphite.metrics_lr (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.01.14 02:24:20.916719 [ 7 ] {} graphite.metrics_lr (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received

2019.01.14 02:24:26.813686 [ 4 ] {} graphite.data_lr (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::

2019.01.14 02:24:32.580035 [ 16 ] {} graphite.data_lr (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::

[filimonov]

Most probably duplicate of #3891. The issue was fixed in master, but not released yet.

[eagle1981]

Looks like it is. Any plans to promote changes to :latest ?

[filimonov]

When new version will be ready it will be released. Stay tuned :)
For now, you can use 18.14.19, or build latest with needed fixes by your own.

[zzn01]

what's the affection of this error? Is it safe to ignore?

[eagle1981]

what's the affection of this error? Is it safe to ignore?

No visual effect on functions, only disk space wasting in log-files.

[ztlpn]

@andywow reports that the No message received error is still present on 19.1.6. @alesapin can you take a look?

[alesapin]

@andywow Can you describe in more details? Maybe provide some logs? We got No message received error in our tests, but in this PR https://github.com/yandex/ClickHouse/pull/3932 problem was fixed. Maybe you have other problem with same 'awesome' message.

[andywow]

@alesapin, here is log example:

2019.01.31 15:39:16.661361 [ 8 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45182_45182_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:16.680103 [ 29 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:16.685351 [ 3 ] {} <Debug> logdb.logs (MergerMutator): Merging 5 parts: from 20190131_45168_45168_0 to 20190131_45172_45172_0 into tmp_merge_20190131_45168_45172_1
2019.01.31 15:39:16.856240 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:16.862385 [ 46 ] {125fbafa-42b4-41a2-8983-e3b855d6149f} <Debug> executeQuery: (from 10.128.8.1:57990, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:16.910831 [ 51 ] {cbca2d58-9e2b-40e8-b338-bfdbd432efcb} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_15236628106915869693_15382222068285301741', 6014 rows
2019.01.31 15:39:17.139649 [ 31 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375542 - log-0000375542
2019.01.31 15:39:17.166239 [ 31 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:17.451641 [ 51 ] {cbca2d58-9e2b-40e8-b338-bfdbd432efcb} <Debug> MemoryTracker: Peak memory usage (for query): 60.83 MiB.
2019.01.31 15:39:17.451860 [ 51 ] {} <Information> TCPHandler: Processed in 2.310 sec.
2019.01.31 15:39:17.453015 [ 51 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:17.455569 [ 10 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45184_45184_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:17.456064 [ 26 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375543 - log-0000375543
2019.01.31 15:39:17.492125 [ 26 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:17.875326 [ 23 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375544 - log-0000375544
2019.01.31 15:39:17.899918 [ 23 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:17.909871 [ 5 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45185_45185_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:18.046970 [ 48 ] {e58e925f-cbe6-48b9-b2b4-be95f895a047} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_16347631984774990372_16569375850032031628', 114 rows
2019.01.31 15:39:18.110888 [ 36 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375545 - log-0000375545
2019.01.31 15:39:18.126868 [ 36 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:18.197389 [ 52 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:18.203598 [ 52 ] {ee75f492-9571-4748-b9d3-b95b5f948ab8} <Debug> executeQuery: (from 10.130.4.1:53622, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:18.248505 [ 3 ] {} <Debug> logdb.logs (MergerMutator): Selected MergeAlgorithm: Horizontal
2019.01.31 15:39:18.284327 [ 25 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375546 - log-0000375546
2019.01.31 15:39:18.309793 [ 25 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:18.398901 [ 48 ] {e58e925f-cbe6-48b9-b2b4-be95f895a047} <Debug> MemoryTracker: Peak memory usage (for query): 50.53 MiB.
2019.01.31 15:39:18.399061 [ 48 ] {} <Information> TCPHandler: Processed in 2.543 sec.
2019.01.31 15:39:18.399808 [ 48 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:18.441570 [ 51 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:18.447510 [ 51 ] {c19ee605-bc0e-43bc-8b04-2eb894656013} <Debug> executeQuery: (from 10.131.4.1:56840, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:18.458356 [ 16 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45186_45186_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:18.487681 [ 18 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45175_45175_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:18.488393 [ 16 ] {} <Error> logdb.logs (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received
2019.01.31 15:39:18.533057 [ 18 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45186_45186_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:18.801163 [ 27 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375547 - log-0000375547
2019.01.31 15:39:18.836226 [ 27 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:18.867377 [ 14 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45188_45188_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:18.867465 [ 33 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375548 - log-0000375548
2019.01.31 15:39:18.886963 [ 33 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:18.907803 [ 6 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45189_45189_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:19.073651 [ 48 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:19.081883 [ 48 ] {3be7c7c5-b5f8-441b-9557-15aaa7cb1641} <Debug> executeQuery: (from 10.129.4.1:35256, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:19.715096 [ 50 ] {be08e484-d5c5-4bc2-9277-75961a5fd615} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_6287150824869234995_11634570143764135831', 15 rows
2019.01.31 15:39:19.828138 [ 34 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375549 - log-0000375549
2019.01.31 15:39:19.843938 [ 34 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:19.883965 [ 46 ] {125fbafa-42b4-41a2-8983-e3b855d6149f} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190130_7161329962311412675_16877035574352368739', 1 rows
2019.01.31 15:39:19.996008 [ 24 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375550 - log-0000375550
2019.01.31 15:39:20.003958 [ 50 ] {be08e484-d5c5-4bc2-9277-75961a5fd615} <Debug> MemoryTracker: Peak memory usage (for query): 50.27 MiB.
2019.01.31 15:39:20.004662 [ 50 ] {} <Information> TCPHandler: Processed in 3.384 sec.
2019.01.31 15:39:20.004756 [ 50 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:20.005508 [ 11 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45177_45177_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:20.005680 [ 7 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45190_45190_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:20.034334 [ 46 ] {125fbafa-42b4-41a2-8983-e3b855d6149f} <Debug> MemoryTracker: Peak memory usage (for query): 50.24 MiB.
2019.01.31 15:39:20.035376 [ 46 ] {} <Information> TCPHandler: Processed in 3.173 sec.
2019.01.31 15:39:20.034334 [ 7 ] {} <Error> logdb.logs (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received
2019.01.31 15:39:20.035542 [ 46 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:20.048498 [ 24 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:20.077485 [ 11 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45190_45190_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:20.093179 [ 29 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375551 - log-0000375551
2019.01.31 15:39:20.156559 [ 29 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:20.625886 [ 17 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45178_45178_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:20.699732 [ 31 ] {} <Debug> logdb.logs (MergerMutator): Selected 6 parts from 20190131_45173_45173_0 to 20190131_45178_45178_0
2019.01.31 15:39:20.742512 [ 26 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375552 - log-0000375552
2019.01.31 15:39:20.768180 [ 26 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:20.799946 [ 9 ] {} <Debug> logdb.logs (MergerMutator): Merging 6 parts: from 20190131_45173_45173_0 to 20190131_45178_45178_0 into tmp_merge_20190131_45173_45178_1
2019.01.31 15:39:21.033075 [ 23 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375553 - log-0000375553
2019.01.31 15:39:21.046616 [ 23 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:21.144712 [ 36 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375554 - log-0000375554
2019.01.31 15:39:21.188217 [ 36 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:21.277075 [ 13 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45179_45179_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.333644 [ 7 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45193_45193_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.333936 [ 16 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45192_45192_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.334383 [ 7 ] {} <Error> logdb.logs (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received
2019.01.31 15:39:21.365187 [ 15 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45180_45180_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.489950 [ 52 ] {ee75f492-9571-4748-b9d3-b95b5f948ab8} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_6528039023252625981_11318475687759563261', 23 rows
2019.01.31 15:39:21.834537 [ 53 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:21.840048 [ 53 ] {d89a36b5-636b-4acf-9f27-b2ecc81e0e5c} <Debug> executeQuery: (from 10.128.4.1:60542, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:21.857123 [ 35 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375555 - log-0000375555
2019.01.31 15:39:21.892457 [ 35 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:21.905713 [ 27 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375556 - log-0000375556
2019.01.31 15:39:21.963052 [ 15 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45193_45193_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.966984 [ 4 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45181_45181_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:21.968167 [ 52 ] {ee75f492-9571-4748-b9d3-b95b5f948ab8} <Debug> MemoryTracker: Peak memory usage (for query): 50.27 MiB.
2019.01.31 15:39:21.968740 [ 52 ] {} <Information> TCPHandler: Processed in 3.765 sec.
2019.01.31 15:39:21.969419 [ 52 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:21.969745 [ 27 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:21.984459 [ 15 ] {} <Error> logdb.logs (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received
2019.01.31 15:39:22.006068 [ 51 ] {c19ee605-bc0e-43bc-8b04-2eb894656013} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_3167656419313925407_12727283588511619094', 108 rows
2019.01.31 15:39:22.015910 [ 46 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:22.036797 [ 46 ] {c80eab3c-9254-4649-9d01-46d1e35edc86} <Debug> executeQuery: (from 10.130.4.1:53634, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:22.048986 [ 17 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45195_45195_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:22.640416 [ 9 ] {} <Debug> logdb.logs (MergerMutator): Selected MergeAlgorithm: Horizontal
2019.01.31 15:39:22.675019 [ 4 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45193_45193_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:22.675696 [ 8 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetched part 20190131_45182_45182_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:22.696415 [ 4 ] {} <Error> logdb.logs (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received, e.what() = No message received
2019.01.31 15:39:22.696609 [ 51 ] {c19ee605-bc0e-43bc-8b04-2eb894656013} <Debug> MemoryTracker: Peak memory usage (for query): 50.53 MiB.
2019.01.31 15:39:22.697803 [ 51 ] {} <Information> TCPHandler: Processed in 4.250 sec.
2019.01.31 15:39:22.697838 [ 51 ] {} <Information> TCPHandler: Done processing connection.
2019.01.31 15:39:22.741025 [ 29 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375557 - log-0000375557
2019.01.31 15:39:22.780600 [ 29 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:22.819382 [ 48 ] {3be7c7c5-b5f8-441b-9557-15aaa7cb1641} <Debug> logdb.logs (Replicated OutputStream): Wrote block with ID '20190131_11005474187308461911_5406784493284169051', 3016 rows
2019.01.31 15:39:22.854585 [ 24 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375558 - log-0000375558
2019.01.31 15:39:22.898054 [ 24 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.01.31 15:39:22.911515 [ 8 ] {} <Debug> logdb.logs (StorageReplicatedMergeTree): Fetching part 20190131_45193_45193_0 from /clickhouse/logs/tables/1/logs/replicas/clickhouse-0.clickhouse-headless.clickhouse.svc.cluster.local
2019.01.31 15:39:22.976956 [ 50 ] {} <Debug> TCPHandler: Connected ClickHouse client version 19.1.0, revision: 54413, database: logdb, user: fluentd.
2019.01.31 15:39:22.977445 [ 38 ] {} <Debug> logdb.logs (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0000375559 - log-0000375559
2019.01.31 15:39:22.982398 [ 12 ] {} <Debug> logdb.logs (MergerMutator): Merge sorted 15881 rows, containing 19 columns (19 merged, 0 gathered) in 9.41 sec., 1687.71 rows/sec., 1.32 MB/sec.
2019.01.31 15:39:22.991422 [ 50 ] {ed31ae1e-bc37-4334-9809-6a8b9731c962} <Debug> executeQuery: (from 10.129.6.1:58166, user: fluentd) INSERT INTO logs FORMAT JSONEachRow
2019.01.31 15:39:23.025535 [ 48 ] {3be7c7c5-b5f8-441b-9557-15aaa7cb1641} <Debug> MemoryTracker: Peak memory usage (for query): 56.10 MiB.
2019.01.31 15:39:23.025705 [ 48 ] {} <Information> TCPHandler: Processed in 3.944 sec.
2019.01.31 15:39:23.027713 [ 48 ] {} <Information> TCPHandler: Done processing connection. 

[alesapin]

@andywow Unfortunately I can't get any useful information from your log :( Seems like you get some other problem. Can you describe your shard configuration? Do you update all shard servers to 19.1.6? Can you provide logs from other server? Maybe we can discuss this issue in details in telegram?

[evgeny-l]

@alesapin
Hi! Seems like I'm experiencing similar issue with my ClickHouse setup.

ClickHouse error log got spammed with messages like:

019.02.19 20:09:33.781020 [ 2 ] {} events.bid_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:09:47.192792 [ 16 ] {} events.commercial_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:09:48.945355 [ 11 ] {} events.commercial_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:09:53.439429 [ 3 ] {} events.commercial_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:09:57.621721 [ 10 ] {} events.video_events_summing (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:10:06.996773 [ 16 ] {} events.integration_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:10:16.405888 [ 10 ] {} events.commercial_events_summing (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:10:30.415479 [ 9 ] {} events.video_events_summing (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:10:48.778418 [ 9 ] {} events.video_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask():: 2019.02.19 20:10:49.174598 [ 6 ] {} events.commercial_events (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::

If I can assist you somehow in the way to fix that, you can contact me in telegram @eleksunin.

[mikeeremin]

19.3.7 - still present.

[sunadm]

Me too,
After upgrade from 18.14 to 19.3.5.

Change log mode to trace:

2019.03.14 16:21:21.533589 [ 35 ] {} <Debug> report.amg_wms_stock_flow_local (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0003080762 - log-0003080762
2019.03.14 16:21:21.538431 [ 35 ] {} <Debug> report.amg_wms_stock_flow_local (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.03.14 16:21:21.543065 [ 6 ] {} <Debug> report.amg_wms_stock_flow_local (StorageReplicatedMergeTree): Fetching part 201903_203782_203782_0 from /clickhouse/tables/dplus/01/amg_wms_stock_flow/replicas/clickhouse-02
2019.03.14 16:21:21.544489 [ 6 ] {} <Trace> ReadWriteBufferFromHTTP: Sending request to http://clickhouse-02:9009/?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2Fdplus%2F01%2Famg_wms_stock_flow%2Freplicas%2Fclickhouse-02&part=201903_203782_203782_0&compress=false
2019.03.14 16:21:21.544630 [ 6 ] {} <Error> report.amg_wms_stock_flow_local (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received

another trace log:

2019.03.14 16:38:03.913141 [ 2 ] {} <Trace> SystemLog (system.query_log): Flushing system log
2019.03.14 16:38:03.913624 [ 91 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: GET, Address: 100.121.5.1:40794, User-Agent: SLBHealthCheck, Content Type: , Transfer Encoding: identity
2019.03.14 16:38:03.913675 [ 14 ] {} <Trace> MergeTreeSequentialBlockInputStream: Reading 1 marks from part 201903_82403_82403_0, totaly 71 rows starting from the beginning of the part
2019.03.14 16:38:03.914185 [ 14 ] {} <Trace> MergeTreeSequentialBlockInputStream: Reading 1 marks from part 201903_82404_82404_0, totaly 147 rows starting from the beginning of the part
2019.03.14 16:38:03.918575 [ 2 ] {} <Trace> system.query_log (Data): Renaming temporary part tmp_insert_201903_82408_82408_0 to 201903_82408_82408_0.
2019.03.14 16:38:03.925665 [ 14 ] {} <Debug> system.query_thread_log (MergerMutator): Merge sorted 1093 rows, containing 39 columns (39 merged, 0 gathered) in 0.02 sec., 70937.97 rows/sec., 96.22 MB/sec.
2019.03.14 16:38:03.927434 [ 14 ] {} <Trace> system.query_thread_log (Data): Renaming temporary part tmp_merge_201903_82396_82404_2 to 201903_82396_82404_2.
2019.03.14 16:38:03.927817 [ 14 ] {} <Trace> system.query_thread_log (MergerMutator): Merged 5 parts: from 201903_82396_82400_1 to 201903_82404_82404_0
2019.03.14 16:38:03.965780 [ 40 ] {} <Debug> report.amg_wms_stock_period_local (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0005860726 - log-0005860726
2019.03.14 16:38:03.972561 [ 40 ] {} <Debug> report.amg_wms_stock_period_local (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.
2019.03.14 16:38:03.977289 [ 11 ] {} <Debug> report.amg_wms_stock_period_local (StorageReplicatedMergeTree): Fetching part 201903_378474_378474_0 from /clickhouse/tables/dplus/01/amg_wms_stock_period/replicas/clickhouse-02
2019.03.14 16:38:03.978712 [ 11 ] {} <Trace> ReadWriteBufferFromHTTP: Sending request to http://clickhouse-02:9009/?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2Fdplus%2F01%2Famg_wms_stock_period%2Freplicas%2Fclickhouse-02&part=201903_378474_378474_0&compress=false
2019.03.14 16:38:03.978879 [ 11 ] {} <Error> report.amg_wms_stock_period_local (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received

Seems the error occurred when request to interface http://clickhouse-02:9009/?endpoint=DataPartsExchange.

the trace log capture node is clickhouse-01.

other log related to part '201903_378474_378474_0':

......
2019.03.14 16:38:04.025022 [ 9 ] {} <Debug> report.amg_wms_stock_period_local (StorageReplicatedMergeTree): Fetching part 201903_378474_378474_0 from /clickhouse/tables/dplus/01/amg_wms_stock_period/replicas/clickhouse-02
......
2019.03.14 16:38:04.027325 [ 9 ] {} <Trace> ReadWriteBufferFromHTTP: Sending request to http://clickhouse-02:9009/?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2Fdplus%2F01%2Famg_wms_stock_period%2Freplicas%2Fclickhouse-02&part=201903_378474_378474_0&compress=false
......
2019.03.14 16:38:04.031448 [ 9 ] {} <Trace> report.amg_wms_stock_period_local (Data): Renaming temporary part tmp_fetch_201903_378474_378474_0 to 201903_378474_378474_0.
......
2019.03.14 16:38:04.051981 [ 9 ] {} <Debug> report.amg_wms_stock_period_local (StorageReplicatedMergeTree): Fetched part 201903_378474_378474_0 from /clickhouse/tables/dplus/01/amg_wms_stock_period/replicas/clickhouse-02
......
2019.03.14 16:38:23.851412 [ 18 ] {} <Trace> report.amg_wms_stock_period_local (StorageReplicatedMergeTree): Executing log entry to merge parts 201903_378474_378474_0, 201903_378475_378475_0, 201903_378476_378476_0, 201903_378477_378477_0, 201903_378478_378478_0 to 201903_378474_378478_1
......
2019.03.14 16:38:23.851446 [ 18 ] {} <Debug> report.amg_wms_stock_period_local (MergerMutator): Merging 5 parts: from 201903_378474_378474_0 to 201903_378478_378478_0 into tmp_merge_201903_378474_378478_1
......
2019.03.14 16:38:23.851856 [ 18 ] {} <Trace> MergeTreeSequentialBlockInputStream: Reading 1 marks from part 201903_378474_378474_0, totaly 1 rows starting from the beginning of the part
......
2019.03.14 16:38:23.856522 [ 18 ] {} <Trace> report.amg_wms_stock_period_local (MergerMutator): Merged 5 parts: from 201903_378474_378474_0 to 201903_378478_378478_0
......

@alesapin

[madm1keru]

I see the same flood in logs, even at testing 19.4.2.4.

2019.03.22 08:43:01.515845 [ 5 ] {} <Error> SrcData.TTAdmLog (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:43:08.441357 [ 10 ] {} <Error> SrcData.TTAdmLog (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:43:25.061637 [ 16 ] {} <Error> SrcData.TTAdmLog (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:43:26.528284 [ 14 ] {} <Error> SrcData.TTAdmLog (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:44:25.361261 [ 6 ] {} <Error> SrcData.TTStatBase (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:44:25.993816 [ 3 ] {} <Error> SrcData.TTStatBase (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:44:32.062546 [ 4 ] {} <Error> SrcData.TTStatBase (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received 2019.03.22 08:44:32.629462 [ 17 ] {} <Error> SrcData.TTStatBase (StorageReplicatedMergeTree): auto DB::StorageReplicatedMergeTree::queueTask()::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = No message received

[nvartolomei]

Hitting same exception with v19.1.15 replicating from v18.14.17. Node from which replication is tried does not log anything. ~2% failure rate. Eventually it succeeds.

This might be due to connection pooling which was added since then and trying to use a connection which was closed by the server?

[nvartolomei]

@alesapin any clues why would this happen? I'm pretty confident that this is related to connection pooling and getting a closed/close-wait connection from the pool :)

[alesapin]

Sorry for ignoring this issue :( I didn't receive any notifications from GitHub.

Fix: https://github.com/yandex/ClickHouse/pull/4856.
Work around: set <keep_alive_timeout> in config.xml to 8 seconds.

[bzon]

I'm using version 19.4.3. This issue still happens even after running SYSTEM DROP DNS CACHE and <keep_alive_timeout> in config.xml with 8 seconds.

<Error> default.table_sharded (StorageReplicatedMergeTree): DB::StorageReplicatedMergeTree::queueTask()::<lambda(DB::StorageReplicatedMergeTree::LogEntryPtr&)>: Poco::Exception. Code: 1000, e.code() = 0, e.displayText() = Timeout: connect timed out: 10.8.6.25:9009

The exact error is Timeout: connect timed out: 10.8.6.25:9009. That IP is the old IP of the previous container that restarted. My solution is to restart this Clickhouse container and run SYSTEM DROP DNS CACHE in all the Clickhouse containers.