Skip to content

coordination: fix flaky TestCoordinationSemaphore without changing public API#2113

Open
asmyasnikov with Copilot wants to merge 9 commits into
masterfrom
copilot/fix-flaky-test-coordination-semaphore
Open

coordination: fix flaky TestCoordinationSemaphore without changing public API#2113
asmyasnikov with Copilot wants to merge 9 commits into
masterfrom
copilot/fix-flaky-test-coordination-semaphore

Conversation

Copilot AI commented May 3, 2026

Copy link
Copy Markdown
Contributor

Two independent bugs caused TestCoordinationSemaphore to be flaky. Both are fixed without any public API changes.

Root cause 1 — race in receiveLoop (spurious reconnect on session creation)

In receiveLoop, updateLastGoodResponseTime() was called after the blocking sessionStarted <- message.GetSessionStarted() channel send. Once mainLoop received from the channel, it could race into the keep-alive inner loop and read lastGoodResponseTime as Go's zero time (0001-01-01) before receiveLoop had a chance to update it. This made keepAliveTime a massive negative value → time.After fired immediately → keep-alive timeout triggered → cancelStream() called → OnDetach failed non-idempotent operations in the queue (e.g. CreateSemaphore) with ErrOperationStatusUnknown.

Fix: moved updateLastGoodResponseTime() to before the channel send in receiveLoop, guaranteeing the timestamp is set before mainLoop can enter the keep-alive loop.

Root cause 2 — reconnect timing window after Reconnect() (original issue)

Reconnect() is fire-and-forget. The integration test called DescribeSemaphore() immediately after, which works in most cases because the operation is idempotent and queued — but under CI load, the 500 ms sessionReconnectDelay plus gRPC setup time could exceed the server's 1 s SessionGracePeriodMillis, causing the server to expire the session.

Fix: test configuration changes only:

  • SessionGracePeriodMillis: 1000 → 10000 — the server keeps the session alive for 10 seconds after losing contact, giving ample headroom for reconnect under CI load.
  • options.WithSessionReconnectDelay(0) passed to Session() — the client reconnects immediately when the stream drops (no 500 ms default delay).

Because DescribeSemaphore is already idempotent (WithIdempotence(true)) and automatically replayed after reconnect, no additional synchronization is needed.

No public API changes.

Copilot AI linked an issue May 3, 2026 that may be closed by this pull request
@github-actions

github-actions Bot commented May 3, 2026

Copy link
Copy Markdown

summary

Inferred base version: v3.135.10
Suggested version: v3.135.11

@codecov-commenter

codecov-commenter commented May 3, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 72.54%. Comparing base (9955e4c) to head (900d9a8).
⚠️ Report is 72 commits behind head on master.

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #2113      +/-   ##
==========================================
- Coverage   75.16%   72.54%   -2.63%     
==========================================
  Files         427      427              
  Lines       36974    36974              
==========================================
- Hits        27792    26822     -970     
- Misses       7993     8952     +959     
- Partials     1189     1200      +11     
Flag Coverage Δ
experiment ?
go-1.21.x 72.42% <100.00%> (-0.24%) ⬇️
go-1.26.x 72.53% <100.00%> (-2.59%) ⬇️
integration 57.03% <100.00%> (-0.34%) ⬇️
macOS 46.19% <0.00%> (-0.02%) ⬇️
ubuntu 72.54% <100.00%> (-2.63%) ⬇️
unit 46.20% <0.00%> (-0.03%) ⬇️
windows 46.20% <0.00%> (-0.02%) ⬇️
ydb-24.4 56.63% <100.00%> (-0.32%) ⬇️
ydb-edge 56.77% <100.00%> (-0.41%) ⬇️
ydb-latest 56.72% <100.00%> (-0.35%) ⬇️
ydb-nightly ?

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Copilot AI and others added 2 commits May 3, 2026 12:57
…CoordinationSemaphore

- Add `WaitConnected(ctx context.Context) error` to the `coordination.Session` interface
- Implement `WaitConnected` in `internal/coordination/session.go` using a `connectedChan`
  channel guarded by the existing mutex: nil = connected, non-nil = waiting for reconnect
- Add `markConnected()` helper that closes and clears the channel under the mutex
- Update `Reconnect()` to create `connectedChan` if nil, enabling `WaitConnected` to block
- In `mainLoop`, call `markConnected()` when SessionStarted is received with a valid session ID
- Update `tests/integration/coordination_test.go` and `coordination/example_test.go` to call
  `WaitConnected` after `Reconnect()`, ensuring the test waits for the reconnect to complete
  before making further requests
- Add CHANGELOG entry

Agent-Logs-Url: https://github.com/ydb-platform/ydb-go-sdk/sessions/c6517c58-5a1b-4f5a-8029-878fd908e247

Co-authored-by: asmyasnikov <14202262+asmyasnikov@users.noreply.github.com>
Copilot AI changed the title [WIP] Fix flaky TestCoordinationSemaphore coordination: add Session.WaitConnected to fix flaky TestCoordinationSemaphore May 3, 2026
Copilot AI requested a review from asmyasnikov May 3, 2026 13:01
@asmyasnikov asmyasnikov requested a review from Copilot May 3, 2026 16:08
@github-actions github-actions Bot removed the SLO label May 3, 2026

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Adds a synchronization point to coordination sessions so callers (and tests) can deterministically wait for a Reconnect() to finish before issuing subsequent requests, addressing CI flakiness caused by session grace/handshake timing.

Changes:

  • Added Session.WaitConnected(ctx) to block until the session handshake completes after a Reconnect().
  • Implemented reconnect-completion signaling in the internal session loop via a guarded connectedChan and markConnected().
  • Updated the semaphore integration test and the public example to call WaitConnected() after Reconnect().

Reviewed changes

Copilot reviewed 5 out of 5 changed files in this pull request and generated 3 comments.

Show a summary per file
File Description
internal/coordination/session.go Implements reconnect completion signaling and the new WaitConnected() method.
coordination/client.go Extends the public coordination.Session interface with WaitConnected(ctx).
tests/integration/coordination_test.go Fixes flakiness by waiting for reconnect completion before describing the semaphore.
coordination/example_test.go Updates example usage to wait for reconnect completion.
CHANGELOG.md Adds a changelog note for the new public API.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment thread internal/coordination/session.go Outdated
Comment thread coordination/client.go Outdated
Comment thread CHANGELOG.md Outdated

@robot-vibe-db robot-vibe-db Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AI Review Summary

Verdict: ✅ No critical issues found

Critical issues

No critical issues found.

Other findings

  • Minor | High: Misleading doc comment on markConnected() says "Must be called with s.mutex held" but the method acquires the lock itself; calling with mutex held would deadlock — internal/coordination/session.go:550

