github.com/docker/docker@v299999999.0.0-20200612211812-aaf470eca7b5+incompatible/daemon/logger/journald/read.go (about) 1 // +build linux,cgo,!static_build,journald 2 3 package journald // import "github.com/docker/docker/daemon/logger/journald" 4 5 // #include <sys/types.h> 6 // #include <sys/poll.h> 7 // #include <systemd/sd-journal.h> 8 // #include <errno.h> 9 // #include <stdio.h> 10 // #include <stdlib.h> 11 // #include <string.h> 12 // #include <time.h> 13 // #include <unistd.h> 14 // 15 //static int get_message(sd_journal *j, const char **msg, size_t *length, int *partial) 16 //{ 17 // int rc; 18 // size_t plength; 19 // *msg = NULL; 20 // *length = 0; 21 // plength = strlen("CONTAINER_PARTIAL_MESSAGE=true"); 22 // rc = sd_journal_get_data(j, "CONTAINER_PARTIAL_MESSAGE", (const void **) msg, length); 23 // *partial = ((rc == 0) && (*length == plength) && (memcmp(*msg, "CONTAINER_PARTIAL_MESSAGE=true", plength) == 0)); 24 // rc = sd_journal_get_data(j, "MESSAGE", (const void **) msg, length); 25 // if (rc == 0) { 26 // if (*length > 8) { 27 // (*msg) += 8; 28 // *length -= 8; 29 // } else { 30 // *msg = NULL; 31 // *length = 0; 32 // rc = -ENOENT; 33 // } 34 // } 35 // return rc; 36 //} 37 //static int get_priority(sd_journal *j, int *priority) 38 //{ 39 // const void *data; 40 // size_t i, length; 41 // int rc; 42 // *priority = -1; 43 // rc = sd_journal_get_data(j, "PRIORITY", &data, &length); 44 // if (rc == 0) { 45 // if ((length > 9) && (strncmp(data, "PRIORITY=", 9) == 0)) { 46 // *priority = 0; 47 // for (i = 9; i < length; i++) { 48 // *priority = *priority * 10 + ((const char *)data)[i] - '0'; 49 // } 50 // if (length > 9) { 51 // rc = 0; 52 // } 53 // } 54 // } 55 // return rc; 56 //} 57 //static int is_attribute_field(const char *msg, size_t length) 58 //{ 59 // static const struct known_field { 60 // const char *name; 61 // size_t length; 62 // } fields[] = { 63 // {"MESSAGE", sizeof("MESSAGE") - 1}, 64 // {"MESSAGE_ID", sizeof("MESSAGE_ID") - 1}, 65 // {"PRIORITY", sizeof("PRIORITY") - 1}, 66 // {"CODE_FILE", sizeof("CODE_FILE") - 1}, 67 // {"CODE_LINE", sizeof("CODE_LINE") - 1}, 68 // {"CODE_FUNC", sizeof("CODE_FUNC") - 1}, 69 // {"ERRNO", sizeof("ERRNO") - 1}, 70 // {"SYSLOG_FACILITY", sizeof("SYSLOG_FACILITY") - 1}, 71 // {"SYSLOG_IDENTIFIER", sizeof("SYSLOG_IDENTIFIER") - 1}, 72 // {"SYSLOG_PID", sizeof("SYSLOG_PID") - 1}, 73 // {"CONTAINER_NAME", sizeof("CONTAINER_NAME") - 1}, 74 // {"CONTAINER_ID", sizeof("CONTAINER_ID") - 1}, 75 // {"CONTAINER_ID_FULL", sizeof("CONTAINER_ID_FULL") - 1}, 76 // {"CONTAINER_TAG", sizeof("CONTAINER_TAG") - 1}, 77 // }; 78 // unsigned int i; 79 // void *p; 80 // if ((length < 1) || (msg[0] == '_') || ((p = memchr(msg, '=', length)) == NULL)) { 81 // return -1; 82 // } 83 // length = ((const char *) p) - msg; 84 // for (i = 0; i < sizeof(fields) / sizeof(fields[0]); i++) { 85 // if ((fields[i].length == length) && (memcmp(fields[i].name, msg, length) == 0)) { 86 // return -1; 87 // } 88 // } 89 // return 0; 90 //} 91 //static int get_attribute_field(sd_journal *j, const char **msg, size_t *length) 92 //{ 93 // int rc; 94 // *msg = NULL; 95 // *length = 0; 96 // while ((rc = sd_journal_enumerate_data(j, (const void **) msg, length)) > 0) { 97 // if (is_attribute_field(*msg, *length) == 0) { 98 // break; 99 // } 100 // rc = -ENOENT; 101 // } 102 // return rc; 103 //} 104 import "C" 105 106 import ( 107 "errors" 108 "strings" 109 "time" 110 "unsafe" 111 112 "github.com/coreos/go-systemd/v22/journal" 113 "github.com/docker/docker/api/types/backend" 114 "github.com/docker/docker/daemon/logger" 115 "github.com/sirupsen/logrus" 116 ) 117 118 func (s *journald) Close() error { 119 s.mu.Lock() 120 for r := range s.readers { 121 r.ProducerGone() 122 delete(s.readers, r) 123 } 124 s.mu.Unlock() 125 return nil 126 } 127 128 // convert error code returned from a sd_journal_* function 129 // (which returns -errno) to a string 130 func CErr(ret C.int) string { 131 return C.GoString(C.strerror(C.int(-ret))) 132 } 133 134 func (s *journald) drainJournal(logWatcher *logger.LogWatcher, j *C.sd_journal, oldCursor *C.char, untilUnixMicro uint64) (*C.char, bool, int) { 135 var ( 136 msg, data, cursor *C.char 137 length C.size_t 138 stamp C.uint64_t 139 priority, partial C.int 140 done bool 141 shown int 142 ) 143 144 // Walk the journal from here forward until we run out of new entries 145 // or we reach the until value (if provided). 146 drain: 147 for { 148 // Try not to send a given entry twice. 149 if oldCursor != nil { 150 for C.sd_journal_test_cursor(j, oldCursor) > 0 { 151 if C.sd_journal_next(j) <= 0 { 152 break drain 153 } 154 } 155 } 156 // Read and send the logged message, if there is one to read. 157 i := C.get_message(j, &msg, &length, &partial) 158 if i != -C.ENOENT && i != -C.EADDRNOTAVAIL { 159 // Read the entry's timestamp. 160 if C.sd_journal_get_realtime_usec(j, &stamp) != 0 { 161 break 162 } 163 // Break if the timestamp exceeds any provided until flag. 164 if untilUnixMicro != 0 && untilUnixMicro < uint64(stamp) { 165 done = true 166 break 167 } 168 169 // Set up the time and text of the entry. 170 timestamp := time.Unix(int64(stamp)/1000000, (int64(stamp)%1000000)*1000) 171 line := C.GoBytes(unsafe.Pointer(msg), C.int(length)) 172 if partial == 0 { 173 line = append(line, "\n"...) 174 } 175 // Recover the stream name by mapping 176 // from the journal priority back to 177 // the stream that we would have 178 // assigned that value. 179 source := "" 180 if C.get_priority(j, &priority) == 0 { 181 if priority == C.int(journal.PriErr) { 182 source = "stderr" 183 } else if priority == C.int(journal.PriInfo) { 184 source = "stdout" 185 } 186 } 187 // Retrieve the values of any variables we're adding to the journal. 188 var attrs []backend.LogAttr 189 C.sd_journal_restart_data(j) 190 for C.get_attribute_field(j, &data, &length) > C.int(0) { 191 kv := strings.SplitN(C.GoStringN(data, C.int(length)), "=", 2) 192 attrs = append(attrs, backend.LogAttr{Key: kv[0], Value: kv[1]}) 193 } 194 195 // Send the log message, unless the consumer is gone 196 select { 197 case <-logWatcher.WatchConsumerGone(): 198 done = true // we won't be able to write anything anymore 199 break drain 200 case logWatcher.Msg <- &logger.Message{ 201 Line: line, 202 Source: source, 203 Timestamp: timestamp.In(time.UTC), 204 Attrs: attrs, 205 }: 206 shown++ 207 } 208 // Call sd_journal_process() periodically during the processing loop 209 // to close any opened file descriptors for rotated (deleted) journal files. 210 if shown%1024 == 0 { 211 if ret := C.sd_journal_process(j); ret < 0 { 212 // log a warning but ignore it for now 213 logrus.WithField("container", s.vars["CONTAINER_ID_FULL"]). 214 WithField("error", CErr(ret)). 215 Warn("journald: error processing journal") 216 } 217 } 218 } 219 // If we're at the end of the journal, we're done (for now). 220 if C.sd_journal_next(j) <= 0 { 221 break 222 } 223 } 224 225 // free(NULL) is safe 226 C.free(unsafe.Pointer(oldCursor)) 227 if C.sd_journal_get_cursor(j, &cursor) != 0 { 228 // ensure that we won't be freeing an address that's invalid 229 cursor = nil 230 } 231 return cursor, done, shown 232 } 233 234 func (s *journald) followJournal(logWatcher *logger.LogWatcher, j *C.sd_journal, cursor *C.char, untilUnixMicro uint64) *C.char { 235 s.mu.Lock() 236 s.readers[logWatcher] = struct{}{} 237 s.mu.Unlock() 238 239 waitTimeout := C.uint64_t(250000) // 0.25s 240 241 for { 242 status := C.sd_journal_wait(j, waitTimeout) 243 if status < 0 { 244 logWatcher.Err <- errors.New("error waiting for journal: " + CErr(status)) 245 goto cleanup 246 } 247 select { 248 case <-logWatcher.WatchConsumerGone(): 249 goto cleanup // won't be able to write anything anymore 250 case <-logWatcher.WatchProducerGone(): 251 // container is gone, drain journal 252 default: 253 // container is still alive 254 if status == C.SD_JOURNAL_NOP { 255 // no new data -- keep waiting 256 continue 257 } 258 } 259 newCursor, done, recv := s.drainJournal(logWatcher, j, cursor, untilUnixMicro) 260 cursor = newCursor 261 if done || (status == C.SD_JOURNAL_NOP && recv == 0) { 262 break 263 } 264 } 265 266 cleanup: 267 s.mu.Lock() 268 delete(s.readers, logWatcher) 269 s.mu.Unlock() 270 close(logWatcher.Msg) 271 return cursor 272 } 273 274 func (s *journald) readLogs(logWatcher *logger.LogWatcher, config logger.ReadConfig) { 275 var ( 276 j *C.sd_journal 277 cmatch, cursor *C.char 278 stamp C.uint64_t 279 sinceUnixMicro uint64 280 untilUnixMicro uint64 281 ) 282 283 // Get a handle to the journal. 284 if rc := C.sd_journal_open(&j, C.int(0)); rc != 0 { 285 logWatcher.Err <- errors.New("error opening journal: " + CErr(rc)) 286 close(logWatcher.Msg) 287 return 288 } 289 if config.Follow { 290 // Initialize library inotify watches early 291 if rc := C.sd_journal_get_fd(j); rc < 0 { 292 logWatcher.Err <- errors.New("error getting journald fd: " + CErr(rc)) 293 close(logWatcher.Msg) 294 return 295 } 296 } 297 // If we end up following the log, we can set the journal context 298 // pointer and the channel pointer to nil so that we won't close them 299 // here, potentially while the goroutine that uses them is still 300 // running. Otherwise, close them when we return from this function. 301 following := false 302 defer func() { 303 if !following { 304 close(logWatcher.Msg) 305 } 306 C.sd_journal_close(j) 307 }() 308 // Remove limits on the size of data items that we'll retrieve. 309 if rc := C.sd_journal_set_data_threshold(j, C.size_t(0)); rc != 0 { 310 logWatcher.Err <- errors.New("error setting journal data threshold: " + CErr(rc)) 311 return 312 } 313 // Add a match to have the library do the searching for us. 314 cmatch = C.CString("CONTAINER_ID_FULL=" + s.vars["CONTAINER_ID_FULL"]) 315 defer C.free(unsafe.Pointer(cmatch)) 316 if rc := C.sd_journal_add_match(j, unsafe.Pointer(cmatch), C.strlen(cmatch)); rc != 0 { 317 logWatcher.Err <- errors.New("error setting journal match: " + CErr(rc)) 318 return 319 } 320 // If we have a cutoff time, convert it to Unix time once. 321 if !config.Since.IsZero() { 322 nano := config.Since.UnixNano() 323 sinceUnixMicro = uint64(nano / 1000) 324 } 325 // If we have an until value, convert it too 326 if !config.Until.IsZero() { 327 nano := config.Until.UnixNano() 328 untilUnixMicro = uint64(nano / 1000) 329 } 330 if config.Tail >= 0 { 331 // If until time provided, start from there. 332 // Otherwise start at the end of the journal. 333 if untilUnixMicro != 0 { 334 if rc := C.sd_journal_seek_realtime_usec(j, C.uint64_t(untilUnixMicro)); rc != 0 { 335 logWatcher.Err <- errors.New("error seeking provided until value: " + CErr(rc)) 336 return 337 } 338 } else if rc := C.sd_journal_seek_tail(j); rc != 0 { 339 logWatcher.Err <- errors.New("error seeking to end of journal: " + CErr(rc)) 340 return 341 } 342 // (Try to) skip backwards by the requested number of lines... 343 if C.sd_journal_previous_skip(j, C.uint64_t(config.Tail)) >= 0 { 344 // ...but not before "since" 345 if sinceUnixMicro != 0 && 346 C.sd_journal_get_realtime_usec(j, &stamp) == 0 && 347 uint64(stamp) < sinceUnixMicro { 348 C.sd_journal_seek_realtime_usec(j, C.uint64_t(sinceUnixMicro)) 349 } 350 } 351 } else { 352 // Start at the beginning of the journal. 353 if rc := C.sd_journal_seek_head(j); rc != 0 { 354 logWatcher.Err <- errors.New("error seeking to start of journal: " + CErr(rc)) 355 return 356 } 357 // If we have a cutoff date, fast-forward to it. 358 if sinceUnixMicro != 0 { 359 if rc := C.sd_journal_seek_realtime_usec(j, C.uint64_t(sinceUnixMicro)); rc != 0 { 360 logWatcher.Err <- errors.New("error seeking to start time in journal: " + CErr(rc)) 361 return 362 } 363 } 364 if rc := C.sd_journal_next(j); rc < 0 { 365 logWatcher.Err <- errors.New("error skipping to next journal entry: " + CErr(rc)) 366 return 367 } 368 } 369 if config.Tail != 0 { // special case for --tail 0 370 cursor, _, _ = s.drainJournal(logWatcher, j, nil, untilUnixMicro) 371 } 372 if config.Follow { 373 cursor = s.followJournal(logWatcher, j, cursor, untilUnixMicro) 374 // Let followJournal handle freeing the journal context 375 // object and closing the channel. 376 following = true 377 } 378 379 C.free(unsafe.Pointer(cursor)) 380 return 381 } 382 383 func (s *journald) ReadLogs(config logger.ReadConfig) *logger.LogWatcher { 384 logWatcher := logger.NewLogWatcher() 385 go s.readLogs(logWatcher, config) 386 return logWatcher 387 }