Net Exception: Socket is not connected logs error logs with every insert

[sonalm]

Version:
23.11

2024.05.10 10:02:51.643288 [ 1183 ] {} <Error> ServerErrorHandler: Poco::Exception. Code: 1000, e.code() = 107, Net Exception: Socket is not connected, Stack trace (when copying this message, always include the lines below):

0. Poco::Net::SocketImpl::error(int, String const&) @ 0x0000000014c4e1b2 in /usr/bin/clickhouse
1. Poco::Net::SocketImpl::peerAddress() @ 0x0000000014c50816 in /usr/bin/clickhouse
2. DB::HTTPServerRequest::HTTPServerRequest(std::shared_ptr<DB::IHTTPContext>, DB::HTTPServerResponse&, Poco::Net::HTTPServerSession&) @ 0x0000000012233d87 in /usr/bin/clickhouse
3. DB::HTTPServerConnection::run() @ 0x0000000012232504 in /usr/bin/clickhouse
4. Poco::Net::TCPServerConnection::start() @ 0x0000000014c52692 in /usr/bin/clickhouse
5. Poco::Net::TCPServerDispatcher::run() @ 0x0000000014c53491 in /usr/bin/clickhouse
6. Poco::PooledThread::run() @ 0x0000000014d4a327 in /usr/bin/clickhouse
7. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000014d4891c in /usr/bin/clickhouse
8. ? @ 0x00007f690235e609 in ?
9. ? @ 0x00007f6902283353 in ?
 (version 23.11.5.29 (official build))

I am using java clickhouse-client library:

<dependency>
    <groupId>com.clickhouse</groupId>
    <artifactId>clickhouse-jdbc</artifactId>
    <version>0.6.0-patch4</version>
</dependency>

and trying to insert data in a table from csv file like:

ClickHouseClient client = ClickHouseClient.newInstance(ClickHouseProtocol.HTTP);
try {
    var start = System.currentTimeMillis();
    ClickHouseResponse resp = client.write(clickHouseNode)
            .set("format_csv_delimiter", ";")
            .option(ClickHouseClientOption.SOCKET_TIMEOUT, 5 * 60 * 1000) // 5 min 
            .option(ClickHouseClientOption.CONNECTION_TIMEOUT, 5 * 60 * 1000) // 5 min
            .table(tableName)
            .data(chfile)
            .executeAndWait();
    System.out.println(file.getAbsolutePath() + ":" + resp.getSummary().getWrittenRows() + ":" + (System.currentTimeMillis()-start));
} catch (Exception e) {
    e.printStackTrace();
} finally {
    client.close();
}

Can someone please help why are we getting these errors in logs? I see that the insert itself is successful and can see data in tables. But still we got lot of errors.

Thanks.

[Algunenano]

Does it reproduce without clickhouse-jdbc?

Does it happen every time you do an insert?

Some possibilities:

• The client is closing the connection without waiting for a full response.
• The client is timing out and closing the connection before the server does it

[sonalm]

I haven't tried without 'clickhouse-jdbc' library.

It happens with every insert.

The client should not timeout as I have given 5 mins timeout in options, and files are not big that it will take 5 mins to finish.

I have also printed resp summary received, which gives me the count of rows inserted, if the client is timeout or closed:

Q1. Why would I get response object back?
Q2. Why is there no stack trace on java side?

[Algunenano]

To narrow down the problem, I'd recommend doing an insert via curl or similar using the HTTP endpoint in the same machine you are using for the java program and see if it reproduces.

I don't know how the java client works or should be used, so that's what I'd try to move out of the equation first. Maybe it's a matter of calling close differently, or changing some of its options

[den-crane]

Do you have something like a proxy or a loadbalancer in between Clickhouse and your application?
This looks like a loadbalancer is probing Clickhouse http port for an availability.

[sonalm]

This is the current configuration of clickhouse deployed in my cluster:

pwd> kubectl get pods -n ch-ns
NAME                                  READY   STATUS    RESTARTS   AGE
chi-clickhouse-cache-default-0-0-0    1/1     Running   0          31d

pwd> kubectl get services -n ch-ns
NAME                               TYPE           CLUSTER-IP      EXTERNAL-IP   PORT(S)                                        AGE
chi-clickhouse-cache-default-0-0   ClusterIP      None            <none>        9000/TCP,8123/TCP,9009/TCP                     36d
service-clickhouse-cache           LoadBalancer   w.x.y.z         w1.x1.y1.z1   8123:32423/TCP,9000:31842/TCP,9009:30483/TCP   36d