This review was generated automatically. Critical issues require attention; other findings are advisory.
If this comment was useful, please give it a 👍 — it helps us improve the review bot.

Comment thread internal/coordination/session.go Outdated
asmyasnikov and others added 3 commits May 3, 2026 21:06
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>

@robot-vibe-db robot-vibe-db Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AI Review Summary

Verdict: ✅ No critical issues found

Critical issues

No critical issues found.

Other findings

  • Minor | Low: Adding WaitConnected to the public Session interface is technically a breaking change for any external code that implements the interface. In practice, this is a large, domain-specific interface (~12 methods) that is clearly meant to be consumed by callers rather than implemented externally, so the real-world impact is negligible. — coordination/client.go:134
  • Minor | Low: The select in WaitConnected does not prioritize <-ch over <-s.ctx.Done(). If both fire simultaneously (reconnect completes just as the session is closing), Go's random select could return the session error instead of nil. In practice this is harmless — the session is dying either way and subsequent operations would fail — but documenting the precedence might save a future reader some reasoning. — internal/coordination/session.go:590

Implementation notes (not issues):

  • The channel-snapshot pattern in WaitConnected (read connectedChan under lock, then select on the snapshot) is correct and avoids holding the mutex during the blocking wait.
  • markConnected() is properly idempotent: safe to call when connectedChan is already nil.
  • The ordering in mainLoop — calling markConnected() before close(sessionStartedChan) on initial connect — correctly prevents a race where Reconnect() could be called immediately after Session() returns.
  • Reusing an existing connectedChan on consecutive Reconnect() calls (rather than creating a new one) correctly batches multiple waiters onto the same notification event.

This review was generated automatically. Critical issues require attention; other findings are advisory.
If this comment was useful, please give it a 👍 — it helps us improve the review bot.

@asmyasnikov

Copy link
Copy Markdown
Member

@copilot разве нет другого способа починить flaky test TestCoordinationSemaphore, не меняя публичное API?

Instead of adding WaitConnected to the Session interface, fix the root cause
directly in the test configuration:
- Increase SessionGracePeriodMillis from 1000ms to 10000ms so the server keeps
  the session alive long enough for the client to reconnect
- Pass options.WithSessionReconnectDelay(0) to Session() so the client reconnects
  immediately (no 500ms default delay), making reconnect complete well within the
  grace period
- Remove WaitConnected from the Session interface and its internal implementation
- Remove the WaitConnected CHANGELOG entry (no user-facing API change)

Agent-Logs-Url: https://github.com/ydb-platform/ydb-go-sdk/sessions/af4612bd-7e60-40bc-96d6-1e76264ed998

Co-authored-by: asmyasnikov <14202262+asmyasnikov@users.noreply.github.com>

Copilot AI commented May 3, 2026

Copy link
Copy Markdown
Contributor Author

@copilot разве нет другого способа починить flaky test TestCoordinationSemaphore, не меняя публичное API?

Yes — instead of WaitConnected, I fixed the test configuration directly in commit 9879530:

  1. SessionGracePeriodMillis: 1000 → 10000 — the server now keeps the session alive for 10 seconds after losing contact (vs. 1 second), giving ample time for any reconnect.
  2. options.WithSessionReconnectDelay(0) on Session() — the client reconnects immediately after the stream drops (vs. the default 500 ms delay), so the total reconnect time stays well under the grace period even under CI load.

DescribeSemaphore is idempotent and automatically replayed after reconnect, so no WaitConnected is needed — it just blocks until the reconnected stream delivers the response.

All the WaitConnected/connectedChan/markConnected changes have been reverted.

Copilot AI changed the title coordination: add Session.WaitConnected to fix flaky TestCoordinationSemaphore coordination: fix flaky TestCoordinationSemaphore without changing public API May 3, 2026
Copilot AI requested a review from asmyasnikov May 3, 2026 18:57

@robot-vibe-db robot-vibe-db Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AI Review Summary

Verdict: ✅ No critical issues found

Critical issues

No critical issues found.

Other findings

None.

Analysis:

This PR makes a clean, minimal fix for a flaky integration test (TestCoordinationSemaphore) by adjusting two test-only configuration values:

  1. SessionGracePeriodMillis: 1000 → 10000 — gives the server 10× more time to keep the session alive during reconnection, providing ample headroom for CI environments where gRPC setup may be slow.

  2. options.WithSessionReconnectDelay(0) — eliminates the default 500ms reconnect delay so the client re-establishes the gRPC stream immediately after Reconnect(). Combined with the increased grace period, this ensures the session is restored well within the server's tolerance.

WithSessionReconnectDelay(0) is safe here: in Go, time.After(0) fires immediately but still yields to the scheduler (no CPU spin), the server is healthy so reconnection succeeds on the first attempt, and the test context provides a timeout safety net. Since this is test-only code with a single explicit Reconnect() call, the zero-delay poses no risk of tight retry loops.

No production code, public API, or dependency changes. No CHANGELOG entry required.


This review was generated automatically. Critical issues require attention; other findings are advisory.
If this comment was useful, please give it a 👍 — it helps us improve the review bot.

@asmyasnikov

Copy link
Copy Markdown
Member

@copilot тест все еще flaky

лог с последнего прогона

