From 02e9cb1553d7fd21fa777ef7e37ec9f6a5d45576 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Thu, 6 Aug 2026 18:47:02 +0300 Subject: [PATCH 1/4] tail: fix follow retry pacing and diagnostics MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three small defects in the follow fallback plumbing: * the "log file unavailable" message passed no argument for its %q verb and printed %!q(MISSING) instead of the file name (go vet does not catch it: apex/log is not recognized as a printf wrapper); * tryReopenTailer slept retryOpenDelay before the first attempt even when the file was already back in place, and the timer.Stop deferred inside the loop piled up until the function returned — try first, wait only between attempts; * a tailer that stopped without an error was reported through %w with a nil operand, producing "%!w()" — report it as an unexpected termination instead. Part of TNTP-3131 --- cli/tail/follow.go | 24 +++++++++++++++--------- cli/tail/tail.go | 3 ++- 2 files changed, 17 insertions(+), 10 deletions(-) diff --git a/cli/tail/follow.go b/cli/tail/follow.go index 1020cd975..c7d29bf8d 100644 --- a/cli/tail/follow.go +++ b/cli/tail/follow.go @@ -86,16 +86,18 @@ func (f *fileFollower) tryReopenTailer(ctx context.Context, cfg *tail.Config) (* } for i := range maxRetriesReopen { - timer := time.NewTimer(retryOpenDelay) - defer timer.Stop() + if i > 0 { + timer := time.NewTimer(retryOpenDelay) - select { - case <-ctx.Done(): - return nil, fmt.Errorf("context (%w) while waiting to retry for %q", - ctx.Err(), f.name) + select { + case <-ctx.Done(): + timer.Stop() + return nil, fmt.Errorf("context (%w) while waiting to retry for %q", + ctx.Err(), f.name) - case <-timer.C: - log.Infof("Wake up to retry tailing %q", f.name) + case <-timer.C: + log.Infof("Wake up to retry tailing %q", f.name) + } } newT, err := tail.TailFile(f.name, newCfg) @@ -139,7 +141,11 @@ func (f *fileFollower) handleTailerStopStatus(ctx context.Context, curT *tail.Ta return t, nil } - return nil, fmt.Errorf("failed to stop tailer for %q: %w", f.name, stopErr) + if stopErr != nil { + return nil, fmt.Errorf("failed to stop tailer for %q: %w", f.name, stopErr) + } + + return nil, fmt.Errorf("tailer for %q stopped unexpectedly", f.name) } func (f *fileFollower) followFile(ctx context.Context, t *tail.Tail, out chan<- string) { diff --git a/cli/tail/tail.go b/cli/tail/tail.go index 22ba1af0a..cdbb80322 100644 --- a/cli/tail/tail.go +++ b/cli/tail/tail.go @@ -217,7 +217,8 @@ func Follow(ctx context.Context, out chan<- string, logFormatter LogFormatter, f if err != nil { log.Error(err.Error()) } else { - log.Errorf("The log file %q is unavailable for reading. Exiting.") + log.Errorf("The log file %q is unavailable for reading. Exiting.", + t.Filename) } return } From 0c9049195d43cb28a6230e7b01a04d3817c49cbc Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Thu, 6 Aug 2026 18:47:27 +0300 Subject: [PATCH 2/4] tail: yield only complete lines when following Both follow paths asked the tail library for incomplete lines. At EOF the library then yields the half-written line it happened to catch and seeks to the end of the file, which splits a log record in two and can skip bytes appended between the read and the seek. Log records are line-oriented, so buffer the half-written line until its newline arrives instead. Part of TNTP-3131 --- CHANGELOG.md | 3 +++ cli/tail/follow.go | 7 ++++++- cli/tail/tail.go | 12 ++++++++---- 3 files changed, 17 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 16b3d31bf..4326a8ac9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -130,6 +130,9 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0. backup take a cluster-wide recovery point. - `tt backup`: remove `creation_duration` from the cluster manifest — the field was unused and is no longer serialized. +- `tt log -f` / `tt tcm log --follow`: only complete lines are printed. A + half-written line stays buffered until its newline arrives instead of + being split into two records. ### Fixed diff --git a/cli/tail/follow.go b/cli/tail/follow.go index c7d29bf8d..43ab34907 100644 --- a/cli/tail/follow.go +++ b/cli/tail/follow.go @@ -229,7 +229,12 @@ func (f *fileFollower) startFollowing(ctx context.Context, out chan<- string, li MustExist: true, Follow: true, ReOpen: true, - Logger: tail.DiscardingLogger, + // Half-written lines stay buffered until their newline arrives: + // yielding them early would split a log record in two, and the + // seek-to-end after an early yield can skip bytes appended in + // the meantime. + CompleteLines: true, + Logger: tail.DiscardingLogger, } t, err := tail.TailFile(f.name, tCfg) diff --git a/cli/tail/tail.go b/cli/tail/tail.go index cdbb80322..c9cbdbe46 100644 --- a/cli/tail/tail.go +++ b/cli/tail/tail.go @@ -191,10 +191,14 @@ func Follow(ctx context.Context, out chan<- string, logFormatter LogFormatter, f Offset: startPos, Whence: io.SeekStart, }, - MustExist: true, - Follow: true, - ReOpen: true, - CompleteLines: false, + MustExist: true, + Follow: true, + ReOpen: true, + // Half-written lines stay buffered until their newline arrives: + // yielding them early would split a log record in two, and the + // seek-to-end after an early yield can skip bytes appended in + // the meantime. + CompleteLines: true, Logger: tail.DiscardingLogger, }) if err != nil { From 2a542cb247ea69140ee6fdcbbab31385c357e0e7 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Thu, 6 Aug 2026 18:58:08 +0300 Subject: [PATCH 3/4] deps: bump go-tail to fix duplicates and stalls go-tail v1.4.14 could deliver a line twice right after a log rotation: a watch armed while the file was being replaced kept a stale size baseline, so the first write to the new file looked like a truncation and forced a reopen from offset zero; a watch kept across the reopen paths could also be dead with a latched delete notification, forcing one more reopen. A watcher goroutine that lost its events channel exited silently, corrupting the shared watch refcount and stalling the tailer forever. The pinned revision is the head of tarantool/go-tail#6; switch it to the v1.4.15 tag once the fix is released. Part of TNTP-3131 --- CHANGELOG.md | 3 +++ go.mod | 2 +- go.sum | 4 ++-- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4326a8ac9..996ff3724 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -139,6 +139,9 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0. - `tt log -f`: possible line loss/duplication on rename, hanging after a watched log directory is removed, and lines written just as the file was read to the end not showing up until the next write. +- `tt log -f` / `tt tcm log --follow`: a line could be delivered twice + right after a log rotation, and the follow could stall, never picking + up the rotated file (go-tail v1.4.15). ## [2.13.0] - 2026-05-21 diff --git a/go.mod b/go.mod index 72d600f8d..8ab5437e1 100644 --- a/go.mod +++ b/go.mod @@ -32,7 +32,7 @@ require ( github.com/tarantool/go-iproto v1.1.0 github.com/tarantool/go-prompt v1.0.1 github.com/tarantool/go-storage v1.5.0 - github.com/tarantool/go-tail v1.4.14 + github.com/tarantool/go-tail v1.4.15-0.20260806154205-254b9b0cd094 github.com/tarantool/go-tarantool v1.12.3 github.com/tarantool/go-tarantool/v2 v2.4.2 github.com/tarantool/go-xlog v0.0.0-20260707203858-fed522934686 diff --git a/go.sum b/go.sum index b503a6acf..01163a6b6 100644 --- a/go.sum +++ b/go.sum @@ -360,8 +360,8 @@ github.com/tarantool/go-prompt v1.0.1 h1:88Yer6gCFylqGRrdWwikNFVbklRQsqKF7mycvGd github.com/tarantool/go-prompt v1.0.1/go.mod h1:9Vuvi60Bk+3yaXqgYaXNTpLbwPPaaEOeaUgpFW1jqTU= github.com/tarantool/go-storage v1.5.0 h1:WRi5eahOinBHh+Nnc5CmiaFNxYQCd5OoiUfA7n9pe30= github.com/tarantool/go-storage v1.5.0/go.mod h1:Aj8RoWXZGYOI7oWT3Utj9IE7FItvMSDf2smHxHJo96M= -github.com/tarantool/go-tail v1.4.14 h1:myfx/k3Xf9N7RPq/0qyuZw5jqqNb2lrheLdaBHyQUT8= -github.com/tarantool/go-tail v1.4.14/go.mod h1:NqLWssaRJ2w9myxdJWlc4WaZWHU2CLZDdEYfKlSnbEQ= +github.com/tarantool/go-tail v1.4.15-0.20260806154205-254b9b0cd094 h1:uNFHojM8qO8yBwy4FFdrjFDvcztK4v1ucvPaEpPFaEw= +github.com/tarantool/go-tail v1.4.15-0.20260806154205-254b9b0cd094/go.mod h1:7OEbsSv1hZ/XfBlgeglrMry5GUeJS3be9SoGLxbA1fo= github.com/tarantool/go-tarantool v1.12.3 h1:GXabowmrTSW225xFEjX4t+8PlccVDCeGB5OM1VLbBXE= github.com/tarantool/go-tarantool v1.12.3/go.mod h1:QRiXv0jnxwgxHtr9ZmifSr/eRba76gTUBgp69pDMX1U= github.com/tarantool/go-tarantool/v2 v2.4.2 h1:rkzYtFhLJLA9RDIhjzN93MJBN5PBxHW4+soq+RB90gE= From 9129fa829f83f998608ba33b8523df7fa1e015f6 Mon Sep 17 00:00:00 2001 From: Eugene Blikh Date: Thu, 6 Aug 2026 18:58:08 +0300 Subject: [PATCH 4/4] test: drop rotation settle delay in tcm log test The 0.5 s pause between creating the replacement file and writing to it was a crutch for the tailer losing a rotation that landed while its watch was not armed. The tail library now rechecks the file after arming the watch and re-arms it across reopens, so the rotation test can exercise the tight timing again. 20 consecutive runs of all 42 test cases passed with the delay removed. Part of TNTP-3131 --- test/integration/tcm/test_tcm_log.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/test/integration/tcm/test_tcm_log.py b/test/integration/tcm/test_tcm_log.py index e8f711460..f674ed079 100644 --- a/test/integration/tcm/test_tcm_log.py +++ b/test/integration/tcm/test_tcm_log.py @@ -254,10 +254,7 @@ def test_log_rotate( tmp_log.rename(tmp_log.with_suffix(".bak")) assert not tmp_log.exists(), "Temporary log file should be deleted." - # Create the replacement separately so the asynchronous reopen path can - # attach its watcher before new records are written. tmp_log.touch() - time.sleep(0.5) new_lines, cnt_lines = handle_updating_logs(reader, tmp_log, mode, delay_time, is_append=True) stdout_lines.extend(new_lines)