1// Copyright (c) 2015 HPE Software Inc. All rights reserved.
2// Copyright (c) 2013 ActiveState Software Inc. All rights reserved.
3
4// TODO:
5//  * repeat all the tests with Poll:true
6
7package tail
8
9import (
10	_ "fmt"
11	"io"
12	"io/ioutil"
13	"os"
14	"strings"
15	"testing"
16	"time"
17
18	"github.com/nxadm/tail/ratelimiter"
19	"github.com/nxadm/tail/watch"
20)
21
22func init() {
23	// Clear the temporary test directory
24	err := os.RemoveAll(".test")
25	if err != nil {
26		panic(err)
27	}
28}
29
30func TestMain(m *testing.M) {
31	// Use a smaller poll duration for faster test runs. Keep it below
32	// 100ms (which value is used as common delays for tests)
33	watch.POLL_DURATION = 5 * time.Millisecond
34	os.Exit(m.Run())
35}
36
37func TestMustExist(t *testing.T) {
38	tail, err := TailFile("/no/such/file", Config{Follow: true, MustExist: true})
39	if err == nil {
40		t.Error("MustExist:true is violated")
41		tail.Stop()
42	}
43	tail, err = TailFile("/no/such/file", Config{Follow: true, MustExist: false})
44	if err != nil {
45		t.Error("MustExist:false is violated")
46	}
47	tail.Stop()
48	_, err = TailFile("README.md", Config{Follow: true, MustExist: true})
49	if err != nil {
50		t.Error("MustExist:true on an existing file is violated")
51	}
52	tail.Cleanup()
53}
54
55func TestWaitsForFileToExist(t *testing.T) {
56	tailTest := NewTailTest("waits-for-file-to-exist", t)
57	tail := tailTest.StartTail("test.txt", Config{})
58	go tailTest.VerifyTailOutput(tail, []string{"hello", "world"}, false)
59
60	<-time.After(100 * time.Millisecond)
61	tailTest.CreateFile("test.txt", "hello\nworld\n")
62	tailTest.Cleanup(tail, true)
63}
64
65func TestWaitsForFileToExistRelativePath(t *testing.T) {
66	tailTest := NewTailTest("waits-for-file-to-exist-relative", t)
67
68	oldWD, err := os.Getwd()
69	if err != nil {
70		tailTest.Fatal(err)
71	}
72	os.Chdir(tailTest.path)
73	defer os.Chdir(oldWD)
74
75	tail, err := TailFile("test.txt", Config{})
76	if err != nil {
77		tailTest.Fatal(err)
78	}
79
80	go tailTest.VerifyTailOutput(tail, []string{"hello", "world"}, false)
81
82	<-time.After(100 * time.Millisecond)
83	if err := ioutil.WriteFile("test.txt", []byte("hello\nworld\n"), 0600); err != nil {
84		tailTest.Fatal(err)
85	}
86	tailTest.Cleanup(tail, true)
87}
88
89func TestStop(t *testing.T) {
90	tail, err := TailFile("_no_such_file", Config{Follow: true, MustExist: false})
91	if err != nil {
92		t.Error("MustExist:false is violated")
93	}
94	if tail.Stop() != nil {
95		t.Error("Should be stoped successfully")
96	}
97	tail.Cleanup()
98}
99
100func TestStopNonEmptyFile(t *testing.T) {
101	tailTest := NewTailTest("maxlinesize", t)
102	tailTest.CreateFile("test.txt", "hello\nthere\nworld\n")
103	tail := tailTest.StartTail("test.txt", Config{})
104	tail.Stop()
105	tail.Cleanup()
106	// success here is if it doesn't panic.
107}
108
109func TestStopAtEOF(t *testing.T) {
110	tailTest := NewTailTest("maxlinesize", t)
111	tailTest.CreateFile("test.txt", "hello\nthere\nworld\n")
112	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: nil})
113
114	// read "hello"
115	line := <-tail.Lines
116	if line.Text != "hello" {
117		t.Errorf("Expected to get 'hello', got '%s' instead", line.Text)
118	}
119
120	if line.Num != 1 {
121		t.Errorf("Expected to get 1, got %d instead", line.Num)
122	}
123
124	tailTest.VerifyTailOutput(tail, []string{"there", "world"}, false)
125	tail.StopAtEOF()
126	tailTest.Cleanup(tail, true)
127}
128
129func TestMaxLineSizeFollow(t *testing.T) {
130	// As last file line does not end with newline, it will not be present in tail's output
131	maxLineSize(t, true, "hello\nworld\nfin\nhe", []string{"hel", "lo", "wor", "ld", "fin", "he"})
132}
133
134func TestMaxLineSizeNoFollow(t *testing.T) {
135	maxLineSize(t, false, "hello\nworld\nfin\nhe", []string{"hel", "lo", "wor", "ld", "fin", "he"})
136}
137
138func TestOver4096ByteLine(t *testing.T) {
139	tailTest := NewTailTest("Over4096ByteLine", t)
140	testString := strings.Repeat("a", 4097)
141	tailTest.CreateFile("test.txt", "test\n"+testString+"\nhello\nworld\n")
142	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: nil})
143	go tailTest.VerifyTailOutput(tail, []string{"test", testString, "hello", "world"}, false)
144
145	// Delete after a reasonable delay, to give tail sufficient time
146	// to read all lines.
147	<-time.After(100 * time.Millisecond)
148	tailTest.RemoveFile("test.txt")
149	tailTest.Cleanup(tail, true)
150}
151
152func TestOver4096ByteLineWithSetMaxLineSize(t *testing.T) {
153	tailTest := NewTailTest("Over4096ByteLineMaxLineSize", t)
154	testString := strings.Repeat("a", 4097)
155	tailTest.CreateFile("test.txt", "test\n"+testString+"\nhello\nworld\n")
156	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: nil, MaxLineSize: 4097})
157	go tailTest.VerifyTailOutput(tail, []string{"test", testString, "hello", "world"}, false)
158
159	// Delete after a reasonable delay, to give tail sufficient time
160	// to read all lines.
161	<-time.After(100 * time.Millisecond)
162	tailTest.RemoveFile("test.txt")
163	tailTest.Cleanup(tail, true)
164}
165
166func TestReOpenWithCursor(t *testing.T) {
167	delay := 300 * time.Millisecond // account for POLL_DURATION
168	tailTest := NewTailTest("reopen-cursor", t)
169	tailTest.CreateFile("test.txt", "hello\nworld\n")
170	tail := tailTest.StartTail(
171		"test.txt",
172		Config{Follow: true, ReOpen: true, Poll: true})
173	content := []string{"hello", "world", "more", "data", "endofworld"}
174	go tailTest.VerifyTailOutputUsingCursor(tail, content, false)
175
176	// deletion must trigger reopen
177	<-time.After(delay)
178	tailTest.RemoveFile("test.txt")
179	<-time.After(delay)
180	tailTest.CreateFile("test.txt", "hello\nworld\nmore\ndata\n")
181
182	// rename must trigger reopen
183	<-time.After(delay)
184	tailTest.RenameFile("test.txt", "test.txt.rotated")
185	<-time.After(delay)
186	tailTest.CreateFile("test.txt", "hello\nworld\nmore\ndata\nendofworld\n")
187
188	// Delete after a reasonable delay, to give tail sufficient time
189	// to read all lines.
190	<-time.After(delay)
191	tailTest.RemoveFile("test.txt")
192	<-time.After(delay)
193
194	// Do not bother with stopping as it could kill the tomb during
195	// the reading of data written above. Timings can vary based on
196	// test environment.
197	tailTest.Cleanup(tail, false)
198}
199
200func TestLocationFull(t *testing.T) {
201	tailTest := NewTailTest("location-full", t)
202	tailTest.CreateFile("test.txt", "hello\nworld\n")
203	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: nil})
204	go tailTest.VerifyTailOutput(tail, []string{"hello", "world"}, false)
205
206	// Delete after a reasonable delay, to give tail sufficient time
207	// to read all lines.
208	<-time.After(100 * time.Millisecond)
209	tailTest.RemoveFile("test.txt")
210	tailTest.Cleanup(tail, true)
211}
212
213func TestLocationFullDontFollow(t *testing.T) {
214	tailTest := NewTailTest("location-full-dontfollow", t)
215	tailTest.CreateFile("test.txt", "hello\nworld\n")
216	tail := tailTest.StartTail("test.txt", Config{Follow: false, Location: nil})
217	go tailTest.VerifyTailOutput(tail, []string{"hello", "world"}, false)
218
219	// Add more data only after reasonable delay.
220	<-time.After(100 * time.Millisecond)
221	tailTest.AppendFile("test.txt", "more\ndata\n")
222	<-time.After(100 * time.Millisecond)
223
224	tailTest.Cleanup(tail, true)
225}
226
227func TestLocationEnd(t *testing.T) {
228	tailTest := NewTailTest("location-end", t)
229	tailTest.CreateFile("test.txt", "hello\nworld\n")
230	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: &SeekInfo{0, io.SeekEnd}})
231	go tailTest.VerifyTailOutput(tail, []string{"more", "data"}, false)
232
233	<-time.After(100 * time.Millisecond)
234	tailTest.AppendFile("test.txt", "more\ndata\n")
235
236	// Delete after a reasonable delay, to give tail sufficient time
237	// to read all lines.
238	<-time.After(100 * time.Millisecond)
239	tailTest.RemoveFile("test.txt")
240	tailTest.Cleanup(tail, true)
241}
242
243func TestLocationMiddle(t *testing.T) {
244	// Test reading from middle.
245	tailTest := NewTailTest("location-middle", t)
246	tailTest.CreateFile("test.txt", "hello\nworld\n")
247	tail := tailTest.StartTail("test.txt", Config{Follow: true, Location: &SeekInfo{-6, io.SeekEnd}})
248	go tailTest.VerifyTailOutput(tail, []string{"world", "more", "data"}, false)
249
250	<-time.After(100 * time.Millisecond)
251	tailTest.AppendFile("test.txt", "more\ndata\n")
252
253	// Delete after a reasonable delay, to give tail sufficient time
254	// to read all lines.
255	<-time.After(100 * time.Millisecond)
256	tailTest.RemoveFile("test.txt")
257	tailTest.Cleanup(tail, true)
258}
259
260// The use of polling file watcher could affect file rotation
261// (detected via renames), so test these explicitly.
262
263func TestReOpenInotify(t *testing.T) {
264	reOpen(t, false)
265}
266
267func TestReOpenPolling(t *testing.T) {
268	reOpen(t, true)
269}
270
271// The use of polling file watcher could affect file rotation
272// (detected via renames), so test these explicitly.
273
274func TestReSeekInotify(t *testing.T) {
275	reSeek(t, false)
276}
277
278func TestReSeekPolling(t *testing.T) {
279	reSeek(t, true)
280}
281
282func TestReSeekWithCursor(t *testing.T) {
283	tailTest := NewTailTest("reseek-cursor", t)
284	tailTest.CreateFile("test.txt", "a really long string goes here\nhello\nworld\n")
285	tail := tailTest.StartTail(
286		"test.txt",
287		Config{Follow: true, ReOpen: false, Poll: false})
288
289	go tailTest.VerifyTailOutputUsingCursor(tail, []string{
290		"a really long string goes here", "hello", "world", "but", "not", "me"}, false)
291
292	// truncate now
293	<-time.After(100 * time.Millisecond)
294	tailTest.TruncateFile("test.txt", "skip\nme\nplease\nbut\nnot\nme\n")
295
296	// Delete after a reasonable delay, to give tail sufficient time
297	// to read all lines.
298	<-time.After(100 * time.Millisecond)
299	tailTest.RemoveFile("test.txt")
300
301	// Do not bother with stopping as it could kill the tomb during
302	// the reading of data written above. Timings can vary based on
303	// test environment.
304	tailTest.Cleanup(tail, false)
305}
306
307func TestRateLimiting(t *testing.T) {
308	tailTest := NewTailTest("rate-limiting", t)
309	tailTest.CreateFile("test.txt", "hello\nworld\nagain\nextra\n")
310	config := Config{
311		Follow:      true,
312		RateLimiter: ratelimiter.NewLeakyBucket(2, time.Second)}
313	leakybucketFull := "Too much log activity; waiting a second before resuming tailing"
314	tail := tailTest.StartTail("test.txt", config)
315
316	// TODO: also verify that tail resumes after the cooloff period.
317	go tailTest.VerifyTailOutput(tail, []string{
318		"hello", "world", "again",
319		leakybucketFull,
320		"more", "data",
321		leakybucketFull}, false)
322
323	// Add more data only after reasonable delay.
324	<-time.After(1200 * time.Millisecond)
325	tailTest.AppendFile("test.txt", "more\ndata\n")
326
327	// Delete after a reasonable delay, to give tail sufficient time
328	// to read all lines.
329	<-time.After(100 * time.Millisecond)
330	tailTest.RemoveFile("test.txt")
331
332	tailTest.Cleanup(tail, true)
333}
334
335func TestTell(t *testing.T) {
336	tailTest := NewTailTest("tell-position", t)
337	tailTest.CreateFile("test.txt", "hello\nworld\nagain\nmore\n")
338	config := Config{
339		Follow:   false,
340		Location: &SeekInfo{0, io.SeekStart}}
341	tail := tailTest.StartTail("test.txt", config)
342	// read one line
343	line := <-tail.Lines
344	if line.Num != 1 {
345		tailTest.Errorf("expected line to have number 1 but got %d", line.Num)
346	}
347	offset, err := tail.Tell()
348	if err != nil {
349		tailTest.Errorf("Tell return error: %s", err.Error())
350	}
351	tail.Stop()
352
353	config = Config{
354		Follow:   false,
355		Location: &SeekInfo{offset, io.SeekStart}}
356	tail = tailTest.StartTail("test.txt", config)
357	for l := range tail.Lines {
358		// it may readed one line in the chan(tail.Lines),
359		// so it may lost one line.
360		if l.Text != "world" && l.Text != "again" {
361			tailTest.Fatalf("mismatch; expected world or again, but got %s",
362				l.Text)
363			if l.Num < 1 || l.Num > 2 {
364				tailTest.Errorf("expected line number to be between 1 and 2 but got %d", l.Num)
365			}
366		}
367		break
368	}
369	tailTest.RemoveFile("test.txt")
370	tail.Stop()
371	tail.Cleanup()
372}
373
374func TestBlockUntilExists(t *testing.T) {
375	tailTest := NewTailTest("block-until-file-exists", t)
376	config := Config{
377		Follow: true,
378	}
379	tail := tailTest.StartTail("test.txt", config)
380	go func() {
381		time.Sleep(100 * time.Millisecond)
382		tailTest.CreateFile("test.txt", "hello world\n")
383	}()
384	for l := range tail.Lines {
385		if l.Text != "hello world" {
386			tailTest.Fatalf("mismatch; expected hello world, but got %s",
387				l.Text)
388		}
389		break
390	}
391	tailTest.RemoveFile("test.txt")
392	tail.Stop()
393	tail.Cleanup()
394}
395
396func maxLineSize(t *testing.T, follow bool, fileContent string, expected []string) {
397	tailTest := NewTailTest("maxlinesize", t)
398	tailTest.CreateFile("test.txt", fileContent)
399	tail := tailTest.StartTail("test.txt", Config{Follow: follow, Location: nil, MaxLineSize: 3})
400	go tailTest.VerifyTailOutput(tail, expected, false)
401
402	// Delete after a reasonable delay, to give tail sufficient time
403	// to read all lines.
404	<-time.After(100 * time.Millisecond)
405	tailTest.RemoveFile("test.txt")
406	tailTest.Cleanup(tail, true)
407}
408
409func reOpen(t *testing.T, poll bool) {
410	var name string
411	var delay time.Duration
412	if poll {
413		name = "reopen-polling"
414		delay = 300 * time.Millisecond // account for POLL_DURATION
415	} else {
416		name = "reopen-inotify"
417		delay = 100 * time.Millisecond
418	}
419	tailTest := NewTailTest(name, t)
420	tailTest.CreateFile("test.txt", "hello\nworld\n")
421	tail := tailTest.StartTail(
422		"test.txt",
423		Config{Follow: true, ReOpen: true, Poll: poll})
424	content := []string{"hello", "world", "more", "data", "endofworld"}
425	go tailTest.VerifyTailOutput(tail, content, false)
426
427	if poll {
428		// deletion must trigger reopen
429		<-time.After(delay)
430		tailTest.RemoveFile("test.txt")
431		<-time.After(delay)
432		tailTest.CreateFile("test.txt", "more\ndata\n")
433	} else {
434		// In inotify mode, fsnotify is currently unable to deliver notifications
435		// about deletion of open files, so we are not testing file deletion.
436		// (see https://github.com/fsnotify/fsnotify/issues/194 for details).
437		<-time.After(delay)
438		tailTest.AppendToFile("test.txt", "more\ndata\n")
439	}
440
441	// rename must trigger reopen
442	<-time.After(delay)
443	tailTest.RenameFile("test.txt", "test.txt.rotated")
444	<-time.After(delay)
445	tailTest.CreateFile("test.txt", "endofworld\n")
446
447	// Delete after a reasonable delay, to give tail sufficient time
448	// to read all lines.
449	<-time.After(delay)
450	tailTest.RemoveFile("test.txt")
451	<-time.After(delay)
452
453	// Do not bother with stopping as it could kill the tomb during
454	// the reading of data written above. Timings can vary based on
455	// test environment.
456	tailTest.Cleanup(tail, false)
457}
458
459func TestInotify_WaitForCreateThenMove(t *testing.T) {
460	tailTest := NewTailTest("wait-for-create-then-reopen", t)
461	os.Remove(tailTest.path + "/test.txt") // Make sure the file does NOT exist.
462
463	tail := tailTest.StartTail(
464		"test.txt",
465		Config{Follow: true, ReOpen: true, Poll: false})
466
467	content := []string{"hello", "world", "endofworld"}
468	go tailTest.VerifyTailOutput(tail, content, false)
469
470	time.Sleep(50 * time.Millisecond)
471	tailTest.CreateFile("test.txt", "hello\nworld\n")
472	time.Sleep(50 * time.Millisecond)
473	tailTest.RenameFile("test.txt", "test.txt.rotated")
474	time.Sleep(50 * time.Millisecond)
475	tailTest.CreateFile("test.txt", "endofworld\n")
476	time.Sleep(50 * time.Millisecond)
477	tailTest.RemoveFile("test.txt.rotated")
478	tailTest.RemoveFile("test.txt")
479
480	// Do not bother with stopping as it could kill the tomb during
481	// the reading of data written above. Timings can vary based on
482	// test environment.
483	tailTest.Cleanup(tail, false)
484}
485
486func reSeek(t *testing.T, poll bool) {
487	var name string
488	if poll {
489		name = "reseek-polling"
490	} else {
491		name = "reseek-inotify"
492	}
493	tailTest := NewTailTest(name, t)
494	tailTest.CreateFile("test.txt", "a really long string goes here\nhello\nworld\n")
495	tail := tailTest.StartTail(
496		"test.txt",
497		Config{Follow: true, ReOpen: false, Poll: poll})
498
499	go tailTest.VerifyTailOutput(tail, []string{
500		"a really long string goes here", "hello", "world", "h311o", "w0r1d", "endofworld"}, false)
501
502	// truncate now
503	<-time.After(100 * time.Millisecond)
504	tailTest.TruncateFile("test.txt", "h311o\nw0r1d\nendofworld\n")
505
506	// Delete after a reasonable delay, to give tail sufficient time
507	// to read all lines.
508	<-time.After(100 * time.Millisecond)
509	tailTest.RemoveFile("test.txt")
510
511	// Do not bother with stopping as it could kill the tomb during
512	// the reading of data written above. Timings can vary based on
513	// test environment.
514	tailTest.Cleanup(tail, false)
515}
516
517// Test library
518
519type TailTest struct {
520	Name string
521	path string
522	done chan struct{}
523	*testing.T
524}
525
526func NewTailTest(name string, t *testing.T) TailTest {
527	tt := TailTest{name, ".test/" + name, make(chan struct{}), t}
528	err := os.MkdirAll(tt.path, os.ModeTemporary|0700)
529	if err != nil {
530		tt.Fatal(err)
531	}
532
533	return tt
534}
535
536func (t TailTest) CreateFile(name string, contents string) {
537	err := ioutil.WriteFile(t.path+"/"+name, []byte(contents), 0600)
538	if err != nil {
539		t.Fatal(err)
540	}
541}
542
543func (t TailTest) AppendToFile(name string, contents string) {
544	err := ioutil.WriteFile(t.path+"/"+name, []byte(contents), 0600|os.ModeAppend)
545	if err != nil {
546		t.Fatal(err)
547	}
548}
549
550func (t TailTest) RemoveFile(name string) {
551	err := os.Remove(t.path + "/" + name)
552	if err != nil {
553		t.Fatal(err)
554	}
555}
556
557func (t TailTest) RenameFile(oldname string, newname string) {
558	oldname = t.path + "/" + oldname
559	newname = t.path + "/" + newname
560	err := os.Rename(oldname, newname)
561	if err != nil {
562		t.Fatal(err)
563	}
564}
565
566func (t TailTest) AppendFile(name string, contents string) {
567	f, err := os.OpenFile(t.path+"/"+name, os.O_APPEND|os.O_WRONLY, 0600)
568	if err != nil {
569		t.Fatal(err)
570	}
571	defer f.Close()
572	_, err = f.WriteString(contents)
573	if err != nil {
574		t.Fatal(err)
575	}
576}
577
578func (t TailTest) TruncateFile(name string, contents string) {
579	f, err := os.OpenFile(t.path+"/"+name, os.O_TRUNC|os.O_WRONLY, 0600)
580	if err != nil {
581		t.Fatal(err)
582	}
583	defer f.Close()
584	_, err = f.WriteString(contents)
585	if err != nil {
586		t.Fatal(err)
587	}
588}
589
590func (t TailTest) StartTail(name string, config Config) *Tail {
591	tail, err := TailFile(t.path+"/"+name, config)
592	if err != nil {
593		t.Fatal(err)
594	}
595	return tail
596}
597
598func (t TailTest) VerifyTailOutput(tail *Tail, lines []string, expectEOF bool) {
599	defer close(t.done)
600	t.ReadLines(tail, lines, false)
601	// It is important to do this if only EOF is expected
602	// otherwise we could block on <-tail.Lines
603	if expectEOF {
604		line, ok := <-tail.Lines
605		if ok {
606			t.Fatalf("more content from tail: %+v", line)
607		}
608	}
609}
610
611func (t TailTest) VerifyTailOutputUsingCursor(tail *Tail, lines []string, expectEOF bool) {
612	defer close(t.done)
613	t.ReadLines(tail, lines, true)
614	// It is important to do this if only EOF is expected
615	// otherwise we could block on <-tail.Lines
616	if expectEOF {
617		line, ok := <-tail.Lines
618		if ok {
619			t.Fatalf("more content from tail: %+v", line)
620		}
621	}
622}
623
624func (t TailTest) ReadLines(tail *Tail, lines []string, useCursor bool) {
625	cursor := 1
626
627	for _, line := range lines {
628		for {
629			tailedLine, ok := <-tail.Lines
630			if !ok {
631				// tail.Lines is closed and empty.
632				err := tail.Err()
633				if err != nil {
634					t.Fatalf("tail ended with error: %v", err)
635				}
636				t.Fatalf("tail ended early; expecting more: %v", lines[cursor:])
637			}
638			if tailedLine == nil {
639				t.Fatalf("tail.Lines returned nil; not possible")
640			}
641
642			if useCursor && tailedLine.Num < cursor {
643				// skip lines up until cursor
644				continue
645			}
646
647			// Note: not checking .Err as the `lines` argument is designed
648			// to match error strings as well.
649			if tailedLine.Text != line {
650				t.Fatalf(
651					"unexpected line/err from tail: "+
652						"expecting <<%s>>>, but got <<<%s>>>",
653					line, tailedLine.Text)
654			}
655
656			cursor++
657			break
658		}
659	}
660}
661
662func (t TailTest) Cleanup(tail *Tail, stop bool) {
663	<-t.done
664	if stop {
665		tail.Stop()
666	}
667	tail.Cleanup()
668}
669