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

Dear monks,

I would like to highlight the stderr output somehow in the logs of cron jobs, yet maintain the order of the output the same as if the script were run interactively.

For example, I would like to prepend "@@@@@" to all stderr output in the log so that it's more distinguishable. However, I'd like to keep it in context so that I know what part of the program(s) the statement is coming from.

The base output would be from a command like

find /fst/home/ -name '*ooo*'

where there are lots of

find: /fst/home/m1rxp01/.mozilla: Permission denied

types of lines and the occassional

/fst/home/m1rxp01/.openoffice/share/dict/ooo.

In my shell in emacs, I've somehow got it configured to display stdout in green and stderr in orange. I'd like to log my cron output in a similar way. I've tried stuff such as

system("(((find /fst/home/ -name '*ooo*') | 3>&1 1>&2 2>&3 ) | sed 's/^/STDERR:/')");

but even that puts the STDOUT out of sync with the STDERR, and the files aren't in alphabetical order (in the base case this is true).

I've tried

find /fst/home/ -name '*ooo*' 2>&1 >> h1.log | sed 's/^/STDERR:/' >> h1.log

as well, but with the same mis-timing in the results.

I've tried running the same commands in a Perl script both before and after "unbuffering" STDOUT and STDERR with no change in results.

I know that this is a fairly deep issue, and have spent a day reading up on how Linux handles this, but am coming up empty. Thank you.

  • Comment on Prepending a string to STDERR output, and logging STDOUT & STDERR synchronously to a file

