selinux: log how much time it takes to load the SELinux policy and database

src/label.c

@@ -47,6 +47,7 @@ int label_init(void) {
         int r = 0;
 
 #ifdef HAVE_SELINUX
+        usec_t n;
 
         if (!use_selinux())
                 return 0;
@@ -54,12 +55,20 @@ int label_init(void) {
         if (label_hnd)
                 return 0;
 
+        n = now(CLOCK_MONOTONIC);
         label_hnd = selabel_open(SELABEL_CTX_FILE, NULL, 0);
         if (!label_hnd) {
                 log_full(security_getenforce() == 1 ? LOG_ERR : LOG_DEBUG,
                          "Failed to initialize SELinux context: %m");
                 r = security_getenforce() == 1 ? -errno : 0;
+        } else  {
+                char buf[FORMAT_TIMESPAN_MAX];
+
+                n = now(CLOCK_MONOTONIC) - n;
+                log_info("Successfully loaded SELinux database in %s.",
+                         format_timespan(buf, sizeof(buf), n));
         }
+
 #endif
 
         return r;

src/log.c

@@ -231,6 +231,12 @@ void log_set_target(LogTarget target) {
         log_target = target;
 }
 
+void log_close(void) {
+        log_close_console();
+        log_close_kmsg();
+        log_close_syslog();
+}
+
 void log_set_max_level(int level) {
         assert((level & LOG_PRIMASK) == level);
 

src/log.h

@@ -56,6 +56,7 @@ LogTarget log_get_target(void);
 int log_get_max_level(void);
 
 int log_open(void);
+void log_close(void);
 
 void log_close_syslog(void);
 void log_close_kmsg(void);

src/main.c

@@ -1046,6 +1046,7 @@ int main(int argc, char *argv[]) {
         if (getpid() == 1) {
                 arg_running_as = MANAGER_SYSTEM;
                 log_set_target(detect_container(NULL) > 0 ? LOG_TARGET_CONSOLE : LOG_TARGET_SYSLOG_OR_KMSG);
+                log_open();
 
                 /* This might actually not return, but cause a
                  * reexecution */
@@ -1064,9 +1065,11 @@ int main(int argc, char *argv[]) {
                         else
                                 log_info("RTC configured in localtime, applying delta of %i minutes to system time.", min);
                 }
+
         } else {
                 arg_running_as = MANAGER_USER;
                 log_set_target(LOG_TARGET_AUTO);
+                log_open();
         }
 
         if (set_default_unit(SPECIAL_DEFAULT_TARGET) < 0)
@@ -1122,6 +1125,9 @@ int main(int argc, char *argv[]) {
 
         assert_se(arg_action == ACTION_RUN || arg_action == ACTION_TEST);
 
+        /* Close logging fds, in order not to confuse fdset below */
+        log_close();
+
         /* Remember open file descriptors for later deserialization */
         if (serialization) {
                 if ((r = fdset_new_fill(&fds)) < 0) {

src/selinux-setup.c

@@ -37,6 +37,7 @@
 int selinux_setup(char *const argv[]) {
 #ifdef HAVE_SELINUX
        int enforce = 0;
+       usec_t n;
 
        /* Already initialized? */
        if (path_is_mount_point("/sys/fs/selinux") > 0 ||
@@ -48,8 +49,13 @@ int selinux_setup(char *const argv[]) {
         * relabel things. */
        touch("/dev/.systemd-relabel-run-dev");
 
+       n = now(CLOCK_MONOTONIC);
        if (selinux_init_load_policy(&enforce) == 0) {
-               log_debug("Successfully loaded SELinux policy, reexecuting.");
+               char buf[FORMAT_TIMESPAN_MAX];
+
+               n = now(CLOCK_MONOTONIC) - n;
+               log_info("Successfully loaded SELinux policy in %s, reexecuting.",
+                         format_timespan(buf, sizeof(buf), n));
 
                /* FIXME: Ideally we'd just call setcon() here instead
                 * of having to reexecute ourselves here. */