github.com/docker/docker@v299999999.0.0-20200612211812-aaf470eca7b5+incompatible/daemon/logger/loggerutils/logfile_test.go (about) 1 package loggerutils 2 3 import ( 4 "bufio" 5 "context" 6 "io" 7 "io/ioutil" 8 "os" 9 "path/filepath" 10 "strings" 11 "testing" 12 "time" 13 14 "github.com/docker/docker/daemon/logger" 15 "github.com/docker/docker/pkg/pubsub" 16 "github.com/docker/docker/pkg/tailfile" 17 "gotest.tools/v3/assert" 18 "gotest.tools/v3/poll" 19 ) 20 21 type testDecoder struct { 22 rdr io.Reader 23 scanner *bufio.Scanner 24 } 25 26 func (d *testDecoder) Decode() (*logger.Message, error) { 27 if d.scanner == nil { 28 d.scanner = bufio.NewScanner(d.rdr) 29 } 30 if !d.scanner.Scan() { 31 return nil, d.scanner.Err() 32 } 33 // some comment 34 return &logger.Message{Line: d.scanner.Bytes(), Timestamp: time.Now()}, nil 35 } 36 37 func (d *testDecoder) Reset(rdr io.Reader) { 38 d.rdr = rdr 39 d.scanner = bufio.NewScanner(rdr) 40 } 41 42 func (d *testDecoder) Close() { 43 d.rdr = nil 44 d.scanner = nil 45 } 46 47 func TestTailFiles(t *testing.T) { 48 s1 := strings.NewReader("Hello.\nMy name is Inigo Montoya.\n") 49 s2 := strings.NewReader("I'm serious.\nDon't call me Shirley!\n") 50 s3 := strings.NewReader("Roads?\nWhere we're going we don't need roads.\n") 51 52 files := []SizeReaderAt{s1, s2, s3} 53 watcher := logger.NewLogWatcher() 54 55 tailReader := func(ctx context.Context, r SizeReaderAt, lines int) (io.Reader, int, error) { 56 return tailfile.NewTailReader(ctx, r, lines) 57 } 58 dec := &testDecoder{} 59 60 for desc, config := range map[string]logger.ReadConfig{} { 61 t.Run(desc, func(t *testing.T) { 62 started := make(chan struct{}) 63 go func() { 64 close(started) 65 tailFiles(files, watcher, dec, tailReader, config) 66 }() 67 <-started 68 }) 69 } 70 71 config := logger.ReadConfig{Tail: 2} 72 started := make(chan struct{}) 73 go func() { 74 close(started) 75 tailFiles(files, watcher, dec, tailReader, config) 76 }() 77 <-started 78 79 select { 80 case <-time.After(60 * time.Second): 81 t.Fatal("timeout waiting for tail line") 82 case err := <-watcher.Err: 83 assert.NilError(t, err) 84 case msg := <-watcher.Msg: 85 assert.Assert(t, msg != nil) 86 assert.Assert(t, string(msg.Line) == "Roads?", string(msg.Line)) 87 } 88 89 select { 90 case <-time.After(60 * time.Second): 91 t.Fatal("timeout waiting for tail line") 92 case err := <-watcher.Err: 93 assert.NilError(t, err) 94 case msg := <-watcher.Msg: 95 assert.Assert(t, msg != nil) 96 assert.Assert(t, string(msg.Line) == "Where we're going we don't need roads.", string(msg.Line)) 97 } 98 } 99 100 type dummyDecoder struct{} 101 102 func (dummyDecoder) Decode() (*logger.Message, error) { 103 return &logger.Message{}, nil 104 } 105 106 func (dummyDecoder) Close() {} 107 func (dummyDecoder) Reset(io.Reader) {} 108 109 func TestFollowLogsConsumerGone(t *testing.T) { 110 lw := logger.NewLogWatcher() 111 112 f, err := ioutil.TempFile("", t.Name()) 113 assert.NilError(t, err) 114 defer func() { 115 f.Close() 116 os.Remove(f.Name()) 117 }() 118 119 dec := dummyDecoder{} 120 121 followLogsDone := make(chan struct{}) 122 var since, until time.Time 123 go func() { 124 followLogs(f, lw, make(chan interface{}), dec, since, until) 125 close(followLogsDone) 126 }() 127 128 select { 129 case <-lw.Msg: 130 case err := <-lw.Err: 131 assert.NilError(t, err) 132 case <-followLogsDone: 133 t.Fatal("follow logs finished unexpectedly") 134 case <-time.After(10 * time.Second): 135 t.Fatal("timeout waiting for log message") 136 } 137 138 lw.ConsumerGone() 139 select { 140 case <-followLogsDone: 141 case <-time.After(20 * time.Second): 142 t.Fatal("timeout waiting for followLogs() to finish") 143 } 144 } 145 146 type dummyWrapper struct { 147 dummyDecoder 148 fn func() error 149 } 150 151 func (d *dummyWrapper) Decode() (*logger.Message, error) { 152 if err := d.fn(); err != nil { 153 return nil, err 154 } 155 return d.dummyDecoder.Decode() 156 } 157 158 func TestFollowLogsProducerGone(t *testing.T) { 159 lw := logger.NewLogWatcher() 160 161 f, err := ioutil.TempFile("", t.Name()) 162 assert.NilError(t, err) 163 defer os.Remove(f.Name()) 164 165 var sent, received, closed int 166 dec := &dummyWrapper{fn: func() error { 167 switch closed { 168 case 0: 169 sent++ 170 return nil 171 case 1: 172 closed++ 173 t.Logf("logDecode() closed after sending %d messages\n", sent) 174 return io.EOF 175 default: 176 t.Fatal("logDecode() called after closing!") 177 return io.EOF 178 } 179 }} 180 var since, until time.Time 181 182 followLogsDone := make(chan struct{}) 183 go func() { 184 followLogs(f, lw, make(chan interface{}), dec, since, until) 185 close(followLogsDone) 186 }() 187 188 // read 1 message 189 select { 190 case <-lw.Msg: 191 received++ 192 case err := <-lw.Err: 193 assert.NilError(t, err) 194 case <-followLogsDone: 195 t.Fatal("followLogs() finished unexpectedly") 196 case <-time.After(10 * time.Second): 197 t.Fatal("timeout waiting for log message") 198 } 199 200 // "stop" the "container" 201 closed = 1 202 lw.ProducerGone() 203 204 // should receive all the messages sent 205 readDone := make(chan struct{}) 206 go func() { 207 defer close(readDone) 208 for { 209 select { 210 case <-lw.Msg: 211 received++ 212 if received == sent { 213 return 214 } 215 case err := <-lw.Err: 216 assert.NilError(t, err) 217 } 218 } 219 }() 220 select { 221 case <-readDone: 222 case <-time.After(30 * time.Second): 223 t.Fatalf("timeout waiting for log messages to be read (sent: %d, received: %d", sent, received) 224 } 225 226 t.Logf("messages sent: %d, received: %d", sent, received) 227 228 // followLogs() should be done by now 229 select { 230 case <-followLogsDone: 231 case <-time.After(30 * time.Second): 232 t.Fatal("timeout waiting for followLogs() to finish") 233 } 234 235 select { 236 case <-lw.WatchConsumerGone(): 237 t.Fatal("consumer should not have exited") 238 default: 239 } 240 } 241 242 func TestCheckCapacityAndRotate(t *testing.T) { 243 dir, err := ioutil.TempDir("", t.Name()) 244 assert.NilError(t, err) 245 defer os.RemoveAll(dir) 246 247 f, err := ioutil.TempFile(dir, "log") 248 assert.NilError(t, err) 249 250 l := &LogFile{ 251 f: f, 252 capacity: 5, 253 maxFiles: 3, 254 compress: true, 255 notifyRotate: pubsub.NewPublisher(0, 1), 256 perms: 0600, 257 marshal: func(msg *logger.Message) ([]byte, error) { 258 return msg.Line, nil 259 }, 260 } 261 defer l.Close() 262 263 assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")})) 264 _, err = os.Stat(f.Name() + ".1") 265 assert.Assert(t, os.IsNotExist(err), dirStringer{dir}) 266 267 assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")})) 268 poll.WaitOn(t, checkFileExists(f.Name()+".1"), poll.WithTimeout(30*time.Second)) 269 270 assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")})) 271 poll.WaitOn(t, checkFileExists(f.Name()+".1"), poll.WithTimeout(30*time.Second)) 272 poll.WaitOn(t, checkFileExists(f.Name()+".2.gz"), poll.WithTimeout(30*time.Second)) 273 274 // Now let's simulate a failed rotation where the file was able to be closed but something else happened elsewhere 275 // down the line. 276 // We want to make sure that we can recover in the case that `l.f` was closed while attempting a rotation. 277 l.f.Close() 278 assert.NilError(t, l.WriteLogEntry(&logger.Message{Line: []byte("hello world!")})) 279 } 280 281 type dirStringer struct { 282 d string 283 } 284 285 func (d dirStringer) String() string { 286 ls, err := ioutil.ReadDir(d.d) 287 if err != nil { 288 return "" 289 } 290 var s strings.Builder 291 s.WriteString("\n") 292 293 for _, fi := range ls { 294 s.WriteString(fi.Name() + "\n") 295 } 296 return s.String() 297 } 298 299 func checkFileExists(name string) poll.Check { 300 return func(t poll.LogT) poll.Result { 301 _, err := os.Stat(name) 302 switch { 303 case err == nil: 304 return poll.Success() 305 case os.IsNotExist(err): 306 return poll.Continue("waiting for %s to exist", name) 307 default: 308 t.Logf("%s", dirStringer{filepath.Dir(name)}) 309 return poll.Error(err) 310 } 311 } 312 }