Stop reporting a missing post as a failed read

Trog::Data::FlatFile::read() took the direct-id shortcut by naming
data/files/$id whether or not it was there, and the loop below then reported the
missing file as a failed read.  DataModule::add() asks get(id => ...) before
every single insert, to choose between version 0 and a version bump, so every
new post announced itself as a read failure -- with a full Carp::Always stack
trace, on stdout, which in the test suite lands in the middle of the TAP stream.

A miss is the ordinary answer to "is there a post with this id".  Only index the
file when it exists; the other branch takes its paths from _index(), which greps
-f, so this was the only way a path that isn't there could reach the read.

The two diagnostics that remain are real failures, so send them through
Trog::Log rather than printing to stdout, which in a PSGI worker is not a log.
Also test the slurp with defined() rather than truthiness, so that an empty file
falls through to the JSON parser and gets an error describing what is actually
wrong with it instead of being blamed on the read.

That exposed two more in Trog::Log itself.  DEBUG, INFO, WARN and FATAL all
called straight through an undefined $log before log_init() had run, dying with
"Can't call method on an undefined value" -- so reaching for a diagnostic in any
uninitialized context (the scripts in bin/, the test suite, a failure early
enough in startup) turned the diagnostic into an outage.  They now fall back to
stderr, and FATAL still dies, since callers depend on that.  And uuid() is undef
until the server stamps one, which spliced an uninitialized-value warning into
the middle of every line logged before that; it reads NONE now.

t/Trog-Data-FlatFile-read.t covers the four cases read() has to tell apart --
present, missing, unparseable, unreadable -- and the logger's uninitialized
fallback.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01T6Q1gRJ2Rr85S8FQ47EjnQ

lib/Trog/Data/FlatFile.pm

@@ -15,6 +15,7 @@ use Path::Tiny();
 use Capture::Tiny qw{capture_merged};
 
 use lib 'lib';
+use Trog::Log qw{:all};
 use Trog::SQLite::TagIndex;
 
 use parent qw{Trog::DataModule};