i use w1.x1.y1.z1 to connect to clickhouse from my java application running in the same kubernetes cluster.

Regarding,

This looks like a loadbalancer is probing Clickhouse http port for an availability.

Why does it seem to happen only during inserts?

[den-crane]

Why does it seem to happen only during inserts?

How do you know this? Do you use jdbc (http/8123) for other queries as well?
Can you share more logs? With visible inserts? I think [ 1183 ] this thread is not related to the insert connection.

[sonalm]

For read connection, i am using the same java library but not creating ClickHouseClient but instead a datasource connection like this:

Properties props = new Properties();
props.setProperty("url", url);
props.setProperty("username", user);
props.setProperty("password", pwd);
props.setProperty("driverClassName", "com.clickhouse.jdbc.ClickHouseDriver");
props.setProperty("defaultReadOnly", "true");
DataSource ds = BasicDataSourceFactory.createDataSource(props);
connector.setupConnection(ds);

but i believe ClickHouseClient should do something similar internally.

Also, i noticed that these error logs are only during insert, because i stopped all other process, and ran the process which was writing data to clickhouse.

Can you share more logs? With visible inserts? I think [ 1183 ] this thread is not related to the insert connection.

What more logs do you need?

[den-crane]

What more logs do you need?

This is a log of the insert:

