Add xsyslog_ev - a logfmt style logger

[wolfsage]

This implements roughly the same logging format as https://metacpan.org/dist/Log-Dispatchouli/source/lib/Log/Fmt.pm.

It's structed in a way to maintain compiler time safety checks around variable assignments, type conversions, and printf format strings.

A simple usage looks like:

int errors = 0;
...
xsyslog_ev(LOG_ERR, "name of event", lf_d("error-count", errors));

which will produce a log entry looking like:

event="name of event" error-count=3

This provides a number of common printf-style formats used in our existing logs as macros to get the same behaviour. For example, for '%d', you'd use lf_d("key", value), for '%s', lf_s(...), etc...

If you want more control over formatting, there's also lf_raw:

xsyslog_ev(LOG_ERR, "event", lf_raw("float", "%.02f", 3.14159));

which produces:

event="event" float=3.14

(lf_raw should probably be used sparingly as it adds more inline code to each place that uses it, increasing binary size...)

You can use as many macros together as necessary. Taking a real example:

xsyslog(LOG_ERR, "DBERROR: database needs upgrade",
                 "fname=<%s> have=<%d> want=<%d> error=<%s>",
                 open->fname, open->version, version,
                 sqlite3_errmsg(open->db));

becomes:

xsyslog_ev(LOG_ERR, "DBERROR: database needs upgrade",
    lf_s("fname", open->fname),
    lf_d("have", open->version),
    lf_d("want", version),
    lf_s("error", sqlite3_errmsg(open->db))
);

_xsyslog_ev_escape() comes from Ken Murchison with modifications by Mark Jason Dominus and myself.

This work is based off of some back and forth conversations with ellie.

[ksmurchison]

LGTM

[rjbs]

I'll try to come back and look at writing tests, but I suspect this is not quite enough. The Perl version, of course, can do all kinds of stuff for free, and it's okay to do worse, here, but we should consider that this is likely going to get called on email headers, so \t should be handled, at the very least. Probably the biggest question is whether we want to assume that non-ASCII UTF-8 can/should be logged escaped or not. I think we can punt on that and come back to it later, because we could "just" fix it later. So, then what do we need to do now?

• \x21 \x23-\x3C \x3E-x7E do not force quoting and remain as is
• the existing special cases ([\\ \n \r "]) force quoting and become two chars
• literal space forces quoting and remains space
• any other character is forces quoting and remains self for now

That last case is the more complex one. It leaves a hard tab in place, which kind of sucks, but it lets "ÿ" look correct when catted. I think the UTF-8 string case is more common for now. (The ideal solution without respect to complexity would be to iterate over Unicode codepoints and act based on general properties. :) )

[wolfsage]

Fixed, see what you think?

Relatedly... you say \x3E-x7E but that includes 0x5C which is a '' which you then say should be quoted and escaped.

It looks like the perl implementation doesn't detect '' as needing escaping or quoting (unless something else is detected as needed escaping). I think that's a bug?

[rjbs]

0x5C is not ", it's \

" is 0x22. So, we do NOT quote things with \. I think this is fine:

  DB<4> x Log::Fmt->format_event_string([ a => qq{pan\\ama} ])
0  'a=pan\\ama'

It is not ambiguous when parsing.

[wolfsage]

I wonder if we even want to support/use %m or errno in this way. It's possible something could change errno by the time we get to it here due to one of the buf_printfs doing something weird, or if a xsyslog_ev(...) uses a function as an argument that changes errno...

I can work around it, but it makes me think our existing uses of '%m' could be wrong and that xsyslog even has this wrong...

[wolfsage]

Something like this:

diff --git a/cunit/xsyslog_ev.testc b/cunit/xsyslog_ev.testc
index 7618d31e7e..646800b254 100644
--- a/cunit/xsyslog_ev.testc
+++ b/cunit/xsyslog_ev.testc
@@ -131,6 +131,13 @@ static void test_lf_f(void)
     CU_ASSERT_SYSLOG(/*all*/0, 1);
 }
 
+int mess_with_errno()
+{
+    errno = errno + 1;
+
+    return 1;
+}
+
 static void test_lf_m(void)
 {
     struct buf expect = BUF_INITIALIZER;
@@ -139,7 +146,7 @@ static void test_lf_m(void)
     size_t i;
     int needs_quotes = 0;
 
-    buf_printf(&expect, "event=\"lf_m test\"");
+    buf_printf(&expect, "event=\"lf_m test\" a=1");
 
     // escape error string if necessary...
     for (i = 0; i < strlen(errstr); i++) {
@@ -175,9 +182,15 @@ static void test_lf_m(void)
         buf_printf(&expect, " error=%s", buf_cstring(&errbuf));
     }
 
+    buf_printf(&expect, " b=1");
+
     CU_SYSLOG_MATCH(buf_cstring(&expect));
     errno = 1;
-    xsyslog_ev(LOG_ERR, "lf_m test", lf_m("error"));
+    xsyslog_ev(LOG_ERR, "lf_m test",
+        lf_d("a", mess_with_errno()),
+        lf_m("error"),
+        lf_d("b", mess_with_errno())
+    );
     CU_ASSERT_SYSLOG(/*all*/0, 1);
 
     buf_free(&errbuf);
diff --git a/lib/util.c b/lib/util.c
index 67463ee437..b8c885b8df 100644
--- a/lib/util.c
+++ b/lib/util.c
@@ -2272,11 +2272,10 @@ static char *_xsyslog_ev_escape(const char *val)
     return buf_release(&buf);
 }
 
-EXPORTED void _xsyslog_ev(int priority, const char *event,
+EXPORTED void _xsyslog_ev(int saved_errno, int priority, const char *event,
                           logfmt_arg_list *arg)
 {
     static struct buf buf = BUF_INITIALIZER;
-    int saved_errno = errno;
 
     char *escaped = _xsyslog_ev_escape(event);
     buf_printf(&buf, "event=%s", escaped);
@@ -2298,7 +2297,7 @@ EXPORTED void _xsyslog_ev(int priority, const char *event,
         case LF_LLX: buf_printf(&buf, "%llx", arg->data[i].llu); break;
         case LF_F:   buf_printf(&buf, "%f",   arg->data[i].f);   break;
         case LF_M:
-            char *escaped_errno = _xsyslog_ev_escape(strerror(errno));
+            char *escaped_errno = _xsyslog_ev_escape(strerror(saved_errno));
             buf_appendcstr(&buf, escaped_errno);
             free(escaped_errno);
             break;
diff --git a/lib/util.h b/lib/util.h
index ef7352da49..52a2686ac8 100644
--- a/lib/util.h
+++ b/lib/util.h
@@ -474,11 +474,14 @@ typedef struct logfmt_arg_list {
         (logfmt_arg []){ARRAY}                               \
     }
 
-void _xsyslog_ev(int priority, const char *event,
+void _xsyslog_ev(int saved_errno, int priority, const char *event,
                  logfmt_arg_list *arg);
 
-#define xsyslog_ev(priority, event, ...)                       \
-    _xsyslog_ev(priority, event, logfmt_arg_LIST(__VA_ARGS__))
+#define xsyslog_ev(priority, event, ...)                                \
+    do {                                                                \
+        int se = errno;                                                 \
+        _xsyslog_ev(se, priority, event, logfmt_arg_LIST(__VA_ARGS__)); \
+    } while (0)
 
 enum logfmt_type {
     LF_C,

[wolfsage]

I've gone and applied this patch. I think it's right.

[rsto]

This looks to do what it says on the tin and I think it's much cleaner than the previous proposal. Just have some nits.