Run go test -race -tags integration -coverpkg=./... -coverprofile experiment.txt -covermode atomic ./...
go: downloading github.com/stretchr/testify v1.10.0
go: downloading github.com/ydb-platform/ydb-go-genproto v0.0.0-20260311095541-ebbf792c1180
go: downloading google.golang.org/grpc v1.78.0
go: downloading github.com/golang-jwt/jwt/v4 v4.5.2
go: downloading github.com/google/uuid v1.6.0
go: downloading go.uber.org/mock v0.4.0
go: downloading github.com/jonboulle/clockwork v0.5.0
go: downloading google.golang.org/protobuf v1.36.10
go: downloading github.com/rekby/fixenv v0.6.1
go: downloading golang.org/x/sync v0.19.0
go: downloading golang.org/x/net v0.48.0
go: downloading github.com/davecgh/go-spew v1.1.1
go: downloading github.com/pmezard/go-difflib v1.0.0
go: downloading google.golang.org/genproto/googleapis/rpc v0.0.0-20251202230838-ff82c1b0f217
go: downloading go.uber.org/goleak v1.3.0
go: downloading go.uber.org/zap v1.27.0
go: downloading golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1
go: downloading golang.org/x/sys v0.39.0
go: downloading go.uber.org/multierr v1.10.0
go: downloading golang.org/x/text v0.32.0
ok  	github.com/ydb-platform/ydb-go-sdk/v3	2.807s	coverage: 3.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/balancers	1.317s	coverage: 0.5% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/coordination	1.293s	coverage: 0.2% of statements in ./... [no tests to run]
	github.com/ydb-platform/ydb-go-sdk/v3/coordination/options		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/credentials		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/discovery	1.212s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/background	3.400s	coverage: 0.7% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/backoff	1.396s	coverage: 0.4% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer	3.741s	coverage: 3.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer/cluster	10.022s	coverage: 0.7% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/bind	1.461s	coverage: 2.2% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/certificates		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/clone		coverage: 0.0% of statements
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/closer	[no test files]
	github.com/ydb-platform/ydb-go-sdk/v3/internal/cmd/gstack		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/cmd/gstack/utils		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/cmd/gtrace		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/conn	1.635s	coverage: 2.8% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/conn/state	1.333s	coverage: 0.0% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination	1.392s	coverage: 0.9% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination/config	1.207s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination/conversation	1.364s	coverage: 0.4% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/credentials	52.124s	coverage: 2.8% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/discovery	1.221s	coverage: 0.7% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/discovery/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/dsn	1.337s	coverage: 0.5% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/empty	[no test files]
	github.com/ydb-platform/ydb-go-sdk/v3/internal/endpoint		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/feature		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawoptional		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawscheme		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic	1.227s	coverage: 0.1% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic/rawtopiccommon	1.202s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic/rawtopicreader	1.269s	coverage: 0.1% of statements in ./... [no tests to run]
	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic/rawtopicreadermock		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic/rawtopicwriter		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawydb	1.202s	coverage: 0.1% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/kv	1.218s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/meta	1.245s	coverage: 0.7% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/mock		coverage: 0.0% of statements
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/node	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/operation	1.233s	coverage: 0.3% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/operation/metadata		coverage: 0.0% of statements
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/operation/options	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/params	1.604s	coverage: 3.8% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/pg	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/pool	27.677s	coverage: 2.9% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/query	15.345s	coverage: 6.9% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/query/arrow	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/query/config	1.332s	coverage: 0.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/query/options	1.305s	coverage: 0.3% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/query/result	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/query/scanner	1.257s	coverage: 1.4% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/ratelimiter		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/ratelimiter/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/ratelimiter/errors	1.261s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/repeater	1.289s	coverage: 0.5% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/scanner	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/scheme	1.263s	coverage: 0.1% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/scheme/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/scheme/helpers	1.226s	coverage: 0.4% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/scripting		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/scripting/config		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/secret	1.315s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/stack	2.314s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/stats	1.230s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/table	31.066s	coverage: 5.6% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/table/config	1.473s	coverage: 0.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/table/scanner	27.372s	coverage: 2.1% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic	1.390s	coverage: 0.6% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicclientinternal		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topiclistenerinternal	1.433s	coverage: 1.9% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicmock		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicmultiwriter	10.388s	coverage: 3.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicmultiwriter/partitionchooser	1.350s	coverage: 0.4% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicmultiwriter/stubs		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicreadercommon	4.050s	coverage: 1.6% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicreaderinternal	37.027s	coverage: 5.1% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicwritercommon	2.026s	coverage: 0.9% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicwriterinternal	24.551s	coverage: 9.7% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/tx	1.377s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/types	1.337s	coverage: 0.9% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/value	1.396s	coverage: 5.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/version	1.334s	coverage: 0.4% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xcontext	1.329s	coverage: 0.6% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors	1.292s	coverage: 1.1% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/internal/xiter	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xlist	1.351s	coverage: 0.2% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/xrand		coverage: 0.0% of statements
	github.com/ydb-platform/ydb-go-sdk/v3/internal/xresolver		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xruntime	1.315s	coverage: 0.0% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsql	1.810s	coverage: 3.5% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsql/badconn	1.401s	coverage: 0.6% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsql/common		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsql/xquery	1.322s	coverage: 0.7% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsql/xtable	1.225s	coverage: 0.4% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/internal/xsync	8.757s	coverage: 1.0% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/log	2.301s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/meta	1.265s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/metrics	1.247s	coverage: 0.9% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/operation	1.233s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/pkg/decimal	1.343s	coverage: 1.1% of statements in ./...
	github.com/ydb-platform/ydb-go-sdk/v3/pkg/xerrors		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/pkg/xhash	1.210s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/pkg/xslices	1.190s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/pkg/xstring	1.290s	coverage: 0.0% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/pkg/xtest	1.236s	coverage: 0.3% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/query	1.282s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/ratelimiter	1.364s	coverage: 0.2% of statements in ./... [no tests to run]
	github.com/ydb-platform/ydb-go-sdk/v3/ratelimiter/options		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/retry	2.746s	coverage: 1.8% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/retry/budget	10.641s	coverage: 0.6% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/scheme	1.313s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/scripting	1.334s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/spans	1.327s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/sugar	1.478s	coverage: 1.8% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/table	1.255s	coverage: 0.6% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/table/options	1.377s	coverage: 0.6% of statements in ./...
?   	github.com/ydb-platform/ydb-go-sdk/v3/table/result	[no test files]
?   	github.com/ydb-platform/ydb-go-sdk/v3/table/result/indexed	[no test files]
	github.com/ydb-platform/ydb-go-sdk/v3/table/result/named		coverage: 0.0% of statements
?   	github.com/ydb-platform/ydb-go-sdk/v3/table/stats	[no test files]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/table/types	1.298s	coverage: 0.7% of statements in ./...
[2026-05-03 21:06:11] final registry state:
- gauges:
  - ydb.query.pool.size.index{} = 0.000000
  - ydb.query.pool.size.in_use{} = 0.000000
  - ydb.driver.balancer.endpoints{az=1} = 1.000000
  - ydb.query.pool.size.limit{} = 0.000000
  - ydb.query.session.count{} = 0.000000
  - ydb.info{version=3.135.10} = 1.000000
  - ydb.driver.conns{endpoint=localhost:2136,node_id=1} = 0.000000
  - ydb.query.pool.size.idle{} = 0.000000
  - ydb.query.pool.size.waiters_queue{} = 0.000000
  - ydb.query.pool.size.create_in_progress{} = 0.000000
  - ydb.database.sql.conns{} = 0.000000
  - ydb.database.sql.tx{} = 0.000000
