664402 - retry.py should print process output incrementally

Status: RESOLVED WONTFIX

(Release Engineering :: General, defect, P4)

Description

[[e-mail] (:bhearsum)]

retry.py stores up all the output of a process until it completes, then prints it. This is a bit of pain, especially since we're using it a lot in Buildbot now. We don't get to see incremental output, and because there's no process output, there's a greater chance of steps that run retry.py getting timed out.

Comment 2

[Rail Aliiev [:rail]]

Attachment: retry.py: print as it comes

Not sure how seek/read/tell may work here since subprocess may write to the file at the same time...

Another solution would be dropping output search feature and use stdout/stderr directly. ATM we don't use output search but bufferization hits us sometime.

Comment 3

[Chris AtLee [:catlee]]

Comment on attachment 557101 [details] [diff] [review]
retry.py: print as it comes

Review of attachment 557101 [details] [diff] [review]:
-----------------------------------------------------------------

::: buildfarm/utils/retry.py
@@ +53,5 @@
> +            last_stderr = stderr.tell()
> +            if console_stdout:
> +                print console_stdout,
> +            if console_stderr:
> +                print >> sys.stderr, console_stderr,

I'm not sure if this will work. I think that the subprocess inherits the file descriptors for stdout/stderr, which means that they also share the same offset. I'm worried that by seeking backwards, you'll affect where future output of the process is written.

If you could test whether this is true or not, that would be great!

Comment 4

[Rail Aliiev [:rail]]

Attachment: use NamedTemporaryFile and separate file objects

Comment 5

[Rail Aliiev [:rail]]

Comment on attachment 557436 [details] [diff] [review]
use NamedTemporaryFile and separate file objects

Review of attachment 557436 [details] [diff] [review]:
-----------------------------------------------------------------

::: buildfarm/utils/retry.py
@@ +6,5 @@
>  Return code is 0 if cmd succeeds, and is 1 if cmd fails after all the retries.
>  """
>  
>  import time, subprocess, logging, os, sys, re
> +from tempfile import NamedTemporaryFile

This allows to have a real file accessible by file()

@@ +11,3 @@
>  from operator import xor
>  log = logging.getLogger()
> +logging.basicConfig(format='%(asctime)-15s %(message)s', level=logging.DEBUG)

Make logging prettier.

@@ +58,5 @@
> +                if console_stderr:
> +                    print >> sys.stderr, console_stderr,
> +            except IOError:
> +                pass
> +

Using a separate file descriptor (opened with 'r' mode by default) allows us to use independent seek points (I tested this by printing tell()). I also ignore IOErrors here, mostly EOF.

Comment 6

[Rail Aliiev [:rail]]

Attachment: use Threading

Looks like the only way to read stdout/sterr non blocking is to use Queue.get_nowait() + threading... Otherwise (fctnl) it doesn't work on windows. 

If this approach is OK, I'd like to write some tests for retry.py.

Comment 7

[Rail Aliiev [:rail]]

I'll need to try another approach and use the following scenario: read stdout/stderr of the command, print it to stdout/stderr and a temporary file (if needed) for processing.

Comment 8

[Rail Aliiev [:rail]]

Not working on this bug actively. Back to the pool.

Comment 9

[[e-mail] (:bhearsum)]

Redo doesn't have this problem! WE should probably kill retry.py and use redo's command instead.