Add xsyslog_ev function and related #5186

mjdominus-cyrus · 2024-12-23T20:49:03Z

Per https://linear.app/fastmail/issue/CYR-1407/produce-new-xsyslog-ev-function

Also:

Adds a new test suite, util.testc
Tests pass and valgrind is clean
Includes some unrelated minor documentation fixes and other corrections

rsto

I like improving the log format! It's also great we got proper unit tests for this.

Apart from the few items I found in the code, I wonder:
Is there a canonical specification for logfmt somewhere? I see our tests don't assert how empty strings in the key or value are handled, would that be the empty string or ""?

I'm a bit wary of the magic printf formatter guessing, but it looks well thought out so let's see how it turns out in practice.

One other thing that stands out to me are the commit message: in Cyrus, we typically prefix the commit message with the filename that mostly got changed in this commit (e.g. util.c). Also, our commit messages almost always start with a verb.

lib/util.c

rjbs · 2024-12-24T14:11:35Z

@rsto logfmt is, in my experience, insufficiently documented in the wild. The most cited source is https://brandur.org/logfmt which I find useful but … well, it wouldn't make a good I-D.

I thought we'd improved the clarity of this in the Fastmail internal spec, but I'm wrong. We just use Perl's Log::Fmt, which I wrote. In that, the value must have length, so x="" and not x=. (It serializes Perl's undef value as ~missing~.)

Also start test suite for util.c functions

Also, more comments The history of this commit and the previous is complicated: * MJD wrote an initial draft commit * Ken revised it to use struct buf instead of C strings * MJD came back and restored his original comments and replaced the printf hackery with smaller printf hackery NB: The diff for this commit is a mess --- *unless* you use Git's --patience option.

…mpty string And regression test

mjdominus-cyrus · 2024-12-24T20:16:14Z

The new version has exactly the same changes as before, except:

I redid all the commit messages
There are three new commits on the end to address the case -1, the goto, and the escaped version of the empty string

wolfsage · 2024-12-26T16:37:11Z

lib/util.c

+    va_end(ap);
+
+    if (!s) {
+        syslog(priority, "COULD NOT FORMAT SYSLOG STRING FOR EVENT '%s'", event_name);


Priority might be a LOG_INFO, we probably want to elevate this to LOG_ERR

Yeah -- here, the function is reporting its own errors, so it shouldn't be using the caller's error level. I might even go so far as LOG_CRITICAL (or whatever it's called), since I think this is a programmer error, not a runtime error.

wolfsage · 2024-12-26T16:45:58Z

lib/util.c

+    default:
+        // This seems extreme at first but the alternative is to leave ap pointing to the wrong argument,
+        // and that is already undefined behavior, likely a segfault, so this is really the best we can do
+        abort();


I think instead you want fatal("some descriptive error message", EX_TEMPFAIL) which each program that runs cyrus code defines to do the right thing with the message, and then abort or shut down cleanly based on config and other things.

Alternatively, syslog some useful message before dying?

Yep, fatal() is the thing to do here.

wolfsage · 2024-12-26T17:24:48Z

lib/util.c

+ *
+ *     xsyslog_ev_fmt("earthquake",
+ *                    "location", "%s", "Dubuque",
+ *                    "richter", "%5.1f", 7.9)


This doesn't document the final necessary NULL, we should in all of the examples, etc...

wolfsage · 2024-12-26T17:24:57Z

lib/util.c

+ * char *s = xsyslog_ev_fmt(event_name,
+ *                          key1, fmt1, val1,
+ *                          key2, fmt2, val2,
+ *                          ...);


Maybe ..., NULL);

wolfsage · 2024-12-26T17:26:26Z

lib/util.c

+ *
+ * WARNING:
+ *   the function only supports a subset of sprintf-style escapes.
+ *   in particular, each format string MUST contain EXACTLY ONE %-escape.


This says MUST but that restriction isn't enforced. It might be a good idea to fatal() if the formats have more than one %... specification

elliefm

My review is mostly a handful of style nits and advicey comments.

Bigger picture, I don't like the design; but given the design, this seems like a solid implementation of it. If we're considering this a proof of concept, I'd say it proves I don't like the design. :)