- counters:
  - ydb.query.session.exec.errs{label=undefined,status=OK} = 5
  - ydb.query.session.begin.errs{status=OK} = 3
  - ydb.database.sql.exec{query_mode=QUERY,status=OK} = 4
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/BeginTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/ExecuteQuery,node_id=1} = 10
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/ListDirectory,node_id=1} = 7
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CommitTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/DeleteSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CreateSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/AttachSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/MakeDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/DescribePath,node_id=1} = 1
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=OK} = 28
  - ydb.query.tx.query.errs{label=undefined,status=OK} = 2
  - ydb.query.session.create.errs{status=OK} = 1
  - ydb.driver.balancer.discoveries{cause=init,status=OK} = 2
  - ydb.query.session.delete.errs{status=OK} = 1
  - ydb.database.sql.query{query_mode=QUERY,status=OK} = 3
  - ydb.query.session.query.errs{label=undefined,status=OK} = 2
  - ydb.query.tx.exec.errs{label=undefined,status=OK} = 1
  - ydb.driver.balancer.updates{cause=init} = 1
- timers:
  - ydb.query.tx.query.latency{label=undefined} = 27.522056ms
  - ydb.query.session.delete.latency{} = 947.996µs
  - ydb.query.session.exec.latency{label=undefined} = 39.325148ms
  - ydb.query.tx.exec.latency{label=undefined} = 7.942444ms
  - ydb.query.session.query.latency{label=undefined} = 14.390867ms
  - ydb.database.sql.exec.latency{query_mode=QUERY} = 9.942787ms
  - ydb.database.sql.tx.latency{} = 34.349111ms
  - ydb.query.session.create.latency{} = 7.74552ms
  - ydb.database.sql.query.latency{query_mode=QUERY} = 27.935223ms
  - ydb.query.session.begin.latency{} = 985.475µs
[2026-05-03 21:06:11] final registry state:
- gauges:
  - ydb.info{version=3.135.10} = 1.000000
  - ydb.driver.balancer.endpoints{az=1} = 1.000000
  - ydb.query.pool.size.waiters_queue{} = 0.000000
  - ydb.query.pool.size.create_in_progress{} = 0.000000
  - ydb.driver.conns{endpoint=localhost:2136,node_id=1} = 0.000000
  - ydb.table.sessions{node_id=1} = 0.000000
  - ydb.query.pool.size.index{} = 0.000000
  - ydb.query.pool.size.in_use{} = 0.000000
  - ydb.database.sql.conns{} = 0.000000
  - ydb.database.sql.tx{} = 0.000000
  - ydb.table.pool.limit{} = 0.000000
  - ydb.table.pool.wait{} = 0.000000
  - ydb.table.pool.createInProgress{} = 0.000000
  - ydb.query.pool.size.limit{} = 0.000000
  - ydb.table.pool.index{} = 0.000000
  - ydb.table.pool.idle{} = 0.000000
  - ydb.query.pool.size.idle{} = 0.000000
- counters:
  - ydb.database.sql.query{query_mode=TABLE,status=OK} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/DescribePath,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/ExecuteDataQuery,node_id=1} = 5
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/ExplainDataQuery,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/DeleteSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CreateSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/ListDirectory,node_id=1} = 7
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/ExecuteSchemeQuery,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/BeginTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CommitTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/KeepAlive,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/MakeDirectory,node_id=1} = 1
  - ydb.driver.balancer.updates{cause=init} = 1
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=OK} = 27
  - ydb.database.sql.exec{query_mode=TABLE,status=OK} = 4
  - ydb.driver.balancer.discoveries{cause=init,status=OK} = 2
- timers:
  - ydb.database.sql.query.latency{query_mode=TABLE} = 23.130086ms
  - ydb.database.sql.tx.latency{} = 31.425706ms
  - ydb.database.sql.exec.latency{query_mode=TABLE} = 8.408948ms
[2026-05-03 21:06:11] final registry state:
- gauges:
  - ydb.driver.balancer.endpoints{az=1} = 1.000000
  - ydb.table.pool.with{} = 0.000000
  - ydb.query.pool.size.idle{} = 0.000000
  - ydb.query.pool.size.create_in_progress{} = 0.000000
  - ydb.query.session.count{} = 0.000000
  - ydb.table.sessions{node_id=1} = 0.000000
  - ydb.table.pool.limit{} = 0.000000
  - ydb.query.pool.size.in_use{} = 0.000000
  - ydb.info{version=3.135.10} = 1.000000
  - ydb.table.pool.index{} = 0.000000
  - ydb.table.pool.wait{} = 0.000000
  - ydb.table.pool.createInProgress{} = 0.000000
  - ydb.query.pool.size.index{} = 0.000000
  - ydb.query.pool.size.waiters_queue{} = 0.000000
  - ydb.database.sql.conns{} = 0.000000
  - ydb.database.sql.tx{} = 0.000000
  - ydb.driver.conns{endpoint=localhost:2136,node_id=1} = 0.000000
  - ydb.table.pool.idle{} = 0.000000
  - ydb.query.pool.size.limit{} = 0.000000
- counters:
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=OK} = 36
  - ydb.table.session.query.errs{status=OK} = 0
  - ydb.database.sql.query{query_mode=QUERY,status=OK} = 3
  - ydb.query.session.query.errs{label=undefined,status=OK} = 2
  - ydb.table.pool.get{} = 3
  - ydb.table.pool.put{} = 3
  - ydb.query.session.create.errs{status=OK} = 1
  - ydb.query.session.delete.errs{status=OK} = 1
  - ydb.query.tx.exec.errs{label=undefined,status=OK} = 1
  - ydb.query.tx.query.errs{label=undefined,status=OK} = 2
  - ydb.driver.balancer.updates{cause=init} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/BeginTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CommitTransaction,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/ListDirectory,node_id=1} = 8
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/DescribePath,node_id=1} = 2
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/DropTable,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/RemoveDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/MakeDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/DeleteSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/DeleteSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CreateSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/AttachSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/ExecuteQuery,node_id=1} = 10
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CreateSession,node_id=1} = 1
  - ydb.query.session.exec.errs{label=undefined,status=OK} = 5
  - ydb.query.session.begin.errs{status=OK} = 3
  - ydb.database.sql.exec{query_mode=QUERY,status=OK} = 4
  - ydb.driver.balancer.discoveries{cause=init,status=OK} = 2
- timers:
  - ydb.query.session.begin.latency{} = 960.613µs
  - ydb.query.tx.query.latency{label=undefined} = 24.813452ms
  - ydb.database.sql.query.latency{query_mode=QUERY} = 25.064016ms
  - ydb.database.sql.tx.latency{} = 31.498372ms
  - ydb.query.tx.exec.latency{label=undefined} = 7.719119ms
  - ydb.query.session.create.latency{} = 3.090472ms
  - ydb.query.session.query.latency{label=undefined} = 11.461314ms
  - ydb.database.sql.exec.latency{query_mode=QUERY} = 9.533739ms
  - ydb.query.session.delete.latency{} = 1.73384ms
  - ydb.query.session.exec.latency{label=undefined} = 23.067242ms
  - ydb.table.session.query.latency{} = 8.845182ms