Replies are listed 'Best First'.
Re: Prepending a string to STDERR output, and logging STDOUT & STDERR synchronously to a file
by ikegami (Patriarch) on Apr 18, 2006 at 17:29 UTC

    I'd try the following:

    use IPC::Run qw( run new_chunker ); sub new_prefixer { my ($prefix) = @_; return sub { my ($in_ref, $out_ref) = @_; return input_avail && do { $$out_ref = join('', $$out_ref, $prefix, $$in_ref); $$in_ref = ''; 1 }; } } sub new_printer { my ($fh) = @_; return sub { print $fh ($_[0]); } } { my @cmd = ('find', '/fst/home/', '-name', '*ooo*'); open(my $fh_log, '>>', 'h1.log') or die("Unable to open log file: $!\n"); my $printer = new_printer($fh_log); run \@cmd, '>', \$fh_log, '2>', new_chunker(), new_prefixer('STDERR: '), $printer; or die("Error executing child. Child returned $&\n"); # or: # # run \@cmd, # '>', new_chunker(), new_prefixer('STDOUT: '), $printer, # '2>', new_chunker(), new_prefixer('STDERR: '), $printer; # or die("Error executing child. Child returned $&\n"); }

    Notes:

    • Untested.

    • The above won't work (loss of sync between STDOUT and STDERR) if your application buffers STDOUT. You could try to get around that by changing '>' to '>pty>'. Read these notes for details.

    • May not work on Windows due to inability to select file handles. Windows might also be unable to create PTTYs.

    • new_chunker() assures that the prefix is added to every line.

      Ikegami:

      We don't appear to have the IPC::Run module on our system, and if I can do this with open3, that's the way I'd like to go, because I see lots of "Use"s in the source for IPC::Run that I bet we also don't have.

      Thanks for your response.

        I see lots of "Use"s in the source for IPC::Run that I bet we also don't have.

        Doubtful.
        CarpCore.
        ExporterCore.
        FcntlCore.
        File::BasenameCore.
        File::SpecCore.
        IO::HandleCore.
        IO::FileCore.
        IO::PtyConditionally required. If you need it for IPC::Run, you also need it for IPC::Open3.
        IO::TtyConditionally required. If you need it for IPC::Run, you also need it for IPC::Open3.
        IPC::Run::DebugComes with IPC::Run.
        IPC::Run::IOComes with IPC::Run.
        IPC::Run::TimerComes with IPC::Run.
        IPC::Run::Win32HelperComes with IPC::Run.
        IPC::Run::Win32IOComes with IPC::Run.
        IPC::Run::Win32PumpComes with IPC::Run.
        POSIXCore.
        strictCore.
        SocketCore.
        SymbolCore.
        UNIVERSALCore.
        varsCore.

        Not all of these are necessarily required or loaded.

        Feel free to write your own solution with IPC::Open3.

      Hey!

      So I got a version of IPC::Run installed on one of the machines here and I can't for the life of me get your program to work, ikegami. I get

      /fst/home/m1jwc03/prod1/lib/cron% ./cron2.pl /fst/prod1/hedgefunds/Lipper/test.pl m1jwc03
      Bareword found in conditional at ./cron2.pl line 46.
      Use of uninitialized value in scalar dereference at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      Use of uninitialized value in scalar dereference at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      Use of uninitialized value in scalar dereference at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      Use of uninitialized value in scalar dereference at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      Use of uninitialized value in scalar dereference at ./cron2.pl line 42.
      Use of uninitialized value in join or string at ./cron2.pl line 42.
      
      line 42 is
      $$out_ref = join('', $$out_ref, $prefix, $$in_ref);
      and line 46 is four lines down--the brace that closes the sub definition in the line 'return sub{' in new_prefixer.

      TIA,

      T _________________________________________________________________________________
      Without me, it's just aweso

        Change
        use IPC::Run qw( run new_chunker );
        to
        use IPC::Run qw( run new_chunker input_avail );

        I don't know if that will fix everything, but it's a start. Let me know.

Re: Prepending a string to STDERR output, and logging STDOUT & STDERR synchronously to a file
by Anonymous Monk on Apr 18, 2006 at 17:02 UTC
      Kloogy solution:
      use IPC::Open3; use IO::Select; $cmd="find /fst/home/ -name '*ooo*'"; $pid = open3(*CMD_IN, *CMD_OUT, *CMD_ERR, $cmd); close(CMD_IN); $SIG{CHLD} = sub { print "REAPER: status $? on $pid\n" if waitpid($pid, 0) > 0 }; $selector = IO::Select->new(); $selector->add(*CMD_ERR, *CMD_OUT); while (@ready = $selector->can_read) { foreach $fh (@ready) { $line = scalar <$fh>; if (fileno($fh) == fileno(CMD_ERR)) {print "STDERR: ", $line} else {print "STDOUT: ", $line} ($line) || $selector->remove($fh); } } close(CMD_OUT); close(CMD_ERR);
      • Annoyance: upon completion there are STDOUT: STDERR: in front of the prompt (easy to clean out in the next step)
      • Observation of strange behavior:
      • The messages only come out in the "right" order the first time the program is run in a shell. Subsequent calls mess up the order. Thus I have to exit and reenter the shell each time I debug. Weird.
      OK I went ahead and created an account. Thanks for all the help so far, guys.

      So when I use open3, I create a program (sniped straight from the recipe only with my find command):

      use IPC::Open3; use IO::Select; $cmd="find /fst/home/ -name '*ooo*'"; system("$cmd"); print "@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ +@@@@@@@@@@@@@@@@@@@@@@@@@@@\n"; $pid = open3(*CMD_IN, *CMD_OUT, *CMD_ERR, $cmd); $SIG{CHLD} = sub { print "REAPER: status $? on $pid\n" if waitpid($pid, 0) > 0 }; #print CMD_IN "This line has a vt33 lurking in it\n"; close(CMD_IN); $selector = IO::Select->new(); $selector->add(*CMD_ERR, *CMD_OUT); while (@ready = $selector->can_read) { foreach $fh (@ready) { if (fileno($fh) == fileno(CMD_ERR)) {print "STDERR: ", scalar +<CMD_ERR>} else {print "STDOUT: ", scalar +<CMD_OUT>} $selector->remove($fh) if eof($fh); } } close(CMD_OUT); close(CMD_ERR);

      In this command, there are several dozen lines of output, and two of them go to STDOUT; the rest go to STDERR. The output looks something like

      find: xxxxxxxx .. /path/to/match1 find: xxxxxxxx .. /path/to/match2 find: xxxxxxxx

      however, running the program above, it simply hangs after the second line of output to STDOUT (the rest of STDERR is "left hanging?")

      Edited by planetscape - added code tags

        • Please the <code> tags around your code. (It's custom to PerlMonks.) It makes it (more) readable, preserves whitespace, handles HTML escaping, wraps lines if needed, and provides a mechanism to view the code unwrapped.

        • One problem I see is that you use <FH> instead of sysread. See the warning at the bottom of the documentation for select.

        • Another problem I see if that it only prints "STDOUT: " or "STDERR: " for every chunk, not necessarily every line. You need to split on newlines what you get.

        • I never figured out the use of some methods in IO::Select. What's the use of can_read if you can't check for errors? The proper usage seems to be:

          use IO::Select; $selector = IO::Select->new(); $selector->add(*CMD_ERR, *CMD_OUT); while ($selector->count()) { my ($readable, undef, $error) = IO::Select::select($selector, undef, $selector); $selector->remove($_) foreach @$error; foreach my $fh (@$readable) { ... } )
        • I don't know what you mean by "left hanging".

        Ok so I ran an strace on the program and the last lines are

        <p> read(5, "/fst/home/m1jas05/.openoffice/sh"..., 4096) = 45 write(1, "STDOUT: /fst/home/m1jas05/.openo"..., 53STDOUT: /fst/home/m1 +jas05/.openoffice/share/dict/ooo ) = 53 read(5, <p>

        so it looks like some kind of deadlock, but the child is not reading anything, only the parent is.

        Man I am confused.

Re: Prepending a string to STDERR output, and logging STDOUT & STDERR synchronously to a file
by philcrow (Priest) on Apr 18, 2006 at 15:29 UTC
    At the risk of changing the subject, have you considered using perl's very own File::Find that ships with perl? It will give a lot of control and have the bonus of being readable in ways a shell solution could only dream of.

    Phil

      Sorry if I gave the impression that find was the command I wanted to run in cron. I just used it because it quickly generates lots of output with which to play, for testing only.

      The stuff in cron is SAS, FAME, Splus, Matlab, and usually wrapped in Perl.

      Jonathan (aka Anonymous Perl Monk petitioneer)

Re: Prepending a string to STDERR output, and logging STDOUT & STDERR synchronously to a file
by OfficeLinebacker (Chaplain) on May 17, 2006 at 21:56 UTC
    I am STILL struggling with this issue. It seems that sometimes, the output is arranged perfectly, and sometimes it's out of order. I've tried turning autoflushing on in just about every buffer from the calling script, and even in the called script (a perl script but this won't always be the case), with mixed, but never consistent, results.

    All I want to do is run a comand, and log the STDOUT and STDERR synchronously (in the same order it would appear if the program were run interactively), while encasing lines from STDOUT in some HTML tags.

    Is this even possible using open3 and IO::Select or am I tilting at windmills here? _________________________________________________________________________________
    Without me, it's just aweso