log4perl - accessing logger in subscripts/subroutines?

ck2021 has asked for the wisdom of the Perl Monks concerning the following question:

I am new to Perl and do not have an object oriented coding background.

I have log4perl logger working well with my main scripts and I really like the idea of it. I am creating log files with names that are derived from the script name and the current date stamp when the script is run. I have not been able to understand how to have any subroutines or subscripts called by my main routine log to the same logger though, as in the same files created by the logger configuration in my main routine.

Could someone help me with this? I've attached all related files below.

Thanks Chris

p.s. Any constructive comments with regard to coding standards or doing things a better way in the code you see below are welcome. I am teaching myself and am just starting out.

log4perl_FDO.conf - logger configuration file:

# FDO Standard Logger Configuration File

# Define Loggers
# set category level to INFO and appender to screen
   log4perl.logger= INFO, Screen

# set category level to INFO and appender to screen plus logfiles
   log4perl.logger.logfile= INFO, InfoFile, ErrFile

# set category level to INFO and appender to screen plus logfiles plus
+ errors to email
   log4perl.logger.logfile.logmail= INFO, Mailer


# Define Appenders
#Screen
   log4perl.appender.Screen=Log::Log4perl::Appender::Screen
   log4perl.appender.Screen.stderr = 0
   # [millisecs] source-filename line-number class - message newline
   log4perl.appender.Screen.layout=PatternLayout
   log4perl.appender.Screen.layout.ConversionPattern=[%d] %p %c %H:%F 
+Ln:%L - %m%n

#InfoFile
   log4perl.appender.InfoFile = Log::Log4perl::Appender::File
   log4perl.appender.InfoFile.filename = sub {Get_LogFile("INFO");};
#   log4perl.appender.InfoFile.mode = append
   log4perl.appender.InfoFile.mode = clobber
   # [millisecs] source-filename line-number class - message newline
   log4perl.appender.InfoFile.layout=PatternLayout
   log4perl.appender.InfoFile.layout.ConversionPattern=[%d] %c %H:%F L
+n:%L - %m%n

#ErrFile
   log4perl.filter.MatchErr = Log::Log4perl::Filter::LevelRange
   log4perl.filter.MatchErr.LevelMin = WARN
   log4perl.filter.MatchErr.LevelMax = FATAL
   log4perl.filter.MatchErr.AcceptOnMatch = true

   log4perl.appender.ErrFile = Log::Log4perl::Appender::File
   log4perl.appender.ErrFile.filename = sub {Get_LogFile("ERROR");};
#   log4perl.appender.ErrFile.mode = append
   log4perl.appender.ErrFile.mode = clobber
   # [millisecs] source-filename line-number class - message newline
   log4perl.appender.ErrFile.layout=PatternLayout
   log4perl.appender.ErrFile.layout.ConversionPattern=[%d] %c %H:%F Ln
+:%L - %m%n
   log4perl.appender.ErrFile.Filter = MatchErr

#Mailer
   log4perl.filter.MatchFatalErr = Log::Log4perl::Filter::LevelRange
   log4perl.filter.MatchFatalErr.LevelMin = ERROR
   log4perl.filter.MatchFatalErr.LevelMax = FATAL
   log4perl.filter.MatchFatalErr.AcceptOnMatch = true

   log4perl.appender.Mailer = Log::Dispatch::Email::MailSendmail
   log4perl.appender.Mailer.to = ckelly@telesat.com
   log4perl.appender.Mailer.from = ckelly@telesat.com
   log4perl.appender.Mailer.subject = SCRIPT ERROR
   log4perl.appender.Mailer.buffered = 0
   log4perl.appender.Mailer.layout=PatternLayout
   log4perl.appender.Mailer.layout.ConversionPattern=[%d] %c %H:%F Ln:
+%L - %m%n
   log4perl.appender.Mailer.Filter = MatchFatalErr
[download]

Get_LogFile.pl - subroutine that creates script name and dates stamped log file names:

#!/opt/perl/bin/perl

use strict;
use warnings;