- histograms:
  - ydb.table.session.query.attempts{} = [[0..1]:3,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
[2026-05-03 21:06:12] final registry state:
- gauges:
  - ydb.query.pool.size.limit{} = 0.000000
  - ydb.query.pool.size.create_in_progress{} = 0.000000
  - ydb.info{version=3.135.10} = 1.000000
  - ydb.driver.balancer.endpoints{az=1} = 1.000000
  - ydb.driver.conns{endpoint=localhost:2136,node_id=1} = 0.000000
  - ydb.query.pool.size.idle{} = 0.000000
  - ydb.query.session.count{} = 1.000000
  - ydb.query.pool.size.index{} = 0.000000
  - ydb.query.pool.size.waiters_queue{} = 0.000000
  - ydb.query.pool.size.in_use{} = 0.000000
  - ydb.driver.conn.banned{cause=context/Canceled,endpoint=localhost:2136,node_id=1} = 1.000000
- counters:
  - ydb.query.tx.row.errs{label=undefined,status=OK} = 1
  - ydb.driver.balancer.updates{cause=init} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/ListDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/ExecuteQuery,node_id=1} = 9
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/BeginTransaction,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CommitTransaction,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/DeleteSession,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/MakeDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/DescribePath,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/CreateSession,node_id=1} = 2
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Query.V1.QueryService/AttachSession,node_id=1} = 2
  - ydb.query.session.create.errs{status=OK} = 2
  - ydb.query.session.begin.errs{status=OK} = 1
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=OK} = 19
  - ydb.query.do.exec.errs{label=undefined,status=OK} = 4
  - ydb.query.do.tx.errs{label=,status=OK} = 1
  - ydb.query.row.errs{label=undefined,status=OK} = 2
  - ydb.query.tx.exec.errs{label=undefined,status=OK} = 1
  - ydb.driver.balancer.discoveries{cause=init,status=OK} = 2
  - ydb.query.do.errs{label=undefined,status=OK} = 2
  - ydb.query.session.delete.errs{status=OK} = 1
  - ydb.query.session.query.errs{label=undefined,status=OK} = 1
- timers:
  - ydb.query.session.begin.latency{} = 1.055161ms
  - ydb.query.tx.row.latency{label=undefined} = 11.261333ms
  - ydb.query.do.tx.latency{label=} = 24.027864ms
  - ydb.query.do.exec.latency{label=undefined} = 25.12476ms
  - ydb.query.row.latency{label=undefined} = 14.128859ms
  - ydb.query.session.query.latency{label=undefined} = 21.569354ms
  - ydb.query.do.latency{label=undefined} = 23.318384ms
  - ydb.query.session.create.latency{} = 2.181627ms
  - ydb.query.session.delete.latency{} = 1.085994ms
  - ydb.query.tx.exec.latency{label=undefined} = 7.472745ms
  - ydb.query.pool.with.latency{} = 24.321285ms
- histograms:
  - ydb.query.pool.with.attempts{} = [[0..1]:9,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
  - ydb.query.do.attempts{label=undefined} = [[0..1]:2,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
  - ydb.query.do.tx.attempts{label=} = [[0..1]:1,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
[2026-05-03 21:06:12] final registry state:
- gauges:
  - ydb.table.pool.idle{} = 0.000000
  - ydb.table.pool.limit{} = 0.000000
  - ydb.table.pool.wait{} = 0.000000
  - ydb.table.sessions{node_id=1} = 0.000000
  - ydb.driver.balancer.endpoints{az=1} = 1.000000
  - ydb.driver.conns{endpoint=localhost:2136,node_id=1} = 0.000000
  - ydb.table.pool.createInProgress{} = 0.000000
  - ydb.table.pool.with{} = 0.000000
  - ydb.info{version=3.135.10} = 1.000000
  - ydb.table.pool.index{} = 0.000000
- counters:
  - ydb.driver.balancer.discoveries{cause=init,status=OK} = 2
  - ydb.driver.balancer.updates{cause=init} = 1
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=OK} = 23
  - ydb.driver.conn.request_statuses{endpoint=localhost:2136,node_id=1,status=operation/SCHEME_ERROR} = 3
  - ydb.table.pool.put{} = 12
  - ydb.table.pool.get{} = 13
  - ydb.table.session.query.errs{status=OK} = 0
  - ydb.table.session.tx.errs{status=OK} = 0
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CreateSession,node_id=1} = 2
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/DescribePath,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/DescribeTable,node_id=1} = 6
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CreateTable,node_id=1} = 3
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/ExecuteDataQuery,node_id=1} = 5
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/DeleteSession,node_id=1} = 2
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/StreamExecuteScanQuery,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/StreamReadTable,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/ListDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Scheme.V1.SchemeService/MakeDirectory,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/PrepareDataQuery,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/BeginTransaction,node_id=1} = 1
  - ydb.driver.conn.request_methods{endpoint=localhost:2136,method=/Ydb.Table.V1.TableService/CommitTransaction,node_id=1} = 1
- timers:
  - ydb.table.session.query.latency{} = 14.743636ms
  - ydb.table.session.tx.latency{} = 24.544878ms
