Script output sometimes gets jumbled

[PhilHibbs]

I have a script that opens a Net::Telnet session, runs some commands, parses the output, and writes the results out to STDOUT which I then redirect to a file. This runs on Windows in a .cmd wrapper. It prints out each line of its input, followed by a comma-separated set of values scraped from the telnet session.

Occasionally, I get two input lines written out, followed by the scraped data that those two input lines produced. For example, the following inputs can generate either of the following outputs:

Input:

InputLine1
InputLine2

Output 1 (correct):

InputLine1,RUN OK (1),Mon Jul 27 16:55:35 2009,Mon Jul 27 16:56:17 200
+9
InputLine2,RUN OK (1),Mon Jul 27 16:56:18 2009,Mon Jul 27 16:57:45 200
+9

Output 2 (incorrect):

InputLine1InputLine2,RUN OK (1),Mon Jul 27 16:55:35 2009,Mon Jul 27 16
+:56:17 2009
,RUN OK (1),Mon Jul 27 16:56:18 2009,Mon Jul 27 16:57:45 2009

The result of the unix command that gets executed for each line looks like this:

Job Status      : RUN OK (1)
Job Controller  : not available
Job Start Time  : Mon Jul 27 16:56:18 2009
Job Wave Number : 2
User Status     : not available
Job Control     : 0
Interim Status  : NOT RUNNING (99)
Invocation ID   : not available
Last Run Time   : Mon Jul 27 16:57:45 2009
Job Process ID  : 0
Invocation List : InputLine2
Job Restartable : 0

It only seems to happen if I run the script with STDOUT redirected to a file, so maybe it's a buffering problem. To be honest I think the actual script itself is largely irrelevant to this problem, as it only happens occasionally, I think it's output buffering. Is there anything I can do to mess with buffering? Full script now follows...

@rem = '--*-Perl-*--
@echo off
perl "%~dpnx0" %1 %2 %3 %4 %5 %6 %7 %8 %9
goto endofperl
@rem ';
#!perl
#line 8
use strict;
use warnings;
use Net::Telnet ();
use Term::ReadKey;

print STDERR "Server: ";
my $server = <STDIN>;
chomp $server;

print STDERR "Project: ";
my $project = <STDIN>;
chomp $project;

print STDERR "Username: ";
my $user = <STDIN>;
chomp $user;

print STDERR "Password: ";
ReadMode 2;
my $pass = <STDIN>;
ReadMode 0;

print STDERR "\nConnecting to $server\n";
my $t = new Net::Telnet ( Timeout    => 3600,
                          Input_log  => "c:\\ftp\\telnet.log",
                          Dump_Log   => "C:\\ftp\\dumplog.txt",
                          Output_Log => "C:\\ftp\\outputlog.txt");
$t->open( $server );
print STDERR "Opened connection to $server\n";
$t->login($user, $pass);
print STDERR "Logged in to $server\n";

my @lines;

@lines = $t->cmd("cd `cat /.dshome`\n");
print STDERR @lines;
@lines = $t->cmd(". ./dsenv\n");
print STDERR @lines;

print "JOB,STATUS,START,END\n";
while (<>) {
  @lines = $t->cmd("bin/dsjob -jobinfo $project $_");
    chomp;
    print $_;
    for (@lines) {
        print ",$1" if /Job Status      : (.+)/
                    or /Job Start Time  : (.+)/
                    or /Last Run Time   : (.+)/;
        print "\n" if /Job Restartable/;
    }
}

__END__
:endofperl

(been a long time since I posted so apologies for any layout gaffes)
(Updated to remove some irrelevant date reformatting)

[BioLion]

This sounds like the old suffering from buffering problem. That link describes it far better than i can, so I won't say much more, but you may also find $| and select have some more info too. HTH.

[gmargo]

It might be interesting to see the log files at the time it screws up. But without access to your actual ftptelnet server, this is pretty hard to test.

I would at least try fixing the newlines so you're not sending CRLF to the cmd() function - it expects only the \n. And make sure there are no empty lines. i.e.:

    while(<>) {
        chomp;
        next if !length;
        @lines = $t->cmd("bin/dsjob -jobinfo $project $_\n");

Maybe add an explicit timeout option to the cmd() function as well.