1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
|
package loggers
import (
"context"
"os"
"path/filepath"
"strconv"
"strings"
"sync"
"testing"
"time"
"github.com/mimecast/dtail/internal/config"
)
// withTempLogDir points config.Common.LogDir at a fresh temp dir for the
// duration of a test and restores the previous config afterwards. The file
// logger resolves its output path from config.Common.LogDir at write time.
func withTempLogDir(t *testing.T) string {
t.Helper()
dir := t.TempDir()
prev := config.Common
config.Common = &config.CommonConfig{LogDir: dir}
t.Cleanup(func() { config.Common = prev })
return dir
}
// startFileLogger starts f and returns a stop func that cancels the context and
// JOINS the logger goroutine (wg.Wait). Tests must defer stop() so the goroutine
// has fully exited before returning: withTempLogDir's t.Cleanup restores the
// global config.Common, and a still-running goroutine reading config.Common.LogDir
// would otherwise race that restore. For the same reason none of these tests may
// call t.Parallel — they mutate the process-global config.Common.
func startFileLogger(t *testing.T, f *file) func() {
t.Helper()
ctx, cancel := context.WithCancel(context.Background())
var wg sync.WaitGroup
wg.Add(1)
f.Start(ctx, &wg)
return func() {
cancel()
wg.Wait()
}
}
func readLogFile(t *testing.T, dir, base string) string {
t.Helper()
data, err := os.ReadFile(filepath.Join(dir, base+".log"))
if err != nil {
if os.IsNotExist(err) {
return ""
}
t.Fatalf("reading log file: %v", err)
}
return string(data)
}
// TestFileLoggerNothingLostOnClose verifies every logged line reaches disk when
// the context is cancelled (clean shutdown): the goroutine drains the buffer
// channel and flushes the 64KB writer before closing the fd.
func TestFileLoggerNothingLostOnClose(t *testing.T) {
dir := withTempLogDir(t)
base := "close-test"
f := newFile(Strategy{Rotation: SignalRotation, FileBase: base})
stop := startFileLogger(t, f)
const n = 500
var want strings.Builder
for i := 0; i < n; i++ {
line := "line-" + strconv.Itoa(i)
f.Log(time.Now(), line)
want.WriteString(line + "\n")
}
// stop() cancels the context and joins the goroutine, which flushes and
// closes the fd on the way out — so all output must be on disk afterwards.
stop()
if got := readLogFile(t, dir, base); got != want.String() {
t.Fatalf("lost output on close: got %d bytes, want %d bytes",
len(got), want.Len())
}
}
// TestFileLoggerIdleFlush verifies a single low-volume line (follow/tail style)
// is not stuck behind the 64KB buffer: the idle ticker flushes it to disk
// promptly without any explicit Flush or shutdown. The logger goroutine is
// joined via stop() before returning so it cannot outlive config.Common.
func TestFileLoggerIdleFlush(t *testing.T) {
dir := withTempLogDir(t)
base := "idle-test"
f := newFile(Strategy{Rotation: SignalRotation, FileBase: base})
stop := startFileLogger(t, f)
defer stop()
f.Log(time.Now(), "follow-line")
deadline := time.Now().Add(2 * time.Second)
for time.Now().Before(deadline) {
if strings.Contains(readLogFile(t, dir, base), "follow-line") {
return
}
time.Sleep(5 * time.Millisecond)
}
t.Fatal("follow-style line stuck behind buffer; idle flush did not emit it")
}
// TestFileLoggerExplicitFlush verifies Flush() is SYNCHRONOUS: once it returns,
// the buffered data is already on disk (no polling needed). This is the property
// dlog.FatalPanic relies on to not drop Fatal diagnostics before panicking.
func TestFileLoggerExplicitFlush(t *testing.T) {
dir := withTempLogDir(t)
base := "flush-test"
f := newFile(Strategy{Rotation: SignalRotation, FileBase: base})
stop := startFileLogger(t, f)
defer stop()
f.Log(time.Now(), "flush-me")
f.Flush()
if got := readLogFile(t, dir, base); !strings.Contains(got, "flush-me") {
t.Fatalf("synchronous Flush() did not persist data before returning; got %q", got)
}
}
// TestFileLoggerRotateDoesNotBlockWithoutWrites verifies that Rotate() does
// not deadlock when no log messages have been produced. Previously rotateCh
// was unbuffered and only drained opportunistically from write(), so a SIGHUP
// before any Log() call would block the caller forever.
func TestFileLoggerRotateDoesNotBlockWithoutWrites(t *testing.T) {
f := newFile(Strategy{Rotation: SignalRotation, FileBase: "unit-test"})
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
var wg sync.WaitGroup
wg.Add(1)
f.Start(ctx, &wg)
done := make(chan struct{})
go func() {
f.Rotate()
close(done)
}()
select {
case <-done:
case <-time.After(500 * time.Millisecond):
t.Fatal("Rotate() blocked without any writes; expected prompt return")
}
cancel()
wg.Wait()
}
// TestFileLoggerCancelBeforeFirstWriteDoesNotPanic verifies that cancelling
// the context before any write has happened does not panic. Previously the
// goroutine called f.fd.Close() unconditionally, but f.fd is only populated
// by the first getWriter() call, so a ctx cancel with no prior writes
// panicked on a nil pointer.
func TestFileLoggerCancelBeforeFirstWriteDoesNotPanic(t *testing.T) {
f := newFile(Strategy{Rotation: SignalRotation, FileBase: "unit-test"})
ctx, cancel := context.WithCancel(context.Background())
var wg sync.WaitGroup
wg.Add(1)
f.Start(ctx, &wg)
cancel()
doneCh := make(chan struct{})
go func() {
wg.Wait()
close(doneCh)
}()
select {
case <-doneCh:
case <-time.After(1 * time.Second):
t.Fatal("file logger goroutine did not exit after ctx cancel")
}
}
|
