Syslogging with Perl

Often you'd like your perl programs to log output, errors, or status. While it's simple to use a file for this, programs that run often have to deal with files that grow too big and getting someone to read the messages. Unix-style systems already have a standard facility for logging call Syslog. Syslog takes care of getting the appropriate messages to the right logs, and frequently administrators have processes for rolling and reading the logs.

Fortunately, it's pretty easy to log your perl messages to Syslog, using a module called Sys::Syslog. It's a part of the standard module distribution, so chances are you have it already installed.

This is most obviously applicable to Unix systems, but I believe there are syslogd's available for Win32. I haven't tested it on Win32 however.

A Brief Introduction to Syslog

If you're not familiar with Syslog, a quick overview will be helpful. Syslog uses a daemon called syslogd and a configuration file that's usually /etc/syslog.conf. The config file determines what type of messages will be sent to what log files.

Syslog distinguishes classes of messages based on facility and priority. Facility just means what type of program is doing the logging. Common types are CRON, DAEMON, MAIL, and USER. Priority determines how important the message is. In decreasing importance, the typical priorities are EMERG, ALERT, CRIT, ERR, WARNING, NOTICE, INFO, and DEBUG.

The syslog.conf specifies for a combination of facility and priority where the message should be logged. For instance, you can direct that all mail facility messages with a priority of info and above should go to the file /var/log/maillog, and that everything else should go to /var/log/messages. The syslog.conf file can be elaborate, but usually is fairly simple. Exact syntax varies among unix implementations, so for your syntax and examples see the syslog.conf man page. Remember to send syslogd a HUP signal if you change the configuration.

The output as it appears in the log file contains the date and time of the message, the program name that sent the message, and the message itself.


Using Sys::Syslog

To use syslogging in your perl program, load in the module:

    use Sys::Syslog qw( :DEFAULT setlogsock);

This will import some variables into your namespace. :DEFAULT gives you openlog, closelog, setlogmask, and syslog; you probably also want setlogsock.

To log a message, you'll need to decide on two things: the facility you want to use and the priority of the message. Most regular programs should use the USER facility. Priority is your choice, but INFO, ERR, and DEBUG are probably most common. Here's a simple example with USER facility and INFO priority:

    $user = $ENV{'USER'};
    setlogsock('unix');
    openlog($0,'','user');
    syslog('info', "added $user to documentation database");
    closelog;

This results in the following line in my /var/log/messages:

   Feb 11 22:14:29 lava myprogram: added fprice to documentation database

The first line, setlogsock('unix'), sets the socket type to the UNIX domain socket. If you'd rather have a network socket be used, you can omit this line. If logging to the local syslogd, use the setlogsock('unix') line. I think that for Unix machines, one probably wants to use a unix socket (usually /dev/log). For Windows machines, obviously you should use network sockets.

In this example, we call openlog() with three arguments. The first is an ``ident'' string which will appear in every line in the log. It should identify your program ($0 is a very general but perhaps not terribly helpful choice). The second argument is a list of options; here it is null, but you can have combinations of 'pid', 'ndelay', 'cons', and 'nowait'. The last argument is the facility to be used.

Next, we call syslog() with the actual message we want to log. syslog() can take three arguments as well. The first is the priority; the second is the message to log. This message is printed by printf, so you can have a format string and a list of variables to interpolate. I usually find it easiest to let perl do the interpolation and just have a print string.

Finally, we close the log.


A more complete example

If you plan on logging lots of output, it is useful to have a subroutine in your program that you can easily call. Here's an example called logit() which can be used like this:

    open(CONF, "prog.conf") or 
       logit('err', "Error opening prog.conf: $!");
    logit('debug', "starting $database reorg.") if $debug;

And the message from the first call in my syslog:

   Feb 12 16:01:17 lava myprogram[1006]: Error opening prog.conf: No
   such file or directory

Here's the subroutine. It checks for an allowable priority, then logs the message under USER facility. Notice the options 'pid,cons' in openlog(): this will include the process ID of your program in the syslog message and log to the console if there's an error logging to syslogd.

    sub logit {
        my ($priority, $msg) = @_; 
        return 0 unless ($priority =~ /info|err|debug/);
        setlogsock('unix');
        # $programname is assumed to be a global.  Also log the PID
        # and to CONSole if there's a problem.  Use facility 'user'.
        openlog($programname, 'pid,cons', 'user');
        syslog($priority, $msg);
        closelog();
        return 1;
    }

Log Options

Allowable options to openlog() are CONS, NDELAY, PID, or NOWAIT.

CONS will write the message directly to the system console if there is an error writing to syslogd. NDELAY opens the connection immediately upon calling openlog(), rather than waiting until syslog() is called with a message. PID includes the process ID with each message. NOWAIT tells syslog() not to wait for the fork to the syslog system call to return; this might be useful if you're doing really time-sensitive programming.

Other Nuances

In the string you givc to syslog(), the format variable %m contains the last error message; that is, $!. So you can do this and the current value of $! gets put into the log.

    syslog('error', 'Cannot open file: %m');

If you want to log each time your program exits, you can put the syslog() call in an END block, like this:

    END {
        logit('info', 'shutting down...');
    }

Once you've opened the log, you can call syslog() multiple times, with different priorities, before closing.

Sys::Syslog requires syslog.ph (because it needs system-specific header files, I'm guessing) so you might need to run h2ph to generate it on your system. This will probably work:

    cd /usr/include; h2ph -r -l .

Probably a facility of USER is most appropriate for general use. If you are writing a daemon program, then DAEMON might be ok. You can also use LEVEL1-7 for custom facilities if you want to filter them into their own log file with syslog.conf. However, be aware that some might already be taken by other programs (sudo uses level2, for instance).

One some of my systems, running with -w turned on causes some annoying warnings to be printed about things in syslog.ph being redefined. I turn them off temporarily in my logit subroutine with local $^W = 0.


SEE ALSO

perldoc Sys::Syslog

man syslog.conf

man 3 syslog


Other Resources

Rich thinks that aintx has a syslogd for WinNT. I don't have a good URL for it. I believe there are other syslogd's available for Win32, and I'd like to know if anyone has successfully run Sys::Syslog on Win32.


AUTHOR

Frank Price, fprice@upended.org