@@ -43,7 +44,15 @@ sub read ( $self, $query = {} ) {
     #Optimize direct ID
     my @index;
     if ( $query->{id} ) {
-        @index = ("$datastore/$query->{id}");
+
+        # Only when it's actually there.  A miss here is the ordinary answer to
+        # "is there a post with this id", which is what add() asks before every
+        # single insert to decide between version 0 and a bump -- naming the
+        # file regardless meant every new post reported itself as a failed read.
+        # The other branch gets its paths from _index(), which greps -f, so this
+        # is the only way a path that isn't there can reach the loop below.
+        my $path = "$datastore/$query->{id}";
+        @index = ($path) if -f $path;    ## no critic (ProhibitFiletest_f) -- a missing post is a miss, not an error
     }
     else {
         # Remove tags which we don't care about and sort to keep memoized memory usage down
@@ -66,9 +75,13 @@ sub read ( $self, $query = {} ) {
 
     my @items;
     foreach my $item (@index) {
+
+        # Checked with defined() rather than truthiness so that an empty file
+        # falls through to the JSON parser, which will say what is actually
+        # wrong with it rather than blaming the read.
         my $slurped = eval { File::Slurper::read_text($item) };
-        if ( !$slurped ) {
-            print "Failed to Read $item:\n$@\n";
+        if ( !defined $slurped ) {
+            WARN("Could not read post '$item': $@");
             next;
         }
         my $parsed;
@@ -81,7 +94,7 @@ sub read ( $self, $query = {} ) {
             $slurped = eval { File::Slurper::read_binary($item) };
             $parsed  = eval { $parser->decode($slurped) };
             if ( !$parsed ) {
-                print "JSON Decode error on $item:\n$@\n";
+                WARN("Could not decode post '$item': $@");
                 next;
             }
         }

lib/Trog/Log.pm

@@ -158,7 +158,11 @@ sub _log {
 
     #XXX Log lines must start as an ISO8601 date, anything else breaks fail2ban's beautiful mind
     my $tstamp = strftime "%Y-%m-%dT%H:%M:%SZ", gmtime;
-    my $uuid   = uuid();
+
+    # Undef until the server stamps one, or log_init() sets INIT.  Anything
+    # logged before that still deserves a line rather than an uninitialized
+    # value warning glued into the middle of it.
+    my $uuid = uuid() // 'NONE';
 
     return "$tstamp [$level]: RequestId $uuid From $Trog::Log::ip |$Trog::Log::user| $msg\n";
 }
@@ -173,22 +177,35 @@ timestamp -- fail2ban parses these.
 
 FATAL logs and then dies, so it never returns.
 
+All four work before log_init() has run, falling back to stderr.  Logging is
+the thing you reach for when something has already gone wrong, so a logger that
+dies because it wasn't set up first turns a diagnostic into an outage -- and
+plenty of callers legitimately run uninitialized, such as the scripts in bin/
+and the test suite.
+
 =cut
 
-sub DEBUG {
-    $log->debug( _log( shift, 'DEBUG' ) );
-}
+# One path for every level so the uninitialized fallback only exists once.
+sub _emit ( $level, $method, $msg ) {
+    my $line = _log( $msg, $level );
+    return $log->$method($line) if $log;
 
-sub INFO {
-    $log->info( _log( shift, 'INFO' ) );
+    warn $line;
+    return 1;
 }
 
-sub WARN {
-    $log->warning( _log( shift, 'WARN' ) );
-}
+sub DEBUG { return _emit( 'DEBUG', 'debug', shift ) }
+
+sub INFO { return _emit( 'INFO', 'info', shift ) }
+
+sub WARN { return _emit( 'WARN', 'warning', shift ) }
 
 sub FATAL {
-    $log->log_and_die( level => 'error', message => _log( shift, 'FATAL' ) );
+    my $line = _log( shift, 'FATAL' );
+    $log->log_and_die( level => 'error', message => $line ) if $log;
+
+    # Still fatal with no logger, or the caller's error handling vanishes.
+    die $line;
 }
 
 1;

t/Trog-Data-FlatFile-read.t

@@ -0,0 +1,127 @@
+use strict;
+use warnings;
+
+use Test::More;
+use Test::Fatal qw{exception};
+use File::Path  ();
+use FindBin;
+
+use lib "$FindBin::Bin/../lib";
+
+my ( $ROOT, $OLDCWD );
+
+BEGIN {
+    require File::Temp;
+    require Cwd;
+    $OLDCWD = Cwd::getcwd();
+    $ROOT   = File::Temp::tempdir( 'tcms-flatfile-XXXXXX', TMPDIR => 1, CLEANUP => 1 );
+
+    # Text::Xslate and the loggers both compute paths from $HOME or the cwd at
+    # load time, and $datastore is relative, so both have to be set before the
+    # SUT is loaded.
+    $ENV{HOME} = $ROOT;
+    File::Path::make_path("$ROOT/data/files");
+    File::Path::make_path("$ROOT/schema");
+
+    # Trog::SQLite::TagIndex builds the tag index at load time and wants this
+    # path, hardcoded and relative, before the SUT will even compile.
+    require File::Copy;
+    File::Copy::copy( "$FindBin::Bin/../schema/flatfile.schema", "$ROOT/schema/flatfile.schema" ) or die $!;
+
+    chdir($ROOT) or die "could not chdir to the sandbox: $!";
+}
+
+END {
+    chdir($OLDCWD) if $OLDCWD;
+}
+
+require_ok('Trog::Data::FlatFile') or BAIL_OUT("Can't find SUT");
+require_ok('Trog::Log')            or BAIL_OUT("Can't find SUT");
+
+my $model = bless( {}, 'Trog::Data::FlatFile' );
+
+# Collect whatever the SUT says rather than letting it reach the terminal, so
+# that "did this warn" is a thing the test can assert on.
+my @said;
+local $SIG{__WARN__} = sub { push @said, $_[0] };
+
+sub reads {
+    my ($id) = @_;
+    @said = ();
+    my $posts = $model->read( { id => $id, raw => 1 } );
+    return ( $posts, join( '', @said ) );
+}
+
+open( my $fh, '>', 'data/files/good' ) or die $!;
+print {$fh} '[{"id":"good","title":"Good","tags":["public"],"visibility":"public"}]';
+close $fh;
+
+subtest 'a post that is there' => sub {
+    my ( $posts, $noise ) = reads('good');
+    is( scalar(@$posts), 1,      "the post comes back" );
+    is( $posts->[0]{id}, 'good', "and it is the one asked for" );
+    is( $noise,          '',     "quietly" );
+};
+
+subtest 'a post that is not there' => sub {
+
+    # add() asks this before every single insert, to choose between version 0
+    # and a bump.  It used to name the file regardless of whether it existed,
+    # so every new post reported itself as a failed read.
+    my ( $posts, $noise ) = reads('no-such-post');
+    is( scalar(@$posts), 0,  "a miss is an empty list" );
+    is( $noise,          '', "and says nothing -- a miss is not a failure" );
+};
+
+subtest 'a post that cannot be parsed' => sub {
+    open( my $bad, '>', 'data/files/corrupt' ) or die $!;
+    print {$bad} '[{"id":"corrupt"';
+    close $bad;
+
+    my ( $posts, $noise ) = reads('corrupt');
+    is( scalar(@$posts), 0, "nothing comes back" );
+    like( $noise, qr/corrupt/, "but it says which post, because this one is a real failure" );
+};
+
+subtest 'a post that cannot be read' => sub {
+  SKIP: {
+        skip( "running as root, which can read anything", 2 ) if $> == 0;
+
+        open( my $no, '>', 'data/files/unreadable' ) or die $!;
+        print {$no} 'x';
+        close $no;
+        chmod( 0000, 'data/files/unreadable' ) or die $!;
+
+        my ( $posts, $noise ) = reads('unreadable');
+        is( scalar(@$posts), 0, "nothing comes back" );
+        like( $noise, qr/unreadable/, "and it says which post" );
+
+        chmod( 0644, 'data/files/unreadable' );
+    }
+};
+
+subtest 'the log works before log_init()' => sub {
+
+    # Logging is what you reach for when something has already gone wrong, so
+    # dying because nobody set it up first turns a diagnostic into an outage.
+    no warnings qw{once};
+    is( $Trog::Log::log, undef, "no logger is configured in this process" );
+
+    @said = ();
+    is( exception { Trog::Log::WARN('a warning') }, undef, "WARN does not die" );
+    like( join( '', @said ), qr/\[WARN\].*a warning/, "it lands on stderr instead" );
+
+    @said = ();
+    is( exception { Trog::Log::INFO('a note') },    undef, "INFO does not die" );
+    is( exception { Trog::Log::DEBUG('a detail') }, undef, "DEBUG does not die" );
+
+    # An uninitialized request id used to be spliced into the line as an
+    # uninitialized-value warning.
+    unlike( join( '', @said ), qr/uninitialized/, "and no uninitialized value creeps in" );
+    like( join( '', @said ), qr/RequestId NONE/, "the request id says it has none" );
+
+    # FATAL is fatal either way, or the caller's error handling disappears.
+    like( exception { Trog::Log::FATAL('the roof is on fire') }, qr/the roof is on fire/, "FATAL still dies" );
+};
+
+done_testing();