elliefm · 2024-12-26T23:34:10Z

cunit/util.testc

+        free(result);
+}
+
+    // tests for weird __sep__ feature


nit: these could/should be separate test functions, we're not constrained to one-test-function-per-api-function

elliefm · 2024-12-26T23:37:02Z

cunit/util.testc

+        result = xsyslog_ev_fmt(
+               "event-name",
+               "firstname", "%s", "Fred",
+               NULL);


nit: it would be more typical in this codebase to format these calls something like:

Suggested change

result = xsyslog_ev_fmt(

"event-name",

"firstname", "%s", "Fred",

NULL);

result = xsyslog_ev_fmt("event-name",

"firstname", "%s", "Fred",

NULL);

Further into the review, I saw you formatted this sort of thing elsewhere in the way I suggest here, but I forgot to come back and update this comment.

elliefm · 2024-12-26T23:45:33Z

cunit/util.testc

+     const char *test[] = {
+         /* input,           expected output */
+         "foo",              "foo",
+         "foo bar",          "\"foo bar\"",
+         "call me \"fred\"", "\"call me \\\"fred\\\"\"",
+         "\n",               "\"\\n\"",
+         "\r",               "\"\\r\"",
+         "\r\n",             "\"\\r\\n\"",
+         "-12.345e67",       "-12.345e67",
+         "",                 "\"\"",
+         NULL,
+     };
+


I like to do this sort of thing with a const array of anonymous structs, like:

const struct { const char *input; const char *expected; } tests[] = { { "foo", "foo" }, { "foo bar", "\"foo bar\"" }, // etc // n.b. does not need a NULL element at the end, // because n_tests tells us how many there are }; const size_t n_tests = sizeof(tests) / sizeof(tests[0]); unsigned i; for (i = 0; i < n_tests; i++) { // now we can refer to tests[i].input and tests[i].expected // instead of fiddling with indexes }

I see little benefit either way.

elliefm · 2024-12-26T23:51:38Z

lib/util.c

+    va_end(ap);
+
+    if (!s) {
+        syslog(priority, "COULD NOT FORMAT SYSLOG STRING FOR EVENT '%s'", event_name);


Yeah -- here, the function is reporting its own errors, so it shouldn't be using the caller's error level. I might even go so far as LOG_CRITICAL (or whatever it's called), since I think this is a programmer error, not a runtime error.

elliefm · 2024-12-27T00:00:23Z

lib/util.c

+        // special case: __sep__ means reconfigure the separator
+        if (!strcmp(key, "__sep__")) {
+            sep = va_arg(ap, const char *);
+        }


Is this actually useful? Surely if we're going to all this effort it's because we want our logs to be in a consistent format

Probably not. I only threw it in as a possibly interesting suggestion.

YAGNI says to eliminate it and its associated tests.

elliefm · 2024-12-27T00:06:54Z

lib/util.c

+    default:
+        // This seems extreme at first but the alternative is to leave ap pointing to the wrong argument,
+        // and that is already undefined behavior, likely a segfault, so this is really the best we can do
+        abort();


Yep, fatal() is the thing to do here.

elliefm · 2024-12-27T00:08:36Z

lib/util.c

+    }
+}
+
+/* Quick-and-dirty parser for SINGLE, COMMON printf-type escape strings


If we have to have our own parser for printf escape sequences, have we not lost all value we were going to gain by using them in the first place?

Yeah. I thought @rjbs had suggested that rather than using a printf-style format string, we just use an enum like [CHAR, STRING, INT, FLOAT] and then convert those into format strings

Rik and I discussed that. i think I persuaded him that this is better, because:

You can write "%5.2f" and "%-20s" and other possibly useful formats

Why use and maintain a set of enum constants that mean "%s" and "%d" when you can just use self-documenting "%s" and "%d"

elliefm · 2024-12-27T00:15:19Z

lib/util.c

+ *   p   if the expected argument is a (void *)
+ *   -1  if it's something else
+ */
+static char xsyslog_ev_guess_printf_escape(const char *s) {


This should probably return int rather than char. It's fine for it to be logically a single character still, but it's usual in C to use the int type for single characters, for reasons I don't quite remember, but which might be related to the implicit type promotion rules and/or the fact that the signedness of char is platform-dependent.

See for example the int c argument to char *strchr(const char *s, int c);

rsto · 2024-12-27T07:36:34Z

We just use Perl's Log::Fmt, which I wrote. In that, the value must have length, so x="" and not x=. (It serializes Perl's undef value as ~missing~.)

Requiring a non-zero length value sounds sane to me, we should do the same in the Cyrus implementation.

mjdominus-cyrus · 2024-12-27T20:32:45Z

Today is my last day in this job. Rather than make further revisions to this code, I will leave it to you folks to decide what to do with it, if anything.

mjdominus-cyrus force-pushed the cyr-1407-xsyslog_ev-1223 branch from c471a74 to e5a4647 Compare December 23, 2024 21:10

rsto self-requested a review December 24, 2024 06:04

rsto requested changes Dec 24, 2024

View reviewed changes

lib/util.c Outdated Show resolved Hide resolved

lib/util.c Outdated Show resolved Hide resolved

mjdominus and others added 12 commits December 24, 2024 15:05

unit-tests.rst: fix incorrect HTML anchor target

4fc4e1d

unit-tests.rst fix inconsistent section numbering

607dc52

unit-tests.rst: consistent TOC formatting

610c7f6

Makefile.am: correct path to libtool

d5c1b16

util.c: add xsyslog_ev function

b85e6c9

Also start test suite for util.c functions

util.testc: add more unit tests for xsyslog_ev helpers

a2d4b98

util.testc: add tests for xsyslog_ev_guess_printf_escape

88e8c92

util.c: finish fixes to xsyslog_ev and its tests

00a89e6

util.c: bug fix: xsyslog_ev_escape_value learns to always quote the e…

c4e782a

…mpty string And regression test

util.c: replace goto with while-break logic

7379a1a

util.c: remove nonportable -1 case in switch

7125329

mjdominus-cyrus force-pushed the cyr-1407-xsyslog_ev-1223 branch from e5a4647 to 7379a1a Compare December 24, 2024 20:12

mjdominus-cyrus requested a review from rsto December 24, 2024 20:13

wolfsage reviewed Dec 26, 2024

View reviewed changes

elliefm reviewed Dec 27, 2024

View reviewed changes

rsto removed their request for review January 8, 2025 07:42

wolfsage self-assigned this Jan 9, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add xsyslog_ev function and related #5186

Add xsyslog_ev function and related #5186

mjdominus-cyrus commented Dec 23, 2024

rsto left a comment

rjbs commented Dec 24, 2024

mjdominus-cyrus commented Dec 24, 2024 •

edited

Loading

wolfsage Dec 26, 2024

elliefm Dec 26, 2024

wolfsage Dec 26, 2024

elliefm Dec 27, 2024

wolfsage Dec 26, 2024

wolfsage Dec 26, 2024

wolfsage Dec 26, 2024

elliefm left a comment

elliefm Dec 26, 2024

elliefm Dec 26, 2024

elliefm Dec 27, 2024

elliefm Dec 26, 2024

mjdominus-cyrus Dec 27, 2024

elliefm Dec 26, 2024

elliefm Dec 27, 2024

mjdominus-cyrus Dec 27, 2024

elliefm Dec 27, 2024

elliefm Dec 27, 2024

ksmurchison Dec 27, 2024

mjdominus-cyrus Dec 27, 2024

elliefm Dec 27, 2024

rsto commented Dec 27, 2024

mjdominus-cyrus commented Dec 27, 2024

Add xsyslog_ev function and related #5186

Are you sure you want to change the base?

Add xsyslog_ev function and related #5186

Conversation

mjdominus-cyrus commented Dec 23, 2024

rsto left a comment

Choose a reason for hiding this comment

rjbs commented Dec 24, 2024

mjdominus-cyrus commented Dec 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

elliefm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rsto commented Dec 27, 2024

mjdominus-cyrus commented Dec 27, 2024

mjdominus-cyrus commented Dec 24, 2024 •

edited

Loading