It's LOG!

I have a large code base I am trying to understand and triage, and in order to prioritize things, I wrote

#!/usr/bin/env perl
use strict;
use warnings;
use utf8;
use feature qw{ postderef say signatures state };
no warnings qw{ experimental::postderef experimental::signatures };

use Log::Log4perl;

my $config = join '/', $ENV{HOME}, '.log.conf';
my $argv = join ' ', @ARGV;

my $logger = Log::Log4perl::get_logger('log_me');

This is what is known in the development community as “The Dumbest Thing That Could Possibly Work”, and it does. when I run foo bar test weasel, it logs:

2018/10/10 15:30:14 WARN foo bar test weasel

So, in a whole bunch of shell scripts, I add:

me="$(basename "$(test -L "$0" && readlink "$0" || echo "$0")")"
/path/to/my/bin/ $me

And I’m working on, which has too many flags. I believe the only ones that ever get used are -v, -r, -p and -S.


So I add some things.

for var in "$@"
    argv="$argv $var"
me="$(basename "$(test -L "$0" && readlink "$0" || echo "$0")")"
/depot/gcore/apps/dev/dave/ $me $argv

So I would get:

    2018/10/10 15:30:31 WARN -p -S

But instead I get.

    2018/10/10 15:30:31 WARN -p -S
    2018/10/10 15:30:31 WARN 

If I had paid attention to the logs before, I would’ve noticed the doubling behavior, but here it is again. Without the flags.


Because elsewhere in runs_status, there’s this.


And qsub_load also contained

me="$(basename "$(test -L "$0" && readlink "$0" || echo "$0")")"
/path/to/my/bin/ $me

But because it was sourced, not ran, it gave me $me as runs_status not qsub_load.


The “Oh, that’s the problem?” moment came reasonably early, so I only feel reasably dumb here. I’d guess that “know the behavior of what you’re logging” would come into play here, but really, learning the behavior is why I’m logging in the first place.

If you have any questions or comments, I would be glad to hear it. Ask me on Twitter or make an issue on my blog repo.