Source file src/k8s.io/kubernetes/pkg/kubelet/kuberuntime/logs/logs_test.go

Documentation: k8s.io/kubernetes/pkg/kubelet/kuberuntime/logs

     1  /*
     2  Copyright 2017 The Kubernetes Authors.
     3  
     4  Licensed under the Apache License, Version 2.0 (the "License");
     5  you may not use this file except in compliance with the License.
     6  You may obtain a copy of the License at
     7  
     8      http://www.apache.org/licenses/LICENSE-2.0
     9  
    10  Unless required by applicable law or agreed to in writing, software
    11  distributed under the License is distributed on an "AS IS" BASIS,
    12  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13  See the License for the specific language governing permissions and
    14  limitations under the License.
    15  */
    16  
    17  package logs
    18  
    19  import (
    20  	"bufio"
    21  	"bytes"
    22  	"context"
    23  	"fmt"
    24  	"io"
    25  	"os"
    26  	"path/filepath"
    27  	"testing"
    28  	"time"
    29  
    30  	utiltesting "k8s.io/client-go/util/testing"
    31  
    32  	v1 "k8s.io/api/core/v1"
    33  	apitesting "k8s.io/cri-api/pkg/apis/testing"
    34  	"k8s.io/kubernetes/pkg/kubelet/types"
    35  	"k8s.io/utils/pointer"
    36  
    37  	"github.com/stretchr/testify/assert"
    38  
    39  	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
    40  	runtimeapi "k8s.io/cri-api/pkg/apis/runtime/v1"
    41  )
    42  
    43  func TestLogOptions(t *testing.T) {
    44  	var (
    45  		line         = int64(8)
    46  		bytes        = int64(64)
    47  		timestamp    = metav1.Now()
    48  		sinceseconds = int64(10)
    49  	)
    50  	for c, test := range []struct {
    51  		apiOpts *v1.PodLogOptions
    52  		expect  *LogOptions
    53  	}{
    54  		{ // empty options
    55  			apiOpts: &v1.PodLogOptions{},
    56  			expect:  &LogOptions{tail: -1, bytes: -1},
    57  		},
    58  		{ // test tail lines
    59  			apiOpts: &v1.PodLogOptions{TailLines: &line},
    60  			expect:  &LogOptions{tail: line, bytes: -1},
    61  		},
    62  		{ // test limit bytes
    63  			apiOpts: &v1.PodLogOptions{LimitBytes: &bytes},
    64  			expect:  &LogOptions{tail: -1, bytes: bytes},
    65  		},
    66  		{ // test since timestamp
    67  			apiOpts: &v1.PodLogOptions{SinceTime: &timestamp},
    68  			expect:  &LogOptions{tail: -1, bytes: -1, since: timestamp.Time},
    69  		},
    70  		{ // test since seconds
    71  			apiOpts: &v1.PodLogOptions{SinceSeconds: &sinceseconds},
    72  			expect:  &LogOptions{tail: -1, bytes: -1, since: timestamp.Add(-10 * time.Second)},
    73  		},
    74  	} {
    75  		t.Logf("TestCase #%d: %+v", c, test)
    76  		opts := NewLogOptions(test.apiOpts, timestamp.Time)
    77  		assert.Equal(t, test.expect, opts)
    78  	}
    79  }
    80  
    81  func TestReadLogs(t *testing.T) {
    82  	file, err := os.CreateTemp("", "TestFollowLogs")
    83  	if err != nil {
    84  		t.Fatalf("unable to create temp file")
    85  	}
    86  	defer utiltesting.CloseAndRemove(t, file)
    87  	file.WriteString(`{"log":"line1\n","stream":"stdout","time":"2020-09-27T11:18:01.00000000Z"}` + "\n")
    88  	file.WriteString(`{"log":"line2\n","stream":"stdout","time":"2020-09-27T11:18:02.00000000Z"}` + "\n")
    89  	file.WriteString(`{"log":"line3\n","stream":"stdout","time":"2020-09-27T11:18:03.00000000Z"}` + "\n")
    90  
    91  	testCases := []struct {
    92  		name          string
    93  		podLogOptions v1.PodLogOptions
    94  		expected      string
    95  	}{
    96  		{
    97  			name:          "default pod log options should output all lines",
    98  			podLogOptions: v1.PodLogOptions{},
    99  			expected:      "line1\nline2\nline3\n",
   100  		},
   101  		{
   102  			name: "using TailLines 2 should output last 2 lines",
   103  			podLogOptions: v1.PodLogOptions{
   104  				TailLines: pointer.Int64(2),
   105  			},
   106  			expected: "line2\nline3\n",
   107  		},
   108  		{
   109  			name: "using TailLines 4 should output all lines when the log has less than 4 lines",
   110  			podLogOptions: v1.PodLogOptions{
   111  				TailLines: pointer.Int64(4),
   112  			},
   113  			expected: "line1\nline2\nline3\n",
   114  		},
   115  		{
   116  			name: "using TailLines 0 should output nothing",
   117  			podLogOptions: v1.PodLogOptions{
   118  				TailLines: pointer.Int64(0),
   119  			},
   120  			expected: "",
   121  		},
   122  		{
   123  			name: "using LimitBytes 9 should output first 9 bytes",
   124  			podLogOptions: v1.PodLogOptions{
   125  				LimitBytes: pointer.Int64(9),
   126  			},
   127  			expected: "line1\nlin",
   128  		},
   129  		{
   130  			name: "using LimitBytes 100 should output all bytes when the log has less than 100 bytes",
   131  			podLogOptions: v1.PodLogOptions{
   132  				LimitBytes: pointer.Int64(100),
   133  			},
   134  			expected: "line1\nline2\nline3\n",
   135  		},
   136  		{
   137  			name: "using LimitBytes 0 should output nothing",
   138  			podLogOptions: v1.PodLogOptions{
   139  				LimitBytes: pointer.Int64(0),
   140  			},
   141  			expected: "",
   142  		},
   143  		{
   144  			name: "using SinceTime should output lines with a time on or after the specified time",
   145  			podLogOptions: v1.PodLogOptions{
   146  				SinceTime: &metav1.Time{Time: time.Date(2020, time.Month(9), 27, 11, 18, 02, 0, time.UTC)},
   147  			},
   148  			expected: "line2\nline3\n",
   149  		},
   150  		{
   151  			name: "using SinceTime now should output nothing",
   152  			podLogOptions: v1.PodLogOptions{
   153  				SinceTime: &metav1.Time{Time: time.Now()},
   154  			},
   155  			expected: "",
   156  		},
   157  		{
   158  			name: "using follow should output all log lines",
   159  			podLogOptions: v1.PodLogOptions{
   160  				Follow: true,
   161  			},
   162  			expected: "line1\nline2\nline3\n",
   163  		},
   164  		{
   165  			name: "using follow combined with TailLines 2 should output the last 2 lines",
   166  			podLogOptions: v1.PodLogOptions{
   167  				Follow:    true,
   168  				TailLines: pointer.Int64(2),
   169  			},
   170  			expected: "line2\nline3\n",
   171  		},
   172  		{
   173  			name: "using follow combined with SinceTime should output lines with a time on or after the specified time",
   174  			podLogOptions: v1.PodLogOptions{
   175  				Follow:    true,
   176  				SinceTime: &metav1.Time{Time: time.Date(2020, time.Month(9), 27, 11, 18, 02, 0, time.UTC)},
   177  			},
   178  			expected: "line2\nline3\n",
   179  		},
   180  	}
   181  	for _, tc := range testCases {
   182  		t.Run(tc.name, func(t *testing.T) {
   183  			containerID := "fake-container-id"
   184  			fakeRuntimeService := &apitesting.FakeRuntimeService{
   185  				Containers: map[string]*apitesting.FakeContainer{
   186  					containerID: {
   187  						ContainerStatus: runtimeapi.ContainerStatus{
   188  							State: runtimeapi.ContainerState_CONTAINER_RUNNING,
   189  						},
   190  					},
   191  				},
   192  			}
   193  			// If follow is specified, mark the container as exited or else ReadLogs will run indefinitely
   194  			if tc.podLogOptions.Follow {
   195  				fakeRuntimeService.Containers[containerID].State = runtimeapi.ContainerState_CONTAINER_EXITED
   196  			}
   197  
   198  			opts := NewLogOptions(&tc.podLogOptions, time.Now())
   199  			stdoutBuf := bytes.NewBuffer(nil)
   200  			stderrBuf := bytes.NewBuffer(nil)
   201  			err = ReadLogs(context.TODO(), file.Name(), containerID, opts, fakeRuntimeService, stdoutBuf, stderrBuf)
   202  
   203  			if err != nil {
   204  				t.Fatalf(err.Error())
   205  			}
   206  			if stderrBuf.Len() > 0 {
   207  				t.Fatalf("Stderr: %v", stderrBuf.String())
   208  			}
   209  			if actual := stdoutBuf.String(); tc.expected != actual {
   210  				t.Fatalf("Actual output does not match expected.\nActual:  %v\nExpected: %v\n", actual, tc.expected)
   211  			}
   212  		})
   213  	}
   214  }
   215  
   216  func TestReadRotatedLog(t *testing.T) {
   217  	tmpDir := t.TempDir()
   218  	file, err := os.CreateTemp(tmpDir, "logfile")
   219  	if err != nil {
   220  		assert.NoErrorf(t, err, "unable to create temp file")
   221  	}
   222  	stdoutBuf := &bytes.Buffer{}
   223  	stderrBuf := &bytes.Buffer{}
   224  	containerID := "fake-container-id"
   225  	fakeRuntimeService := &apitesting.FakeRuntimeService{
   226  		Containers: map[string]*apitesting.FakeContainer{
   227  			containerID: {
   228  				ContainerStatus: runtimeapi.ContainerStatus{
   229  					State: runtimeapi.ContainerState_CONTAINER_RUNNING,
   230  				},
   231  			},
   232  		},
   233  	}
   234  	ctx, cancel := context.WithCancel(context.Background())
   235  	defer cancel()
   236  	// Start to follow the container's log.
   237  	fileName := file.Name()
   238  	go func(ctx context.Context) {
   239  		podLogOptions := v1.PodLogOptions{
   240  			Follow: true,
   241  		}
   242  		opts := NewLogOptions(&podLogOptions, time.Now())
   243  		_ = ReadLogs(ctx, fileName, containerID, opts, fakeRuntimeService, stdoutBuf, stderrBuf)
   244  	}(ctx)
   245  
   246  	// log in stdout
   247  	expectedStdout := "line0\nline2\nline4\nline6\nline8\n"
   248  	// log in stderr
   249  	expectedStderr := "line1\nline3\nline5\nline7\nline9\n"
   250  
   251  	dir := filepath.Dir(file.Name())
   252  	baseName := filepath.Base(file.Name())
   253  
   254  	// Write 10 lines to log file.
   255  	// Let ReadLogs start.
   256  	time.Sleep(50 * time.Millisecond)
   257  
   258  	for line := 0; line < 10; line++ {
   259  		// Write the first three lines to log file
   260  		now := time.Now().Format(types.RFC3339NanoLenient)
   261  		if line%2 == 0 {
   262  			file.WriteString(fmt.Sprintf(
   263  				`{"log":"line%d\n","stream":"stdout","time":"%s"}`+"\n", line, now))
   264  		} else {
   265  			file.WriteString(fmt.Sprintf(
   266  				`{"log":"line%d\n","stream":"stderr","time":"%s"}`+"\n", line, now))
   267  		}
   268  		time.Sleep(1 * time.Millisecond)
   269  
   270  		if line == 5 {
   271  			file.Close()
   272  			// Pretend to rotate the log.
   273  			rotatedName := fmt.Sprintf("%s.%s", baseName, time.Now().Format("220060102-150405"))
   274  			rotatedName = filepath.Join(dir, rotatedName)
   275  			if err := os.Rename(filepath.Join(dir, baseName), rotatedName); err != nil {
   276  				assert.NoErrorf(t, err, "failed to rotate log %q to %q", file.Name(), rotatedName)
   277  				return
   278  			}
   279  
   280  			newF := filepath.Join(dir, baseName)
   281  			if file, err = os.Create(newF); err != nil {
   282  				assert.NoError(t, err, "unable to create new log file")
   283  				return
   284  			}
   285  			time.Sleep(20 * time.Millisecond)
   286  		}
   287  	}
   288  
   289  	time.Sleep(20 * time.Millisecond)
   290  	// Make the function ReadLogs end.
   291  	fakeRuntimeService.Lock()
   292  	fakeRuntimeService.Containers[containerID].State = runtimeapi.ContainerState_CONTAINER_EXITED
   293  	fakeRuntimeService.Unlock()
   294  
   295  	assert.Equal(t, expectedStdout, stdoutBuf.String())
   296  	assert.Equal(t, expectedStderr, stderrBuf.String())
   297  }
   298  
   299  func TestParseLog(t *testing.T) {
   300  	timestamp, err := time.Parse(timeFormatIn, "2016-10-20T18:39:20.57606443Z")
   301  	assert.NoError(t, err)
   302  	msg := &logMessage{}
   303  	for c, test := range []struct {
   304  		line string
   305  		msg  *logMessage
   306  		err  bool
   307  	}{
   308  		{ // Docker log format stdout
   309  			line: `{"log":"docker stdout test log","stream":"stdout","time":"2016-10-20T18:39:20.57606443Z"}` + "\n",
   310  			msg: &logMessage{
   311  				timestamp: timestamp,
   312  				stream:    runtimeapi.Stdout,
   313  				log:       []byte("docker stdout test log"),
   314  			},
   315  		},
   316  		{ // Docker log format stderr
   317  			line: `{"log":"docker stderr test log","stream":"stderr","time":"2016-10-20T18:39:20.57606443Z"}` + "\n",
   318  			msg: &logMessage{
   319  				timestamp: timestamp,
   320  				stream:    runtimeapi.Stderr,
   321  				log:       []byte("docker stderr test log"),
   322  			},
   323  		},
   324  		{ // CRI log format stdout
   325  			line: "2016-10-20T18:39:20.57606443Z stdout F cri stdout test log\n",
   326  			msg: &logMessage{
   327  				timestamp: timestamp,
   328  				stream:    runtimeapi.Stdout,
   329  				log:       []byte("cri stdout test log\n"),
   330  			},
   331  		},
   332  		{ // CRI log format stderr
   333  			line: "2016-10-20T18:39:20.57606443Z stderr F cri stderr test log\n",
   334  			msg: &logMessage{
   335  				timestamp: timestamp,
   336  				stream:    runtimeapi.Stderr,
   337  				log:       []byte("cri stderr test log\n"),
   338  			},
   339  		},
   340  		{ // Unsupported Log format
   341  			line: "unsupported log format test log\n",
   342  			msg:  &logMessage{},
   343  			err:  true,
   344  		},
   345  		{ // Partial CRI log line
   346  			line: "2016-10-20T18:39:20.57606443Z stdout P cri stdout partial test log\n",
   347  			msg: &logMessage{
   348  				timestamp: timestamp,
   349  				stream:    runtimeapi.Stdout,
   350  				log:       []byte("cri stdout partial test log"),
   351  			},
   352  		},
   353  		{ // Partial CRI log line with multiple log tags.
   354  			line: "2016-10-20T18:39:20.57606443Z stdout P:TAG1:TAG2 cri stdout partial test log\n",
   355  			msg: &logMessage{
   356  				timestamp: timestamp,
   357  				stream:    runtimeapi.Stdout,
   358  				log:       []byte("cri stdout partial test log"),
   359  			},
   360  		},
   361  	} {
   362  		t.Logf("TestCase #%d: %+v", c, test)
   363  		parse, err := getParseFunc([]byte(test.line))
   364  		if test.err {
   365  			assert.Error(t, err)
   366  			continue
   367  		}
   368  		assert.NoError(t, err)
   369  		err = parse([]byte(test.line), msg)
   370  		assert.NoError(t, err)
   371  		assert.Equal(t, test.msg, msg)
   372  	}
   373  }
   374  
   375  func TestWriteLogs(t *testing.T) {
   376  	timestamp := time.Unix(1234, 43210)
   377  	log := "abcdefg\n"
   378  
   379  	for c, test := range []struct {
   380  		stream       runtimeapi.LogStreamType
   381  		since        time.Time
   382  		timestamp    bool
   383  		expectStdout string
   384  		expectStderr string
   385  	}{
   386  		{ // stderr log
   387  			stream:       runtimeapi.Stderr,
   388  			expectStderr: log,
   389  		},
   390  		{ // stdout log
   391  			stream:       runtimeapi.Stdout,
   392  			expectStdout: log,
   393  		},
   394  		{ // since is after timestamp
   395  			stream: runtimeapi.Stdout,
   396  			since:  timestamp.Add(1 * time.Second),
   397  		},
   398  		{ // timestamp enabled
   399  			stream:       runtimeapi.Stderr,
   400  			timestamp:    true,
   401  			expectStderr: timestamp.Format(timeFormatOut) + " " + log,
   402  		},
   403  	} {
   404  		t.Logf("TestCase #%d: %+v", c, test)
   405  		msg := &logMessage{
   406  			timestamp: timestamp,
   407  			stream:    test.stream,
   408  			log:       []byte(log),
   409  		}
   410  		stdoutBuf := bytes.NewBuffer(nil)
   411  		stderrBuf := bytes.NewBuffer(nil)
   412  		w := newLogWriter(stdoutBuf, stderrBuf, &LogOptions{since: test.since, timestamp: test.timestamp, bytes: -1})
   413  		err := w.write(msg, true)
   414  		assert.NoError(t, err)
   415  		assert.Equal(t, test.expectStdout, stdoutBuf.String())
   416  		assert.Equal(t, test.expectStderr, stderrBuf.String())
   417  	}
   418  }
   419  
   420  func TestWriteLogsWithBytesLimit(t *testing.T) {
   421  	timestamp := time.Unix(1234, 4321)
   422  	timestampStr := timestamp.Format(timeFormatOut)
   423  	log := "abcdefg\n"
   424  
   425  	for c, test := range []struct {
   426  		stdoutLines  int
   427  		stderrLines  int
   428  		bytes        int
   429  		timestamp    bool
   430  		expectStdout string
   431  		expectStderr string
   432  	}{
   433  		{ // limit bytes less than one line
   434  			stdoutLines:  3,
   435  			bytes:        3,
   436  			expectStdout: "abc",
   437  		},
   438  		{ // limit bytes across lines
   439  			stdoutLines:  3,
   440  			bytes:        len(log) + 3,
   441  			expectStdout: "abcdefg\nabc",
   442  		},
   443  		{ // limit bytes more than all lines
   444  			stdoutLines:  3,
   445  			bytes:        3 * len(log),
   446  			expectStdout: "abcdefg\nabcdefg\nabcdefg\n",
   447  		},
   448  		{ // limit bytes for stderr
   449  			stderrLines:  3,
   450  			bytes:        len(log) + 3,
   451  			expectStderr: "abcdefg\nabc",
   452  		},
   453  		{ // limit bytes for both stdout and stderr, stdout first.
   454  			stdoutLines:  1,
   455  			stderrLines:  2,
   456  			bytes:        len(log) + 3,
   457  			expectStdout: "abcdefg\n",
   458  			expectStderr: "abc",
   459  		},
   460  		{ // limit bytes with timestamp
   461  			stdoutLines:  3,
   462  			timestamp:    true,
   463  			bytes:        len(timestampStr) + 1 + len(log) + 2,
   464  			expectStdout: timestampStr + " " + log + timestampStr[:2],
   465  		},
   466  	} {
   467  		t.Logf("TestCase #%d: %+v", c, test)
   468  		msg := &logMessage{
   469  			timestamp: timestamp,
   470  			log:       []byte(log),
   471  		}
   472  		stdoutBuf := bytes.NewBuffer(nil)
   473  		stderrBuf := bytes.NewBuffer(nil)
   474  		w := newLogWriter(stdoutBuf, stderrBuf, &LogOptions{timestamp: test.timestamp, bytes: int64(test.bytes)})
   475  		for i := 0; i < test.stdoutLines; i++ {
   476  			msg.stream = runtimeapi.Stdout
   477  			if err := w.write(msg, true); err != nil {
   478  				assert.EqualError(t, err, errMaximumWrite.Error())
   479  			}
   480  		}
   481  		for i := 0; i < test.stderrLines; i++ {
   482  			msg.stream = runtimeapi.Stderr
   483  			if err := w.write(msg, true); err != nil {
   484  				assert.EqualError(t, err, errMaximumWrite.Error())
   485  			}
   486  		}
   487  		assert.Equal(t, test.expectStdout, stdoutBuf.String())
   488  		assert.Equal(t, test.expectStderr, stderrBuf.String())
   489  	}
   490  }
   491  
   492  func TestReadLogsLimitsWithTimestamps(t *testing.T) {
   493  	logLineFmt := "2022-10-29T16:10:22.592603036-05:00 stdout P %v\n"
   494  	logLineNewLine := "2022-10-29T16:10:22.592603036-05:00 stdout F \n"
   495  
   496  	tmpfile, err := os.CreateTemp("", "log.*.txt")
   497  	assert.NoError(t, err)
   498  
   499  	count := 10000
   500  
   501  	for i := 0; i < count; i++ {
   502  		tmpfile.WriteString(fmt.Sprintf(logLineFmt, i))
   503  	}
   504  	tmpfile.WriteString(logLineNewLine)
   505  
   506  	for i := 0; i < count; i++ {
   507  		tmpfile.WriteString(fmt.Sprintf(logLineFmt, i))
   508  	}
   509  	tmpfile.WriteString(logLineNewLine)
   510  
   511  	// two lines are in the buffer
   512  
   513  	defer os.Remove(tmpfile.Name()) // clean up
   514  
   515  	assert.NoError(t, err)
   516  	tmpfile.Close()
   517  
   518  	var buf bytes.Buffer
   519  	w := io.MultiWriter(&buf)
   520  
   521  	err = ReadLogs(context.Background(), tmpfile.Name(), "", &LogOptions{tail: -1, bytes: -1, timestamp: true}, nil, w, w)
   522  	assert.NoError(t, err)
   523  
   524  	lineCount := 0
   525  	scanner := bufio.NewScanner(bytes.NewReader(buf.Bytes()))
   526  	for scanner.Scan() {
   527  		lineCount++
   528  
   529  		// Split the line
   530  		ts, logline, _ := bytes.Cut(scanner.Bytes(), []byte(" "))
   531  
   532  		// Verification
   533  		//   1. The timestamp should exist
   534  		//   2. The last item in the log should be 9999
   535  		_, err = time.Parse(time.RFC3339, string(ts))
   536  		assert.NoError(t, err, "timestamp not found")
   537  		assert.Equal(t, true, bytes.HasSuffix(logline, []byte("9999")), "is the complete log found")
   538  	}
   539  
   540  	assert.Equal(t, 2, lineCount, "should have two lines")
   541  }
   542  

View as plain text