--- systemd-191.old/src/shared/log.h 2012-09-04 17:13:17.008107424 -0400 +++ systemd-191.new/src/shared/log.h 2012-09-22 00:34:28.988074097 -0400 @@ -84,12 +84,14 @@ int log_metav( const char *format, va_list ap); +const char *log_struct_entry( + const char *format, ...) _sentinel_; + int log_struct_internal( int level, const char *file, int line, - const char *func, - const char *format, ...) _sentinel_; + const char *func, ...) _sentinel_; int log_oom_internal( const char *file, --- systemd-191.old/src/shared/log.c 2012-09-21 06:07:41.885429447 -0400 +++ systemd-191.new/src/shared/log.c 2012-09-22 00:34:29.016074091 -0400 @@ -649,15 +649,29 @@ int log_oom_internal(const char *file, i return -ENOMEM; } +const char *log_struct_entry( + const char *format, ...) { + + char *buf; + va_list ap; + + va_start(ap, format); + if (vasprintf(&buf, format, ap) < 0) + buf = NULL; + + va_end(ap); + return buf; +} + int log_struct_internal( int level, const char *file, int line, - const char *func, - const char *format, ...) { + const char *func, ...) { int saved_errno; va_list ap; + char *buf; int r; if (_likely_(LOG_PRI(level) > log_max_level)) @@ -702,22 +716,14 @@ int log_struct_internal( zero(iovec); IOVEC_SET_STRING(iovec[n++], header); - va_start(ap, format); - while (format && n + 1 < ELEMENTSOF(iovec)) { - char *buf; - - if (vasprintf(&buf, format, ap) < 0) { - r = -ENOMEM; - goto finish; - } + va_start(ap, func); + while ((buf=va_arg(ap, char *)) && n + 1 < ELEMENTSOF(iovec)) { IOVEC_SET_STRING(iovec[n++], buf); iovec[n].iov_base = (char*) &nl; iovec[n].iov_len = 1; n++; - - format = va_arg(ap, char *); } zero(mh); @@ -735,23 +741,20 @@ int log_struct_internal( free(iovec[i].iov_base); } else { - char buf[LINE_MAX]; bool found = false; /* Fallback if journal logging is not available */ - va_start(ap, format); - while (format) { + va_start(ap, func); + while ((buf=va_arg(ap, char *))) { - vsnprintf(buf, sizeof(buf), format, ap); char_array_0(buf); if (startswith(buf, "MESSAGE=")) { found = true; break; } - - format = va_arg(ap, char *); + free(buf); } va_end(ap); @@ -759,6 +762,8 @@ int log_struct_internal( r = log_dispatch(level, file, line, func, buf + 8); else r = -EINVAL; + + if (buf) free(buf); } errno = saved_errno; --- systemd-191.old/src/timedate/timedated.c 2012-09-20 14:50:55.014046686 -0400 +++ systemd-191.new/src/timedate/timedated.c 2012-09-22 00:34:29.017074095 -0400 @@ -701,9 +701,9 @@ static DBusHandlerResult timedate_messag } log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIMEZONE_CHANGE), - "TIMEZONE=%s", tz.zone, - "MESSAGE=Changed timezone to '%s'.", tz.zone, + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIMEZONE_CHANGE)), + log_struct_entry("TIMEZONE=%s", tz.zone), + log_struct_entry("MESSAGE=Changed timezone to '%s'.", tz.zone), NULL); changed = bus_properties_changed_new( @@ -843,9 +843,9 @@ static DBusHandlerResult timedate_messag hwclock_set_time(tm); log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIME_CHANGE), - "REALTIME=%llu", (unsigned long long) timespec_load(&ts), - "MESSAGE=Changed local time to %s", ctime(&ts.tv_sec), + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_TIME_CHANGE)), + log_struct_entry("REALTIME=%llu", (unsigned long long) timespec_load(&ts)), + log_struct_entry("MESSAGE=Changed local time to %s", ctime(&ts.tv_sec)), NULL); } } else if (dbus_message_is_method_call(message, "org.freedesktop.timedate1", "SetNTP")) { --- systemd-191.old/src/login/logind-dbus.c 2012-09-21 09:39:25.188439475 -0400 +++ systemd-191.new/src/login/logind-dbus.c 2012-09-22 00:34:29.019074104 -0400 @@ -1181,9 +1181,10 @@ static int bus_manager_log_shutdown( } return log_struct(LOG_NOTICE, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SHUTDOWN), - p, - q, NULL); + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SHUTDOWN)), + log_struct_entry(p), + log_struct_entry(q), + NULL); } int bus_manager_shutdown_or_sleep_now_or_later( --- systemd-191.old/src/login/logind-session.c 2012-09-21 10:04:48.956899484 -0400 +++ systemd-191.new/src/login/logind-session.c 2012-09-22 00:34:29.066074064 -0400 @@ -547,11 +547,11 @@ int session_start(Session *s) { return r; log_struct(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_START), - "SESSION_ID=%s", s->id, - "USER_ID=%s", s->user->name, - "LEADER=%lu", (unsigned long) s->leader, - "MESSAGE=New session %s of user %s.", s->id, s->user->name, + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_START)), + log_struct_entry("SESSION_ID=%s", s->id), + log_struct_entry("USER_ID=%s", s->user->name), + log_struct_entry("LEADER=%lu", (unsigned long) s->leader), + log_struct_entry("MESSAGE=New session %s of user %s.", s->id, s->user->name), NULL); /* Create cgroup */ @@ -689,11 +689,11 @@ int session_stop(Session *s) { if (s->started) log_struct(s->type == SESSION_TTY || s->type == SESSION_X11 ? LOG_INFO : LOG_DEBUG, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_STOP), - "SESSION_ID=%s", s->id, - "USER_ID=%s", s->user->name, - "LEADER=%lu", (unsigned long) s->leader, - "MESSAGE=Removed session %s.", s->id, + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SESSION_STOP)), + log_struct_entry("SESSION_ID=%s", s->id), + log_struct_entry("USER_ID=%s", s->user->name), + log_struct_entry("LEADER=%lu", (unsigned long) s->leader), + log_struct_entry("MESSAGE=Removed session %s.", s->id), NULL); /* Kill cgroup */ --- systemd-191.old/src/login/logind-seat.c 2012-09-17 05:38:43.609698314 -0400 +++ systemd-191.new/src/login/logind-seat.c 2012-09-22 00:34:29.067074075 -0400 @@ -341,9 +341,9 @@ int seat_start(Seat *s) { return 0; log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SEAT_START), - "SEAT_ID=%s", s->id, - "MESSAGE=New seat %s.", s->id, + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SEAT_START)), + log_struct_entry("SEAT_ID=%s", s->id), + log_struct_entry("MESSAGE=New seat %s.", s->id), NULL); /* Initialize VT magic stuff */ --- systemd-191.old/src/test/test-log.c 2012-09-04 17:13:17.013107395 -0400 +++ systemd-191.new/src/test/test-log.c 2012-09-22 00:34:29.067074075 -0400 @@ -30,16 +30,16 @@ int main(int argc, char* argv[]) { log_open(); log_struct(LOG_INFO, - "MESSAGE=Waldo PID=%lu", (unsigned long) getpid(), - "SERVICE=piepapo", + log_struct_entry("MESSAGE=Waldo PID=%lu", (unsigned long) getpid()), + log_struct_entry("SERVICE=piepapo"), NULL); log_set_target(LOG_TARGET_JOURNAL); log_open(); log_struct(LOG_INFO, - "MESSAGE=Foobar PID=%lu", (unsigned long) getpid(), - "SERVICE=foobar", + log_struct_entry("MESSAGE=Foobar PID=%lu", (unsigned long) getpid()), + log_struct_entry("SERVICE=foobar"), NULL); return 0; --- systemd-191.old/src/sleep/sleep.c 2012-09-04 17:13:17.011107406 -0400 +++ systemd-191.new/src/sleep/sleep.c 2012-09-22 00:34:29.068074085 -0400 @@ -69,15 +69,15 @@ int main(int argc, char *argv[]) { if (streq(argv[1], "suspend")) log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START), - "MESSAGE=Suspending system...", - "SLEEP=suspend", + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START)), + log_struct_entry("MESSAGE=Suspending system..."), + log_struct_entry("SLEEP=suspend"), NULL); else log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START), - "MESSAGE=Hibernating system...", - "SLEEP=hibernate", + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_START)), + log_struct_entry("MESSAGE=Hibernating system..."), + log_struct_entry("SLEEP=hibernate"), NULL); fputs(verb, f); @@ -88,15 +88,15 @@ int main(int argc, char *argv[]) { if (streq(argv[1], "suspend")) log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP), - "MESSAGE=System resumed.", - "SLEEP=suspend", + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP)), + log_struct_entry("MESSAGE=System resumed."), + log_struct_entry("SLEEP=suspend"), NULL); else log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP), - "MESSAGE=System thawed.", - "SLEEP=hibernate", + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_SLEEP_STOP)), + log_struct_entry("MESSAGE=System thawed."), + log_struct_entry("SLEEP=hibernate"), NULL); arguments[1] = (char*) "post"; --- systemd-191.old/src/core/job.c 2012-09-04 17:13:16.979107585 -0400 +++ systemd-191.new/src/core/job.c 2012-09-22 00:34:29.108074133 -0400 @@ -705,26 +705,26 @@ static void job_log_status_message(Unit mid = result == JOB_DONE ? SD_MESSAGE_UNIT_STARTED : SD_MESSAGE_UNIT_FAILED; log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid), - "UNIT=%s", u->id, - "RESULT=%s", job_result_to_string(result), - "MESSAGE=%s", buf, + log_struct_entry("MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid)), + log_struct_entry("UNIT=%s", u->id), + log_struct_entry("RESULT=%s", job_result_to_string(result)), + log_struct_entry("MESSAGE=%s", buf), NULL); } else if (t == JOB_STOP) log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_STOPPED), - "UNIT=%s", u->id, - "RESULT=%s", job_result_to_string(result), - "MESSAGE=%s", buf, + log_struct_entry("MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_STOPPED)), + log_struct_entry("UNIT=%s", u->id), + log_struct_entry("RESULT=%s", job_result_to_string(result)), + log_struct_entry("MESSAGE=%s", buf), NULL); else if (t == JOB_RELOAD) log_struct(result == JOB_DONE ? LOG_INFO : LOG_ERR, - "MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_RELOADED), - "UNIT=%s", u->id, - "RESULT=%s", job_result_to_string(result), - "MESSAGE=%s", buf, + log_struct_entry("MESSSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_UNIT_RELOADED)), + log_struct_entry("UNIT=%s", u->id), + log_struct_entry("RESULT=%s", job_result_to_string(result)), + log_struct_entry("MESSAGE=%s", buf), NULL); } #pragma GCC diagnostic pop --- systemd-191.old/src/core/unit.c 2012-09-19 03:58:34.539757449 -0400 +++ systemd-191.new/src/core/unit.c 2012-09-22 00:34:29.110074135 -0400 @@ -1023,9 +1023,9 @@ static void unit_status_log_starting_sto SD_MESSAGE_UNIT_RELOADING; log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid), - "UNIT=%s", u->id, - "MESSAGE=%s", buf, + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(mid)), + log_struct_entry("UNIT=%s", u->id), + log_struct_entry("MESSAGE=%s", buf), NULL); } #pragma GCC diagnostic pop --- systemd-191.old/src/core/manager.c 2012-09-19 03:58:34.534757442 -0400 +++ systemd-191.new/src/core/manager.c 2012-09-22 00:34:29.112074137 -0400 @@ -2054,15 +2054,16 @@ void manager_check_finished(Manager *m) if (!log_on_console()) log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED), - "KERNEL_USEC=%llu", (unsigned long long) kernel_usec, - "INITRD_USEC=%llu", (unsigned long long) initrd_usec, - "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec, - "MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.", - format_timespan(kernel, sizeof(kernel), kernel_usec), - format_timespan(initrd, sizeof(initrd), initrd_usec), - format_timespan(userspace, sizeof(userspace), userspace_usec), - format_timespan(sum, sizeof(sum), total_usec), + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED)), + log_struct_entry("KERNEL_USEC=%llu", (unsigned long long) kernel_usec), + log_struct_entry("INITRD_USEC=%llu", (unsigned long long) initrd_usec), + log_struct_entry("USERSPACE_USEC=%llu", (unsigned long long) userspace_usec), + log_struct_entry("MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.", + format_timespan(kernel, sizeof(kernel), kernel_usec), + format_timespan(initrd, sizeof(initrd), initrd_usec), + format_timespan(userspace, sizeof(userspace), userspace_usec), + format_timespan(sum, sizeof(sum), total_usec) + ), NULL); } else { kernel_usec = m->userspace_timestamp.monotonic - m->kernel_timestamp.monotonic; @@ -2070,13 +2071,14 @@ void manager_check_finished(Manager *m) if (!log_on_console()) log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED), - "KERNEL_USEC=%llu", (unsigned long long) kernel_usec, - "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec, - "MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.", - format_timespan(kernel, sizeof(kernel), kernel_usec), - format_timespan(userspace, sizeof(userspace), userspace_usec), - format_timespan(sum, sizeof(sum), total_usec), + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED)), + log_struct_entry("KERNEL_USEC=%llu", (unsigned long long) kernel_usec), + log_struct_entry("USERSPACE_USEC=%llu", (unsigned long long) userspace_usec), + log_struct_entry("MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.", + format_timespan(kernel, sizeof(kernel), kernel_usec), + format_timespan(userspace, sizeof(userspace), userspace_usec), + format_timespan(sum, sizeof(sum), total_usec) + ), NULL); } } else { @@ -2085,10 +2087,9 @@ void manager_check_finished(Manager *m) if (!log_on_console()) log_struct(LOG_INFO, - "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED), - "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec, - "MESSAGE=Startup finished in %s.", - format_timespan(sum, sizeof(sum), total_usec), + log_struct_entry("MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED)), + log_struct_entry("USERSPACE_USEC=%llu", (unsigned long long) userspace_usec), + log_struct_entry("MESSAGE=Startup finished in %s.", format_timespan(sum, sizeof(sum), total_usec)), NULL); }