- histograms:
  - ydb.table.session.query.attempts{} = [[0..1]:12,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
  - ydb.table.session.tx.attempts{} = [[0..1]:1,[1..2]:0,[2..3]:0,[3..4]:0,[4..5]:0,[5..7]:0,[7..10]:0,[10...]:0]
2026-05-03 21:06:12.333 TRACE 'ydb.coordination.new' => coordination client starting...
2026-05-03 21:06:12.333 INFO 'ydb.coordination.new' => coordination client start done {"latency":"10.048µs","version":"3.135.10"}
2026-05-03 21:06:12.334 TRACE 'ydb.coordination.node.drop' => drop coordination node starting... {"path":"/local/coordination/node/test"}
2026-05-03 21:06:12.342 ERROR 'ydb.coordination.node.drop' => drop coordination node failed {"latency":"8.841328ms","version":"3.135.10"}
2026-05-03 21:06:12.343 TRACE 'ydb.coordination.node.create' => coordination node create starting... {"path":"/local/coordination/node/test"}
2026-05-03 21:06:12.358 INFO 'ydb.coordination.node.create' => coordination node create done {"latency":"15.245141ms"}
2026-05-03 21:06:12.358 TRACE 'ydb.coordination.node.describe' => describe coordination node starting... {"path":"/local/coordination/node/test"}
2026-05-03 21:06:12.360 INFO 'ydb.coordination.node.describe' => describe coordination node done {"latency":"2.041432ms"}
node description: &{Name:test Owner:root@builtin Type:CoordinationNode Permissions:[] EffectivePermissions:[{Subject:USERS PermissionNames:[ydb.database.connect]} {Subject:METADATA-READERS PermissionNames:[ydb.generic.list]} {Subject:DATA-READERS PermissionNames:[ydb.granular.select_row]} {Subject:DATA-WRITERS PermissionNames:[ydb.tables.modify]} {Subject:DDL-ADMINS PermissionNames:[ydb.granular.create_directory ydb.granular.write_attributes ydb.granular.create_table ydb.granular.remove_schema ydb.granular.create_queue ydb.granular.alter_schema]} {Subject:ACCESS-ADMINS PermissionNames:[ydb.access.grant]} {Subject:DATABASE-ADMINS PermissionNames:[ydb.generic.manage]}]}
node config: &{Path: SelfCheckPeriodMillis:1000 SessionGracePeriodMillis:10000 ReadConsistencyMode:Strict AttachConsistencyMode:Strict RatelimiterCountersMode:Detailed}
2026-05-03 21:06:12.361 TRACE 'ydb.coordination.node.describe' => create coordination session starting...
2026-05-03 21:06:12.361 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream starting...
2026-05-03 21:06:12.361 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream done {"latency":"430.615µs","error":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.361 TRACE 'ydb.coordination.session.start' => coordination session start starting...
2026-05-03 21:06:12.365 TRACE 'ydb.coordination.session.start' => coordination session start done {"latency":"3.166943ms","error":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.365 TRACE 'ydb.coordination.session.receive' => coordination session receive starting...
2026-05-03 21:06:12.367 TRACE 'ydb.coordination.session.receive' => coordination session receive done {"latency":"2.106628ms","error":"<nil>","response":"session_started:{session_id:1}","version":"3.135.10"}
2026-05-03 21:06:12.367 TRACE 'ydb.coordination.session.started' => coordination session started {"sessionID":"1","expectedSessionID":"1"}
2026-05-03 21:06:12.368 TRACE 'ydb.coordination.session.keepAlive.timeout' => coordination session keep alive timeout {"timeout":"10s","lastGoodResponseTime":"0001-01-01 00:00:00 +0000 UTC"}
2026-05-03 21:06:12.368 INFO 'ydb.coordination.node.describe' => create coordination session done {"latency":"7.191461ms"}
session 1 created, id: 1
2026-05-03 21:06:12.371 TRACE 'ydb.coordination.session.receive' => coordination session receive starting...
2026-05-03 21:06:12.372 TRACE 'ydb.coordination.session.receive' => coordination session receive done {"latency":"622.66µs","error":"stream context is done: [\"rpc error: code = Canceled desc = context canceled\",\"'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination.(*session).mainLoop(session.go:347)`\"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)`","response":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.372 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream starting...
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream done {"latency":"458.078µs","error":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.start' => coordination session start starting...
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.start' => coordination session start done {"latency":"91.363µs","error":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.stop' => coordination session stopped {"sessionID":"1"}
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.receive' => coordination session receive starting...
2026-05-03 21:06:12.373 TRACE 'ydb.coordination.session.receive' => coordination session receive done {"latency":"313.907µs","error":"stream context is done: [\"rpc error: code = Canceled desc = context canceled\",\"'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination.(*session).mainLoop(session.go:391)`\"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)`","response":"<nil>","version":"3.135.10"}
2026-05-03 21:06:12.374 TRACE 'ydb.coordination.node.drop' => drop coordination node starting... {"path":"/local/coordination/node/test"}
2026-05-03 21:06:12.372 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream starting...
2026-05-03 21:06:12.374 TRACE 'ydb.coordination.session.stream.new' => new coordination session stream done {"latency":"146.299µs","error":"'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/coordination.(*session).mainLoop(session.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).nextConn(balancer.go:476)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:422)`","version":"3.135.10"}
2026-05-03 21:06:12.382 INFO 'ydb.coordination.node.drop' => drop coordination node done {"latency":"8.220931ms"}
2026-05-03 21:06:12.382 TRACE 'ydb.coordination.close' => close coordination client starting...
2026-05-03 21:06:12.383 INFO 'ydb.coordination.close' => close coordination client done {"latency":"13.977µs"}
--- FAIL: TestCoordinationSemaphore (0.07s)
    coordination_test.go:78: failed to create semaphore: operation status is unknown
2026-05-03 21:07:30.958 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"11.913µs","Limit":"50"}
2026-05-03 21:07:30.958 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"3.58µs","Limit":"50"}
2026-05-03 21:07:30.958 INFO 'ydb.query.new' => create query client done {"latency":"224.568µs"}
2026-05-03 21:11:10.963 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"8.854µs","Limit":"50"}
2026-05-03 21:11:10.963 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"6.236µs","Limit":"50"}
2026-05-03 21:11:10.963 INFO 'ydb.query.new' => create query client done {"latency":"238.264µs"}
2026-05-03 21:11:10.983 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"6.654µs","Limit":"50"}
2026-05-03 21:11:10.983 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"5.235µs","Limit":"50"}
2026-05-03 21:11:10.983 INFO 'ydb.query.new' => create query client done {"latency":"224.374µs"}
2026-05-03 21:11:10.990 WARN 'ydb.query.result.next.part' => query result next part failed {"latency":"2.500164ms","error":"operation/SCHEME_ERROR (code = 400070, address = localhost:2136, nodeID = 1, issues = [{#1030 'Type annotation' [{1:12 => 'At function: KiDropTable!' [{1:12 => #2003 'Cannot find table 'db.[/local/TestIssue1872QueryWarning]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions'}]}]}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:180)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.nextPart(result.go:241)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*streamResult).nextPart(result.go:219)`","version":"3.135.10"}
2026-05-03 21:11:10.990 WARN 'ydb.query.result.new' => query result new failed {"latency":"2.792644ms","error":"operation/SCHEME_ERROR (code = 400070, address = localhost:2136, nodeID = 1, issues = [{#1030 'Type annotation' [{1:12 => 'At function: KiDropTable!' [{1:12 => #2003 'Cannot find table 'db.[/local/TestIssue1872QueryWarning]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions'}]}]}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:180)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.nextPart(result.go:241)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*streamResult).nextPart(result.go:219)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.newResult(result.go:169)`","version":"3.135.10"}
2026-05-03 21:11:10.991 WARN 'ydb.query.pool.try' => query service pool try failed {"latency":"7.392181ms","error":"operation/SCHEME_ERROR (code = 400070, address = localhost:2136, nodeID = 1, issues = [{#1030 'Type annotation' [{1:12 => 'At function: KiDropTable!' [{1:12 => #2003 'Cannot find table 'db.[/local/TestIssue1872QueryWarning]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions'}]}]}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:180)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.nextPart(result.go:241)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*streamResult).nextPart(result.go:219)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.newResult(result.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.execute(execute_query.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).execute(session.go:182)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.clientExec.func1(client.go:379)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)`","version":"3.135.10"}
2026-05-03 21:11:10.992 ERROR 'ydb.query.pool.with' => query pool with failed {"latency":"8.057076ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=false): operation/SCHEME_ERROR (code = 400070, address = localhost:2136, nodeID = 1, issues = [{#1030 'Type annotation' [{1:12 => 'At function: KiDropTable!' [{1:12 => #2003 'Cannot find table 'db.[/local/TestIssue1872QueryWarning]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions'}]}]}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:180)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.nextPart(result.go:241)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*streamResult).nextPart(result.go:219)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.newResult(result.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.execute(execute_query.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).execute(session.go:182)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.clientExec.func1(client.go:379)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)`","Attempts":"1","version":"3.135.10"}
2026-05-03 21:11:10.992 ERROR 'ydb.query.exec' => query exec failed {"latency":"8.354437ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=false): operation/SCHEME_ERROR (code = 400070, address = localhost:2136, nodeID = 1, issues = [{#1030 'Type annotation' [{1:12 => 'At function: KiDropTable!' [{1:12 => #2003 'Cannot find table 'db.[/local/TestIssue1872QueryWarning]' because it does not exist or you do not have access permissions. Please check correctness of table path and user permissions'}]}]}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:180)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.nextPart(result.go:241)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*streamResult).nextPart(result.go:219)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.newResult(result.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.execute(execute_query.go:169)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).execute(session.go:182)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.clientExec.func1(client.go:379)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do(client.go:232)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.clientExec(client.go:393)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Client).Exec(client.go:415)`","version":"3.135.10"}
2026-05-03 21:11:11.092 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"7.123µs","Limit":"50"}
2026-05-03 21:11:11.092 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"5.512µs","Limit":"50"}
2026-05-03 21:11:11.092 INFO 'ydb.query.new' => create query client done {"latency":"198.856µs"}
42
43 44
2026-05-03 21:11:15.429 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"6.455µs","Limit":"50"}
2026-05-03 21:11:15.430 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"10.937µs","Limit":"50"}
2026-05-03 21:11:15.430 INFO 'ydb.query.new' => create query client done {"latency":"188.61µs"}
2026-05-03 21:11:15.470 WARN 'ydb.query.session.begin' => query session begin failed {"latency":"1.169341ms","error":"operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode OnlineReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)`","version":"3.135.10"}
2026-05-03 21:11:15.470 WARN 'ydb.query.pool.try' => query service pool try failed {"latency":"1.669442ms","error":"operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode OnlineReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)`","version":"3.135.10"}
2026-05-03 21:11:15.471 ERROR 'ydb.query.pool.with' => query pool with failed {"latency":"2.14667ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=true): operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode OnlineReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)`","Attempts":"1","version":"3.135.10"}
2026-05-03 21:11:15.471 ERROR 'ydb.query.do.tx' => query doTx failed {"latency":"2.458565ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=true): operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode OnlineReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do(client.go:232)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx(client.go:302)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Client).DoTx(client.go:584)`","attempts":"1","version":"3.135.10"}
2026-05-03 21:11:15.472 WARN 'ydb.query.session.begin' => query session begin failed {"latency":"1.040661ms","error":"operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode StaleReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)`","version":"3.135.10"}
2026-05-03 21:11:15.473 WARN 'ydb.query.pool.try' => query service pool try failed {"latency":"1.489378ms","error":"operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode StaleReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)`","version":"3.135.10"}
2026-05-03 21:11:15.473 ERROR 'ydb.query.pool.with' => query pool with failed {"latency":"1.984021ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=true): operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode StaleReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)`","Attempts":"1","version":"3.135.10"}
2026-05-03 21:11:15.473 ERROR 'ydb.query.do.tx' => query doTx failed {"latency":"2.252517ms","error":"pool.With failed with 1 attempts: non-retryable error occurred on attempt No.1 (idempotent=true): operation/BAD_REQUEST (code = 400010, address = localhost:2136, nodeID = 1, issues = [{'Failed to begin transaction: open transactions not supported for transaction mode StaleReadOnly, use tx_control field in ExecuteDataQueryRequest to begin transaction with this mode'}]) at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.invoke(conn.go:391)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/balancer.(*Balancer).wrapCall(balancer.go:445)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.begin(transaction.go:52)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Session).Begin(session.go:156)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx.func1(client.go:282)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do.func1(client.go:224)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).try(pool.go:505)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With.func2(pool.go:533)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry.func1(retry.go:264)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.opWithRecover(retry.go:418)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.RetryWithResult(retry.go:358)` at `github.com/ydb-platform/ydb-go-sdk/v3/retry.Retry(retry.go:270)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/pool.(*Pool).With(pool.go:539)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.do(client.go:232)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.doTx(client.go:302)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/query.(*Client).DoTx(client.go:584)`","attempts":"1","version":"3.135.10"}
2026-05-03 21:11:15.487 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"6.803µs","Limit":"50"}
2026-05-03 21:11:15.487 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"3.632µs","Limit":"50"}
2026-05-03 21:11:15.487 INFO 'ydb.query.new' => create query client done {"latency":"221.248µs"}
2026-05-03 21:11:15.541 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"8.737µs","Limit":"50"}
2026-05-03 21:11:15.541 INFO 'ydb.query.pool.new' => query service create pool done {"latency":"9.207µs","Limit":"50"}
2026-05-03 21:11:15.541 INFO 'ydb.query.new' => create query client done {"latency":"255.016µs"}
Table `/local/TestCopyTables/renamed`:
 - `id` Int64
 - `val` Optional<Utf8>

FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.077787612 [WARN] ydb.driver.conn.stream.RecvMsg: driver receive stream msg failed (map[error:stream context is done: ["rpc error: code = Canceled desc = grpc: the client connection is closing","'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/xcontext.(*CancelsGuard).Cancel(cancels_quard.go:39)`"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)` latency:474.854391ms version:3.135.10])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.077830797 [TRACE] ydb.topic.writer.close: topic writer close starting... (map[reason:ydb: topic reader unretriable error: ydb: failed to receive message from write stream: ydb: failed to read grpc message from writer stream: stream context is done: ["rpc error: code = Canceled desc = grpc: the client connection is closing","'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/xcontext.(*CancelsGuard).WithCancel.func1(cancels_quard.go:28)`"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/grpcwrapper/rawtopic/rawtopicwriter.(*StreamWriter).Recv(streamwriter.go:70)` at `github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicwriterinternal.(*SingleStreamWriter).receiveMessagesLoop(writer_single_stream.go:202)`, was retried (143.307µs) writer_instance_id:5680637797622728555])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.155507569 [INFO] ydb.topic.reader.error: topic reader has grpc stream error (map[error:stream context is done: ["rpc error: code = Canceled desc = grpc: the client connection is closing","'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/xcontext.(*CancelsGuard).Cancel(cancels_quard.go:39)`"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)` reader_connection_id:consumer_1_86_4491283927661046187_v1 version:3.135.10])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.155655253 [TRACE] ydb.topic.reader.close: topic reader close starting... (map[close_reason:stream context is done: ["rpc error: code = Canceled desc = grpc: the client connection is closing","'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/xcontext.(*CancelsGuard).Cancel(cancels_quard.go:39)`"] at `github.com/ydb-platform/ydb-go-sdk/v3/internal/conn.(*grpcClientStream).RecvMsg(grpc_client_stream.go:155)` reader_connection_id:consumer_1_86_4491283927661046187_v1])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.155884202 [TRACE] ydb.topic.reader.close: topic reader close starting... (map[close_reason:'context canceled' at `github.com/ydb-platform/ydb-go-sdk/v3/internal/topic/topicreaderinternal.(*topicStreamReaderImpl).CloseWithError.func2(stream_reader_impl.go:846)` reader_connection_id:consumer_1_86_4491283927661046187_v1])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.155934353 [TRACE] ydb.driver.conn.stream.CloseSend: driver send stream close starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.155965776 [TRACE] ydb.topic.reader.close: topic reader close done (map[latency:101.977µs reader_connection_id:consumer_1_86_4491283927661046187_v1])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.156018925 [TRACE] ydb.driver.conn.stream.CloseSend: driver connection stream closed done (map[latency:27.688µs])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.156141067 [WARN] ydb.topic.reader.close: topic reader close failed (map[error:context canceled latency:480.219µs reader_connection_id:consumer_1_86_4491283927661046187_v1 version:3.135.10])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.195243348 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.195365568 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:86.554µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.195437293 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.19551536 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:51.002µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.201919925 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.202007248 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:58.012µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.202063685 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.202114038 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:41.134µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.344078921 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.344216525 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:95.82µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.344273112 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.344350127 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:37.397µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363110476 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363230787 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:93.172µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363288841 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363352536 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:40.504µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363409711 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363484475 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:364.76µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363536595 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.363612942 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:38.503µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.45008347 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.450185501 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:70.377µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.450241269 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.450287962 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:31.163µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.855215273 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.855316455 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:77.095µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.855361802 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:03.855431952 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:45.665µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:04.180318896 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:04.180412711 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:69.781µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:04.180457013 [TRACE] ydb.topic.reader.reconnect: topic reader reconnect starting... (map[])


FINISHED TEST "TestManyConcurentReadersWriters":
TestManyConcurentReadersWriters: 21:14:04.180499394 [INFO] ydb.topic.reader.reconnect: topic reader reconnect done (map[latency:28.019µs reason:retryable/CUSTOM (code = -1, source error = "ydb: first connection attempt not finished")])

table items count 0
table items count 1
table items count 0
table items count 1
FAIL
coverage: 58.3% of statements in ./...
FAIL	github.com/ydb-platform/ydb-go-sdk/v3/tests/integration	492.014s
ok  	github.com/ydb-platform/ydb-go-sdk/v3/testutil	1.395s	coverage: 1.0% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic	1.353s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic/topiclistener	1.368s	coverage: 0.1% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic/topicoptions	1.393s	coverage: 0.2% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic/topicreader	1.354s	coverage: 0.1% of statements in ./... [no tests to run]
	github.com/ydb-platform/ydb-go-sdk/v3/topic/topicsugar		coverage: 0.0% of statements
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic/topictypes	1.268s	coverage: 0.4% of statements in ./...
ok  	github.com/ydb-platform/ydb-go-sdk/v3/topic/topicwriter	1.315s	coverage: 0.2% of statements in ./... [no tests to run]
ok  	github.com/ydb-platform/ydb-go-sdk/v3/trace	1.328s	coverage: 1.4% of statements in ./...
FAIL

…t keep-alive check

The receiveLoop was calling `sessionStarted <- message.GetSessionStarted()` (blocking
channel send) and THEN `s.updateLastGoodResponseTime()`. Once mainLoop received from
the channel, it could race into the inner keep-alive loop and read lastGoodResponseTime
as zero (Go zero time: 0001-01-01) before receiveLoop updated it. This made keepAliveTime
a massive negative value, causing time.After to fire immediately, triggering a spurious
reconnect that would fail non-idempotent operations (e.g. CreateSemaphore) with
ErrOperationStatusUnknown.

Fix: move updateLastGoodResponseTime() to BEFORE the channel send so the value is
guaranteed to be set by the time mainLoop enters the keep-alive inner loop.

Agent-Logs-Url: https://github.com/ydb-platform/ydb-go-sdk/sessions/8a1fdbdc-9eb3-40ae-962a-fbcfb944dd5e

Co-authored-by: asmyasnikov <14202262+asmyasnikov@users.noreply.github.com>

Copilot AI commented May 3, 2026

Copy link
Copy Markdown
Contributor Author

@copilot тест все еще flaky

лог с последнего прогона
...

Found the root cause by inspecting the CI logs. The failure was coordination_test.go:78: failed to create semaphore: operation status is unknown — triggered by a spurious reconnect that happened immediately after session creation, not by the Reconnect() call the test makes later.

Root cause (commit 900d9a8): In receiveLoop, the code was:

case *Ydb_Coordination.SessionResponse_SessionStarted_:
    sessionStarted <- message.GetSessionStarted()  // unblocks mainLoop
    s.updateLastGoodResponseTime()                  // called AFTER channel send

Once mainLoop received from the channel, it could race into the keep-alive inner loop and read lastGoodResponseTime as zero (0001-01-01) before receiveLoop had a chance to update it. This made keepAliveTime a massive negative value → time.After fired immediately → keep-alive timeout check triggered → cancelStream() called → OnDetach failed the in-flight non-idempotent CreateSemaphore with ErrOperationStatusUnknown.

Fix: swapped the two lines so updateLastGoodResponseTime() is called before the channel send. The timestamp is now guaranteed to be set by the time mainLoop reads it.

Copilot AI requested a review from asmyasnikov May 3, 2026 21:42
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

dev: flaky TestCoordinationSemaphore

4 participants