github.com/demonoid81/moby@v0.0.0-20200517203328-62dd8e17c460/daemon/logger/local/local_test.go (about) 1 package local 2 3 import ( 4 "bytes" 5 "context" 6 "encoding/binary" 7 "fmt" 8 "io" 9 "io/ioutil" 10 "os" 11 "path/filepath" 12 "strings" 13 "testing" 14 "time" 15 16 "github.com/demonoid81/moby/api/types/backend" 17 "github.com/demonoid81/moby/api/types/plugins/logdriver" 18 "github.com/demonoid81/moby/daemon/logger" 19 protoio "github.com/gogo/protobuf/io" 20 "gotest.tools/v3/assert" 21 is "gotest.tools/v3/assert/cmp" 22 ) 23 24 func TestWriteLog(t *testing.T) { 25 t.Parallel() 26 27 dir, err := ioutil.TempDir("", t.Name()) 28 assert.NilError(t, err) 29 defer os.RemoveAll(dir) 30 31 logPath := filepath.Join(dir, "test.log") 32 33 l, err := New(logger.Info{LogPath: logPath}) 34 assert.NilError(t, err) 35 defer l.Close() 36 37 m1 := logger.Message{Source: "stdout", Timestamp: time.Now().Add(-1 * 30 * time.Minute), Line: []byte("message 1")} 38 m2 := logger.Message{Source: "stdout", Timestamp: time.Now().Add(-1 * 20 * time.Minute), Line: []byte("message 2"), PLogMetaData: &backend.PartialLogMetaData{Last: true, ID: "0001", Ordinal: 1}} 39 m3 := logger.Message{Source: "stderr", Timestamp: time.Now().Add(-1 * 10 * time.Minute), Line: []byte("message 3")} 40 41 // copy the log message because the underying log writer resets the log message and returns it to a buffer pool 42 err = l.Log(copyLogMessage(&m1)) 43 assert.NilError(t, err) 44 err = l.Log(copyLogMessage(&m2)) 45 assert.NilError(t, err) 46 err = l.Log(copyLogMessage(&m3)) 47 assert.NilError(t, err) 48 49 f, err := os.Open(logPath) 50 assert.NilError(t, err) 51 defer f.Close() 52 dec := protoio.NewUint32DelimitedReader(f, binary.BigEndian, 1e6) 53 54 var ( 55 proto logdriver.LogEntry 56 testProto logdriver.LogEntry 57 partial logdriver.PartialLogEntryMetadata 58 ) 59 60 lenBuf := make([]byte, encodeBinaryLen) 61 seekMsgLen := func() { 62 io.ReadFull(f, lenBuf) 63 } 64 65 err = dec.ReadMsg(&proto) 66 assert.NilError(t, err) 67 messageToProto(&m1, &testProto, &partial) 68 assert.Check(t, is.DeepEqual(testProto, proto), "expected:\n%+v\ngot:\n%+v", testProto, proto) 69 seekMsgLen() 70 71 err = dec.ReadMsg(&proto) 72 assert.NilError(t, err) 73 messageToProto(&m2, &testProto, &partial) 74 assert.Check(t, is.DeepEqual(testProto, proto)) 75 seekMsgLen() 76 77 err = dec.ReadMsg(&proto) 78 assert.NilError(t, err) 79 messageToProto(&m3, &testProto, &partial) 80 assert.Check(t, is.DeepEqual(testProto, proto), "expected:\n%+v\ngot:\n%+v", testProto, proto) 81 } 82 83 func TestReadLog(t *testing.T) { 84 t.Parallel() 85 86 dir, err := ioutil.TempDir("", t.Name()) 87 assert.NilError(t, err) 88 defer os.RemoveAll(dir) 89 90 logPath := filepath.Join(dir, "test.log") 91 l, err := New(logger.Info{LogPath: logPath}) 92 assert.NilError(t, err) 93 defer l.Close() 94 95 m1 := logger.Message{Source: "stdout", Timestamp: time.Now().Add(-1 * 30 * time.Minute), Line: []byte("a message")} 96 m2 := logger.Message{Source: "stdout", Timestamp: time.Now().Add(-1 * 20 * time.Minute), Line: []byte("another message"), PLogMetaData: &backend.PartialLogMetaData{Ordinal: 1, Last: true}} 97 longMessage := []byte("a really long message " + strings.Repeat("a", initialBufSize*2)) 98 m3 := logger.Message{Source: "stderr", Timestamp: time.Now().Add(-1 * 10 * time.Minute), Line: longMessage} 99 m4 := logger.Message{Source: "stderr", Timestamp: time.Now().Add(-1 * 10 * time.Minute), Line: []byte("just one more message")} 100 101 // copy the log message because the underlying log writer resets the log message and returns it to a buffer pool 102 err = l.Log(copyLogMessage(&m1)) 103 assert.NilError(t, err) 104 err = l.Log(copyLogMessage(&m2)) 105 assert.NilError(t, err) 106 err = l.Log(copyLogMessage(&m3)) 107 assert.NilError(t, err) 108 err = l.Log(copyLogMessage(&m4)) 109 assert.NilError(t, err) 110 111 lr := l.(logger.LogReader) 112 113 testMessage := func(t *testing.T, lw *logger.LogWatcher, m *logger.Message) { 114 t.Helper() 115 ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) 116 defer cancel() 117 select { 118 case <-ctx.Done(): 119 assert.Assert(t, ctx.Err()) 120 case err := <-lw.Err: 121 assert.NilError(t, err) 122 case msg, open := <-lw.Msg: 123 if !open { 124 select { 125 case err := <-lw.Err: 126 assert.NilError(t, err) 127 default: 128 assert.Assert(t, m == nil) 129 return 130 } 131 } 132 assert.Assert(t, m != nil) 133 if m.PLogMetaData == nil { 134 // a `\n` is appended on read to make this work with the existing API's when the message is not a partial. 135 // make sure it's the last entry in the line, and then truncate it for the deep equal below. 136 assert.Check(t, msg.Line[len(msg.Line)-1] == '\n') 137 msg.Line = msg.Line[:len(msg.Line)-1] 138 } 139 assert.Check(t, is.DeepEqual(m, msg), fmt.Sprintf("\n%+v\n%+v", m, msg)) 140 } 141 } 142 143 t.Run("tail exact", func(t *testing.T) { 144 lw := lr.ReadLogs(logger.ReadConfig{Tail: 4}) 145 146 testMessage(t, lw, &m1) 147 testMessage(t, lw, &m2) 148 testMessage(t, lw, &m3) 149 testMessage(t, lw, &m4) 150 testMessage(t, lw, nil) // no more messages 151 }) 152 153 t.Run("tail less than available", func(t *testing.T) { 154 lw := lr.ReadLogs(logger.ReadConfig{Tail: 2}) 155 156 testMessage(t, lw, &m3) 157 testMessage(t, lw, &m4) 158 testMessage(t, lw, nil) // no more messages 159 }) 160 161 t.Run("tail more than available", func(t *testing.T) { 162 lw := lr.ReadLogs(logger.ReadConfig{Tail: 100}) 163 164 testMessage(t, lw, &m1) 165 testMessage(t, lw, &m2) 166 testMessage(t, lw, &m3) 167 testMessage(t, lw, &m4) 168 testMessage(t, lw, nil) // no more messages 169 }) 170 } 171 172 func BenchmarkLogWrite(b *testing.B) { 173 f, err := ioutil.TempFile("", b.Name()) 174 assert.Assert(b, err) 175 defer os.Remove(f.Name()) 176 f.Close() 177 178 local, err := New(logger.Info{LogPath: f.Name()}) 179 assert.Assert(b, err) 180 defer local.Close() 181 182 t := time.Now().UTC() 183 for _, data := range [][]byte{ 184 []byte(""), 185 []byte("a short string"), 186 bytes.Repeat([]byte("a long string"), 100), 187 bytes.Repeat([]byte("a really long string"), 10000), 188 } { 189 b.Run(fmt.Sprintf("%d", len(data)), func(b *testing.B) { 190 entry := &logdriver.LogEntry{Line: data, Source: "stdout", TimeNano: t.UnixNano()} 191 b.SetBytes(int64(entry.Size() + encodeBinaryLen + encodeBinaryLen)) 192 b.ResetTimer() 193 for i := 0; i < b.N; i++ { 194 msg := logger.NewMessage() 195 msg.Line = data 196 msg.Timestamp = t 197 msg.Source = "stdout" 198 if err := local.Log(msg); err != nil { 199 b.Fatal(err) 200 } 201 } 202 }) 203 } 204 } 205 206 func copyLogMessage(src *logger.Message) *logger.Message { 207 dst := logger.NewMessage() 208 dst.Source = src.Source 209 dst.Timestamp = src.Timestamp 210 dst.Attrs = src.Attrs 211 dst.Err = src.Err 212 dst.Line = append(dst.Line, src.Line...) 213 if src.PLogMetaData != nil { 214 dst.PLogMetaData = &(*src.PLogMetaData) 215 } 216 return dst 217 }