Print and pexpect logging

Question

I have a bit of a code that uses pexpect to control a process and some prints in the code. The main goal (in this question) is to have the pexpect output and prints logged into some log file. The problem I ran into is that the pexpect lines (data sent and received) is mingled with the prints with no apparent logic. I was expecting that the print strings and pexpect outputs will be logged in the order they were issued.

Sample code is the following:

#!/usr/bin/env python

import pexpect
import time, sys, os

###############################################################################
# Subclass of file object to avoid recording extensive whitespace characters
class CleanFile(file):
    def write (self, text):
        # Remove the whitespaces
        out_text = ''
        # process the backspace properly
        bline = ''
        for c in text:
            if (ord(c) == 0x8):
                if (len(bline) == 0):
                    # Move the file pointer.
                    file.seek(self, -1, os.SEEK_CUR);
                else:
                    bline = bline[:-1]
            else:
                bline += c

        # remove whitespaces from inside a line
        out_text += ''.join(c for c in bline if (ord(c) >= 32 or ord(c) == 10));

        file.write(self, out_text);

###############################################################################
def main():
    fout = CleanFile ("options.log_file.log", 'w')

    sys.stdout = os.fdopen (sys.stdout.fileno(), 'w', 0)
    os.dup2 (fout.fileno(), sys.stdout.fileno());

    p = pexpect.spawn ('tclsh')
    p.logfile = fout

    print "Got into tclsh."
    p.sendline('ls');
    p.expect (['%',pexpect.EOF])

    p.sendline('info tclversion');
    p.expect (['%',pexpect.EOF])

    print "Got the version\n"

    p.sendline('info commands %');
    p.expect (['%',pexpect.EOF])

    p.sendline('exit');

    print 'Ended session'

###############################################################################
if __name__ == "__main__":
    main()

This is the output log file contents:

Got into tclsh.
ls
% lsinfo tclversion

log  options.log_file.log  pexpect_test.py  runtests.py  runtests_steinway.py
% info tclversionGot the version

info commands %

8.4
% info commands %exit
Ended session

Is there any way to make the pexpect and print outputs sequential?

---

Update: Based on the pexpect manual page: "Please note, however, that buffering can affect this behavior, since input arrives in unpredictable chunks". So it may potentially affect the logging.

Answer 1

If you can wait until the script ends for the results, don't set a log file for pexpect commands, save results of the commands to variables, and print everything in the end.

Note also that you are missing the output of the info commands command. This can be fixed by adding one expect() for waiting the tclsh interpreter to start and removing the '%' from the end of the command. I assumed that was a typo.

Modify main function to be:

def main():                                                          
    fout = CleanFile ("options.log_file.log", 'w')                   

    sys.stdout = os.fdopen (sys.stdout.fileno(), 'w', 0)             
    os.dup2 (fout.fileno(), sys.stdout.fileno());                    

    p = pexpect.spawn ('tclsh')                                      
    p.expect (['%',pexpect.EOF])                                     

    p.sendline('ls');                                                
    p.expect (['%',pexpect.EOF])                                     
    ls = p.before                                                    

    p.sendline('info tclversion');                                   
    p.expect (['%',pexpect.EOF])                                     
    tclversion = p.before                                            

    p.sendline('info commands');                                     
    p.expect (['%',pexpect.EOF])                                     
    commands = p.before                                              

    p.sendline('exit');                                              
    p.close()                                                        

    print "Got into tclsh."                                          
    print ls                                                         
    print tclversion                                                 
    print "Got the version\n"                                        
    print commands                                                   
    print "Ended session"                                            

The output is then:

Got into tclsh.                                                      
 ls                                                                  
options.log_file.log  pexpect_test.py                                

 info tclversion                                                     
8.5                                                                  

Got the version                                                      

 info commands                                           
tell socket subst open eof pwd glob list pid exec auto_load_index time unknown  
eval lassign lrange fblocked lsearch auto_import gets case lappend proc break v 
ariable llength auto_execok return linsert error catch clock info split array i 
f fconfigure concat join lreplace source fcopy global switch auto_qualify updat 
e close cd for auto_load file append lreverse format unload read package set bi 
nary namespace scan apply trace seek while chan flush after vwait dict continue 
 uplevel foreach lset rename fileevent regexp lrepeat upvar encoding expr unset 
 load regsub history interp exit puts incr lindex lsort tclLog string           

Ended session