Closed Bug 1452239 Opened 2 years ago Closed Last year

mozdevice - Missing convenient way of processing shell() output as it happens

Categories

(Testing :: Mozbase, defect, P1)

Version 3
defect

Tracking

(firefox61 fixed)

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

(Reporter: gbrown, Assigned: gbrown)

References

Details

Attachments

(1 file, 3 obsolete files)

In bug 1445716, a new Android test suite is being added for on-device junit tests. The tests are run with 'adb shell am instrument ...' It looks like the suite might run for 10 minutes or so initially, and of course will likely run longer over time, as more tests are added.

If the new harness calls 

  out = shell_output(cmd)
  self.log.info(out)

it won't log anything all the time the tests are running. That's a poor experience if running locally and watching for results. And in automation, I suppose it might result in a misleading log (missing information) for some hang scenarios.

For situations like this, I'd like to get output as it happens. (I don't mind a little buffering.)
This works for me, but I feel like a bull in a china shop. Suggestions for a more elegant approach are welcome!

I neglect your exit code processing -- I can live without an accurate exit code.
Attachment #8965846 - Flags: review?(bob)
I have a couple of nits so far, but I'd like to think about this for a bit. I can see the use case but I'm not entirely happy. Give me a bit and I'll get back to you.
Comment on attachment 8965846 [details] [diff] [review]
call callback for each line of output

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

Let's try this on a try run and see if it works for you. I'll do the final r then.

::: testing/mozbase/mozdevice/mozdevice/adb.py
@@ +39,2 @@
>                                       stderr=subprocess.STDOUT)
>  

As we discussed, let's drop this stdout and use the temp stdout_file object as is.

@@ +725,5 @@
>          """Get the exitcode from the last line of the file_obj for shell
>          commands.
>          """
> +        if not file_obj:
> +            return None

then we can drop this.

@@ +1059,5 @@
>              envstr = '&& '.join(map(lambda x: 'export %s=%s' %
>                                      (x[0], x[1]), env.iteritems()))
>              cmd = envstr + "&& " + cmd
> +        if not stdout_callback:
> +            cmd += "; echo rc=$?"

As we discussed, let's leave this in.

@@ +1070,5 @@
>          if self._device_serial:
>              args.extend(['-s', self._device_serial])
>          args.extend(["wait-for-device", "shell", cmd])
> +        stdout = subprocess.PIPE if stdout_callback else None
> +        adb_process = ADBProcess(args, stdout=stdout)

won't need these changes.

@@ +1079,5 @@
>          start_time = time.time()
>          exitcode = adb_process.proc.poll()
>          while ((time.time() - start_time) <= timeout) and exitcode is None:
> +            if stdout_callback:
> +                line = adb_process.proc.stdout.readline()

I found the timedReadLine thing in sisyphus/bughunter:
https://hg.mozilla.org/automation/sisyphus/file/tip/python/sisyphus/automation/utils.py#l93
https://hg.mozilla.org/automation/sisyphus/file/tip/python/sisyphus/automation/utils.py#l97

this should prevent the readline from blocking us.

@@ +1094,5 @@
>          else:
>              adb_process.exitcode = exitcode
>  
> +        if adb_process.stdout_file:
> +            adb_process.stdout_file.seek(0, os.SEEK_SET)

won't need this change.
Attachment #8965846 - Flags: review?(bob)
(In reply to Bob Clary [:bc:] from comment #3)

Thanks for the timedReadLine links - should come in handy.

> As we discussed, let's drop this stdout and use the temp stdout_file object
> as is.

I like this idea in general. 

I am having some trouble with the implementation. In particular, we'll have Popen appending to the stdout_file from TemporaryFile while the shell() loop is reading from the same file. To keep file pointers sane I think I need to dup stdout_file and read from the dup...but that's not working. I am making slow progress toward debugging, but wouldn't mind jumping to a solution if someone (hey :bc) can see what I'm doing wrong.
Attachment #8965846 - Attachment is obsolete: true
Priority: -- → P1
(In reply to Geoff Brown [:gbrown] from comment #4)
> I am having some trouble with the implementation.

I found that I need to seek() before each read. That doesn't seem right to me, but it works...
Perhaps we should open the open the temp file with mode="w+" to be consistent but it appears that the seek is required.

Does it work on all platforms? Particularly Windows?
(In reply to Bob Clary [:bc:] from comment #8)
> Does it work on all platforms? Particularly Windows?

I haven't tried on Windows. All the low-level file operations I used are supposed to work on Windows, but the signal stuff in timedReadLine is not available on Windows. I like the idea of timedReadLine, but I actually haven't had any trouble just using readline() instead.
This does what I need for geckoview-junit tests.

It seems signal.SIGALRM throws an AttributeError on Windows, so the callback feature will not work on Windows hosts (I'm not too concerned, but I'm open to suggestions too).
Attachment #8967113 - Attachment is obsolete: true
Attachment #8967808 - Flags: review?(bob)
Comment on attachment 8967808 [details] [diff] [review]
add optional callback parameter to shell()

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

r+ with comments.

::: testing/mozbase/mozdevice/mozdevice/adb.py
@@ +1040,5 @@
> +
> +        def _timed_read_line(filehandle, timeout=None):
> +            """
> +            Attempt to readline from filehandle. If readline does not return
> +            within timeout seconds, raise IOError('ReadLineTimeout')

Add a comment about how this is not supported on Windows and as a result there may be cases where the readline blocks.

I guess the only other possibility is to use threads to get cross platform support but I don't think that we need to go that far until it is proven to be a problem. All of our automation will be running on Linux anyway.

@@ +1041,5 @@
> +        def _timed_read_line(filehandle, timeout=None):
> +            """
> +            Attempt to readline from filehandle. If readline does not return
> +            within timeout seconds, raise IOError('ReadLineTimeout')
> +            """

We should check if signal.SIGALRM is supported and handle that case otherwise we will be totally broken on Windows.

if not hasattr(signal, 'SIGALRM'):
    return filehandle.readline().rstrip()

...

@@ +1043,5 @@
> +            Attempt to readline from filehandle. If readline does not return
> +            within timeout seconds, raise IOError('ReadLineTimeout')
> +            """
> +            if timeout is None:
> +                timeout = 5

Is 5 seconds sufficient?
Attachment #8967808 - Flags: review?(bob) → review+
(In reply to Bob Clary [:bc:] from comment #11)
> @@ +1043,5 @@
> > +            Attempt to readline from filehandle. If readline does not return
> > +            within timeout seconds, raise IOError('ReadLineTimeout')
> > +            """
> > +            if timeout is None:
> > +                timeout = 5
> 
> Is 5 seconds sufficient?

I think it is okay. I'm thinking that I don't want a test harness to block for much longer than that if tests are complete; and I don't want to be timing out and giving up on reads frequently: I think most tests will generate a line of output within 5 seconds (junit tests are chatty -- rarely quiet for more than 1 second).
Added the SIGALRM check and comment update -- thanks.
https://hg.mozilla.org/mozilla-central/rev/8eaced3b0ff4
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
You need to log in before you can comment on or make changes to this bug.