sub Get_LogFile($)  #logfile takes "INFO" or "ERROR"
{
  my($fileType)= @_;
  my($scriptName)= fileparse($0);
  my($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = gm
+time;
  my $curEpoch = sprintf("%4.4d%3.3d%2.2d%2.2d%2.2d",$year+1900, $yday
++1, $hour, $min, $sec);


  if (lc($fileType) =~ /^info/) 
  {
     return "/tmp/$scriptName.$curEpoch.info.log";
  }
  elsif (lc($fileType) =~ /^error/) 
  {
     return "/tmp/$scriptName.$curEpoch.err.log";
  }
  else
  {
     return "/tmp/$scriptName.$curEpoch.log";
  }
}
1;  # need this for the require to work in calling file
[download]

TestCheckInhibits - main script

#!/opt/perl/bin/perl

use strict;
use warnings;

# Add in my file with the subroutine to generate the log file names
# This is called by the loggers that output to log files - see logfile
+_FDO.conf
   require "/usr/fds/fdo/scripts/Get_LogFile.pl";    # should make thi
+s into a module
   require "/usr/fds/fdo/scripts/Check_Inhibits.pl";    # should make 
+this into a module
# Subroutine prototypes
   sub Get_LogFile($);  #logfile takes "INFO" or "ERROR"
   sub Check_Inhibits($$$$);

# PERL modules
   use Sys::Hostname;
   use File::Basename;
   use File::Copy;
   use Net::FTP;
   use Getopt::Long;
   use MIME::Lite;
   use Log::Dispatch::Email::MIMELite;
   use Log::Log4perl;
#  use Log::Log4perl qw(get_logger :no_extra_logdie_message) ;

# initialize logger instance at the logfile category
# which logs INFO and up messages to the screen and to a log file
# and WARN and up message to an additional error log file
   Log::Log4perl->init("/usr/fds/fdo/scripts/log4perl_FDO.conf");
   my($log) = Log::Log4perl->get_logger("logfile");
   my($infoFileApp) = Log::Log4perl->appender_by_name("InfoFile");
   my($errFileApp) = Log::Log4perl->appender_by_name("ErrFile");
   my($infoLogFile) = $infoFileApp->filename();
   my($errLogFile) = $errFileApp->filename();

   $log->info("Execution Started");
   $log->info("Log File: $infoLogFile");
   $log->info("Error Log File: $errLogFile");

   my($inhWarn) = Check_Inhibits("2009:016:22","2009:016:22:30", "/tmp
+/Test.inhibit.out", 30);

   print "inhMsg:\n $inhWarn";


   $log->info("Execution Complete");
   exit 1;  # successful end
[download]

Check_Inhibits.pl - subroutine called by main script

#!/opt/perl/bin/perl

use strict;
use warnings;

sub Check_Inhibits($$$$){     # Check_Inhibits takes StartEpoch, EndEp
+och, InhibitFile, Padding

# Add in my file with the subroutine to generate the log file names
# This is called by the loggers that output to log files - see logfile
+_FDO.conf
#  require "/usr/fds/fdo/scripts/Get_LogFile.pl";    # should make thi
+s into a module
# Subroutine prototypes
#  sub Get_LogFile($);  #logfile takes "INFO" or "ERROR"

# PERL modules
   use Sys::Hostname;
   use File::Basename;
   use File::Copy;
   use Net::FTP;
   use Getopt::Long;
   use MIME::Lite;
   use Log::Dispatch::Email::MIMELite;
   use Log::Log4perl;
#  use Log::Log4perl qw(get_logger :no_extra_logdie_message) ;

# initialize logger instance (?? from main script - how??)   
   my($log) = Log::Log4perl->get_logger();
   $log->info("Execution Started");

# get calling arguments
   my($startEp)=$_[0];
   my($endEp)=$_[1];
   my($inhibitFile)=$_[2];
   my($padding) = $_[3];

   $log->info("User Input - Checking Start Epoch entered: $startEp");
   $log->info("User Input - Checking End Epoch entered: $endEp");
   $log->info("User Input - Inhibit File entered: $inhibitFile");
   $log->info("User Input - Inhibit Padding entered: $padding min");

# parse the input epochs
# Start Epoch
   my($startEpYear, $startEpDay, $startEpHour, $startEpMin, $startEpSe
+c, $startEpMsec) = split(/:/,$startEp);
   if (!defined $startEpYear || !defined $startEpDay) {$log->logdie("S
+tart Epoch $startEp not defined (yyyy:dd[:hh:mm:ss:msc])\n")};
   if (!defined $startEpHour) {$startEpHour=0};
   if (!defined $startEpMin) {$startEpMin=0};
   if (!defined $startEpSec) {$startEpSec=0};
   if (!defined $startEpMsec) {$startEpMsec=0};
   my($startEpNSec) = (((($startEpDay*24.0)+$startEpHour)*60.0)+$start
+EpMin)*60.0 + $startEpSec + $startEpMsec/1000.0;

# End Epoch
   my($endEpYear, $endEpDay, $endEpHour, $endEpMin, $endEpSec, $endEpM
+sec) = split(/:/,$endEp);
   if (!defined $endEpYear || !defined $endEpDay) {$log->logdie("Start
+ Epoch $endEp not defined (yyyy:dd[:hh:mm:ss:msc])\n")};
   if (!defined $endEpHour) {$endEpHour=0};
   if (!defined $endEpMin) {$endEpMin=0};
   if (!defined $endEpSec) {$endEpSec=0};
   if (!defined $endEpMsec) {$endEpMsec=0};
   my($endEpNSec) = (((($endEpDay*24.0)+$endEpHour)*60.0)+$endEpMin)*6
+0.0 + $endEpSec + $endEpMsec/1000.0;

# Convert padding from minutes to seconds
   my($paddingSec)=$padding*60.0;

# open inhibit file for read access
   open(INH_FH, "<$inhibitFile") || $log->logdie("Could not open inhib
+it file $inhibitFile: $!\n");

#
   my($inhMsg)='';
   while(<INH_FH>) {
     next unless (m#^\s+\d+:\d+# );
     next unless (my(@inhArray)=m#(\d+:\d+:*\d*:*\d*)#g);
#    print "@inhArray,\n";

     my($inhStartYear,$inhStartDay) = split(/:/,$inhArray[0]);
     my($inhEndYear) = $inhStartYear;
     my($inhEndDay) = $inhStartDay;
     my($inhStartHour,$inhStartMin, $inhStartSec) = split(/:/,$inhArra
+y[1]);
     my($inhEndHour,$inhEndMin, $inhEndSec) = split(/:/,$inhArray[$#in
+hArray]);
     if ($inhEndHour < $inhStartHour) {$inhEndDay = $inhEndDay +1};
     my($inhStartNSec) = (((($inhStartDay*24.0)+$inhStartHour)*60.0)+$
+inhStartMin)*60.0 + $inhStartSec - $paddingSec;
     my($inhEndNSec) = (((($inhEndDay*24.0)+$inhEndHour)*60.0)+$inhEnd
+Min)*60.0 + $inhEndSec + $paddingSec;
#    print ("inhStartNSec = $inhStartNSec and inhEndNSec = $inhEndNSec
+\n");
#    print ("startEpNSec = $startEpNSec and endEpNSec = $endEpNSec\n")
+;

     if ( ($inhStartNSec <= $startEpNSec && $startEpNSec <= $inhEndNSe
+c) || 
                          ($inhStartNSec <= $endEpNSec && $endEpNSec <
+= $inhEndNSec)){
        $log->warn("Event ($startEp \- $endEp) and inhibit conflict: $
+_\n");
        $inhMsg .= "Event ($startEp \- $endEp) and inhibit conflict: $
+_\n";
     }
     elsif ($inhStartDay == $startEpDay || $inhEndDay == $startEpDay |
+| $inhEndDay == $startEpDay || $inhEndDay == $startEpDay ||
            $inhStartDay == $endEpDay || $inhEndDay == $endEpDay || $i
+nhEndDay == $endEpDay || $inhEndDay == $endEpDay){
        $log->info("Inhibit occurs on event day ($startEp \- $endEp) w
+ithout conflict: $_\n");
        $inhMsg .= "Inhibit occurs on event day ($startEp \- $endEp) w
+ithout conflict: $_\n";
     }
        
}
   close(INH_FH);


   $log->info("Execution Complete");
   return $inhMsg;
}
1;  # need this for the require to work in calling file
[download]

Test.inhibit.out - sample file read by script

  2008:352   UTC     22:53:47    23:10:33    00:21:51    01:33:08    0
+1:50:13       .9 (N)   64.5
  2009:004           11:53:56                13:22:10                1
+4:50:24      3.1 (N)   50.9
  2009:013           20:42:14    20:59:06    22:10:46    23:22:26    2
+3:39:37      1.7 (N)   88.8
  2009:015           21:31:25    21:48:29    22:59:37    00:10:45    0
+0:27:29      2.7 (S)   72.2
  2009:016           22:16:21    22:33:23    23:44:28    00:55:33    0
+1:12:16      2.7 (S)   62.2

  2009:041           19:17:16    19:34:06    20:45:41    21:57:16    2
+2:14:26      1.1 (N)   97.6
  2009:043           20:06:42    20:23:47    21:35:01    22:46:16    2
+3:03:02       .2 (S)   86.9

  2009:068           17:04:33    17:21:25    18:33:04    19:44:44    2
+0:01:54      1.8 (N)   97.8
  2009:070           17:55:22    18:12:27    19:23:46    20:35:04    2
+0:51:50      2.7 (S)   99.4
  2009:071           18:42:10    18:59:16    20:10:35    21:21:53    2
+1:38:39      2.8 (S)   96.5
[download]

Comment on log4perl - accessing logger in subscripts/subroutines? Select or Download Code

Replies are listed 'Best First'.
Re: log4perl - accessing logger in subscripts/subroutines? by sathiya.sw (Monk) on Jan 19, 2009 at 06:29 UTC
Not able to grasp the whole idea of yours... as there is a large chunk. Anyway, if you want to use the same logger in the all the places, it is simple. Way 1: store the log handle as a global variable to all the modules, and use it. Way 2: send the log handle to the subroutines where ever you want, and use that handle. When ever you use the same log handle by one of the above way, all your subroutine use the same properties for logging... thus you can achieve your requirement... got it ?? Sathiyamoorthy	[reply]
Re: log4perl - accessing logger in subscripts/subroutines? by zwon (Abbot) on Jan 19, 2009 at 08:24 UTC
You should initialize Log::Log4perl in your main script (though you can do it also in any module). And in modules (subscripts as you call them) you can get logger using `get_logger` function. This function will return the same logger every time.	[reply]
Re^2: log4perl - accessing logger in subscripts/subroutines? by ck2021 (Initiate) on Jan 19, 2009 at 17:57 UTC
Yes, this is what I understand I should be able to do from reading up on log4perl, call get_logger. I do understand I could pass the log handle to subscripts, modules, subroutines as a few people have suggested, but my impression was that log4perl should be able to work such that I don't have to pass the variable around. In my subroutine I called get_logger() however when I ran this what I got was a new instance with the root logger being set up which means the log messages do not go to the logfiles created in my main script. I've just tried again by calling get_logger("logfile") in the subroutine exactly as it was called in my main script and it now seems to be doing what I want. I also ran 2 instances of the main script at the same time and got 2 instances of my log files as I want. Update: I guess the question would be, is there a way to call get_logger in the subroutine such that I don't have to know what logger the main script called get_logger with? If I have a 2nd script which could be called from the main script or could be called independently then would I do the Log::Log4perl->init_once so it would work under both scenarios? And again I would need to be calling get_logger("logfile") the same way for it to refer to the logger of the main script if being scheduled from the main script? Is this what you were suggesting and does this approach make sense in terms of how the log4perl module works? I think my lack of object oriented coding skills is making it a bit difficult for me to really get how the logger instance and get_logger is working. I'm trying to fully understand so that I can set up a configuration and approach that will work generically for all our scripts. Thanks for the help	[reply]
Re: log4perl - accessing logger in subscripts/subroutines? by AnomalousMonk (Archbishop) on Jan 19, 2009 at 06:13 UTC
One way to do things better WRT PerlMonks would be to enclose the huge wadges of code, data and output in `<readmore> ... </readmore>` tags. Please see How do I post a question effectively? and Writeup Formatting Tips and links therefrom.	[reply] [d/l]
Re: log4perl - accessing logger in subscripts/subroutines? by moritz (Cardinal) on Jan 19, 2009 at 08:11 UTC
I have not been able to understand how to have any subroutines or subscripts called by my main routine log to the same logger though, Just pass them your `$log` object, and call `$log->info()` as in your normal script. (Update: or use `get_logger` as zwon suggested - then you don't have to clutter your argument lists). Any constructive comments with regard to coding standards or doing things a better way in the code you see below are welcome Instead of writing # should make this into a module you should actually make it into a module. If you know a better way to do something, do it. (And making a module of something isn't hard).	[reply] [d/l] [select]
Re: log4perl - accessing logger in subscripts/subroutines? by weismat (Friar) on Jan 19, 2009 at 09:15 UTC
From my point of view you are mixing code and configuration file in a bad way when using references to source code inside the configuration file. The logging inside the source code should be totally independent of the configuration of the logging - the only exception should be the location of the configuration file of the logging. In an "industrial" environment it is normal, that the programmers write the perl code and admins change the configuration of the logging depending on the situation - e.g. increasing log levels only in case of problems, etc. For the modules one should use a seperate logger for each module - I am usually using a local variable for each module and have an init log function which checks if the logger is initialised or not.	[reply]
Re^2: log4perl - accessing logger in subscripts/subroutines? by ck2021 (Initiate) on Jan 19, 2009 at 18:12 UTC
The source code reference inside the config file I actually took from an example in some Perl documentation and it seemed to fit well with my requirements. I am looking to use log4perl in a bit of a different way I think, in that I am not looking at setting up logging for a system. I want to track, record, email on error the results of each run of individual scripts. Our scripts are used to supplement and automate an in-house software package. Each main script is really standing alone as a separate function when it is run and I want to be able to access/distribute the ouput of that run separately from any other run. If you have any suggestions about a better way to implement this type of requirement, that would be great. Thanks Chris	[reply]