ClickHouse / ClickHouse/clickhouse-go

system.query_log: single native-protocol INSERT logged twice with two distinct query_id values — server rewrites query with fully-qualified table name and assigns new UUID

Open
#1,997 1 comment 0 reactions 0 assignees View on GitHub
bug needs triage
Dominant language
Go
Stars
3.3k
Forks
680
Avg merge
2d 3h
Merged PRs (30d)
14

Description

## Observed

1. A single `PrepareBatch` + `Send()` call from the Go native client — with an explicit, known `query_id` set via `clickhouse.WithQueryID` — produces **two** `QueryStart`/`QueryFinish` pairs in `system.query_log`, each with a distinct `query_id` and both with `is_initial_query = 1`.
2. The server-generated second entry rewrites the query: the client sent `INSERT INTO dup_test_events (id, value) FORMAT Native`; the server logged `INSERT INTO vts_dup_test3.dup_test_events (id, value) FORMAT Native` — fully qualifying the table name and altering formatting — under a new server-assigned UUID.
3. Physical storage (`system.parts`) on a plain `MergeTree` table (no deduplication mechanism) shows exactly the expected row count (10 rows, not 20), proving only one write reached storage despite two log entries each claiming `written_rows = 10`.

## Expected behaviour

Exactly one `QueryStart`/`QueryFinish` pair per client `Send()` call, carrying the client-supplied `query_id`. The server should not generate an additional top-level `query_log` entry with a rewritten query string and a new UUID for the same physical insert.

## Code example

```go
package main

import (
"context"
"fmt"
"log"
"time"

"github.com/ClickHouse/clickhouse-go/v2"
)

const insertDupTestEvents = `INSERT INTO dup_test_events
(
id,
value
)`

const explicitQueryID = "vts-explicit-query-id-test-0001"

func main() {
options := &clickhouse.Options{
Addr: []string{"127.0.0.1:9000"},
Auth: clickhouse.Auth{
Database: "vts_dup_test3",
Username: "vts",
Password: "vts123",
},
Compression: &clickhouse.Compression{Method: clickhouse.CompressionLZ4},
DialTimeout: 5 * time.Second,
MaxOpenConns: 5,
MaxIdleConns: 5,
ConnMaxLifetime: 10 * time.Minute,
}

conn, err := clickhouse.Open(options)
if err != nil {
log.Fatalf("open: %v", err)
}
defer conn.Close()

ctx := clickhouse.Context(context.Background(), clickhouse.WithQueryID(explicitQueryID))
if err := conn.Ping(ctx); err != nil {
log.Fatalf("ping: %v", err)
}

batch, err := conn.PrepareBatch(ctx, insertDupTestEvents)
if err != nil {
log.Fatalf("prepare batch: %v", err)
}
defer batch.Close()

for i := 0; i < 10; i++ {
if err := batch.Append(uint64(i), fmt.Sprintf("row-%d", i)); err != nil {
log.Fatalf("append row %d: %v", i, err)
}
}

if err := batch.Send(); err != nil {
log.Fatalf("send: %v", err)
}
fmt.Printf("sent with explicit query_id=%s\n", explicitQueryID)
}
```

After running, query:

```sql
SELECT
query_id,
initial_query_id,
is_initial_query,
type,
written_rows,
query
FROM system.query_log
WHERE (query ILIKE '%dup_test_events%') AND (query ILIKE '%INSERT%')
ORDER BY event_time_microseconds ASC
FORMAT Vertical;
```

And verify physical row count:

```sql
SELECT sum(rows)
FROM system.parts
WHERE database = 'vts_dup_test3'
AND table = 'dup_test_events'
AND active = 1;
```

## Error log

```log
No error returned to the client. The anomaly is silent —
batch.Send() returns nil. The duplicate entry is only
visible in system.query_log.
```

## Details

### Environment
* `clickhouse-go` version: v2.40.3
* Interface: ClickHouse API (`clickhouse.Open`, native protocol)
* Go version: *(please fill in)*
* Operating system: *(please fill in)*
* ClickHouse version: 26.7.1.1315
* Is it a ClickHouse Cloud? No (self-hosted single node)
* ClickHouse Server non-default settings, if any: None relevant; isolated test database, no replicas, no distributed tables, no materialized views
* `CREATE TABLE` statement:

```sql
CREATE DATABASE IF NOT EXISTS vts_dup_test3;

CREATE TABLE vts_dup_test3.dup_test_events
(
id UInt64,
value String
)
ENGINE = MergeTree()
ORDER BY id;
```

* Sample data: 10 synthetic rows (`id` 0–9, `value` `"row-0"` … `"row-9"`), no obfuscation needed.

Contributor guide

Open the contributing guide

Research direction

Reproduce the issue with the Go native client using PrepareBatch, Send, and clickhouse.WithQueryID, then inspect the resulting system.query_log rows and system.parts count. Compare the client-supplied query_id and query text with the server-generated entry. Done means one QueryStart/QueryFinish pair remains, carries the explicit query_id, and the physical row count is unchanged.

Written by the indexing model from the issue text.

Assessment

Tech stack
go, sql
Domain
backend, database
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
48/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.