Double Output in Log4perl Log File

Question

I'm working on a new feature in an existing Perl codebase that will allow us to log the commands being sent to the database. I'm basing the solution off of Log4perl, which prevents me from having to reinvent several wheels.

Unfortunately, I'm running into a snag: every message gets sent to the log file twice. I'd like it to stop doing that.

My research (Google) has indicated that getting the same message sent to two different log files is a common enough problem, but that's not what I'm seeing. Each and every message appears twice within the single log file.

Does anybody have any tips on where I should start looking for ways to correct this behavior?

Edit: The config file looks like this:

my $log_packages = undef;

sub _get_logging_modifications {
    # Hash that is keyed by a package name
    # and the value is the level at which
    # to log that package
    return %{$log_packages} if defined $log_packages;
    $log_packages = {};

    my $log_info = $ENV{PROJECT_LOG_INFO} || '';

    for my $log_specification (split(/,/, $log_info)) {
        # Skip to the next log specification unless we have
        # a well formed log spec. i.e., Package::Name/LOGLEVEL
        next unless $log_specification =~ m!([^/]+)/([A-Z]+)!i;

        my $package   = $1;
        my $log_level = $2;

        $log_packages->{$package} = $log_level;
    }

    return %{$log_packages};
}

BEGIN {
    my $layout = Log::Log4perl::Layout::PatternLayout->new(
        '[%d] +%X{user_name}+ ||%X{request_uri}||%n  ' .
        '%C:%L - %P - %p - %n  ' .
        '%m%n'
    );

    my $web_data_path = $ENV{PROJECT_DATA_DIR}
        || File::Temp::tempdir( CLEANUP => 1 );

    my $logfile = "${web_data_path}/app.log";
    my $log = Log::Log4perl->get_logger('');

    my $app = Log::Log4perl::Appender->new(
        "Log::Dispatch::File",
        name     => 'APP',
        filename => $logfile,
    );

    $app->layout($layout);
    $log->add_appender($app);
    $log->level($WARN);

    my %levels = (
        FATAL => $FATAL,
        ERROR => $ERROR,
        WARN  => $WARN,
        INFO  => $INFO,
        DEBUG => $DEBUG,
    );

    my %mods = _get_logging_modifications();

    for my $cat (keys %mods) {
        my $level = uc($mods{$cat});
        next unless exists($levels{$level});
        my $other_log = Log::Log4perl->get_logger($cat);
        $other_log->level($levels{$level});
    }

    # NEW BLAIRHIPPO CODE STARTS HERE
    my $dbi_log = Log::Log4perl->get_logger('Project::NewLoggerThing');
    my $dbi_layout = Log::Log4perl::Layout::PatternLayout->new('%m%n');
    my $dbi_logfile = "/opt/home/blairhippo/test.log"; # FIXME: Make this configurable
    my $dbi_app = Log::Log4perl::Appender->new(
        "Log::Dispatch::File",
        name     => 'APP',
        filename => $dbi_logfile,
    );

    $dbi_app->layout($dbi_layout);
    $dbi_log->add_appender($dbi_app);
    $dbi_log->level($DEBUG); # FIXME:  Make this configurable   
}

1;

I wish this was a nice pretty .conf file, but I'm working with the existing code.

Can you post some log4perl initialization code or configuration to help with debug? This is not an issue I've seen with Log4perl. — justkt, Mar 14 '11 at 17:24
Create a compact test case that reproduces the problem and post it up here. — a'r, Mar 14 '11 at 17:24
The nature of the existing code makes a compact test case considerably more challenging than I wish it were. I'll see what I can do about that, along with permission to post the configuration stuff. (It's labeled "Proprietary and confidential", unfortunately.) — BlairHippo, Mar 14 '11 at 17:35
You might find that converting your Log4perl code above to a simple .conf file takes care of the problem. If you can't figure it out, this is what I'd do, since it needs to be done anyway. — Ether, Mar 14 '11 at 18:56
@Ether: Agreed that a .conf would be far preferable, but I'm the new kid on the project, so I'm being pretty conservative as far as recommending changes to entrenched bits that aren't actually breaking. — BlairHippo, Mar 14 '11 at 20:09

score 6 · Accepted Answer · answered Mar 14 '11 at 19:01

6

In the Log::Log4perl FAQ there is a question: I keep getting duplicate log messages! What's wrong?.

answered Mar 14 '11 at 19:01

bvr

9,687
22
28

1

This lead me to the solution, which is to insert `$dbi_log->additivity(0);` before the add_appender call. Thanks! – BlairHippo Mar 14 '11 at 20:07

score 3 · Answer 2 · answered Mar 14 '11 at 17:25

3

I've had similar issues with the log4* libraries; this is indicative of using two different logging instantiations where internally both are tied against a singleton. You will have to select two separate logging strings, as I recall.

answered Mar 14 '11 at 17:25

Paul Nathan

39,638
28
112
212

score 1 · Answer 3 · answered Oct 16 '13 at 22:58

1

log4perl.oneMessagePerAppender = 1

answered Oct 16 '13 at 22:58

Jinyu

169
2
9

Double Output in Log4perl Log File

3 Answers3