Print log at runtime instead of dumping all at once later

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

I have a Perl script that runs from Jenkins slave. The script executes a shell script kept on remote box A. This shell script actually deploys war on machine A itself. Both machines, Jenkins slave and remote box are CentOS instances.

use strict;
use warnings;
use Cwd;
use File::Copy;
use Getopt::Long;
use File::Basename;
use Net::OpenSSH;

my ($conf_file, $environment, $doexec, $exec, $job, $dest_file, $user,
+ $host, $IP, $TARGET_SERVER, $JENKINS_JOB, $wrapper, $src_file, $src_
+path, $src_dist_path, $src_full_path, $id_file, $ssh, @array, $line);

init();

sub init {
    $JENKINS_JOB = $ENV{'JOB_NAME'};

    $conf_file = "/home/ec2-user/SCM/conf/deploy_build.conf";
    open (FH, "<", $conf_file) or die "Cannot open < $conf_file: $!";

    while (<FH>) {
        if ( $_ =~ /\b$JENKINS_JOB\b/ ) {
            push @array, $_;
        } else {
            next;
        }
    }

    foreach $line (@array) {
        ($job, $src_path, $dest_file, $user, $wrapper) = split(':', $l
+ine);

        $id_file = "/home/ec2-user/.ssh/priv_key";

        $ssh = Net::OpenSSH->new($IP, key_path => $id_file, user => $u
+ser);
        $ssh->error and die "Couldn't establish SSH connection: ". $ss
+h->error;
        
        printf "\n";
        if (length $wrapper) {        
            printf "Initiating subroutine for executing wrapper on rem
+ote machine...\n";
            &exec_wrapper;
        } else {
                printf "*** No wrapper specified ****\n";
        }
    }
}


sub exec_wrapper {
    my ($stdout, $errput) = $ssh->capture2("~/release/$wrapper");

    printf "Output: $stdout\n" if $stdout;
    die "Error: $errput\n" if $errput;
    printf "\n\n\n";
}
[download]

Now the issue is that though the program runs fine, it prints output after a while. Whole output is captured in $stdout and then dumped later. Since this job runs as a Jenkins job, the end user has no idea what's going on until the output is dumped. I wanted to print each line as event occurs (runtime) instead of waiting for the whole output to be stored in the variable and dumped later. I did read this article but i'm not sure whether it applies to my case and if it does, how can i implement it. Just to mention, efficiency is *not* a concern in my scenario. Any help will really be appreciated.

Comment on Print log at runtime instead of dumping all at once later Download Code

