Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: output log even log is rotated #3200

Merged
merged 2 commits into from
Aug 5, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ require (
github.com/fahedouch/go-logrotate v0.2.1
github.com/fatih/color v1.17.0
github.com/fluent/fluent-logger-golang v1.9.0
github.com/fsnotify/fsnotify v1.7.0
github.com/ipfs/go-cid v0.4.1
github.com/klauspost/compress v1.17.9
github.com/mattn/go-isatty v0.0.20
Expand Down
2 changes: 2 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -111,6 +111,8 @@ github.com/felixge/httpsnoop v1.0.4 h1:NFTV2Zj1bL4mc9sqWACXbQFVBBg2W3GPvqp8/ESS2
github.com/felixge/httpsnoop v1.0.4/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U=
github.com/fluent/fluent-logger-golang v1.9.0 h1:zUdY44CHX2oIUc7VTNZc+4m+ORuO/mldQDA7czhWXEg=
github.com/fluent/fluent-logger-golang v1.9.0/go.mod h1:2/HCT/jTy78yGyeNGQLGQsjF3zzzAuy6Xlk6FCMV5eU=
github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA=
github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM=
github.com/go-jose/go-jose/v4 v4.0.3 h1:o8aphO8Hv6RPmH+GfzVuyf7YXSBibp+8YyHdOoDESGo=
github.com/go-jose/go-jose/v4 v4.0.3/go.mod h1:NKb5HO1EZccyMpiZNbdUw/14tiXNyUJh188dfnMCAfc=
github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
Expand Down
51 changes: 49 additions & 2 deletions pkg/logging/cri_logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ package logging
import (
"bufio"
"bytes"
"context"
"errors"
"fmt"
"io"
Expand All @@ -35,6 +36,7 @@ import (

"github.com/containerd/log"
"github.com/containerd/nerdctl/v2/pkg/logging/tail"
"github.com/fsnotify/fsnotify"
)

// LogStreamType is the type of the stream in CRI container log.
Expand All @@ -45,6 +47,9 @@ const (
Stdout LogStreamType = "stdout"
// Stderr is the stream type for stderr.
Stderr LogStreamType = "stderr"

// logForceCheckPeriod is the period to check for a new read
logForceCheckPeriod = 1 * time.Second
)

// LogTag is the tag of a log line in CRI container log.
Expand Down Expand Up @@ -89,7 +94,9 @@ func ReadLogs(opts *LogViewOptions, stdout, stderr io.Writer, stopChannel chan o
if err != nil {
return fmt.Errorf("failed to open log file %q: %v", logPath, err)
}
defer f.Close()
defer func() {
f.Close()
}()

// Search start point based on tail line.
start, err := tail.FindTailLineStartIndex(f, opts.Tail)
Expand All @@ -101,6 +108,8 @@ func ReadLogs(opts *LogViewOptions, stdout, stderr io.Writer, stopChannel chan o
return fmt.Errorf("failed to seek in log file %q: %v", logPath, err)
}

var watcher *fsnotify.Watcher

limitedMode := (opts.Tail > 0) && (!opts.Follow)
limitedNum := opts.Tail
// Start parsing the logs.
Expand All @@ -110,6 +119,9 @@ func ReadLogs(opts *LogViewOptions, stdout, stderr io.Writer, stopChannel chan o
isNewLine := true
writer := newLogWriter(stdout, stderr, opts)
msg := &logMessage{}
baseName := filepath.Base(logPath)
dir := filepath.Dir(logPath)

for {
select {
case <-stopChannel:
Expand All @@ -126,13 +138,48 @@ func ReadLogs(opts *LogViewOptions, stdout, stderr io.Writer, stopChannel chan o
return fmt.Errorf("failed to read log file %q: %v", logPath, err)
}
if opts.Follow {

// Reset seek so that if this is an incomplete line,
// it will be read again.
if _, err := f.Seek(-int64(len(l)), io.SeekCurrent); err != nil {
return fmt.Errorf("failed to reset seek in log file %q: %v", logPath, err)
}

if watcher == nil {
// Initialize the watcher if it has not been initialized yet.
if watcher, err = NewLogFileWatcher(dir); err != nil {
return err
}
defer watcher.Close()
// If we just created the watcher, try again to read as we might have missed
// the event.
continue
}

var recreated bool
// Wait until the next log change.
recreated, err = startTail(context.Background(), baseName, watcher)
if err != nil {
return err
}
if recreated {
newF, err := openFileShareDelete(logPath)
if err != nil {
if errors.Is(err, os.ErrNotExist) {
//If the user application outputs logs too quickly,
//There is a slight possibility that nerdctl has just rotated the log file,
//try opening it once more.
time.Sleep(10 * time.Millisecond)
}
newF, err = openFileShareDelete(logPath)
if err != nil {
return fmt.Errorf("failed to open cri logfile %q: %w", logPath, err)
}
}
f.Close()
f = newF
r = bufio.NewReader(f)
}

// If the container exited consume data until the next EOF
continue
}
Expand Down
83 changes: 83 additions & 0 deletions pkg/logging/cri_logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ import (
"fmt"
"io"
"os"
"path/filepath"
"reflect"
"testing"
"time"
Expand Down Expand Up @@ -230,3 +231,85 @@ func TestReadLogsLimitsWithTimestamps(t *testing.T) {
t.Errorf("should have two lines, lineCount= %d", lineCount)
}
}

func TestReadRotatedLog(t *testing.T) {
tmpDir := t.TempDir()
file, err := os.CreateTemp(tmpDir, "logfile")
if err != nil {
t.Errorf("unable to create temp file, error: %s", err.Error())
}
stdoutBuf := &bytes.Buffer{}
stderrBuf := &bytes.Buffer{}
containerStoped := make(chan os.Signal)
// Start to follow the container's log.
fileName := file.Name()
go func() {
lvOpts := &LogViewOptions{
Follow: true,
LogPath: fileName,
}
_ = ReadLogs(lvOpts, stdoutBuf, stderrBuf, containerStoped)
}()

// log in stdout
expectedStdout := "line0line2line4line6line8"
// log in stderr
expectedStderr := "line1line3line5line7line9"

dir := filepath.Dir(file.Name())
baseName := filepath.Base(file.Name())

// Write 10 lines to log file.
// Let ReadLogs start.
time.Sleep(50 * time.Millisecond)

for line := 0; line < 10; line++ {
// Write the first three lines to log file
now := time.Now().Format(time.RFC3339Nano)
if line%2 == 0 {
file.WriteString(fmt.Sprintf(
"%s stdout P line%d\n", now, line))
} else {
file.WriteString(fmt.Sprintf(
"%s stderr P line%d\n", now, line))
}

time.Sleep(1 * time.Millisecond)

if line == 5 {
file.Close()
// Pretend to rotate the log.
rotatedName := fmt.Sprintf("%s.%s", baseName, time.Now().Format("220060102-150405"))
rotatedName = filepath.Join(dir, rotatedName)
if err := os.Rename(filepath.Join(dir, baseName), rotatedName); err != nil {
t.Errorf("failed to rotate log %q to %q, error: %s", file.Name(), rotatedName, err.Error())
return
}

time.Sleep(20 * time.Millisecond)
newF := filepath.Join(dir, baseName)
if file, err = os.Create(newF); err != nil {
t.Errorf("unable to create new log file, error: %s", err.Error())
return
}
}
}

// Finished writing into the file, close it, so we can delete it later.
err = file.Close()
if err != nil {
t.Errorf("could not close file, error: %s", err.Error())
}

time.Sleep(2 * time.Second)
// Make the function ReadLogs end.
close(containerStoped)

if expectedStdout != stdoutBuf.String() {
t.Errorf("expected: %s, acoutal: %s", expectedStdout, stdoutBuf.String())
}

if expectedStderr != stderrBuf.String() {
t.Errorf("expected: %s, acoutal: %s", expectedStderr, stderrBuf.String())
}
}
Loading