I would expect the code in Tools.pm to log, but it does not. Couldn't quite restrict it to 20 lines, it is as short as I could get it:

#!/usr/local/nik/ess2/perlbrew/perls/perl-5.22.2/bin/perl -w
use strict;
use lib '/testmod';
use Tools;

use Log::Log4perl;

my $conf = q(
    log4perl.category.ess2_loader=DEBUG, LOGFILE
    log4perl.category.Tools.run_test=INFO, LOGFILE

    log4perl.appender.LOGFILE=Log::Log4perl::Appender::File
    log4perl.appender.LOGFILE.filename=/testmod/debug.log
    log4perl.appender.LOGFILE.mode=append
 
    log4perl.appender.LOGFILE.layout=PatternLayout
    log4perl.appender.LOGFILE.layout.ConversionPattern=%d %P [%r] %F %
+L %c - %m%n
);
Log::Log4perl::init( \$conf );
my $log = Log::Log4perl::get_logger("ess2_loader");

$log->info("logging successfully");

run_monitor( { foo => 'bar', baz => 'foobar' } );

sub run_monitor {
    my $href = shift;
    $log->info("trying to spawn child for periodic check...");
    if (my $ps = fork) {
        $log->info("successfully spawned PID $ps");
        $SIG{CHLD} = "IGNORE";
    } else {
        $log->info("running check as PID $$");
        Tools::run_tests($href);
    }
}
[download]

The module called from the child:

use warnings;
use strict;
package Tools;

use Log::Log4perl;
my $log = Log::Log4perl::get_logger("Tools::run_test");

my $href = shift;

sub run_tests {
    foreach my $test (keys %{$href}) {
        $log->info("running test $test with parameters $href->{$test}"
+);
    }
    exit;
}

1;
[download]

Whether I define the category as category.Tools or category.Tools.run_tests makes no difference in this example.

To my understanding category settings propagate to sub-categories, unless these are defined with their own settings. That's why I originally defined the category as 'Tools', to cover all subroutines in Tools.pm

The definition of $href is outside the sub run_tests(). Move it inside and you might get more ...

use Data::Dumper;

sub run_tests {
    my $href = shift;

    # by doubt always try to dump the data
    # print STDERR Dumper( $href );

    foreach my $test (keys %{$href}) {
        $log->info("running test $test with parameters $href->{$test}"
+);
    }
    exit;
}
[download]

Log by original code:

2016/10/31 13:47:06 7732 [0] logger_1175005.pl 23 ess2_loader - loggin
+g successfully
2016/10/31 13:47:06 7732 [0] logger_1175005.pl 29 ess2_loader - trying
+ to spawn child for periodic check...
2016/10/31 13:47:06 7732 [11] logger_1175005.pl 31 ess2_loader - succe
+ssfully spawned PID -5796
2016/10/31 13:47:06 -5796 [11] logger_1175005.pl 34 ess2_loader - runn
+ing check as PID -5796
[download]

After var moved:

2016/10/31 13:47:21 19276 [0] logger_1175005.pl 23 ess2_loader - loggi
+ng successfully
2016/10/31 13:47:21 19276 [0] logger_1175005.pl 29 ess2_loader - tryin
+g to spawn child for periodic check...
2016/10/31 13:47:21 19276 [14] logger_1175005.pl 31 ess2_loader - succ
+essfully spawned PID -5168
2016/10/31 13:47:21 -5168 [14] logger_1175005.pl 34 ess2_loader - runn
+ing check as PID -5168
2016/10/31 13:47:21 -5168 [19] Tools.pm 22 Tools.run_test - running te
+st baz with parameters foobar
2016/10/31 13:47:21 -5168 [19] Tools.pm 22 Tools.run_test - running te
+st foo with parameters bar
[download]

Thank you - that indeed worked but only comes to show I failed to provide an adequate example as the problem persisted in my application :)

I made an effort to further/better isolate the problem and I think I have a solution. I was starting Dancer2 with a system($plackup $args) command. After looking at the source code of plackup, I started it directly in a fork:

use Plack::Runner;
if (my $ps = fork) {
    $log->info("successfully spawned PID $ps");
    $SIG{CHLD} = "IGNORE";
} else {
    $log->info("starting Dancer2 as PID $$");
    my @args = split(' ', $cmd);
    my $runner = Plack::Runner->new;
    $runner->parse_options(@args) or $log->logdie("Plack::Runner faile
+d to parse startup options");
    $runner->run or $log->logdie("failed to start Dancer2 app");
}
[download]

I need to check whether failures to start are captured correctly, but on the logging front its a win, plus it should be a better way to start it anyway

I still don't know why it was failing before - I did check that processes are running the same version of perl and @INC is the same when started via system() and directly

Line 6 refers to Tools::run_test while the actual sub is run_tests. Based on your previous remark about ess_loader vs supervisor, perhaps this is just another typo, but if not it might be the source of the problem.

As an aside, you should be able to copy-and-paste code into posts here. The introduction of typos is an unnecessary distraction, especially since they are often the real culprit.

But God demonstrates His own love toward us, in that while we were yet sinners, Christ died for us. Romans 5:8 (NASB)

---