Parse a log line for the metrics database without matching pipes

The patterns that pick apart a log line wrote their classes as
alternations, [\w|\-|:] and [\w|\.|:].  Inside a class a | is a literal
character, so a request id or an address with a pipe in it was taken
for a real one, and the line became a row.  The classes are now
[\w:-], [\w-] and [\w.:].

Every line is also parsed once now, by one pattern for what Trog::Log
puts at the front of each line, and a second pattern for the rest of a
request line.  Before, it was one pattern for a request line and a
second for the rest that repeated the first's front half.

A line that names no request returned 1, as a buffered message does.
The POD says that log_message() returns undef for a line it cannot make
sense of, and now it does.

The new tests cover the messages that wait for their request, which no
test did, and the lines that are dropped.  Against the old patterns,
the four assertions about dropped lines fail: two lines with a pipe
became rows.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

lib/Trog/Log/DBI.pm

@@ -67,6 +67,18 @@ sub create_statement {
 
 my %buffer;
 
+# A line as Trog::Log formats it: the time, the level, who asked, and what
+# happened.
+my $STAMP   = qr/[\w:-]+/;
+my $REQUEST = qr/[\w-]+/;
+my $ADDRESS = qr/[\w.:]+/;
+my $WHO     = qr/RequestId[ ]($REQUEST)[ ]From[ ]($ADDRESS)[ ]\|(\w+)\|/;
+my $LINE    = qr/\A($STAMP)[ ]\[(\w+)\]:[ ]$WHO[ ](\N+)/;
+
+# What happened, when that is a request that was served: the method, the
+# code, the bytes, and the route.
+my $SERVED = qr/\A(\w+)[ ](\d+)[ ](\d+)[ ](\N+)/;
+
 =head2 log_message(HASH params) = MIXED
 
 Record one log line.
@@ -80,26 +92,17 @@ A write that fails is a warning on stderr, and never dies.
 sub log_message {
     my ( $self, %params ) = @_;
 
-    # Rip apart the message.  If it's got any extended info, lets grab that too.
-    my $msg = $params{message};
-    my $message;
-    my ( $date, $uuid, $ip, $user, $method, $code, undef, $route ) = $msg =~ m!^([\w|\-|:]+)[ ]\[INFO\]:[ ]RequestId[ ]([\w|\-]+)[ ]From[ ]([\w|\.|:]+)[ ]\|(\w+)\|[ ](\w+)[ ](\d+)[ ](\d+)[ ](\N+)!;
+    my ( $date, $level, $uuid, $ip, $user, $message ) = $params{message} =~ $LINE;
+    return unless $uuid;
 
-    # Otherwise, let's mark it down in the "messages" table.  This will be deferred until the final write.
-    if ( !$date ) {
-        ( $date, $uuid, $ip, $user, $message ) = $msg =~ m!^([\w|\-|:]+)[ ]\[\w+\]:[ ]RequestId[ ]([\w|\-]+)[ ]From[ ]([\w|\.|:]+)[ ]\|(\w+)\|[ ](\N+)!;
+    my ( $method, $code, undef, $route ) = $level eq 'INFO' ? $message =~ $SERVED : ();
 
-        # If we can't figure out its request, ignore the message
-        if ($uuid) {
-            $buffer{$uuid} //= [];
-            push( @{ $buffer{$uuid} }, $message );
-        }
+    # Anything else goes in the "messages" table, once its request is written.
+    if ( !defined $method ) {
+        push( @{ $buffer{$uuid} }, $message );
         return 1;
     }
 
-    # If this is a mangled log, forget it.
-    return unless $date && $uuid;
-
     # 2024-01-20T22:37:41Z
     # Transform the date into an epoch so we can do math on it
     my $fmt     = "%Y-%m-%dT%H:%M:%SZ";

t/Trog-Log-DBI.t

@@ -41,7 +41,26 @@ subtest 'a write the database refuses is a warning, not a die' => sub {
 
     is( $died, undef, 'the caller of the log does not die' );
     is( $res,  undef, 'the write reports that it failed' );
-    like( $stderr, qr/Could[ ]not[ ]record[ ]request[ ]r-2[ ]in[ ]the[ ]metrics[ ]database:[ ]\N*refused[ ]for[ ]the[ ]test/, 'and says why on stderr' );
+    my $why = 'Could not record request r-2 in the metrics database: ';
+    like( $stderr, qr/\Q$why\E\N*refused[ ]for[ ]the[ ]test/, 'and says why on stderr' );
+};
+
+subtest 'a message waits for the line of its request' => sub {
+    is( $output->log_message( message => "2026-09-29T12:00:01Z [WARN]: RequestId r-3 From 192.0.2.1 |nobody| a thing went sideways\n" ), 1, 'the message is buffered' );
+    my ($early) = $dbh->selectrow_array("SELECT count(*) FROM messages WHERE uuid='r-3'");
+    is( $early, 0, 'and not written before its request' );
+
+    ok( $output->log_message( message => $line =~ s/r-1/r-3/r ), 'the request line is written' );
+    my $messages = $dbh->selectcol_arrayref("SELECT message FROM messages WHERE uuid='r-3'");
+    is_deeply( $messages, ['a thing went sideways'], 'and the message with it' );
+};
+
+subtest 'a line that names no request is dropped' => sub {
+    is( $output->log_message( message => "not a log line at all\n" ), undef, 'text that is not a log line' );
+    is( $output->log_message( message => $line =~ s/r-1/r|4/r ),                  undef, 'a request id with a pipe in it' );
+    is( $output->log_message( message => $line =~ s/192\.0\.2\.1/192.0.2.1|x/r ), undef, 'an address with a pipe in it' );
+    my ($count) = $dbh->selectrow_array("SELECT count(*) FROM all_requests WHERE uuid LIKE 'r|%' OR ip_address LIKE '%|%'");
+    is( $count, 0, 'and none of them is a row' );
 };
 
 done_testing();