github.com/openshift/moby-moby@v1.13.2-0.20170601211448-f5ec1e2936dc/daemon/logger/jsonfilelog/read.go (about) 1 package jsonfilelog 2 3 import ( 4 "bytes" 5 "encoding/json" 6 "errors" 7 "fmt" 8 "io" 9 "os" 10 "time" 11 12 "github.com/fsnotify/fsnotify" 13 "golang.org/x/net/context" 14 15 "github.com/Sirupsen/logrus" 16 "github.com/docker/docker/daemon/logger" 17 "github.com/docker/docker/pkg/filenotify" 18 "github.com/docker/docker/pkg/ioutils" 19 "github.com/docker/docker/pkg/jsonlog" 20 "github.com/docker/docker/pkg/tailfile" 21 ) 22 23 const maxJSONDecodeRetry = 20000 24 25 func decodeLogLine(dec *json.Decoder, l *jsonlog.JSONLog) (*logger.Message, error) { 26 l.Reset() 27 if err := dec.Decode(l); err != nil { 28 return nil, err 29 } 30 msg := &logger.Message{ 31 Source: l.Stream, 32 Timestamp: l.Created, 33 Line: []byte(l.Log), 34 Attrs: l.Attrs, 35 } 36 return msg, nil 37 } 38 39 // ReadLogs implements the logger's LogReader interface for the logs 40 // created by this driver. 41 func (l *JSONFileLogger) ReadLogs(config logger.ReadConfig) *logger.LogWatcher { 42 logWatcher := logger.NewLogWatcher() 43 44 go l.readLogs(logWatcher, config) 45 return logWatcher 46 } 47 48 func (l *JSONFileLogger) readLogs(logWatcher *logger.LogWatcher, config logger.ReadConfig) { 49 defer close(logWatcher.Msg) 50 51 // lock so the read stream doesn't get corrupted due to rotations or other log data written while we read 52 // This will block writes!!! 53 l.mu.Lock() 54 55 pth := l.writer.LogPath() 56 var files []io.ReadSeeker 57 for i := l.writer.MaxFiles(); i > 1; i-- { 58 f, err := os.Open(fmt.Sprintf("%s.%d", pth, i-1)) 59 if err != nil { 60 if !os.IsNotExist(err) { 61 logWatcher.Err <- err 62 break 63 } 64 continue 65 } 66 defer f.Close() 67 68 files = append(files, f) 69 } 70 71 latestFile, err := os.Open(pth) 72 if err != nil { 73 logWatcher.Err <- err 74 l.mu.Unlock() 75 return 76 } 77 defer latestFile.Close() 78 79 if config.Tail != 0 { 80 tailer := ioutils.MultiReadSeeker(append(files, latestFile)...) 81 tailFile(tailer, logWatcher, config.Tail, config.Since) 82 } 83 84 // close all the rotated files 85 for _, f := range files { 86 if err := f.(io.Closer).Close(); err != nil { 87 logrus.WithField("logger", "json-file").Warnf("error closing tailed log file: %v", err) 88 } 89 } 90 91 if !config.Follow { 92 if err := latestFile.Close(); err != nil { 93 logrus.Errorf("Error closing file: %v", err) 94 } 95 l.mu.Unlock() 96 return 97 } 98 99 if config.Tail >= 0 { 100 latestFile.Seek(0, os.SEEK_END) 101 } 102 103 l.readers[logWatcher] = struct{}{} 104 l.mu.Unlock() 105 106 notifyRotate := l.writer.NotifyRotate() 107 followLogs(latestFile, logWatcher, notifyRotate, config.Since) 108 109 l.mu.Lock() 110 delete(l.readers, logWatcher) 111 l.mu.Unlock() 112 113 l.writer.NotifyRotateEvict(notifyRotate) 114 } 115 116 func tailFile(f io.ReadSeeker, logWatcher *logger.LogWatcher, tail int, since time.Time) { 117 var rdr io.Reader 118 rdr = f 119 if tail > 0 { 120 ls, err := tailfile.TailFile(f, tail) 121 if err != nil { 122 logWatcher.Err <- err 123 return 124 } 125 rdr = bytes.NewBuffer(bytes.Join(ls, []byte("\n"))) 126 } 127 dec := json.NewDecoder(rdr) 128 l := &jsonlog.JSONLog{} 129 for { 130 msg, err := decodeLogLine(dec, l) 131 if err != nil { 132 if err != io.EOF { 133 logWatcher.Err <- err 134 } 135 return 136 } 137 if !since.IsZero() && msg.Timestamp.Before(since) { 138 continue 139 } 140 select { 141 case <-logWatcher.WatchClose(): 142 return 143 case logWatcher.Msg <- msg: 144 } 145 } 146 } 147 148 func watchFile(name string) (filenotify.FileWatcher, error) { 149 fileWatcher, err := filenotify.New() 150 if err != nil { 151 return nil, err 152 } 153 154 if err := fileWatcher.Add(name); err != nil { 155 logrus.WithField("logger", "json-file").Warnf("falling back to file poller due to error: %v", err) 156 fileWatcher.Close() 157 fileWatcher = filenotify.NewPollingWatcher() 158 159 if err := fileWatcher.Add(name); err != nil { 160 fileWatcher.Close() 161 logrus.Debugf("error watching log file for modifications: %v", err) 162 return nil, err 163 } 164 } 165 return fileWatcher, nil 166 } 167 168 func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate chan interface{}, since time.Time) { 169 dec := json.NewDecoder(f) 170 l := &jsonlog.JSONLog{} 171 172 name := f.Name() 173 fileWatcher, err := watchFile(name) 174 if err != nil { 175 logWatcher.Err <- err 176 return 177 } 178 defer func() { 179 f.Close() 180 fileWatcher.Remove(name) 181 fileWatcher.Close() 182 }() 183 184 ctx, cancel := context.WithCancel(context.Background()) 185 defer cancel() 186 go func() { 187 select { 188 case <-logWatcher.WatchClose(): 189 fileWatcher.Remove(name) 190 cancel() 191 case <-ctx.Done(): 192 return 193 } 194 }() 195 196 var retries int 197 handleRotate := func() error { 198 f.Close() 199 fileWatcher.Remove(name) 200 201 // retry when the file doesn't exist 202 for retries := 0; retries <= 5; retries++ { 203 f, err = os.Open(name) 204 if err == nil || !os.IsNotExist(err) { 205 break 206 } 207 } 208 if err != nil { 209 return err 210 } 211 if err := fileWatcher.Add(name); err != nil { 212 return err 213 } 214 dec = json.NewDecoder(f) 215 return nil 216 } 217 218 errRetry := errors.New("retry") 219 errDone := errors.New("done") 220 waitRead := func() error { 221 select { 222 case e := <-fileWatcher.Events(): 223 switch e.Op { 224 case fsnotify.Write: 225 dec = json.NewDecoder(f) 226 return nil 227 case fsnotify.Rename, fsnotify.Remove: 228 select { 229 case <-notifyRotate: 230 case <-ctx.Done(): 231 return errDone 232 } 233 if err := handleRotate(); err != nil { 234 return err 235 } 236 return nil 237 } 238 return errRetry 239 case err := <-fileWatcher.Errors(): 240 logrus.Debug("logger got error watching file: %v", err) 241 // Something happened, let's try and stay alive and create a new watcher 242 if retries <= 5 { 243 fileWatcher.Close() 244 fileWatcher, err = watchFile(name) 245 if err != nil { 246 return err 247 } 248 retries++ 249 return errRetry 250 } 251 return err 252 case <-ctx.Done(): 253 return errDone 254 } 255 } 256 257 handleDecodeErr := func(err error) error { 258 if err == io.EOF { 259 for { 260 err := waitRead() 261 if err == nil { 262 break 263 } 264 if err == errRetry { 265 continue 266 } 267 return err 268 } 269 return nil 270 } 271 // try again because this shouldn't happen 272 if _, ok := err.(*json.SyntaxError); ok && retries <= maxJSONDecodeRetry { 273 dec = json.NewDecoder(f) 274 retries++ 275 return nil 276 } 277 // io.ErrUnexpectedEOF is returned from json.Decoder when there is 278 // remaining data in the parser's buffer while an io.EOF occurs. 279 // If the json logger writes a partial json log entry to the disk 280 // while at the same time the decoder tries to decode it, the race condition happens. 281 if err == io.ErrUnexpectedEOF && retries <= maxJSONDecodeRetry { 282 reader := io.MultiReader(dec.Buffered(), f) 283 dec = json.NewDecoder(reader) 284 retries++ 285 return nil 286 } 287 return err 288 } 289 290 // main loop 291 for { 292 msg, err := decodeLogLine(dec, l) 293 if err != nil { 294 if err := handleDecodeErr(err); err != nil { 295 if err == errDone { 296 return 297 } 298 // we got an unrecoverable error, so return 299 logWatcher.Err <- err 300 return 301 } 302 // ready to try again 303 continue 304 } 305 306 retries = 0 // reset retries since we've succeeded 307 if !since.IsZero() && msg.Timestamp.Before(since) { 308 continue 309 } 310 select { 311 case logWatcher.Msg <- msg: 312 case <-ctx.Done(): 313 logWatcher.Msg <- msg 314 for { 315 msg, err := decodeLogLine(dec, l) 316 if err != nil { 317 return 318 } 319 if !since.IsZero() && msg.Timestamp.Before(since) { 320 continue 321 } 322 logWatcher.Msg <- msg 323 } 324 } 325 } 326 }