Replies are listed 'Best First'.
Re: Print log at runtime instead of dumping all at once later by 1nickt (Canon) on Jul 01, 2015 at 19:22 UTC
Try setting at the top of your script `$\| = 1;` [download] which tells Perl to not buffer the output. Remember: Ne dederis in spiritu molere illegitimi!	[reply] [d/l]
Re^2: Print log at runtime instead of dumping all at once later by Technext (Acolyte) on Jul 02, 2015 at 03:52 UTC
@1nickt: Thanks. I tried putting `$\| = 1;` at the top of script but nothing happened. I also tried placing it just before initializing ssh object but it didn't work in any of the cases.	[reply] [d/l]
Re^3: Print log at runtime instead of dumping all at once later by 1nickt (Canon) on Jul 02, 2015 at 09:38 UTC
Right, well as others have said since then, there are other things buffering up your output. Check them off, one by one :-) Remember: Ne dederis in spiritu molere illegitimi!	[reply] [d/l]
Re: Print log at runtime instead of dumping all at once later by Laurent_R (Canon) on Jul 01, 2015 at 20:30 UTC
The solution presented by 1nickt, making "hot" the FH, is the right one most of the time. There are, however, some operating systems (such as VMS) where this does not really work: you just can't see, or not even know the size, of a file that has not been closed. In this case, the best solution that I know is to open the target file for append, print and close the log file each time you write something to it. This might seem inefficient, and it is indeed not very efficient, but if it is just a log file not getting too much input, it is OK. But, admittedly, this is very OS specific, I don't need that under Unix or Linux (and probably not under Windows, as far as I know).	[reply]
Re^2: Print log at runtime instead of dumping all at once later by Technext (Acolyte) on Jul 02, 2015 at 03:56 UTC
@Laurent_R: Apologies for not mentioning the OS. I have now updated the post. Both machines, Jenkins slave and remote box are CentOS instances.	[reply]
Re^3: Print log at runtime instead of dumping all at once later by Laurent_R (Canon) on Jul 02, 2015 at 06:35 UTC
No problem, I was just saying that there are some cases where setting `$\|` to a true value is not sufficient. I do not know what a Jenkins job is, and don't understand the details of what you're doing, but if the `$\|` solution doesn't work for you, maybe the solution I outlined for VMS might be adapted to your case.	[reply] [d/l] [select]
Re^4: Print log at runtime instead of dumping all at once later by Technext (Acolyte) on Jul 02, 2015 at 17:08 UTC
Re: Print log at runtime instead of dumping all at once later by salva (Canon) on Jul 02, 2015 at 10:21 UTC
Quite unsurprisingly (I hope), `capture2` captures the output from the remote side. If you want to let the remote output go directly to stdout and stderr, unbuffered, just use the `system` method: `sub exec_wrapper { $ssh->system("~/release/$wrapper"); $ssh->die_on_error("execution of ~/release/$wrapper failed"); }` [download]	[reply] [d/l] [select]
Re^2: Print log at runtime instead of dumping all at once later by Technext (Acolyte) on Jul 02, 2015 at 17:16 UTC
This is what i was looking for. Thanks a lot @salva! :)	[reply]
Re: Print log at runtime instead of dumping all at once later.. Net::SSH output buffer by Discipulus (Canon) on Jul 02, 2015 at 07:48 UTC
Ok, i'm not a guru in InterProcessCommunication nor i know what a Jenkins jobs is.. but i have some hint for you: capture2 is a method provided by Net::SSH. It must have some sort of buffering: 'cause of this is not sufficient to autoflush buffer in your main program, i think yous should try to do in the wrapped, remote program. capture2 and many other methods are shorcut around open_ex: look carefully at what docs says about this method. Also probably they all rely on dup(2) or pipe(2). if i understand `$stdout, $errput` are filehandle: if so you can set autoflush for them (if they are regular IO::Handle). Maybe is worth to read also IPC::Open2 to verify that your open2 can support same features (>&FH). do not use `printf` whilst a simple `print` is sufficient L* There are no rules, there are no thumbs.. Reinvent the wheel, then learn The Wheel; may be one day you reinvent one of THE WHEELS.	[reply] [d/l] [select]
Re^2: Print log at runtime instead of dumping all at once later.. Net::SSH output buffer by salva (Canon) on Jul 02, 2015 at 10:32 UTC
if i understand $stdout, $errput are filehandle No, they are the ouput captured coming from the stdout and stderr streams of the remote process.	[reply]
Re^3: Print log at runtime instead of dumping all at once later.. Net::SSH output buffer by Discipulus (Canon) on Jul 02, 2015 at 10:52 UTC
Ah thanks for the clarification salva so they are strings and the method wait the remote command to complete before passing to next instruction? How the `stdout_fh => $fh` option is inteded to be used? is sufficient a `waitpid` call to be sure no more infos will came in the buffer? As you can understand i lack a lot of info about the overall schema, but if you have the patience to write some lines i'll be glad. L* There are no rules, there are no thumbs.. Reinvent the wheel, then learn The Wheel; may be one day you reinvent one of THE WHEELS.	[reply] [d/l] [select]
Re^4: Print log at runtime instead of dumping all at once later.. Net::SSH output buffer by salva (Canon) on Jul 02, 2015 at 11:04 UTC
Re^5: Print log at runtime instead of dumping all at once later.. Net::SSH output buffer by Technext (Acolyte) on Jul 02, 2015 at 17:14 UTC
Re: Print log at runtime instead of dumping all at once later by RichardK (Parson) on Jul 02, 2015 at 07:47 UTC
Well of course it buffers, you collect all the output from the remote command into a string and then print it. What else is it going to do ? Try using pipe_out instead. `my ($stdout, $errput) = $ssh->capture2("~/release/$wrapper"); printf "Output: $stdout\n" if $stdout;` [download]	[reply] [d/l]
Re^2: Print log at runtime instead of dumping all at once later by Technext (Acolyte) on Jul 02, 2015 at 17:03 UTC
Yes RichardK, i know that i'm collecting the output in a string and thus, it'll print only after completion. :) I was looking for a way where i could instead print logs at runtime. Thanks for the suggestion! :) I was looking for pipe_out but salva's comment did the trick.	[reply]