diff options
Diffstat (limited to 'src/journal/journald-server.c')
| -rw-r--r-- | src/journal/journald-server.c | 1181 |
1 files changed, 810 insertions, 371 deletions
diff --git a/src/journal/journald-server.c b/src/journal/journald-server.c index 46358e1c1a..381182fa2c 100644 --- a/src/journal/journald-server.c +++ b/src/journal/journald-server.c @@ -1,5 +1,3 @@ -/*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: nil -*-*/ - /*** This file is part of systemd. @@ -19,45 +17,60 @@ along with systemd; If not, see <http://www.gnu.org/licenses/>. ***/ -#include <sys/signalfd.h> -#include <sys/ioctl.h> -#include <linux/sockios.h> -#include <sys/statvfs.h> -#include <sys/mman.h> - #ifdef HAVE_SELINUX #include <selinux/selinux.h> #endif +#include <sys/ioctl.h> +#include <sys/mman.h> +#include <sys/signalfd.h> +#include <sys/statvfs.h> +#include <linux/sockios.h> -#include <libudev.h> - +#include "libudev.h" +#include "sd-daemon.h" #include "sd-journal.h" #include "sd-messages.h" -#include "sd-daemon.h" -#include "mkdir.h" -#include "rm-rf.h" -#include "hashmap.h" -#include "journal-file.h" -#include "socket-util.h" + +#include "acl-util.h" +#include "alloc-util.h" +#include "audit-util.h" #include "cgroup-util.h" -#include "missing.h" #include "conf-parser.h" -#include "selinux-util.h" -#include "acl-util.h" +#include "dirent-util.h" +#include "extract-word.h" +#include "fd-util.h" +#include "fileio.h" #include "formats-util.h" -#include "process-util.h" +#include "fs-util.h" +#include "hashmap.h" #include "hostname-util.h" -#include "signal-util.h" +#include "id128-util.h" +#include "io-util.h" +#include "journal-authenticate.h" +#include "journal-file.h" #include "journal-internal.h" #include "journal-vacuum.h" -#include "journal-authenticate.h" -#include "journald-rate-limit.h" +#include "journald-audit.h" #include "journald-kmsg.h" -#include "journald-syslog.h" -#include "journald-stream.h" #include "journald-native.h" -#include "journald-audit.h" +#include "journald-rate-limit.h" #include "journald-server.h" +#include "journald-stream.h" +#include "journald-syslog.h" +#include "log.h" +#include "missing.h" +#include "mkdir.h" +#include "parse-util.h" +#include "proc-cmdline.h" +#include "process-util.h" +#include "rm-rf.h" +#include "selinux-util.h" +#include "signal-util.h" +#include "socket-util.h" +#include "stdio-util.h" +#include "string-table.h" +#include "string-util.h" +#include "user-util.h" #define USER_JOURNALS_MAX 1024 @@ -66,88 +79,66 @@ #define DEFAULT_RATE_LIMIT_BURST 1000 #define DEFAULT_MAX_FILE_USEC USEC_PER_MONTH -#define RECHECK_AVAILABLE_SPACE_USEC (30*USEC_PER_SEC) - -static const char* const storage_table[_STORAGE_MAX] = { - [STORAGE_AUTO] = "auto", - [STORAGE_VOLATILE] = "volatile", - [STORAGE_PERSISTENT] = "persistent", - [STORAGE_NONE] = "none" -}; - -DEFINE_STRING_TABLE_LOOKUP(storage, Storage); -DEFINE_CONFIG_PARSE_ENUM(config_parse_storage, storage, Storage, "Failed to parse storage setting"); +#define RECHECK_SPACE_USEC (30*USEC_PER_SEC) -static const char* const split_mode_table[_SPLIT_MAX] = { - [SPLIT_LOGIN] = "login", - [SPLIT_UID] = "uid", - [SPLIT_NONE] = "none", -}; +#define NOTIFY_SNDBUF_SIZE (8*1024*1024) -DEFINE_STRING_TABLE_LOOKUP(split_mode, SplitMode); -DEFINE_CONFIG_PARSE_ENUM(config_parse_split_mode, split_mode, SplitMode, "Failed to parse split mode setting"); +/* The period to insert between posting changes for coalescing */ +#define POST_CHANGE_TIMER_INTERVAL_USEC (250*USEC_PER_MSEC) -static uint64_t available_space(Server *s, bool verbose) { - char ids[33]; - _cleanup_free_ char *p = NULL; - sd_id128_t machine; - struct statvfs ss; - uint64_t sum = 0, ss_avail = 0, avail = 0; - int r; +static int determine_space_for( + Server *s, + JournalMetrics *metrics, + const char *path, + const char *name, + bool verbose, + bool patch_min_use, + uint64_t *available, + uint64_t *limit) { + + uint64_t sum = 0, ss_avail, avail; _cleanup_closedir_ DIR *d = NULL; + struct dirent *de; + struct statvfs ss; + const char *p; usec_t ts; - const char *f; - JournalMetrics *m; - - ts = now(CLOCK_MONOTONIC); - if (s->cached_available_space_timestamp + RECHECK_AVAILABLE_SPACE_USEC > ts - && !verbose) - return s->cached_available_space; + assert(s); + assert(metrics); + assert(path); + assert(name); - r = sd_id128_get_machine(&machine); - if (r < 0) - return 0; + ts = now(CLOCK_MONOTONIC); - if (s->system_journal) { - f = "/var/log/journal/"; - m = &s->system_metrics; - } else { - f = "/run/log/journal/"; - m = &s->runtime_metrics; - } + if (!verbose && s->cached_space_timestamp + RECHECK_SPACE_USEC > ts) { - assert(m); + if (available) + *available = s->cached_space_available; + if (limit) + *limit = s->cached_space_limit; - p = strappend(f, sd_id128_to_string(machine, ids)); - if (!p) return 0; + } + p = strjoina(path, SERVER_MACHINE_ID(s)); d = opendir(p); if (!d) - return 0; + return log_full_errno(errno == ENOENT ? LOG_DEBUG : LOG_ERR, errno, "Failed to open %s: %m", p); if (fstatvfs(dirfd(d), &ss) < 0) - return 0; + return log_error_errno(errno, "Failed to fstatvfs(%s): %m", p); - for (;;) { + FOREACH_DIRENT_ALL(de, d, break) { struct stat st; - struct dirent *de; - - errno = 0; - de = readdir(d); - if (!de && errno != 0) - return 0; - - if (!de) - break; if (!endswith(de->d_name, ".journal") && !endswith(de->d_name, ".journal~")) continue; - if (fstatat(dirfd(d), de->d_name, &st, AT_SYMLINK_NOFOLLOW) < 0) + if (fstatat(dirfd(d), de->d_name, &st, AT_SYMLINK_NOFOLLOW) < 0) { + log_debug_errno(errno, "Failed to stat %s/%s, ignoring: %m", p, de->d_name); continue; + } if (!S_ISREG(st.st_mode)) continue; @@ -155,89 +146,216 @@ static uint64_t available_space(Server *s, bool verbose) { sum += (uint64_t) st.st_blocks * 512UL; } - ss_avail = ss.f_bsize * ss.f_bavail; - - /* If we reached a high mark, we will always allow this much - * again, unless usage goes above max_use. This watermark - * value is cached so that we don't give up space on pressure, - * but hover below the maximum usage. */ + /* If requested, then let's bump the min_use limit to the + * current usage on disk. We do this when starting up and + * first opening the journal files. This way sudden spikes in + * disk usage will not cause journald to vacuum files without + * bounds. Note that this means that only a restart of + * journald will make it reset this value. */ - if (m->use < sum) - m->use = sum; + if (patch_min_use) + metrics->min_use = MAX(metrics->min_use, sum); - avail = LESS_BY(ss_avail, m->keep_free); + ss_avail = ss.f_bsize * ss.f_bavail; + avail = LESS_BY(ss_avail, metrics->keep_free); - s->cached_available_space = LESS_BY(MIN(m->max_use, avail), sum); - s->cached_available_space_timestamp = ts; + s->cached_space_limit = MIN(MAX(sum + avail, metrics->min_use), metrics->max_use); + s->cached_space_available = LESS_BY(s->cached_space_limit, sum); + s->cached_space_timestamp = ts; if (verbose) { char fb1[FORMAT_BYTES_MAX], fb2[FORMAT_BYTES_MAX], fb3[FORMAT_BYTES_MAX], - fb4[FORMAT_BYTES_MAX], fb5[FORMAT_BYTES_MAX]; + fb4[FORMAT_BYTES_MAX], fb5[FORMAT_BYTES_MAX], fb6[FORMAT_BYTES_MAX]; + format_bytes(fb1, sizeof(fb1), sum); + format_bytes(fb2, sizeof(fb2), metrics->max_use); + format_bytes(fb3, sizeof(fb3), metrics->keep_free); + format_bytes(fb4, sizeof(fb4), ss_avail); + format_bytes(fb5, sizeof(fb5), s->cached_space_limit); + format_bytes(fb6, sizeof(fb6), s->cached_space_available); server_driver_message(s, SD_MESSAGE_JOURNAL_USAGE, - "%s journal is using %s (max allowed %s, " - "trying to leave %s free of %s available → current limit %s).", - s->system_journal ? "Permanent" : "Runtime", - format_bytes(fb1, sizeof(fb1), sum), - format_bytes(fb2, sizeof(fb2), m->max_use), - format_bytes(fb3, sizeof(fb3), m->keep_free), - format_bytes(fb4, sizeof(fb4), ss_avail), - format_bytes(fb5, sizeof(fb5), s->cached_available_space + sum)); + LOG_MESSAGE("%s (%s) is %s, max %s, %s free.", + name, path, fb1, fb5, fb6), + "JOURNAL_NAME=%s", name, + "JOURNAL_PATH=%s", path, + "CURRENT_USE=%"PRIu64, sum, + "CURRENT_USE_PRETTY=%s", fb1, + "MAX_USE=%"PRIu64, metrics->max_use, + "MAX_USE_PRETTY=%s", fb2, + "DISK_KEEP_FREE=%"PRIu64, metrics->keep_free, + "DISK_KEEP_FREE_PRETTY=%s", fb3, + "DISK_AVAILABLE=%"PRIu64, ss_avail, + "DISK_AVAILABLE_PRETTY=%s", fb4, + "LIMIT=%"PRIu64, s->cached_space_limit, + "LIMIT_PRETTY=%s", fb5, + "AVAILABLE=%"PRIu64, s->cached_space_available, + "AVAILABLE_PRETTY=%s", fb6, + NULL); } - return s->cached_available_space; + if (available) + *available = s->cached_space_available; + if (limit) + *limit = s->cached_space_limit; + + return 1; } -void server_fix_perms(Server *s, JournalFile *f, uid_t uid) { - int r; +static int determine_space(Server *s, bool verbose, bool patch_min_use, uint64_t *available, uint64_t *limit) { + JournalMetrics *metrics; + const char *path, *name; + + assert(s); + + if (s->system_journal) { + path = "/var/log/journal/"; + metrics = &s->system_metrics; + name = "System journal"; + } else { + path = "/run/log/journal/"; + metrics = &s->runtime_metrics; + name = "Runtime journal"; + } + + return determine_space_for(s, metrics, path, name, verbose, patch_min_use, available, limit); +} + +static void server_add_acls(JournalFile *f, uid_t uid) { #ifdef HAVE_ACL - acl_t acl; - acl_entry_t entry; - acl_permset_t permset; + int r; #endif - assert(f); - r = fchmod(f->fd, 0640); - if (r < 0) - log_warning_errno(r, "Failed to fix access mode on %s, ignoring: %m", f->path); - #ifdef HAVE_ACL if (uid <= SYSTEM_UID_MAX) return; - acl = acl_get_fd(f->fd); - if (!acl) { - log_warning_errno(errno, "Failed to read ACL on %s, ignoring: %m", f->path); - return; + r = add_acls_for_user(f->fd, uid); + if (r < 0) + log_warning_errno(r, "Failed to set ACL on %s, ignoring: %m", f->path); +#endif +} + +static int open_journal( + Server *s, + bool reliably, + const char *fname, + int flags, + bool seal, + JournalMetrics *metrics, + JournalFile **ret) { + int r; + JournalFile *f; + + assert(s); + assert(fname); + assert(ret); + + if (reliably) + r = journal_file_open_reliably(fname, flags, 0640, s->compress, seal, metrics, s->mmap, s->deferred_closes, NULL, &f); + else + r = journal_file_open(-1, fname, flags, 0640, s->compress, seal, metrics, s->mmap, s->deferred_closes, NULL, &f); + if (r < 0) + return r; + + r = journal_file_enable_post_change_timer(f, s->event, POST_CHANGE_TIMER_INTERVAL_USEC); + if (r < 0) { + (void) journal_file_close(f); + return r; } - r = acl_find_uid(acl, uid, &entry); - if (r <= 0) { + *ret = f; + return r; +} + +static bool flushed_flag_is_set(void) { + return (access("/run/systemd/journal/flushed", F_OK) >= 0); +} - if (acl_create_entry(&acl, &entry) < 0 || - acl_set_tag_type(entry, ACL_USER) < 0 || - acl_set_qualifier(entry, &uid) < 0) { - log_warning_errno(errno, "Failed to patch ACL on %s, ignoring: %m", f->path); - goto finish; +static int system_journal_open(Server *s, bool flush_requested) { + bool flushed = false; + const char *fn; + int r = 0; + + if (!s->system_journal && + (s->storage == STORAGE_PERSISTENT || s->storage == STORAGE_AUTO) && + (flush_requested || (flushed = flushed_flag_is_set()))) { + + /* If in auto mode: first try to create the machine + * path, but not the prefix. + * + * If in persistent mode: create /var/log/journal and + * the machine path */ + + if (s->storage == STORAGE_PERSISTENT) + (void) mkdir_p("/var/log/journal/", 0755); + + fn = strjoina("/var/log/journal/", SERVER_MACHINE_ID(s)); + (void) mkdir(fn, 0755); + + fn = strjoina(fn, "/system.journal"); + r = open_journal(s, true, fn, O_RDWR|O_CREAT, s->seal, &s->system_metrics, &s->system_journal); + if (r >= 0) { + server_add_acls(s->system_journal, 0); + (void) determine_space_for(s, &s->system_metrics, "/var/log/journal/", "System journal", true, true, NULL, NULL); + } else if (r < 0) { + if (r != -ENOENT && r != -EROFS) + log_warning_errno(r, "Failed to open system journal: %m"); + + r = 0; } - } - /* We do not recalculate the mask unconditionally here, - * so that the fchmod() mask above stays intact. */ - if (acl_get_permset(entry, &permset) < 0 || - acl_add_perm(permset, ACL_READ) < 0 || - calc_acl_mask_if_needed(&acl) < 0) { - log_warning_errno(errno, "Failed to patch ACL on %s, ignoring: %m", f->path); - goto finish; + /* If the runtime journal is open, and we're post-flush, we're + * recovering from a failed system journal rotate (ENOSPC) + * for which the runtime journal was reopened. + * + * Perform an implicit flush to var, leaving the runtime + * journal closed, now that the system journal is back. + */ + if (s->runtime_journal && flushed) + (void) server_flush_to_var(s); } - if (acl_set_fd(f->fd, acl) < 0) - log_warning_errno(errno, "Failed to set ACL on %s, ignoring: %m", f->path); + if (!s->runtime_journal && + (s->storage != STORAGE_NONE)) { -finish: - acl_free(acl); -#endif + fn = strjoina("/run/log/journal/", SERVER_MACHINE_ID(s), "/system.journal"); + + if (s->system_journal) { + + /* Try to open the runtime journal, but only + * if it already exists, so that we can flush + * it into the system journal */ + + r = open_journal(s, false, fn, O_RDWR, false, &s->runtime_metrics, &s->runtime_journal); + if (r < 0) { + if (r != -ENOENT) + log_warning_errno(r, "Failed to open runtime journal: %m"); + + r = 0; + } + + } else { + + /* OK, we really need the runtime journal, so create + * it if necessary. */ + + (void) mkdir("/run/log", 0755); + (void) mkdir("/run/log/journal", 0755); + (void) mkdir_parents(fn, 0750); + + r = open_journal(s, true, fn, O_RDWR|O_CREAT, false, &s->runtime_metrics, &s->runtime_journal); + if (r < 0) + return log_error_errno(r, "Failed to open runtime journal: %m"); + } + + if (s->runtime_journal) { + server_add_acls(s->runtime_journal, 0); + (void) determine_space_for(s, &s->runtime_metrics, "/run/log/journal/", "Runtime journal", true, true, NULL, NULL); + } + } + + return r; } static JournalFile* find_journal(Server *s, uid_t uid) { @@ -248,6 +366,17 @@ static JournalFile* find_journal(Server *s, uid_t uid) { assert(s); + /* A rotate that fails to create the new journal (ENOSPC) leaves the + * rotated journal as NULL. Unless we revisit opening, even after + * space is made available we'll continue to return NULL indefinitely. + * + * system_journal_open() is a noop if the journals are already open, so + * we can just call it here to recover from failed rotates (or anything + * else that's left the journals as NULL). + * + * Fixes https://github.com/systemd/systemd/issues/3968 */ + (void) system_journal_open(s, false); + /* We split up user logs only on /var, not on /run. If the * runtime file is open, we write to it exclusively, in order * to guarantee proper order as soon as we flush /run to @@ -256,14 +385,14 @@ static JournalFile* find_journal(Server *s, uid_t uid) { if (s->runtime_journal) return s->runtime_journal; - if (uid <= SYSTEM_UID_MAX) + if (uid <= SYSTEM_UID_MAX || uid_is_dynamic(uid)) return s->system_journal; r = sd_id128_get_machine(&machine); if (r < 0) return s->system_journal; - f = ordered_hashmap_get(s->user_journals, UINT32_TO_PTR(uid)); + f = ordered_hashmap_get(s->user_journals, UID_TO_PTR(uid)); if (f) return f; @@ -275,18 +404,18 @@ static JournalFile* find_journal(Server *s, uid_t uid) { /* Too many open? Then let's close one */ f = ordered_hashmap_steal_first(s->user_journals); assert(f); - journal_file_close(f); + (void) journal_file_close(f); } - r = journal_file_open_reliably(p, O_RDWR|O_CREAT, 0640, s->compress, s->seal, &s->system_metrics, s->mmap, NULL, &f); + r = open_journal(s, true, p, O_RDWR|O_CREAT, s->seal, &s->system_metrics, &f); if (r < 0) return s->system_journal; - server_fix_perms(s, f, uid); + server_add_acls(f, uid); - r = ordered_hashmap_put(s->user_journals, UINT32_TO_PTR(uid), f); + r = ordered_hashmap_put(s->user_journals, UID_TO_PTR(uid), f); if (r < 0) { - journal_file_close(f); + (void) journal_file_close(f); return s->system_journal; } @@ -306,14 +435,14 @@ static int do_rotate( if (!*f) return -EINVAL; - r = journal_file_rotate(f, s->compress, seal); + r = journal_file_rotate(f, s->compress, seal, s->deferred_closes); if (r < 0) if (*f) log_error_errno(r, "Failed to rotate %s: %m", (*f)->path); else log_error_errno(r, "Failed to create new %s journal: %m", name); else - server_fix_perms(s, *f, uid); + server_add_acls(*f, uid); return r; } @@ -326,35 +455,41 @@ void server_rotate(Server *s) { log_debug("Rotating..."); - do_rotate(s, &s->runtime_journal, "runtime", false, 0); - do_rotate(s, &s->system_journal, "system", s->seal, 0); + (void) do_rotate(s, &s->runtime_journal, "runtime", false, 0); + (void) do_rotate(s, &s->system_journal, "system", s->seal, 0); ORDERED_HASHMAP_FOREACH_KEY(f, k, s->user_journals, i) { - r = do_rotate(s, &f, "user", s->seal, PTR_TO_UINT32(k)); + r = do_rotate(s, &f, "user", s->seal, PTR_TO_UID(k)); if (r >= 0) ordered_hashmap_replace(s->user_journals, k, f); else if (!f) /* Old file has been closed and deallocated */ ordered_hashmap_remove(s->user_journals, k); } + + /* Perform any deferred closes which aren't still offlining. */ + SET_FOREACH(f, s->deferred_closes, i) + if (!journal_file_is_offlining(f)) { + (void) set_remove(s->deferred_closes, f); + (void) journal_file_close(f); + } } void server_sync(Server *s) { JournalFile *f; - void *k; Iterator i; int r; if (s->system_journal) { - r = journal_file_set_offline(s->system_journal); + r = journal_file_set_offline(s->system_journal, false); if (r < 0) - log_error_errno(r, "Failed to sync system journal: %m"); + log_warning_errno(r, "Failed to sync system journal, ignoring: %m"); } - ORDERED_HASHMAP_FOREACH_KEY(f, k, s->user_journals, i) { - r = journal_file_set_offline(f); + ORDERED_HASHMAP_FOREACH(f, s->user_journals, i) { + r = journal_file_set_offline(f, false); if (r < 0) - log_error_errno(r, "Failed to sync user journal: %m"); + log_warning_errno(r, "Failed to sync user journal, ignoring: %m"); } if (s->sync_event_source) { @@ -368,43 +503,50 @@ void server_sync(Server *s) { static void do_vacuum( Server *s, - const char *id, JournalFile *f, - const char* path, - JournalMetrics *metrics) { + JournalMetrics *metrics, + const char *path, + const char *name, + bool verbose, + bool patch_min_use) { const char *p; + uint64_t limit; int r; + assert(s); + assert(metrics); + assert(path); + assert(name); + if (!f) return; - p = strjoina(path, id); - r = journal_directory_vacuum(p, metrics->max_use, s->max_retention_usec, &s->oldest_file_usec, false); + p = strjoina(path, SERVER_MACHINE_ID(s)); + + limit = metrics->max_use; + (void) determine_space_for(s, metrics, path, name, verbose, patch_min_use, NULL, &limit); + + r = journal_directory_vacuum(p, limit, metrics->n_max_files, s->max_retention_usec, &s->oldest_file_usec, verbose); if (r < 0 && r != -ENOENT) - log_error_errno(r, "Failed to vacuum %s: %m", p); + log_warning_errno(r, "Failed to vacuum %s, ignoring: %m", p); } -void server_vacuum(Server *s) { - char ids[33]; - sd_id128_t machine; - int r; +int server_vacuum(Server *s, bool verbose, bool patch_min_use) { + assert(s); log_debug("Vacuuming..."); s->oldest_file_usec = 0; - r = sd_id128_get_machine(&machine); - if (r < 0) { - log_error_errno(r, "Failed to get machine ID: %m"); - return; - } - sd_id128_to_string(machine, ids); + do_vacuum(s, s->system_journal, &s->system_metrics, "/var/log/journal/", "System journal", verbose, patch_min_use); + do_vacuum(s, s->runtime_journal, &s->runtime_metrics, "/run/log/journal/", "Runtime journal", verbose, patch_min_use); - do_vacuum(s, ids, s->system_journal, "/var/log/journal/", &s->system_metrics); - do_vacuum(s, ids, s->runtime_journal, "/run/log/journal/", &s->runtime_metrics); + s->cached_space_limit = 0; + s->cached_space_available = 0; + s->cached_space_timestamp = 0; - s->cached_available_space_timestamp = 0; + return 0; } static void server_cache_machine_id(Server *s) { @@ -452,57 +594,89 @@ static void server_cache_hostname(Server *s) { } static bool shall_try_append_again(JournalFile *f, int r) { + switch(r) { - /* -E2BIG Hit configured limit - -EFBIG Hit fs limit - -EDQUOT Quota limit hit - -ENOSPC Disk full - -EIO I/O error of some kind (mmap) - -EHOSTDOWN Other machine - -EBUSY Unclean shutdown - -EPROTONOSUPPORT Unsupported feature - -EBADMSG Corrupted - -ENODATA Truncated - -ESHUTDOWN Already archived - -EIDRM Journal file has been deleted */ - - if (r == -E2BIG || r == -EFBIG || r == -EDQUOT || r == -ENOSPC) + case -E2BIG: /* Hit configured limit */ + case -EFBIG: /* Hit fs limit */ + case -EDQUOT: /* Quota limit hit */ + case -ENOSPC: /* Disk full */ log_debug("%s: Allocation limit reached, rotating.", f->path); - else if (r == -EHOSTDOWN) + return true; + + case -EIO: /* I/O error of some kind (mmap) */ + log_warning("%s: IO error, rotating.", f->path); + return true; + + case -EHOSTDOWN: /* Other machine */ log_info("%s: Journal file from other machine, rotating.", f->path); - else if (r == -EBUSY) + return true; + + case -EBUSY: /* Unclean shutdown */ log_info("%s: Unclean shutdown, rotating.", f->path); - else if (r == -EPROTONOSUPPORT) + return true; + + case -EPROTONOSUPPORT: /* Unsupported feature */ log_info("%s: Unsupported feature, rotating.", f->path); - else if (r == -EBADMSG || r == -ENODATA || r == ESHUTDOWN) + return true; + + case -EBADMSG: /* Corrupted */ + case -ENODATA: /* Truncated */ + case -ESHUTDOWN: /* Already archived */ log_warning("%s: Journal file corrupted, rotating.", f->path); - else if (r == -EIO) - log_warning("%s: IO error, rotating.", f->path); - else if (r == -EIDRM) + return true; + + case -EIDRM: /* Journal file has been deleted */ log_warning("%s: Journal file has been deleted, rotating.", f->path); - else - return false; + return true; + + case -ETXTBSY: /* Journal file is from the future */ + log_warning("%s: Journal file is from the future, rotating.", f->path); + return true; - return true; + default: + return false; + } } static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, unsigned n, int priority) { + bool vacuumed = false, rotate = false; + struct dual_timestamp ts; JournalFile *f; - bool vacuumed = false; int r; assert(s); assert(iovec); assert(n > 0); - f = find_journal(s, uid); - if (!f) - return; + /* Get the closest, linearized time we have for this log event from the event loop. (Note that we do not use + * the source time, and not even the time the event was originally seen, but instead simply the time we started + * processing it, as we want strictly linear ordering in what we write out.) */ + assert_se(sd_event_now(s->event, CLOCK_REALTIME, &ts.realtime) >= 0); + assert_se(sd_event_now(s->event, CLOCK_MONOTONIC, &ts.monotonic) >= 0); + + if (ts.realtime < s->last_realtime_clock) { + /* When the time jumps backwards, let's immediately rotate. Of course, this should not happen during + * regular operation. However, when it does happen, then we should make sure that we start fresh files + * to ensure that the entries in the journal files are strictly ordered by time, in order to ensure + * bisection works correctly. */ + + log_debug("Time jumped backwards, rotating."); + rotate = true; + } else { + + f = find_journal(s, uid); + if (!f) + return; + + if (journal_file_rotate_suggested(f, s->max_file_usec)) { + log_debug("%s: Journal header limits reached or header out-of-date, rotating.", f->path); + rotate = true; + } + } - if (journal_file_rotate_suggested(f, s->max_file_usec)) { - log_debug("%s: Journal header limits reached or header out-of-date, rotating.", f->path); + if (rotate) { server_rotate(s); - server_vacuum(s); + server_vacuum(s, false, false); vacuumed = true; f = find_journal(s, uid); @@ -510,7 +684,9 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, unsigned return; } - r = journal_file_append_entry(f, NULL, iovec, n, &s->seqnum, NULL, NULL); + s->last_realtime_clock = ts.realtime; + + r = journal_file_append_entry(f, &ts, iovec, n, &s->seqnum, NULL, NULL); if (r >= 0) { server_schedule_sync(s, priority); return; @@ -522,20 +698,58 @@ static void write_to_journal(Server *s, uid_t uid, struct iovec *iovec, unsigned } server_rotate(s); - server_vacuum(s); + server_vacuum(s, false, false); f = find_journal(s, uid); if (!f) return; log_debug("Retrying write."); - r = journal_file_append_entry(f, NULL, iovec, n, &s->seqnum, NULL, NULL); + r = journal_file_append_entry(f, &ts, iovec, n, &s->seqnum, NULL, NULL); if (r < 0) log_error_errno(r, "Failed to write entry (%d items, %zu bytes) despite vacuuming, ignoring: %m", n, IOVEC_TOTAL_SIZE(iovec, n)); else server_schedule_sync(s, priority); } +static int get_invocation_id(const char *cgroup_root, const char *slice, const char *unit, char **ret) { + _cleanup_free_ char *escaped = NULL, *slice_path = NULL, *p = NULL; + char *copy, ids[SD_ID128_STRING_MAX]; + int r; + + /* Read the invocation ID of a unit off a unit. It's stored in the "trusted.invocation_id" extended attribute + * on the cgroup path. */ + + r = cg_slice_to_path(slice, &slice_path); + if (r < 0) + return r; + + escaped = cg_escape(unit); + if (!escaped) + return -ENOMEM; + + p = strjoin(cgroup_root, "/", slice_path, "/", escaped, NULL); + if (!p) + return -ENOMEM; + + r = cg_get_xattr(SYSTEMD_CGROUP_CONTROLLER, p, "trusted.invocation_id", ids, 32); + if (r < 0) + return r; + if (r != 32) + return -EINVAL; + ids[32] = 0; + + if (!id128_is_valid(ids)) + return -EINVAL; + + copy = strdup(ids); + if (!copy) + return -ENOMEM; + + *ret = copy; + return 0; +} + static void dispatch_message_real( Server *s, struct iovec *iovec, unsigned n, unsigned m, @@ -574,7 +788,7 @@ static void dispatch_message_real( assert(s); assert(iovec); assert(n > 0); - assert(n + N_IOVEC_META_FIELDS + (object_pid ? N_IOVEC_OBJECT_FIELDS : 0) <= m); + assert(n + N_IOVEC_META_FIELDS + (object_pid > 0 ? N_IOVEC_OBJECT_FIELDS : 0) <= m); if (ucred) { realuid = ucred->uid; @@ -632,6 +846,7 @@ static void dispatch_message_real( r = cg_pid_get_path_shifted(ucred->pid, s->cgroup_root, &c); if (r >= 0) { + _cleanup_free_ char *raw_unit = NULL, *raw_slice = NULL; char *session = NULL; x = strjoina("_SYSTEMD_CGROUP=", c); @@ -651,9 +866,8 @@ static void dispatch_message_real( IOVEC_SET_STRING(iovec[n++], owner_uid); } - if (cg_path_get_unit(c, &t) >= 0) { - x = strjoina("_SYSTEMD_UNIT=", t); - free(t); + if (cg_path_get_unit(c, &raw_unit) >= 0) { + x = strjoina("_SYSTEMD_UNIT=", raw_unit); IOVEC_SET_STRING(iovec[n++], x); } else if (unit_id && !session) { x = strjoina("_SYSTEMD_UNIT=", unit_id); @@ -669,12 +883,25 @@ static void dispatch_message_real( IOVEC_SET_STRING(iovec[n++], x); } - if (cg_path_get_slice(c, &t) >= 0) { - x = strjoina("_SYSTEMD_SLICE=", t); + if (cg_path_get_slice(c, &raw_slice) >= 0) { + x = strjoina("_SYSTEMD_SLICE=", raw_slice); + IOVEC_SET_STRING(iovec[n++], x); + } + + if (cg_path_get_user_slice(c, &t) >= 0) { + x = strjoina("_SYSTEMD_USER_SLICE=", t); free(t); IOVEC_SET_STRING(iovec[n++], x); } + if (raw_slice && raw_unit) { + if (get_invocation_id(s->cgroup_root, raw_slice, raw_unit, &t) >= 0) { + x = strjoina("_SYSTEMD_INVOCATION_ID=", t); + free(t); + IOVEC_SET_STRING(iovec[n++], x); + } + } + free(c); } else if (unit_id) { x = strjoina("_SYSTEMD_UNIT=", unit_id); @@ -682,14 +909,14 @@ static void dispatch_message_real( } #ifdef HAVE_SELINUX - if (mac_selinux_use()) { + if (mac_selinux_have()) { if (label) { x = alloca(strlen("_SELINUX_CONTEXT=") + label_len + 1); *((char*) mempcpy(stpcpy(x, "_SELINUX_CONTEXT="), label, label_len)) = 0; IOVEC_SET_STRING(iovec[n++], x); } else { - security_context_t con; + char *con; if (getpidcon(ucred->pid, &con) >= 0) { x = strjoina("_SELINUX_CONTEXT=", con); @@ -780,13 +1007,25 @@ static void dispatch_message_real( IOVEC_SET_STRING(iovec[n++], x); } + if (cg_path_get_slice(c, &t) >= 0) { + x = strjoina("OBJECT_SYSTEMD_SLICE=", t); + free(t); + IOVEC_SET_STRING(iovec[n++], x); + } + + if (cg_path_get_user_slice(c, &t) >= 0) { + x = strjoina("OBJECT_SYSTEMD_USER_SLICE=", t); + free(t); + IOVEC_SET_STRING(iovec[n++], x); + } + free(c); } } assert(n <= m); if (tv) { - sprintf(source_time, "_SOURCE_REALTIME_TIMESTAMP=%llu", (unsigned long long) timeval_load(tv)); + sprintf(source_time, "_SOURCE_REALTIME_TIMESTAMP=" USEC_FMT, timeval_load(tv)); IOVEC_SET_STRING(iovec[n++], source_time); } @@ -822,34 +1061,56 @@ static void dispatch_message_real( void server_driver_message(Server *s, sd_id128_t message_id, const char *format, ...) { char mid[11 + 32 + 1]; - char buffer[16 + LINE_MAX + 1]; - struct iovec iovec[N_IOVEC_META_FIELDS + 4]; - int n = 0; + struct iovec iovec[N_IOVEC_META_FIELDS + 5 + N_IOVEC_PAYLOAD_FIELDS]; + unsigned n = 0, m; + int r; va_list ap; struct ucred ucred = {}; assert(s); assert(format); - IOVEC_SET_STRING(iovec[n++], "PRIORITY=6"); - IOVEC_SET_STRING(iovec[n++], "_TRANSPORT=driver"); + assert_cc(3 == LOG_FAC(LOG_DAEMON)); + IOVEC_SET_STRING(iovec[n++], "SYSLOG_FACILITY=3"); + IOVEC_SET_STRING(iovec[n++], "SYSLOG_IDENTIFIER=systemd-journald"); - memcpy(buffer, "MESSAGE=", 8); - va_start(ap, format); - vsnprintf(buffer + 8, sizeof(buffer) - 8, format, ap); - va_end(ap); - IOVEC_SET_STRING(iovec[n++], buffer); + IOVEC_SET_STRING(iovec[n++], "_TRANSPORT=driver"); + assert_cc(6 == LOG_INFO); + IOVEC_SET_STRING(iovec[n++], "PRIORITY=6"); - if (!sd_id128_equal(message_id, SD_ID128_NULL)) { + if (!sd_id128_is_null(message_id)) { snprintf(mid, sizeof(mid), LOG_MESSAGE_ID(message_id)); IOVEC_SET_STRING(iovec[n++], mid); } + m = n; + + va_start(ap, format); + r = log_format_iovec(iovec, ELEMENTSOF(iovec), &n, false, 0, format, ap); + /* Error handling below */ + va_end(ap); + ucred.pid = getpid(); ucred.uid = getuid(); ucred.gid = getgid(); - dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), &ucred, NULL, NULL, 0, NULL, LOG_INFO, 0); + if (r >= 0) + dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), &ucred, NULL, NULL, 0, NULL, LOG_INFO, 0); + + while (m < n) + free(iovec[m++].iov_base); + + if (r < 0) { + /* We failed to format the message. Emit a warning instead. */ + char buf[LINE_MAX]; + + xsprintf(buf, "MESSAGE=Entry printing failed: %s", strerror(-r)); + + n = 3; + IOVEC_SET_STRING(iovec[n++], "PRIORITY=4"); + IOVEC_SET_STRING(iovec[n++], buf); + dispatch_message_real(s, iovec, n, ELEMENTSOF(iovec), &ucred, NULL, NULL, 0, NULL, LOG_INFO, 0); + } } void server_dispatch_message( @@ -864,6 +1125,7 @@ void server_dispatch_message( int rl, r; _cleanup_free_ char *path = NULL; + uint64_t available = 0; char *c; assert(s); @@ -903,112 +1165,21 @@ void server_dispatch_message( } } - rl = journal_rate_limit_test(s->rate_limit, path, - priority & LOG_PRIMASK, available_space(s, false)); - + (void) determine_space(s, false, false, &available, NULL); + rl = journal_rate_limit_test(s->rate_limit, path, priority & LOG_PRIMASK, available); if (rl == 0) return; /* Write a suppression message if we suppressed something */ if (rl > 1) server_driver_message(s, SD_MESSAGE_JOURNAL_DROPPED, - "Suppressed %u messages from %s", rl - 1, path); + LOG_MESSAGE("Suppressed %u messages from %s", rl - 1, path), + NULL); finish: dispatch_message_real(s, iovec, n, m, ucred, tv, label, label_len, unit_id, priority, object_pid); } - -static int system_journal_open(Server *s, bool flush_requested) { - int r; - char *fn; - sd_id128_t machine; - char ids[33]; - - r = sd_id128_get_machine(&machine); - if (r < 0) - return log_error_errno(r, "Failed to get machine id: %m"); - - sd_id128_to_string(machine, ids); - - if (!s->system_journal && - (s->storage == STORAGE_PERSISTENT || s->storage == STORAGE_AUTO) && - (flush_requested - || access("/run/systemd/journal/flushed", F_OK) >= 0)) { - - /* If in auto mode: first try to create the machine - * path, but not the prefix. - * - * If in persistent mode: create /var/log/journal and - * the machine path */ - - if (s->storage == STORAGE_PERSISTENT) - (void) mkdir_p("/var/log/journal/", 0755); - - fn = strjoina("/var/log/journal/", ids); - (void) mkdir(fn, 0755); - - fn = strjoina(fn, "/system.journal"); - r = journal_file_open_reliably(fn, O_RDWR|O_CREAT, 0640, s->compress, s->seal, &s->system_metrics, s->mmap, NULL, &s->system_journal); - - if (r >= 0) - server_fix_perms(s, s->system_journal, 0); - else if (r < 0) { - if (r != -ENOENT && r != -EROFS) - log_warning_errno(r, "Failed to open system journal: %m"); - - r = 0; - } - } - - if (!s->runtime_journal && - (s->storage != STORAGE_NONE)) { - - fn = strjoin("/run/log/journal/", ids, "/system.journal", NULL); - if (!fn) - return -ENOMEM; - - if (s->system_journal) { - - /* Try to open the runtime journal, but only - * if it already exists, so that we can flush - * it into the system journal */ - - r = journal_file_open(fn, O_RDWR, 0640, s->compress, false, &s->runtime_metrics, s->mmap, NULL, &s->runtime_journal); - free(fn); - - if (r < 0) { - if (r != -ENOENT) - log_warning_errno(r, "Failed to open runtime journal: %m"); - - r = 0; - } - - } else { - - /* OK, we really need the runtime journal, so create - * it if necessary. */ - - (void) mkdir("/run/log", 0755); - (void) mkdir("/run/log/journal", 0755); - (void) mkdir_parents(fn, 0750); - - r = journal_file_open_reliably(fn, O_RDWR|O_CREAT, 0640, s->compress, false, &s->runtime_metrics, s->mmap, NULL, &s->runtime_journal); - free(fn); - - if (r < 0) - return log_error_errno(r, "Failed to open runtime journal: %m"); - } - - if (s->runtime_journal) - server_fix_perms(s, s->runtime_journal, 0); - } - - available_space(s, true); - - return r; -} - int server_flush_to_var(Server *s) { sd_id128_t machine; sd_journal *j = NULL; @@ -1026,7 +1197,7 @@ int server_flush_to_var(Server *s) { if (!s->runtime_journal) return 0; - system_journal_open(s, true); + (void) system_journal_open(s, true); if (!s->system_journal) return 0; @@ -1070,7 +1241,7 @@ int server_flush_to_var(Server *s) { } server_rotate(s); - server_vacuum(s); + server_vacuum(s, false, false); if (!s->system_journal) { log_notice("Didn't flush runtime journal since rotation of system journal wasn't successful."); @@ -1086,18 +1257,23 @@ int server_flush_to_var(Server *s) { } } + r = 0; + finish: journal_file_post_change(s->system_journal); - journal_file_close(s->runtime_journal); - s->runtime_journal = NULL; + s->runtime_journal = journal_file_close(s->runtime_journal); if (r >= 0) (void) rm_rf("/run/log/journal", REMOVE_ROOT); sd_journal_close(j); - server_driver_message(s, SD_ID128_NULL, "Time spent on flushing to /var is %s for %u entries.", format_timespan(ts, sizeof(ts), now(CLOCK_MONOTONIC) - start, 0), n); + server_driver_message(s, SD_ID128_NULL, + LOG_MESSAGE("Time spent on flushing to /var is %s for %u entries.", + format_timespan(ts, sizeof(ts), now(CLOCK_MONOTONIC) - start, 0), + n), + NULL); return r; } @@ -1226,28 +1402,37 @@ int server_process_datagram(sd_event_source *es, int fd, uint32_t revents, void static int dispatch_sigusr1(sd_event_source *es, const struct signalfd_siginfo *si, void *userdata) { Server *s = userdata; + int r; assert(s); - log_info("Received request to flush runtime journal from PID %"PRIu32, si->ssi_pid); + log_info("Received request to flush runtime journal from PID " PID_FMT, si->ssi_pid); - server_flush_to_var(s); + (void) server_flush_to_var(s); server_sync(s); - server_vacuum(s); + server_vacuum(s, false, false); - touch("/run/systemd/journal/flushed"); + r = touch("/run/systemd/journal/flushed"); + if (r < 0) + log_warning_errno(r, "Failed to touch /run/systemd/journal/flushed, ignoring: %m"); return 0; } static int dispatch_sigusr2(sd_event_source *es, const struct signalfd_siginfo *si, void *userdata) { Server *s = userdata; + int r; assert(s); - log_info("Received request to rotate journal from PID %"PRIu32, si->ssi_pid); + log_info("Received request to rotate journal from PID " PID_FMT, si->ssi_pid); server_rotate(s); - server_vacuum(s); + server_vacuum(s, true, true); + + /* Let clients know when the most recent rotation happened. */ + r = write_timestamp_file_atomic("/run/systemd/journal/rotated", now(CLOCK_MONOTONIC)); + if (r < 0) + log_warning_errno(r, "Failed to write /run/systemd/journal/rotated, ignoring: %m"); return 0; } @@ -1263,12 +1448,30 @@ static int dispatch_sigterm(sd_event_source *es, const struct signalfd_siginfo * return 0; } +static int dispatch_sigrtmin1(sd_event_source *es, const struct signalfd_siginfo *si, void *userdata) { + Server *s = userdata; + int r; + + assert(s); + + log_debug("Received request to sync from PID " PID_FMT, si->ssi_pid); + + server_sync(s); + + /* Let clients know when the most recent sync happened. */ + r = write_timestamp_file_atomic("/run/systemd/journal/synced", now(CLOCK_MONOTONIC)); + if (r < 0) + log_warning_errno(r, "Failed to write /run/systemd/journal/synced, ignoring: %m"); + + return 0; +} + static int setup_signals(Server *s) { int r; assert(s); - assert(sigprocmask_many(SIG_SETMASK, NULL, SIGINT, SIGTERM, SIGUSR1, SIGUSR2, -1) >= 0); + assert(sigprocmask_many(SIG_SETMASK, NULL, SIGINT, SIGTERM, SIGUSR1, SIGUSR2, SIGRTMIN+1, -1) >= 0); r = sd_event_add_signal(s->event, &s->sigusr1_event_source, SIGUSR1, dispatch_sigusr1, s); if (r < 0) @@ -1282,17 +1485,41 @@ static int setup_signals(Server *s) { if (r < 0) return r; + /* Let's process SIGTERM late, so that we flush all queued + * messages to disk before we exit */ + r = sd_event_source_set_priority(s->sigterm_event_source, SD_EVENT_PRIORITY_NORMAL+20); + if (r < 0) + return r; + + /* When journald is invoked on the terminal (when debugging), + * it's useful if C-c is handled equivalent to SIGTERM. */ r = sd_event_add_signal(s->event, &s->sigint_event_source, SIGINT, dispatch_sigterm, s); if (r < 0) return r; + r = sd_event_source_set_priority(s->sigint_event_source, SD_EVENT_PRIORITY_NORMAL+20); + if (r < 0) + return r; + + /* SIGRTMIN+1 causes an immediate sync. We process this very + * late, so that everything else queued at this point is + * really written to disk. Clients can watch + * /run/systemd/journal/synced with inotify until its mtime + * changes to see when a sync happened. */ + r = sd_event_add_signal(s->event, &s->sigrtmin1_event_source, SIGRTMIN+1, dispatch_sigrtmin1, s); + if (r < 0) + return r; + + r = sd_event_source_set_priority(s->sigrtmin1_event_source, SD_EVENT_PRIORITY_NORMAL+15); + if (r < 0) + return r; + return 0; } static int server_parse_proc_cmdline(Server *s) { _cleanup_free_ char *line = NULL; - const char *w, *state; - size_t l; + const char *p; int r; r = proc_cmdline(&line); @@ -1301,12 +1528,16 @@ static int server_parse_proc_cmdline(Server *s) { return 0; } - FOREACH_WORD_QUOTED(w, l, line, state) { - _cleanup_free_ char *word; + p = line; + for (;;) { + _cleanup_free_ char *word = NULL; + + r = extract_first_word(&p, &word, NULL, 0); + if (r < 0) + return log_error_errno(r, "Failed to parse journald syntax \"%s\": %m", line); - word = strndup(w, l); - if (!word) - return -ENOMEM; + if (r == 0) + break; if (startswith(word, "systemd.journald.forward_to_syslog=")) { r = parse_boolean(word + 35); @@ -1335,16 +1566,16 @@ static int server_parse_proc_cmdline(Server *s) { } else if (startswith(word, "systemd.journald")) log_warning("Invalid systemd.journald parameter. Ignoring."); } - /* do not warn about state here, since probably systemd already did */ + /* do not warn about state here, since probably systemd already did */ return 0; } static int server_parse_config_file(Server *s) { assert(s); - return config_parse_many("/etc/systemd/journald.conf", - CONF_DIRS_NULSTR("systemd/journald.conf"), + return config_parse_many_nulstr(PKGSYSCONFDIR "/journald.conf", + CONF_PATHS_NULSTR("systemd/journald.conf.d"), "Journal\0", config_item_perf_lookup, journald_gperf_lookup, false, s); @@ -1432,8 +1663,7 @@ static int server_open_hostname(Server *s) { /* kernels prior to 3.2 don't support polling this file. Ignore * the failure. */ if (r == -EPERM) { - log_warning("Failed to register hostname fd in event loop: %s. Ignoring.", - strerror(-r)); + log_warning_errno(r, "Failed to register hostname fd in event loop, ignoring: %m"); s->hostname_fd = safe_close(s->hostname_fd); return 0; } @@ -1448,17 +1678,184 @@ static int server_open_hostname(Server *s) { return 0; } +static int dispatch_notify_event(sd_event_source *es, int fd, uint32_t revents, void *userdata) { + Server *s = userdata; + int r; + + assert(s); + assert(s->notify_event_source == es); + assert(s->notify_fd == fd); + + /* The $NOTIFY_SOCKET is writable again, now send exactly one + * message on it. Either it's the watchdog event, the initial + * READY=1 event or an stdout stream event. If there's nothing + * to write anymore, turn our event source off. The next time + * there's something to send it will be turned on again. */ + + if (!s->sent_notify_ready) { + static const char p[] = + "READY=1\n" + "STATUS=Processing requests..."; + ssize_t l; + + l = send(s->notify_fd, p, strlen(p), MSG_DONTWAIT); + if (l < 0) { + if (errno == EAGAIN) + return 0; + + return log_error_errno(errno, "Failed to send READY=1 notification message: %m"); + } + + s->sent_notify_ready = true; + log_debug("Sent READY=1 notification."); + + } else if (s->send_watchdog) { + + static const char p[] = + "WATCHDOG=1"; + + ssize_t l; + + l = send(s->notify_fd, p, strlen(p), MSG_DONTWAIT); + if (l < 0) { + if (errno == EAGAIN) + return 0; + + return log_error_errno(errno, "Failed to send WATCHDOG=1 notification message: %m"); + } + + s->send_watchdog = false; + log_debug("Sent WATCHDOG=1 notification."); + + } else if (s->stdout_streams_notify_queue) + /* Dispatch one stream notification event */ + stdout_stream_send_notify(s->stdout_streams_notify_queue); + + /* Leave us enabled if there's still more to do. */ + if (s->send_watchdog || s->stdout_streams_notify_queue) + return 0; + + /* There was nothing to do anymore, let's turn ourselves off. */ + r = sd_event_source_set_enabled(es, SD_EVENT_OFF); + if (r < 0) + return log_error_errno(r, "Failed to turn off notify event source: %m"); + + return 0; +} + +static int dispatch_watchdog(sd_event_source *es, uint64_t usec, void *userdata) { + Server *s = userdata; + int r; + + assert(s); + + s->send_watchdog = true; + + r = sd_event_source_set_enabled(s->notify_event_source, SD_EVENT_ON); + if (r < 0) + log_warning_errno(r, "Failed to turn on notify event source: %m"); + + r = sd_event_source_set_time(s->watchdog_event_source, usec + s->watchdog_usec / 2); + if (r < 0) + return log_error_errno(r, "Failed to restart watchdog event source: %m"); + + r = sd_event_source_set_enabled(s->watchdog_event_source, SD_EVENT_ON); + if (r < 0) + return log_error_errno(r, "Failed to enable watchdog event source: %m"); + + return 0; +} + +static int server_connect_notify(Server *s) { + union sockaddr_union sa = { + .un.sun_family = AF_UNIX, + }; + const char *e; + int r; + + assert(s); + assert(s->notify_fd < 0); + assert(!s->notify_event_source); + + /* + So here's the problem: we'd like to send notification + messages to PID 1, but we cannot do that via sd_notify(), + since that's synchronous, and we might end up blocking on + it. Specifically: given that PID 1 might block on + dbus-daemon during IPC, and dbus-daemon is logging to us, + and might hence block on us, we might end up in a deadlock + if we block on sending PID 1 notification messages — by + generating a full blocking circle. To avoid this, let's + create a non-blocking socket, and connect it to the + notification socket, and then wait for POLLOUT before we + send anything. This should efficiently avoid any deadlocks, + as we'll never block on PID 1, hence PID 1 can safely block + on dbus-daemon which can safely block on us again. + + Don't think that this issue is real? It is, see: + https://github.com/systemd/systemd/issues/1505 + */ + + e = getenv("NOTIFY_SOCKET"); + if (!e) + return 0; + + if ((e[0] != '@' && e[0] != '/') || e[1] == 0) { + log_error("NOTIFY_SOCKET set to an invalid value: %s", e); + return -EINVAL; + } + + if (strlen(e) > sizeof(sa.un.sun_path)) { + log_error("NOTIFY_SOCKET path too long: %s", e); + return -EINVAL; + } + + s->notify_fd = socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0); + if (s->notify_fd < 0) + return log_error_errno(errno, "Failed to create notify socket: %m"); + + (void) fd_inc_sndbuf(s->notify_fd, NOTIFY_SNDBUF_SIZE); + + strncpy(sa.un.sun_path, e, sizeof(sa.un.sun_path)); + if (sa.un.sun_path[0] == '@') + sa.un.sun_path[0] = 0; + + r = connect(s->notify_fd, &sa.sa, SOCKADDR_UN_LEN(sa.un)); + if (r < 0) + return log_error_errno(errno, "Failed to connect to notify socket: %m"); + + r = sd_event_add_io(s->event, &s->notify_event_source, s->notify_fd, EPOLLOUT, dispatch_notify_event, s); + if (r < 0) + return log_error_errno(r, "Failed to watch notification socket: %m"); + + if (sd_watchdog_enabled(false, &s->watchdog_usec) > 0) { + s->send_watchdog = true; + + r = sd_event_add_time(s->event, &s->watchdog_event_source, CLOCK_MONOTONIC, now(CLOCK_MONOTONIC) + s->watchdog_usec/2, s->watchdog_usec/4, dispatch_watchdog, s); + if (r < 0) + return log_error_errno(r, "Failed to add watchdog time event: %m"); + } + + /* This should fire pretty soon, which we'll use to send the + * READY=1 event. */ + + return 0; +} + int server_init(Server *s) { _cleanup_fdset_free_ FDSet *fds = NULL; int n, r, fd; + bool no_sockets; assert(s); zero(*s); - s->syslog_fd = s->native_fd = s->stdout_fd = s->dev_kmsg_fd = s->audit_fd = s->hostname_fd = -1; + s->syslog_fd = s->native_fd = s->stdout_fd = s->dev_kmsg_fd = s->audit_fd = s->hostname_fd = s->notify_fd = -1; s->compress = true; s->seal = true; + s->watchdog_usec = USEC_INFINITY; + s->sync_interval_usec = DEFAULT_SYNC_INTERVAL_USEC; s->sync_scheduled = false; @@ -1475,18 +1872,19 @@ int server_init(Server *s) { s->max_level_console = LOG_INFO; s->max_level_wall = LOG_EMERG; - memset(&s->system_metrics, 0xFF, sizeof(s->system_metrics)); - memset(&s->runtime_metrics, 0xFF, sizeof(s->runtime_metrics)); + journal_reset_metrics(&s->system_metrics); + journal_reset_metrics(&s->runtime_metrics); server_parse_config_file(s); server_parse_proc_cmdline(s); + if (!!s->rate_limit_interval ^ !!s->rate_limit_burst) { log_debug("Setting both rate limit interval and burst from "USEC_FMT",%u to 0,0", s->rate_limit_interval, s->rate_limit_burst); s->rate_limit_interval = s->rate_limit_burst = 0; } - mkdir_p("/run/systemd/journal", 0755); + (void) mkdir_p("/run/systemd/journal", 0755); s->user_journals = ordered_hashmap_new(NULL); if (!s->user_journals) @@ -1496,12 +1894,14 @@ int server_init(Server *s) { if (!s->mmap) return log_oom(); + s->deferred_closes = set_new(NULL); + if (!s->deferred_closes) + return log_oom(); + r = sd_event_default(&s->event); if (r < 0) return log_error_errno(r, "Failed to create event loop: %m"); - sd_event_set_watchdog(s->event, true); - n = sd_listen_fds(true); if (n < 0) return log_error_errno(n, "Failed to read listening file descriptors from environment: %m"); @@ -1559,30 +1959,44 @@ int server_init(Server *s) { } } - r = server_open_stdout_socket(s, fds); - if (r < 0) - return r; + /* Try to restore streams, but don't bother if this fails */ + (void) server_restore_streams(s, fds); if (fdset_size(fds) > 0) { log_warning("%u unknown file descriptors passed, closing.", fdset_size(fds)); fds = fdset_free(fds); } + no_sockets = s->native_fd < 0 && s->stdout_fd < 0 && s->syslog_fd < 0 && s->audit_fd < 0; + + /* always open stdout, syslog, native, and kmsg sockets */ + + /* systemd-journald.socket: /run/systemd/journal/stdout */ + r = server_open_stdout_socket(s); + if (r < 0) + return r; + + /* systemd-journald-dev-log.socket: /run/systemd/journal/dev-log */ r = server_open_syslog_socket(s); if (r < 0) return r; + /* systemd-journald.socket: /run/systemd/journal/socket */ r = server_open_native_socket(s); if (r < 0) return r; + /* /dev/ksmg */ r = server_open_dev_kmsg(s); if (r < 0) return r; - r = server_open_audit(s); - if (r < 0) - return r; + /* Unless we got *some* sockets and not audit, open audit socket */ + if (s->audit_fd >= 0 || no_sockets) { + r = server_open_audit(s); + if (r < 0) + return r; + } r = server_open_kernel_seqnum(s); if (r < 0) @@ -1612,11 +2026,9 @@ int server_init(Server *s) { server_cache_boot_id(s); server_cache_machine_id(s); - r = system_journal_open(s, false); - if (r < 0) - return r; + (void) server_connect_notify(s); - return 0; + return system_journal_open(s, false); } void server_maybe_append_tags(Server *s) { @@ -1639,17 +2051,22 @@ void server_done(Server *s) { JournalFile *f; assert(s); + if (s->deferred_closes) { + journal_file_close_set(s->deferred_closes); + set_free(s->deferred_closes); + } + while (s->stdout_streams) stdout_stream_free(s->stdout_streams); if (s->system_journal) - journal_file_close(s->system_journal); + (void) journal_file_close(s->system_journal); if (s->runtime_journal) - journal_file_close(s->runtime_journal); + (void) journal_file_close(s->runtime_journal); while ((f = ordered_hashmap_steal_first(s->user_journals))) - journal_file_close(f); + (void) journal_file_close(f); ordered_hashmap_free(s->user_journals); @@ -1663,7 +2080,10 @@ void server_done(Server *s) { sd_event_source_unref(s->sigusr2_event_source); sd_event_source_unref(s->sigterm_event_source); sd_event_source_unref(s->sigint_event_source); + sd_event_source_unref(s->sigrtmin1_event_source); sd_event_source_unref(s->hostname_event_source); + sd_event_source_unref(s->notify_event_source); + sd_event_source_unref(s->watchdog_event_source); sd_event_unref(s->event); safe_close(s->syslog_fd); @@ -1672,6 +2092,7 @@ void server_done(Server *s) { safe_close(s->dev_kmsg_fd); safe_close(s->audit_fd); safe_close(s->hostname_fd); + safe_close(s->notify_fd); if (s->rate_limit) journal_rate_limit_free(s->rate_limit); @@ -1687,6 +2108,24 @@ void server_done(Server *s) { if (s->mmap) mmap_cache_unref(s->mmap); - if (s->udev) - udev_unref(s->udev); + udev_unref(s->udev); } + +static const char* const storage_table[_STORAGE_MAX] = { + [STORAGE_AUTO] = "auto", + [STORAGE_VOLATILE] = "volatile", + [STORAGE_PERSISTENT] = "persistent", + [STORAGE_NONE] = "none" +}; + +DEFINE_STRING_TABLE_LOOKUP(storage, Storage); +DEFINE_CONFIG_PARSE_ENUM(config_parse_storage, storage, Storage, "Failed to parse storage setting"); + +static const char* const split_mode_table[_SPLIT_MAX] = { + [SPLIT_LOGIN] = "login", + [SPLIT_UID] = "uid", + [SPLIT_NONE] = "none", +}; + +DEFINE_STRING_TABLE_LOOKUP(split_mode, SplitMode); +DEFINE_CONFIG_PARSE_ENUM(config_parse_split_mode, split_mode, SplitMode, "Failed to parse split mode setting"); |