gopkg.in/dotcloud/docker.v1@v1.13.1/daemon/logger/copier_test.go (about)

     1  package logger
     2  
     3  import (
     4  	"bytes"
     5  	"encoding/json"
     6  	"fmt"
     7  	"io"
     8  	"os"
     9  	"strings"
    10  	"sync"
    11  	"testing"
    12  	"time"
    13  )
    14  
    15  type TestLoggerJSON struct {
    16  	*json.Encoder
    17  	mu    sync.Mutex
    18  	delay time.Duration
    19  }
    20  
    21  func (l *TestLoggerJSON) Log(m *Message) error {
    22  	if l.delay > 0 {
    23  		time.Sleep(l.delay)
    24  	}
    25  	l.mu.Lock()
    26  	defer l.mu.Unlock()
    27  	return l.Encode(m)
    28  }
    29  
    30  func (l *TestLoggerJSON) Close() error { return nil }
    31  
    32  func (l *TestLoggerJSON) Name() string { return "json" }
    33  
    34  func TestCopier(t *testing.T) {
    35  	stdoutLine := "Line that thinks that it is log line from docker stdout"
    36  	stderrLine := "Line that thinks that it is log line from docker stderr"
    37  	stdoutTrailingLine := "stdout trailing line"
    38  	stderrTrailingLine := "stderr trailing line"
    39  
    40  	var stdout bytes.Buffer
    41  	var stderr bytes.Buffer
    42  	for i := 0; i < 30; i++ {
    43  		if _, err := stdout.WriteString(stdoutLine + "\n"); err != nil {
    44  			t.Fatal(err)
    45  		}
    46  		if _, err := stderr.WriteString(stderrLine + "\n"); err != nil {
    47  			t.Fatal(err)
    48  		}
    49  	}
    50  
    51  	// Test remaining lines without line-endings
    52  	if _, err := stdout.WriteString(stdoutTrailingLine); err != nil {
    53  		t.Fatal(err)
    54  	}
    55  	if _, err := stderr.WriteString(stderrTrailingLine); err != nil {
    56  		t.Fatal(err)
    57  	}
    58  
    59  	var jsonBuf bytes.Buffer
    60  
    61  	jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)}
    62  
    63  	c := NewCopier(
    64  		map[string]io.Reader{
    65  			"stdout": &stdout,
    66  			"stderr": &stderr,
    67  		},
    68  		jsonLog)
    69  	c.Run()
    70  	wait := make(chan struct{})
    71  	go func() {
    72  		c.Wait()
    73  		close(wait)
    74  	}()
    75  	select {
    76  	case <-time.After(1 * time.Second):
    77  		t.Fatal("Copier failed to do its work in 1 second")
    78  	case <-wait:
    79  	}
    80  	dec := json.NewDecoder(&jsonBuf)
    81  	for {
    82  		var msg Message
    83  		if err := dec.Decode(&msg); err != nil {
    84  			if err == io.EOF {
    85  				break
    86  			}
    87  			t.Fatal(err)
    88  		}
    89  		if msg.Source != "stdout" && msg.Source != "stderr" {
    90  			t.Fatalf("Wrong Source: %q, should be %q or %q", msg.Source, "stdout", "stderr")
    91  		}
    92  		if msg.Source == "stdout" {
    93  			if string(msg.Line) != stdoutLine && string(msg.Line) != stdoutTrailingLine {
    94  				t.Fatalf("Wrong Line: %q, expected %q or %q", msg.Line, stdoutLine, stdoutTrailingLine)
    95  			}
    96  		}
    97  		if msg.Source == "stderr" {
    98  			if string(msg.Line) != stderrLine && string(msg.Line) != stderrTrailingLine {
    99  				t.Fatalf("Wrong Line: %q, expected %q or %q", msg.Line, stderrLine, stderrTrailingLine)
   100  			}
   101  		}
   102  	}
   103  }
   104  
   105  // TestCopierLongLines tests long lines without line breaks
   106  func TestCopierLongLines(t *testing.T) {
   107  	// Long lines (should be split at "bufSize")
   108  	const bufSize = 16 * 1024
   109  	stdoutLongLine := strings.Repeat("a", bufSize)
   110  	stderrLongLine := strings.Repeat("b", bufSize)
   111  	stdoutTrailingLine := "stdout trailing line"
   112  	stderrTrailingLine := "stderr trailing line"
   113  
   114  	var stdout bytes.Buffer
   115  	var stderr bytes.Buffer
   116  
   117  	for i := 0; i < 3; i++ {
   118  		if _, err := stdout.WriteString(stdoutLongLine); err != nil {
   119  			t.Fatal(err)
   120  		}
   121  		if _, err := stderr.WriteString(stderrLongLine); err != nil {
   122  			t.Fatal(err)
   123  		}
   124  	}
   125  
   126  	if _, err := stdout.WriteString(stdoutTrailingLine); err != nil {
   127  		t.Fatal(err)
   128  	}
   129  	if _, err := stderr.WriteString(stderrTrailingLine); err != nil {
   130  		t.Fatal(err)
   131  	}
   132  
   133  	var jsonBuf bytes.Buffer
   134  
   135  	jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf)}
   136  
   137  	c := NewCopier(
   138  		map[string]io.Reader{
   139  			"stdout": &stdout,
   140  			"stderr": &stderr,
   141  		},
   142  		jsonLog)
   143  	c.Run()
   144  	wait := make(chan struct{})
   145  	go func() {
   146  		c.Wait()
   147  		close(wait)
   148  	}()
   149  	select {
   150  	case <-time.After(1 * time.Second):
   151  		t.Fatal("Copier failed to do its work in 1 second")
   152  	case <-wait:
   153  	}
   154  	dec := json.NewDecoder(&jsonBuf)
   155  	for {
   156  		var msg Message
   157  		if err := dec.Decode(&msg); err != nil {
   158  			if err == io.EOF {
   159  				break
   160  			}
   161  			t.Fatal(err)
   162  		}
   163  		if msg.Source != "stdout" && msg.Source != "stderr" {
   164  			t.Fatalf("Wrong Source: %q, should be %q or %q", msg.Source, "stdout", "stderr")
   165  		}
   166  		if msg.Source == "stdout" {
   167  			if string(msg.Line) != stdoutLongLine && string(msg.Line) != stdoutTrailingLine {
   168  				t.Fatalf("Wrong Line: %q, expected 'stdoutLongLine' or 'stdoutTrailingLine'", msg.Line)
   169  			}
   170  		}
   171  		if msg.Source == "stderr" {
   172  			if string(msg.Line) != stderrLongLine && string(msg.Line) != stderrTrailingLine {
   173  				t.Fatalf("Wrong Line: %q, expected 'stderrLongLine' or 'stderrTrailingLine'", msg.Line)
   174  			}
   175  		}
   176  	}
   177  }
   178  
   179  func TestCopierSlow(t *testing.T) {
   180  	stdoutLine := "Line that thinks that it is log line from docker stdout"
   181  	var stdout bytes.Buffer
   182  	for i := 0; i < 30; i++ {
   183  		if _, err := stdout.WriteString(stdoutLine + "\n"); err != nil {
   184  			t.Fatal(err)
   185  		}
   186  	}
   187  
   188  	var jsonBuf bytes.Buffer
   189  	//encoder := &encodeCloser{Encoder: json.NewEncoder(&jsonBuf)}
   190  	jsonLog := &TestLoggerJSON{Encoder: json.NewEncoder(&jsonBuf), delay: 100 * time.Millisecond}
   191  
   192  	c := NewCopier(map[string]io.Reader{"stdout": &stdout}, jsonLog)
   193  	c.Run()
   194  	wait := make(chan struct{})
   195  	go func() {
   196  		c.Wait()
   197  		close(wait)
   198  	}()
   199  	<-time.After(150 * time.Millisecond)
   200  	c.Close()
   201  	select {
   202  	case <-time.After(200 * time.Millisecond):
   203  		t.Fatalf("failed to exit in time after the copier is closed")
   204  	case <-wait:
   205  	}
   206  }
   207  
   208  type BenchmarkLoggerDummy struct {
   209  }
   210  
   211  func (l *BenchmarkLoggerDummy) Log(m *Message) error { return nil }
   212  
   213  func (l *BenchmarkLoggerDummy) Close() error { return nil }
   214  
   215  func (l *BenchmarkLoggerDummy) Name() string { return "dummy" }
   216  
   217  func BenchmarkCopier64(b *testing.B) {
   218  	benchmarkCopier(b, 1<<6)
   219  }
   220  func BenchmarkCopier128(b *testing.B) {
   221  	benchmarkCopier(b, 1<<7)
   222  }
   223  func BenchmarkCopier256(b *testing.B) {
   224  	benchmarkCopier(b, 1<<8)
   225  }
   226  func BenchmarkCopier512(b *testing.B) {
   227  	benchmarkCopier(b, 1<<9)
   228  }
   229  func BenchmarkCopier1K(b *testing.B) {
   230  	benchmarkCopier(b, 1<<10)
   231  }
   232  func BenchmarkCopier2K(b *testing.B) {
   233  	benchmarkCopier(b, 1<<11)
   234  }
   235  func BenchmarkCopier4K(b *testing.B) {
   236  	benchmarkCopier(b, 1<<12)
   237  }
   238  func BenchmarkCopier8K(b *testing.B) {
   239  	benchmarkCopier(b, 1<<13)
   240  }
   241  func BenchmarkCopier16K(b *testing.B) {
   242  	benchmarkCopier(b, 1<<14)
   243  }
   244  func BenchmarkCopier32K(b *testing.B) {
   245  	benchmarkCopier(b, 1<<15)
   246  }
   247  func BenchmarkCopier64K(b *testing.B) {
   248  	benchmarkCopier(b, 1<<16)
   249  }
   250  func BenchmarkCopier128K(b *testing.B) {
   251  	benchmarkCopier(b, 1<<17)
   252  }
   253  func BenchmarkCopier256K(b *testing.B) {
   254  	benchmarkCopier(b, 1<<18)
   255  }
   256  
   257  func piped(b *testing.B, iterations int, delay time.Duration, buf []byte) io.Reader {
   258  	r, w, err := os.Pipe()
   259  	if err != nil {
   260  		b.Fatal(err)
   261  		return nil
   262  	}
   263  	go func() {
   264  		for i := 0; i < iterations; i++ {
   265  			time.Sleep(delay)
   266  			if n, err := w.Write(buf); err != nil || n != len(buf) {
   267  				if err != nil {
   268  					b.Fatal(err)
   269  				}
   270  				b.Fatal(fmt.Errorf("short write"))
   271  			}
   272  		}
   273  		w.Close()
   274  	}()
   275  	return r
   276  }
   277  
   278  func benchmarkCopier(b *testing.B, length int) {
   279  	b.StopTimer()
   280  	buf := []byte{'A'}
   281  	for len(buf) < length {
   282  		buf = append(buf, buf...)
   283  	}
   284  	buf = append(buf[:length-1], []byte{'\n'}...)
   285  	b.StartTimer()
   286  	for i := 0; i < b.N; i++ {
   287  		c := NewCopier(
   288  			map[string]io.Reader{
   289  				"buffer": piped(b, 10, time.Nanosecond, buf),
   290  			},
   291  			&BenchmarkLoggerDummy{})
   292  		c.Run()
   293  		c.Wait()
   294  		c.Close()
   295  	}
   296  }