[ 295306 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: [::ffff:10.252.126.143]:53950, User-Agent: Vector/0.33.0 (x86_64-unknown-linux-gnu 89605fb 2023-09-27 14:18:24.180809939), Length: 300, Content Type: application/x-ndjson, Transfer Encoding: identity, X-Forwarded-For:
[ 295306 ] {} <Trace> DynamicQueryHandler: Request URI: /?input_format_import_nested_json=1&query=INSERT+INTO+%22ads_logs%22.%22log_shard%22+FORMAT+JSONEachRow
[ 295306 ] {} <Debug> HTTP-Session: 3d0d2de2-517d-40c9-ae3c-1b725dc5ebb5 Authenticating user 'ads_logs' from [::ffff:10.252.126.143]:53950
[ 295306 ] {} <Debug> HTTP-Session: 3d0d2de2-517d-40c9-ae3c-1b725dc5ebb5 Authenticated with global context as user dd45d0e9-a4bc-8047-3090-0aee180d149b
[ 295306 ] {} <Debug> HTTP-Session: 3d0d2de2-517d-40c9-ae3c-1b725dc5ebb5 Creating session context with user_id: dd45d0e9-a4bc-8047-3090-0aee180d149b
[ 295306 ] {} <Trace> HTTP-Session: 3d0d2de2-517d-40c9-ae3c-1b725dc5ebb5 Creating query context from session context, user_id: dd45d0e9-a4bc-8047-3090-0aee180d149b, parent context user: ads_logs
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Debug> executeQuery: (from [::ffff:10.252.126.143]:53950, user: ads_logs) INSERT INTO "ads_logs"."log_shard" FORMAT JSONEachRow  (stage: Complete)
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Trace> ContextAccess (ads_logs): Access granted: INSERT(timestamp, requestID, rawLog, httpStatusCode, responseTime, contentLength, physicalServerName, podName, remoteClient, method, path, protocol, headers, dc, app) ON ads_logs.log_shard
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Trace> ads_logs.log_shard (a6490af1-1570-4eda-b1a9-31584894f6ba): Trying to reserve 1.00 MiB using storage policy from min volume index 0
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Trace> DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 2.49 TiB.
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Trace> MergedBlockOutputStream: filled checksums 20240510_35942_35942_0 (state Temporary)
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Debug> ads_logs.log_shard (a6490af1-1570-4eda-b1a9-31584894f6ba) (Replicated OutputStream): Wrote block with ID '20240510_3997472543717008523_11387758334628620882', 1 rows
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Trace> ads_logs.log_shard (a6490af1-1570-4eda-b1a9-31584894f6ba): Renaming temporary part tmp_insert_20240510_35942_35942_0 to 20240510_5493_5493_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Debug> executeQuery: Read 1 rows, 311.00 B in 0.014343 sec., 69.72042111134351 rows/sec., 21.17 KiB/sec.
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Debug> DynamicQueryHandler: Done processing query
[ 295306 ] {67962859-a30b-4bfd-a356-9e47245c73b7} <Debug> MemoryTracker: Peak memory usage (for query): 4.35 MiB.
[ 295306 ] {} <Debug> HTTP-Session: 3d0d2de2-517d-40c9-ae3c-1b725dc5ebb5 Logout, user_id: dd45d0e9-a4bc-8047-3090-0aee180d149b

I would like to see that the error [ 1183 ] {} <Error> ServerErrorHandler happens in the same insert / same thread.

[sonalm]

What log level do i need to keep? trace? currently my log level is warning.

[den-crane]

trace

[sonalm]

@den-crane

2024.05.15 16:08:47.624077 [ 767 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: 10.96.12.20:49647, User-Agent: ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4), Content Type: text/plain; charset=UTF-8, Transfer Encoding: chunked, X-Forwarded-For: (none)
2024.05.15 16:08:47.624134 [ 767 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=INSERT+INTO+fx_rate%0A+FORMAT+CSV&compress=1&extremes=0&format_csv_delimiter=%3B
2024.05.15 16:08:47.624168 [ 767 ] {} <Debug> HTTP-Session: e6837541-40d5-41df-9b0a-b690390cf005 Authenticating user 'someuser' from 10.96.12.20:49647
2024.05.15 16:08:47.624205 [ 767 ] {} <Debug> HTTP-Session: e6837541-40d5-41df-9b0a-b690390cf005 Authenticated with global context as user bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.624226 [ 767 ] {} <Debug> HTTP-Session: e6837541-40d5-41df-9b0a-b690390cf005 Creating session context with user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.624320 [ 767 ] {} <Trace> HTTP-Session: e6837541-40d5-41df-9b0a-b690390cf005 Creating query context from session context, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf, parent context user: someuser
2024.05.15 16:08:47.624496 [ 767 ] {4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e} <Debug> executeQuery: (from 10.96.12.20:49647, user: someuser) INSERT INTO fx_rate FORMAT CSV  (stage: Complete)
2024.05.15 16:08:47.624569 [ 767 ] {4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e} <Trace> ContextAccess (someuser): Access granted: INSERT(securityId, dateOfData, rate, updated_at) ON fx_rate
2024.05.15 16:08:47.624750 [ 767 ] {4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e} <Trace> ParallelParsingInputFormat: Parallel parsing is used
2024.05.15 16:08:47.625425 [ 767 ] {4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e} <Debug> DynamicQueryHandler: Done processing query
2024.05.15 16:08:47.625456 [ 767 ] {} <Debug> HTTP-Session: e6837541-40d5-41df-9b0a-b690390cf005 Logout, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.625879 [ 767 ] {} <Error> ServerErrorHandler: Poco::Exception. Code: 1000, e.code() = 107, Net Exception: Socket is not connected, Stack trace (when copying this message, always include the lines below):

0. Poco::Net::SocketImpl::error(int, String const&) @ 0x0000000014c0be72
1. Poco::Net::SocketImpl::peerAddress() @ 0x0000000014c0e4d6
2. DB::HTTPServerRequest::HTTPServerRequest(std::shared_ptr<DB::IHTTPContext>, DB::HTTPServerResponse&, Poco::Net::HTTPServerSession&, StrongTypedef<unsigned long, ProfileEvents::EventTag> const&) @ 0x00000000122cd529
3. DB::HTTPServerConnection::run() @ 0x00000000122cbc6c
4. Poco::Net::TCPServerConnection::start() @ 0x0000000014c105b2
5. Poco::Net::TCPServerDispatcher::run() @ 0x0000000014c113f9
6. Poco::PooledThread::run() @ 0x0000000014d09a61
7. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000014d07ffd
8. ? @ 0x00007f9699ef7609
9. ? @ 0x00007f9699e12353
 (version 24.4.1.2088 (official build))

[den-crane]

@sonalm there is no information about a created part. What is a type of the fx_rate table?

[sonalm]

CREATE TABLE IF NOT EXISTS fx_rate(
`securityId` String, 
`dateOfData` Date,
`rate` Nullable(Float64),
`updated_at` UInt32 DEFAULT toUnixTimestamp(now()),
)
ENGINE = ReplacingMergeTree(updated_at)
PRIMARY KEY (securityId, dateOfData)
ORDER BY (securityId, dateOfData)
SETTINGS index_granularity = 8192

[den-crane]

Then I would expect something like

default.fx_rate (02e13f3a-ab3b-419e-a10a-13e880f56b61): Trying to reserve 1.00 MiB using storage policy from min volume index 0
DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 49.69 GiB.
MergedBlockOutputStream: filled checksums all_3_3_0 (state Temporary)
default.fx_rate (02e13f3a-ab3b-419e-a10a-13e880f56b61): Renaming temporary part tmp_insert_all_3_3_0 to all_3_3_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
executeQuery: Read 1 rows, 27.00 B in 0.001614 sec., 619.5786864931846 rows/sec., 16.34 KiB/sec.

Is it async insert ?

[sonalm]

ClickHouseResponse resp = client.write(clickHouseNode)
            .set("format_csv_delimiter", ";")
            .option(ClickHouseClientOption.SOCKET_TIMEOUT, 5 * 60 * 1000) // 5 min 
            .option(ClickHouseClientOption.CONNECTION_TIMEOUT, 5 * 60 * 1000) // 5 min
            .table(tableName)
            .data(chfile)
            .executeAndWait();

i am waiting for the response back.

[den-crane]

No, I mean: async_insert https://clickhouse.com/docs/en/optimize/asynchronous-inserts

Can you share

select * 
from system.query_log 
where event_date >=today() -1 and query_id = '4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e'
format Vertical;


select * 
from system.part_log
 where event_date >=today() -1  and query_id ='4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e';
format Vertical;

[sonalm]

SELECT *
FROM system.query_log
WHERE (event_date >= (today() - 1)) AND (query_id = '4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e')
FORMAT Vertical

Query id: c891a802-ca2a-492b-b0ae-c39ea41ec91f

Row 1:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryStart
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.624439
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.624439
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          0
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e
address:                               ::ffff:10.96.12.20
port:                                  49647
initial_user:                          someuser
initial_query_id:                      4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e
initial_address:                       ::ffff:10.96.12.20
initial_port:                          49647
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.624439
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            []
peak_threads_usage:                    0
ProfileEvents:                         {}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          []
used_functions:                        []
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     Unknown
asynchronous_read_counters:            {}

Row 2:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryFinish
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.625183
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.624439
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          1792
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e
address:                               ::ffff:10.96.12.20
port:                                  49647
initial_user:                          someuser
initial_query_id:                      4ff861c6-fc6b-42b5-b6d7-7e30f701ef7e
initial_address:                       ::ffff:10.96.12.20
initial_port:                          49647
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.624439
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            [868,810,767]
peak_threads_usage:                    3
ProfileEvents:                         {'Query':1,'InsertQuery':1,'InitialQuery':1,'NetworkReceiveElapsedMicroseconds':6,'NetworkReceiveBytes':5,'ContextLock':11,'RWLockAcquiredReadLocks':2,'PartsLockHoldMicroseconds':3,'RealTimeMicroseconds':1079,'UserTimeMicroseconds':686,'OSCPUWaitMicroseconds':37,'OSCPUVirtualTimeMicroseconds':686,'OSReadChars':1316,'OSWriteChars':1014,'LogTrace':2,'LogDebug':1,'InterfaceHTTPReceiveBytes':5}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          ['CSV']
used_functions:                        ['replicate']
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     None
asynchronous_read_counters:            {}

2 rows in set. Elapsed: 0.034 sec. Processed 48.86 thousand rows, 11.76 MB (1.43 million rows/s., 344.87 MB/s.)

part_log table didnt return any result.

[sonalm]

also, i pulled out logs from another thread which showed this exception:

2024.05.15 16:08:47.385884 [ 747 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: 10.96.12.20:3083, User-Agent: ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4), Content Type: text/plain; charset=UTF-8, Transfer Encoding: chunked, X-Forwarded-For: (none)
2024.05.15 16:08:47.385954 [ 747 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=INSERT+INTO+fx_rate%0A+FORMAT+CSV&compress=1&extremes=0&format_csv_delimiter=%3B
2024.05.15 16:08:47.385985 [ 747 ] {} <Debug> HTTP-Session: d98e011b-706a-4eb0-8bac-9cad471f8c52 Authenticating user 'someuser' from 10.96.12.20:3083
2024.05.15 16:08:47.386013 [ 747 ] {} <Debug> HTTP-Session: d98e011b-706a-4eb0-8bac-9cad471f8c52 Authenticated with global context as user bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.386030 [ 747 ] {} <Debug> HTTP-Session: d98e011b-706a-4eb0-8bac-9cad471f8c52 Creating session context with user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.386114 [ 747 ] {} <Trace> HTTP-Session: d98e011b-706a-4eb0-8bac-9cad471f8c52 Creating query context from session context, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf, parent context user: someuser
2024.05.15 16:08:47.386496 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Debug> executeQuery: (from 10.96.12.20:3083, user: someuser) INSERT INTO fx_rate FORMAT CSV  (stage: Complete)
2024.05.15 16:08:47.386569 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> ContextAccess (someuser): Access granted: INSERT(securityId, dateOfData, rate, updated_at) ON db.fx_rate
2024.05.15 16:08:47.386785 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> ParallelParsingInputFormat: Parallel parsing is used
2024.05.15 16:08:47.387499 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> db.fx_rate (a30afe15-3676-4af7-b9f4-ae7a6a30008a): Trying to reserve 1.00 MiB using storage policy from min volume index 0
2024.05.15 16:08:47.387540 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 962.91 GiB.
2024.05.15 16:08:47.387945 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> MergedBlockOutputStream: filled checksums all_39_39_0 (state Temporary)
2024.05.15 16:08:47.388233 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Trace> db.fx_rate (a30afe15-3676-4af7-b9f4-ae7a6a30008a): Renaming temporary part tmp_insert_all_39_39_0 to all_7080_7080_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
2024.05.15 16:08:47.388407 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Debug> executeQuery: Read 159 rows, 4.19 KiB in 0.002058 sec., 77259.47521865889 rows/sec., 1.99 MiB/sec.
2024.05.15 16:08:47.388749 [ 747 ] {29b3adda-91a4-4054-87ba-35fa62ae2eac} <Debug> DynamicQueryHandler: Done processing query
2024.05.15 16:08:47.388784 [ 747 ] {} <Debug> HTTP-Session: d98e011b-706a-4eb0-8bac-9cad471f8c52 Logout, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.407288 [ 747 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: 10.96.12.20:8597, User-Agent: ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4), Content Type: text/plain; charset=UTF-8, Transfer Encoding: chunked, X-Forwarded-For: (none)
2024.05.15 16:08:47.407386 [ 747 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=INSERT+INTO+fx_rate%0A+FORMAT+CSV&compress=1&extremes=0&format_csv_delimiter=%3B
2024.05.15 16:08:47.407425 [ 747 ] {} <Debug> HTTP-Session: 64c31be6-0ad3-4dc9-b419-a4b0def1b47f Authenticating user 'someuser' from 10.96.12.20:8597
2024.05.15 16:08:47.407464 [ 747 ] {} <Debug> HTTP-Session: 64c31be6-0ad3-4dc9-b419-a4b0def1b47f Authenticated with global context as user bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.407478 [ 747 ] {} <Debug> HTTP-Session: 64c31be6-0ad3-4dc9-b419-a4b0def1b47f Creating session context with user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.407595 [ 747 ] {} <Trace> HTTP-Session: 64c31be6-0ad3-4dc9-b419-a4b0def1b47f Creating query context from session context, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf, parent context user: someuser
2024.05.15 16:08:47.407768 [ 747 ] {32e42ebe-f422-445b-9f73-02948e62ba03} <Debug> executeQuery: (from 10.96.12.20:8597, user: someuser) INSERT INTO fx_rate FORMAT CSV  (stage: Complete)
2024.05.15 16:08:47.407854 [ 747 ] {32e42ebe-f422-445b-9f73-02948e62ba03} <Trace> ContextAccess (someuser): Access granted: INSERT(securityId, dateOfData, rate, updated_at) ON db.fx_rate
2024.05.15 16:08:47.408000 [ 747 ] {32e42ebe-f422-445b-9f73-02948e62ba03} <Trace> ParallelParsingInputFormat: Parallel parsing is used
2024.05.15 16:08:47.408759 [ 747 ] {32e42ebe-f422-445b-9f73-02948e62ba03} <Debug> DynamicQueryHandler: Done processing query
2024.05.15 16:08:47.409027 [ 747 ] {} <Debug> HTTP-Session: 64c31be6-0ad3-4dc9-b419-a4b0def1b47f Logout, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.414002 [ 747 ] {} <Error> ServerErrorHandler: Poco::Exception. Code: 1000, e.code() = 107, Net Exception: Socket is not connected, Stack trace (when copying this message, always include the lines below):

0. Poco::Net::SocketImpl::error(int, String const&) @ 0x0000000014c0be72
1. Poco::Net::SocketImpl::peerAddress() @ 0x0000000014c0e4d6
2. DB::HTTPServerRequest::HTTPServerRequest(std::shared_ptr<DB::IHTTPContext>, DB::HTTPServerResponse&, Poco::Net::HTTPServerSession&, StrongTypedef<unsigned long, ProfileEvents::EventTag> const&) @ 0x00000000122cd529
3. DB::HTTPServerConnection::run() @ 0x00000000122cbc6c
4. Poco::Net::TCPServerConnection::start() @ 0x0000000014c105b2
5. Poco::Net::TCPServerDispatcher::run() @ 0x0000000014c113f9
6. Poco::PooledThread::run() @ 0x0000000014d09a61
7. Poco::ThreadImpl::runnableEntry(void*) @ 0x0000000014d07ffd
8. ? @ 0x00007f9699ef7609
9. ? @ 0x00007f9699e12353
(version 24.4.1.2088 (official build))

2024.05.15 16:08:47.427835 [ 747 ] {} <Trace> HTTPHandler-factory: HTTP Request for HTTPHandler-factory. Method: POST, Address: 10.96.12.20:63463, User-Agent: ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4), Content Type: text/plain; charset=UTF-8, Transfer Encoding: chunked, X-Forwarded-For: (none)
2024.05.15 16:08:47.427887 [ 747 ] {} <Trace> DynamicQueryHandler: Request URI: /?query=INSERT+INTO+fx_rate%0A+FORMAT+CSV&compress=1&extremes=0&format_csv_delimiter=%3B
2024.05.15 16:08:47.427952 [ 747 ] {} <Debug> HTTP-Session: 8cfc7d35-b93e-40d7-8ea3-a81cd79c056d Authenticating user 'someuser' from 10.96.12.20:63463
2024.05.15 16:08:47.427978 [ 747 ] {} <Debug> HTTP-Session: 8cfc7d35-b93e-40d7-8ea3-a81cd79c056d Authenticated with global context as user bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.427990 [ 747 ] {} <Debug> HTTP-Session: 8cfc7d35-b93e-40d7-8ea3-a81cd79c056d Creating session context with user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf
2024.05.15 16:08:47.428086 [ 747 ] {} <Trace> HTTP-Session: 8cfc7d35-b93e-40d7-8ea3-a81cd79c056d Creating query context from session context, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf, parent context user: someuser
2024.05.15 16:08:47.428278 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Debug> executeQuery: (from 10.96.12.20:63463, user: someuser) INSERT INTO fx_rate FORMAT CSV  (stage: Complete)
2024.05.15 16:08:47.428341 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> ContextAccess (someuser): Access granted: INSERT(securityId, dateOfData, rate, updated_at) ON db.fx_rate
2024.05.15 16:08:47.428499 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> ParallelParsingInputFormat: Parallel parsing is used
2024.05.15 16:08:47.433218 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> db.fx_rate (a30afe15-3676-4af7-b9f4-ae7a6a30008a): Trying to reserve 1.00 MiB using storage policy from min volume index 0
2024.05.15 16:08:47.433255 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 962.91 GiB.
2024.05.15 16:08:47.433618 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> MergedBlockOutputStream: filled checksums all_49_49_0 (state Temporary)
2024.05.15 16:08:47.433968 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Trace> db.fx_rate (a30afe15-3676-4af7-b9f4-ae7a6a30008a): Renaming temporary part tmp_insert_all_49_49_0 to all_7090_7090_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
2024.05.15 16:08:47.434153 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Debug> executeQuery: Read 159 rows, 4.19 KiB in 0.005942 sec., 26758.66711544934 rows/sec., 705.55 KiB/sec.
2024.05.15 16:08:47.435604 [ 747 ] {c7c08809-64e4-4c32-af77-6d91be379f9d} <Debug> DynamicQueryHandler: Done processing query
2024.05.15 16:08:47.435628 [ 747 ] {} <Debug> HTTP-Session: 8cfc7d35-b93e-40d7-8ea3-a81cd79c056d Logout, user_id: bd95cd89-cbdb-cfb6-dc68-e4031d4d1bcf

As you see from logs, the thread handled multiple inserts and thrown exception in between and continued with other inserts

[den-crane]

All of this is very suspicious

query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0

0 rows ? Empty CSV (zero bytes)?

ReplacingMergeTree
prefer_localhost_replica':'0

??????????????

used_functions: ['replicate']

?????

Do you have MaterializedViews attached to fx_rate ? select table, database from system.tables where create_table_query like '%fx_rate%'

[sonalm]

no, we dont have any MaterializedViews

[sonalm]

did a query on query_log table for query_ids from logs of thread [747] in comment #63598 (comment)

SELECT *
FROM system.query_log
WHERE (event_date >= (today() - 1)) AND (query_id = '29b3adda-91a4-4054-87ba-35fa62ae2eac')
FORMAT Vertical

Query id: c43630b0-4587-46c3-ace2-94180356af49

Row 1:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryStart
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.386324
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.386324
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          0
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              29b3adda-91a4-4054-87ba-35fa62ae2eac
address:                               ::ffff:10.96.12.20
port:                                  3083
initial_user:                          someuser
initial_query_id:                      29b3adda-91a4-4054-87ba-35fa62ae2eac
initial_address:                       ::ffff:10.96.12.20
initial_port:                          3083
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.386324
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            []
peak_threads_usage:                    0
ProfileEvents:                         {}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          []
used_functions:                        []
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     Unknown
asynchronous_read_counters:            {}

Row 2:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryFinish
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.388393
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.386324
query_duration_ms:                     2
read_rows:                             159
read_bytes:                            4293
written_rows:                          159
written_bytes:                         4293
result_rows:                           159
result_bytes:                          4293
memory_usage:                          27628
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              29b3adda-91a4-4054-87ba-35fa62ae2eac
address:                               ::ffff:10.96.12.20
port:                                  3083
initial_user:                          someuser
initial_query_id:                      29b3adda-91a4-4054-87ba-35fa62ae2eac
initial_address:                       ::ffff:10.96.12.20
initial_port:                          3083
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.386324
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            [840,712,747]
peak_threads_usage:                    3
ProfileEvents:                         {'Query':1,'InsertQuery':1,'InitialQuery':1,'FileOpen':9,'WriteBufferFromFileDescriptorWrite':9,'WriteBufferFromFileDescriptorWriteBytes':2602,'IOBufferAllocs':22,'IOBufferAllocBytes':3392591,'FunctionExecute':4,'DiskWriteElapsedMicroseconds':73,'InsertedRows':159,'InsertedBytes':4293,'SelectedRows':159,'SelectedBytes':4293,'MergeTreeDataWriterRows':159,'MergeTreeDataWriterUncompressedBytes':4293,'MergeTreeDataWriterCompressedBytes':2209,'MergeTreeDataWriterBlocks':1,'MergeTreeDataWriterSortingBlocksMicroseconds':17,'MergeTreeDataWriterMergingBlocksMicroseconds':30,'InsertedCompactParts':1,'ContextLock':20,'RWLockAcquiredReadLocks':2,'PartsLockHoldMicroseconds':103,'RealTimeMicroseconds':2696,'UserTimeMicroseconds':1423,'SystemTimeMicroseconds':10,'SoftPageFaults':1,'OSCPUWaitMicroseconds':267,'OSCPUVirtualTimeMicroseconds':1430,'OSWriteBytes':36864,'OSReadChars':1320,'OSWriteChars':5180,'LogTrace':6,'LogDebug':1}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               ['UInt32']
used_dictionaries:                     []
used_formats:                          ['CSV']
used_functions:                        ['replicate','_CAST','toUnixTimestamp','now']
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     None
asynchronous_read_counters:            {}

--------

SELECT *
FROM system.query_log
WHERE (event_date >= (today() - 1)) AND (query_id = '32e42ebe-f422-445b-9f73-02948e62ba03')
FORMAT Vertical

Query id: d3c6990f-3a12-41b6-8ce3-c3735165b78b

Row 1:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryStart
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.407718
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.407718
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          0
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              32e42ebe-f422-445b-9f73-02948e62ba03
address:                               ::ffff:10.96.12.20
port:                                  8597
initial_user:                          someuser
initial_query_id:                      32e42ebe-f422-445b-9f73-02948e62ba03
initial_address:                       ::ffff:10.96.12.20
initial_port:                          8597
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.407718
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            []
peak_threads_usage:                    0
ProfileEvents:                         {}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          []
used_functions:                        []
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     Unknown
asynchronous_read_counters:            {}

Row 2:
──────
hostname:                              chi-clickhouse-cache-default-0-0-0.chi-clickhouse-cache-default-0-0.pcs-ch.svc.cluster.local
type:                                  QueryFinish
event_date:                            2024-05-15
event_time:                            2024-05-15 16:08:47
event_time_microseconds:               2024-05-15 16:08:47.408321
query_start_time:                      2024-05-15 16:08:47
query_start_time_microseconds:         2024-05-15 16:08:47.407718
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          1792
current_database:                      db
query:                                 INSERT INTO fx_rate
 FORMAT CSV

formatted_query:
normalized_query_hash:                 12498815706244389060
query_kind:                            Insert
databases:                             ['db']
tables:                                ['db.fx_rate']
columns:                               []
partitions:                            []
projections:                           []
views:                                 []
exception_code:                        0
exception:
stack_trace:
is_initial_query:                      1
user:                                  someuser
query_id:                              32e42ebe-f422-445b-9f73-02948e62ba03
address:                               ::ffff:10.96.12.20
port:                                  8597
initial_user:                          someuser
initial_query_id:                      32e42ebe-f422-445b-9f73-02948e62ba03
initial_address:                       ::ffff:10.96.12.20
initial_port:                          8597
initial_query_start_time:              2024-05-15 16:08:47
initial_query_start_time_microseconds: 2024-05-15 16:08:47.407718
interface:                             2
is_secure:                             0
os_user:
client_hostname:
client_name:
client_revision:                       0
client_version_major:                  0
client_version_minor:                  0
client_version_patch:                  0
http_method:                           2
http_user_agent:                       ClickHouse-JavaClient/0.6.0-patch4 (Linux/5.15.0-1059-azure; OpenJDK 64-Bit Server VM/Microsoft-8297088; Apache-HttpClient/5.2.4; rv:6a4ffc4)
http_referer:
forwarded_for:
quota_key:
distributed_depth:                     0
revision:                              54485
log_comment:
thread_ids:                            [870,728,747]
peak_threads_usage:                    3
ProfileEvents:                         {'Query':1,'InsertQuery':1,'InitialQuery':1,'NetworkReceiveElapsedMicroseconds':6,'NetworkReceiveBytes':5,'ContextLock':11,'RWLockAcquiredReadLocks':2,'PartsLockHoldMicroseconds':3,'RealTimeMicroseconds':841,'UserTimeMicroseconds':564,'SystemTimeMicroseconds':6,'OSCPUWaitMicroseconds':20,'OSCPUVirtualTimeMicroseconds':569,'OSReadChars':1319,'OSWriteChars':1012,'LogTrace':2,'LogDebug':1,'InterfaceHTTPReceiveBytes':5}
Settings:                              {'connect_timeout_with_failover_ms':'1000','load_balancing':'nearest_hostname','distributed_aggregation_memory_efficient':'1','do_not_merge_across_partitions_select_final':'1','os_thread_priority':'2','log_queries':'1','prefer_localhost_replica':'0','parallel_view_processing':'1','format_csv_delimiter':';'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          ['CSV']
used_functions:                        ['replicate']
used_storages:                         []
used_table_functions:                  []
used_row_policies:                     []
transaction_id:                        (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage:                     None
asynchronous_read_counters:            {}

for first id, i see following in Row2(QueryFinish):

query_duration_ms:                     2
read_rows:                             159
read_bytes:                            4293
written_rows:                          159
written_bytes:                         4293
result_rows:                           159
result_bytes:                          4293
memory_usage:                          27628 

whereas for second qurey_id, this is:

query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          1792

[sonalm]

btw, its possible to have empty csv files as well! But why would that be the case for exception?

[den-crane]

BWT the same issue

• Error log full of ServerErrorHandler: Poco::Exception. Code: 1000, e.code() = 107, Net Exception: Socket is not connected #34218

[den-crane]

At this point I would start to use tcpdump/tshark, now I am more sure that it's a balancer is probing http port.

[sonalm]

FYI, i removed the upload for empty files, but still see the exceptions in the log!

[sonalm]

BWT the same issue

• Error log full of ServerErrorHandler: Poco::Exception. Code: 1000, e.code() = 107, Net Exception: Socket is not connected #34218

this is still open!

[sonalm]

At this point I would start to use tcpdump/tshark, now I am more sure that it's a balancer is probing http port.

But why only during inserts and not at any other time?

[den-crane]

May be it's related to the data. For example you may use /r/n as a line separator. Who knows.
Try to make reproducible example, data-sample, curl ...
Start with

curl 'localhost:8123?query=INSERT+INTO+fx_rate%0A+FORMAT+CSV&compress=0&extremes=0&format_csv_delimiter=%3B' --data-binary @yourfile.csv