1. No Profile Picture
    Registered User
    Devshed Newbie (0 - 499 posts)

    Join Date
    Sep 2012
    Rep Power

    Peculiarity with file logging in subprocess

    Hi all

    I'm fresh new here, so greetings and salutations! Or "fresh" - I have been around from time to time to "sneak around", learn and such

    I have a bit of a peculiar problem - or rather, I don't fully understand a particular way my code is behaving.

    I have one perlscript which kickstartes another as a daemon using Proc:aemon. This works great.

    The daemon script also works just well, except from it's logging. It DOES work, but the behaviour in which it is working is making me scratch the back of my head.

    The daemon does, in fact, create a socket on a port and starts an endless loop listening for incoming connections and parsing data received. Logging is implemented for each connection+data and likewise for bad data.

    If I log like this:

    PHP Code:
    print FH"my string\n"
    The logging is done immediately.

    If I log like this:

    PHP Code:
    &log("my string"); 
    The logging is queued and not written to the logfile BEFORE I terminate the daemon.

    The log function is just like this, nothing special:

    PHP Code:
    sub log {
    my $msg shift;
    my $ts strftime("%d-%m-%Y %H:%M:%S"localtime);
            if (!
    $supr_log) { # Supress logging entirely if set
    print FH "$me [$0:$$] $ts:  $msg\n";

    I am struggling to understand why no logging is done BEFORE the daemon terminates when I use my log() function. WHEN the log "queue" (I'm using the word queue because when I terminate my daemon it has made several calls to log() which is then executed in correct succession when the daemon is terminated).

    Again, if I just print to the file handle directly, and thus avoid my log() function, the data is writting to the file immediately, without delay or "queing symptoms".

    In the daemon script itself, there is no forking or anything "magical" taking place. Any forking is done in the startup script using Proc:aemon. The daemon is - quite literally just a socket with an endless loop handling connections, data and error-handling.

    Have any of you seen this peculiarity before?

    Your help is much appreciated!

    Thanks for a good forum!
  2. #2
  3. No Profile Picture
    Contributing User
    Devshed Regular (2000 - 2499 posts)

    Join Date
    Apr 2009
    Rep Power
    We would need to see more of your code, possibly the entire daemon script, to see what's going on, but even without seeing it, my recommendation would be to rework your method of logging.

    For robust and trouble free logging I'd use Log::Log4perl especially for daemon scripts.
  4. #3
  5. Guru Meditation
    Devshed Beginner (1000 - 1499 posts)

    Join Date
    Jan 2004
    Rep Power
    I'm guessing it's the output buffer which is only flushed once it's full. Try to set $| = 1; and see what happens.

    If set to nonzero, forces a flush right away and after every write or print on the currently selected output channel. Default is 0 (regardless of whether the channel is really buffered by the system or not; $| tells you only whether you've asked Perl explicitly to flush after each write). STDOUT will typically be line buffered if output is to the terminal and block buffered otherwise. Setting this variable is useful primarily when you are outputting to a pipe or socket, such as when you are running a Perl program under rsh and want to see the output as it's happening. This has no effect on input buffering. See getc for that. See select on how to select the output channel. See also IO::Handle.
    www.booking.com is hiring Perl developers!
    Work along some of the biggest names in Perl community. Live in Amsterdam - relocation assistance is provided (paperwork/visa and financial) for you and your family members - for details send me an message

IMN logo majestic logo threadwatch logo seochat tools logo