feat(trace): Log output readability and consistency (#583)

The motivation of this change is to improve the readability of the logs
without introducing a new formatter or breaking our existing
compatibility with the logfmt standard.

## Timestamp

Currently our log messages have the timestamp at the end of the line.
This means the timestamp is in a different position for every log
message, making it difficult to find when you're quickly skimming the
logs.

This PR moves the timestamp to the beginning of the line. This is
typically where loggers display the time, so it's what most people will
be used to.

Putting fixed-size items at the beginning of the line improves the
alignment of the log contents, which makes the logs more organized and
consistent. This helps the logs look a little more like a table instead
of randomly scattered text.

It's typical to look at the timestamp for multiple messages at once, to
understand how long certain processes are taking. By keeping the
timestamp in a consistent location, this process is easier.

## Warn

I also changed "warning" messages to be printed as "warn". This also has
multiple benefits:
- Consistency between the code and logs: Previously the code said "warn"
and the logs said "warning". Now both say "warn"
- Consistency with other logging libraries: "Warn" is more commonly used
as a log level than "warning" in most other languages. The standard
loggers in Zig, Rust, Go, and Java all use the word "warn."
- Log alignment. Similar to the point for the timestamp, "warn" helps
improve the alignment and visual appearance of the logs. With 4
characters, it's closer in length to other log levels.

## Refactor

I refactored the `writeLog` and `countLog` functions to extract out the
common logic into a single function. This makes it easier to keep the
two functions consistent with each other.

## Other ideas

I was also tempted to pad out the log-level with spaces to ensure that
it always uses the a consistent number of characters, thus perfectly
aligning the next field (scope). All log levels are 4 or 5 characters,
so this would mean adding an extra space whenever the log level is 4
characters. I didn't implement this because I'm not sure if it deviates
from the logfmt standard. Probably not, but I'm playing it safe since
it's not a huge benefit either.

src/trace/level.zig

@@ -16,7 +16,7 @@ pub const Level = enum {
     pub fn asText(self: Level) []const u8 {
         return switch (self) {
             .err => "error",
-            .warn => "warning",
+            .warn => "warn",
             .info => "info",
             .debug => "debug",
             .trace => "trace",

src/trace/log.zig

@@ -440,5 +440,5 @@ test "channel logger" {
     logger.deinit();
 
     const actual = stream.getWritten();
-    try std.testing.expectEqualSlices(u8, "level=info message=\"hello world\"", actual[0..32]);
+    try std.testing.expectEqualSlices(u8, "level=info message=\"hello world\"\n", actual[30..]);
 }

src/trace/logfmt.zig

@@ -28,28 +28,14 @@ pub fn writeLog(
     comptime fmt: []const u8,
     args: anytype,
 ) !void {
-    try std.fmt.format(writer, "level={s} ", .{level.asText()});
-
-    if (maybe_scope) |scope| {
-        try std.fmt.format(writer, "scope={s} ", .{scope});
-    }
-
-    try std.fmt.format(writer, "message=\"", .{});
-    try std.fmt.format(writer, fmt ++ "\" ", args);
-
-    inline for (@typeInfo(@TypeOf(fields)).Struct.fields) |field| {
-        try std.fmt.format(writer, fieldFmtString(field.type), .{
-            field.name,
-            @field(fields, field.name),
-        });
-    }
-
     // format time as ISO8601
     const utc_format = "YYYY-MM-DDTHH:mm:ss.SSS";
     try std.fmt.format(writer, "time=", .{});
     const now = time.DateTime.now();
     try now.format(utc_format, .{}, writer);
-    try std.fmt.format(writer, "Z\n", .{});
+    try writer.writeByte('Z');
+
+    try writeLogWithoutTime(writer, maybe_scope, level, fields, fmt, args);
 }
 
 /// Returns the number of bytes needed to format the log message.
@@ -60,23 +46,39 @@ pub fn countLog(
     comptime fmt: []const u8,
     args: anytype,
 ) usize {
-    var count: usize = 30; // timestamp is 30 chars
+    const time_len: usize = 29;
 
-    if (maybe_scope) |scope| count += std.fmt.count("scope={s} ", .{scope});
+    var counter = std.io.countingWriter(std.io.null_writer);
+    try writeLogWithoutTime(counter.writer(), maybe_scope, level, fields, fmt, args);
 
-    count += std.fmt.count("level={s} ", .{level.asText()});
+    return time_len + counter.bytes_written;
+}
+
+/// Formats the log message as a string, excluding the time.
+fn writeLogWithoutTime(
+    writer: anytype,
+    comptime maybe_scope: ?[]const u8,
+    level: Level,
+    fields: anytype,
+    comptime fmt: []const u8,
+    args: anytype,
+) !void {
+    try std.fmt.format(writer, " level={s}", .{level.asText()});
+
+    if (maybe_scope) |scope| {
+        try std.fmt.format(writer, " scope={s}", .{scope});
+    }
+
+    try std.fmt.format(writer, " message=\"" ++ fmt ++ "\"", args);
 
     inline for (@typeInfo(@TypeOf(fields)).Struct.fields) |field| {
-        count += std.fmt.count(fieldFmtString(field.type), .{
+        try writer.writeByte(' ');
+        try std.fmt.format(writer, fieldFmtString(field.type), .{
             field.name,
             @field(fields, field.name),
         });
     }
-
-    count += std.fmt.count("message=\"", .{});
-    count += std.fmt.count(fmt ++ "\"\n", args);
-
-    return count;
+    try std.fmt.format(writer, "\n", .{});
 }
 
 test "countLog matches writeLog" {