6

I'm writing a backup script I intend to execute in a cronjob every night.

The script sets sys.stdout and sys.stderr to an output file to keep a log of what happens.

To do the backup I use the following code

cmd = 'rsync -av --del --stats --filter "- .thumbnails/" ' + \
    '--filter "- *~" --filter "- *.iso" --filter "- lost+found/" ' + \
    '--filter "- .cache/" --filter "- tmp/" --filter "- *.mp3" ' + \
    '--filter "- *.log" ' + srcDir + ' ' + dstDir

print "Executing '"+cmd+"' ..."
try:
    sys.stdout.flush()
    sys.stderr.flush()
    retcode = subprocess.call( cmd, stdin = sys.stdin, stdout = sys.stdout,
        stderr=sys.stderr, shell=False )
    if retcode < 0:
        print >>sys.stderr, "Command was terminated by signal", -retcode
    elif retcode > 0:
        print >>sys.stderr, "Command returned code ", retcode
except OSError, e:
    print >>sys.stderr, "Execution failed:", e

I add print statements before and after the subprocess call. The problem is that I get the output of the subprocess call before any output of my print instructions before the call. I added the flush() calls but it has no effect.

Why is this happening and how could I change this behaviour ?

Cœur
  • 37,241
  • 25
  • 195
  • 267
chmike
  • 20,922
  • 21
  • 83
  • 106
  • 1
    How are you setting sys.stdout and sys.stderr? – Ned Oct 31 '09 at 17:10
  • 1
    It seems correct and shouldn't behave like that (and doesn't when I try), could you describe your environment (OS, shell from which you launch the script)? – RedGlyph Oct 31 '09 at 17:32
  • Why don't you use existing tools such as `rsnapshot` (it also uses `rsync`). – jfs Oct 31 '09 at 20:02
  • First, the script above cannot work, because you have to provide call() with a list of arguments — not a string of space-separated arguments — if you are going to supply "shell=False". So call() should have complained "No such file or directory". Second, as RedGlyph says, the script both looks correct and works for us when we ourselves try it. Could you share with us more about the environment you are working in? On any system where Python handles I/O correctly, the script should work really well — you've written it to do the flushing correctly from what we can see from here! – Brandon Rhodes Oct 31 '09 at 22:46
  • @Sebastian: don't know of the existence of rsnapshot. Here I control what I do. I send the log file in a mail, etc. – chmike Nov 01 '09 at 12:49
  • @Brandon: It runs on Ubuntu 8.04 without problem. I checked the documentation and what I do seem all Ok. The problem was that the opened file used buffering and flush() is not enough. Opening the file with the thrid argument set to 0 solves the problem. – chmike Nov 01 '09 at 12:53

3 Answers3

3

I just found the solution here in a Stackoverflow answer.

Replace 

sys.stderr = sys.stdout = logFile = open( tmpLogFileName, 'a' )

with 

sys.stderr = sys.stdout = logFile = open( tmpLogFileName, 'a', 0 )

This tells python to not assign any output buffer to file.

Community
  • 1
  • 1
chmike
  • 20,922
  • 21
  • 83
  • 106
  • 2
    But this is giving up too soon! :-) We want to help you figure out why flush() isn't working; if you just turn off the buffering, the real problem — whatever it was — won't get fixed. :-) – Brandon Rhodes Oct 31 '09 at 22:35
  • :] That's the solution. I'm not giving up. I think the real problem is inside flush. Investigating and solving this is beyond my competence and my needs. – chmike Nov 01 '09 at 13:02
  • Well, that was an interesting pitfall, glad you overcame it :-) – RedGlyph Nov 03 '09 at 00:20
0

Have you tried putting the flush calls outside the try block?

Ewan Todd
  • 7,315
  • 26
  • 33
  • 2
    No because this should not should have no effect on the output behavior. It looks like the flush is not flushing in fact. Adding >>sys.stdout to the print "Executing" instruction doesn't change de the behavior. – chmike Oct 31 '09 at 17:04
0

Why are you printing to stderr? If the subprocess is writing to stdout while you are writing to stderr, that could explain the odd interleaving.

Ned Batchelder
  • 364,293
  • 75
  • 561
  • 662
  • 2
    I assume the call blocks until the called command ends. Otherwise I wouldn't be able to get the return code. – chmike Oct 31 '09 at 17:01
  • The call does block, as you say, so you can retrieve the return code. But that doesn't explain why you are printing to stderr. If you use the same file as the subcommand, perhaps the output would be properly interleaved. – Ned Batchelder Oct 31 '09 at 17:10
  • 1
    I'm using the same file because I have the instruction 'sys.stdout = sys.stderr = logFile = open( "/tmp/backup.log", "a" )' at the start of the program. Beside specifying stdout=sys.stdout etc. sets the log file as stdout file for the called command. It works. It is just that flush() is not really writing the buffered data to disk. – chmike Oct 31 '09 at 17:40