1046087 - mozdevice devicemanagerADB stopped working in windows

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[vasanth]

Below code part used to work in Windows before but showing error now

STR
---
import mozdevice
import StringIO
dm=mozdevice.devicemanagerADB.DeviceManagerADB()
h=dm.shellCheckOutput(['b2g-ps'])

Error
-----
    raise DMError("Non-zero return code for command: %s (output: '%s', retval: '%s')" % (cmd, output, retval))
mozdevice.devicemanager.DMError: Non-zero return code for command: ['b2g-ps'] (output: '', retval: 'None')


Analysis
--------
Seems the way, marionette trigger adb shell commands is changed now [1] [2]
In windows, with new way [2], there is an empty line after each output line.

Return code is usually obtained by appending “; echo $?” to actual command and then reading last output line [3]

Since last line is empty in windows, proper return code is not received and scripts are failing.

Checking if line != “” before [4] makes it work. 
Is that an acceptable fix?

[1] Older way using subprocess 
[2] Now using ProcessHandler
http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#128
[3] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py#109
[4] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozprocess/mozprocess/processhandler.py#774

Comment 1

[William Lachance (:wlach)]

In general we recommend using mozdevice/marionette on Linux as that's the codepath we use in automation and test most extensively. However, this problem looks reasonably easy to fix, though I'm almost certain that the problem is in mozdevice and not mozprocess (which has been extensively tested). Armen, could you have a look?

Comment 2

[Armen [:armenzg]]

I will look at it this afternoon.

Comment 3

[Armen [:armenzg]]

I did not have time to look at this yesterday due to other work. Tomorrow I'm off and Monday is a holiday in Canada. I will be looking at this a bit at this but I don't know if I will have a results before Tuesday.

Please let us know if this cannot wait until Tuesday.

Comment 4

[Armen [:armenzg]]

As a workaround, if I understand correctly, you should be able to create another virtualenv with 0.37 until I can get a fix out on Tuesday. I hope this should be good for you.

I'm currently setting up my environment.

This is what I've got so far:
* Install pip following steps in [1]
* Follow to most extent the instructions in here [2]
** I installed the 16 packages that are selected by default
* Append C:\Program Files (x86)\Android\android-sdk\platform-tools to PATH

Then I tested two scenarios:
* Create and activate a venv and pip install mozdevice==0.38 [3]
* Create and activate a venv and pip install mozdevice==0.37 [4]

Running the code on the description with mozdevice 0.38 fails and with 0.37 works.

I will dig into it deeper on Tuesday and have a fix.

[1] http://www.tylerbutler.com/2012/05/how-to-install-python-pip-and-virtualenv-on-windows-with-powershell/
[2] http://wiki.yobi.be/wiki/Android_SDK
[3]
$ pip freeze
mozdevice==0.38
mozfile==1.1
mozinfo==0.7
mozlog==2.1
moznetwork==0.24
mozprocess==0.19
[4]
$ pip freeze
mozdevice==0.37
mozfile==1.1
mozinfo==0.7
mozlog==2.1
moznetwork==0.24

Binaries downloaded:
* http://dl.google.com/android/installer_r23.0.2-windows.exe
* http://download.oracle.com/otn-pub/java/jdk/8u11-b12/jdk-8u11-windows-x64.exe

Comment 5

[vasanth]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #4)
> * Create and activate a venv and pip install mozdevice==0.37 [4]

Thanks! This works for now.

Comment 6

[Armen [:armenzg]]

Switch from subprocess.Popen() to mozprocess has shown an underlying bug in mozprocess. I had seen the issue in one of the tbpl logs but never chasing down.

The bug is in processhandler.py, this fixes the issue [1]:
-                    return (f.readline(), False)
+                    return (f.readline().rstrip(), False)

You can look at the output of one run without the fix and one with the fix.

To increase the output all I did is add a logLevel:
dm=mozdevice.devicemanagerADB.DeviceManagerADB(logLevel=mozlog.DEBUG)

I will post a patch in a little bit.

[1] http://hg.mozilla.org/mozilla-central/file/b50bb656674e/testing/mozbase/mozprocess/mozprocess/processhandler.py#l858

mozdevice DEBUG | shell - command: adb shell b2g-ps; echo $?
mozdevice DEBUG | APPLICATION      USER     PID   PPID  VSIZE  RSS     WCHAN    PC         NAME
mozdevice DEBUG |
mozdevice DEBUG | b2g              root      135   1     187620 74388 ffffffff 40087604 S /system/b2g/b2g
mozdevice DEBUG |
mozdevice DEBUG | (Nuwa)           root      337   135   53136  20076 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG |
mozdevice DEBUG | Homescreen       app_365   365   337   88124  28744 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG |
mozdevice DEBUG | Settings         app_469   469   337   71244  31800 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG |
mozdevice DEBUG | (Preallocated a  app_642   642   337   59276  20504 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG |
mozdevice DEBUG | 0
mozdevice DEBUG |
Traceback (most recent call last):
  File "my_script.py", line 5, in <module>
    h=dm.shellCheckOutput(['b2g-ps'])
  File "c:\Users\Mozilla\.venvs\bug1046087\lib\site-packages\mozdevice\devicemanager.py", line 396, in shellCheckOutput
    raise DMError("Non-zero return code for command: %s (output: '%s', retval: '%s')" % (cmd, output, retval))
mozdevice.devicemanager.DMError: Non-zero return code for command: ['b2g-ps'] (output: '', retval: 'None')
(bug1046087)

[2]
mozdevice DEBUG | shell - command: adb shell b2g-ps; echo $?
mozdevice DEBUG | APPLICATION      USER     PID   PPID  VSIZE  RSS     WCHAN    PC         NAME
mozdevice DEBUG | b2g              root      135   1     186468 74264 ffffffff 40087604 S /system/b2g/b2g
mozdevice DEBUG | (Nuwa)           root      337   135   53136  20076 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG | Homescreen       app_365   365   337   88124  28744 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG | Settings         app_469   469   337   71244  31800 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG | (Preallocated a  app_642   642   337   59276  20504 ffffffff 400a9604 S /system/b2g/plugin-container
mozdevice DEBUG | 0
(bug1046087)

Comment 7

[Armen [:armenzg]]

Attachment: strip remaining whitespaces of a line

I've also pushed it to the try server to make sure that we don't regress anything.

Even though, I highly doubt there will be any issue:
https://tbpl.mozilla.org/?tree=Try&rev=73adf9b154f9

I will land on m-i tomorrow and release a new version to pypi if there are no issues in the review and the CI run.

Comment 8

[Andrew Halberstadt [:ahal]]

Comment on attachment 8468044 [details] [diff] [review]
strip remaining whitespaces of a line

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

This change worries me a bit, mostly because I don't understand how it fixes anything. We call line.rstrip() before passing it in to processOutputLine here:
http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozprocess/mozprocess/processhandler.py#774

Also "foobar\n".splitlines() returns ["foobar"] (is this different on windows or something?) so I don't see how this patch would fix anything.. I guess if it works and there are no failures (though that try run looks a little scary) then it's ok to land.

Still, please address the commment below.

::: testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ +854,5 @@
>                          raise OSError("readWithTimeout got error: %d", err)
>                  if l.value > 0:
>                      # we're assuming that the output is line-buffered,
>                      # which is not unreasonable
> +                    return (f.readline().rstrip(), False)

There's another "return (f.readline(), False)" above.

Comment 9

[Armen [:armenzg]]

This is breaking cpp unit tests: [1]
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-73adf9b154f9/try-win32/try_xp-ix_test-cppunit-bm110-tests1-windows-build1383.txt.gz

06:44:22     INFO -  Should Release twice and destroy one |TestRefObject|:
06:44:22     INFO -    Release to 1 on TestRefObject 02E1AC80.
06:44:22     INFO -    Release to 0 on TestRefObject 02E1AC80.
06:44:22     INFO -    Destroying TestRefObject 02E1AC80.
06:47:52     INFO -  cppunittests ERROR | [Error 32] The process cannot access the file because it is being used by another process: 'c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\tmpqb5y1r'
06:47:55     INFO -  Error Code 6 trying to query IO Completion Port, exiting
06:47:55     INFO -  Exception in thread Thread-19:
06:47:55     INFO -  Traceback (most recent call last):
06:47:55     INFO -    File "c:\mozilla-build\python27\Lib\threading.py", line 551, in __bootstrap_inner
06:47:55     INFO -      self.run()
06:47:55     INFO -    File "c:\mozilla-build\python27\Lib\threading.py", line 504, in run
06:47:55     INFO -      self.__target(*self.__args, **self.__kwargs)
06:47:55     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 321, in _procmgr
06:47:55     INFO -      self._poll_iocompletion_port()
06:47:55     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 371, in _poll_iocompletion_port
06:47:55     INFO -      raise WinError(errcode)
06:47:55     INFO -  WindowsError: [Error 6] The handle is invalid.
06:47:55    ERROR - Return code: 1

[1] https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=73adf9b154f9 (Ignore blue and purple jobs).

Comment 10

[Armen [:armenzg]]

splitlines(True) returns this:
['error: device not found\r\n']

just splitlines() returns this:
['error: device not found', '']

It is the "\r\n" on Windows that causes us to have an extra line.

With regards to cppunittests, I can reproduce the issue locally.
I hope to have a fix for it tomorrow.

For some odd reason, after a good cppuninttests run, I see a bunch of directories called like this "cpp-unit-profd-#" under tests\cppunittests. I will add more info if it is relevant.

Comment 11

[Armen [:armenzg]]

Attachment: strip \r\n to avoid extra unexpected lines

This fixes the cpp unit tests which were doing some sort of string and buffer manipulation tests.

I will push to try in the morning as the trees are closed.

I wonder if I should fix the issue in here:
   773                 for line in lines.splitlines():
   774                     self.processOutputLine(line.rstrip())

[1] https://hg.mozilla.org/try/file/73adf9b154f9/testing/mozbase/mozprocess/mozprocess/processhandler.py#l773

Comment 12

[Armen [:armenzg]]

Comment on attachment 8468772 [details] [diff] [review]
strip \r\n to avoid extra unexpected lines

That looks much better:
https://tbpl.mozilla.org/?tree=Try&rev=93dc219487f9

cpp unit tests was in need of empty lines containing \r\n

Comment 13

[Armen [:armenzg]]

Comment on attachment 8468772 [details] [diff] [review]
strip \r\n to avoid extra unexpected lines

After discussing it on IRC, we're going to look into switching mozprocess to use universal newlines
https://docs.python.org/2/glossary.html#term-universal-newlines

Comment 14

[Armen [:armenzg]]

I found out that adb for Windows appends "\r\r\n" at the end of each line. Gotta love it.

Comment 15

[Armen [:armenzg]]

Running this code shows the manipulation of the first line.
$ python my_process3.py
'acct\r\r\n'
'acct\r\n'
'acct'
'cache'
...

#############
import subprocess
import os
p = subprocess.Popen(["adb", "shell", "ls"], stdout=subprocess.PIPE, universal_newlines=False)
p.wait()
log = p.stdout
lines = log.readline()
print repr(lines)
lines = lines.replace("\r\r", "\r")
print repr(lines)
while lines != "":
   for line in lines.splitlines():
       print repr(line)
   lines = log.readline().replace("\r\r", "\r")

Comment 16

[Armen [:armenzg]]

I found this:
  Pexpect runs adb within a pseudo-tty device (see
  http://www.noah.org/wiki/pexpect), so any '\n' printed by adb is written
  as '\r\n' to the logfile. Since adb already uses '\r\n' to terminate
  lines, the log ends up having '\r\r\n' at the end of each line. This
  filter replaces the above with a single '\n' in the data stream
 
From https://src.chromium.org/svn/trunk/src/build/android/pylib/android_commands.py

Comment 17

[Armen [:armenzg]]

Attachment: replace \r\r\n for \n

I can pass an output manipulator through the constructor if you prefer to. That way we would only do the replacement when mozdevice passes it to ProcessHandler.

Comment 18

[Armen [:armenzg]]

Attachment: replace \r+\n only at the end of a line for \n

Comment 19

[William Lachance (:wlach)]

Comment on attachment 8469532 [details] [diff] [review]
replace \r+\n only at the end of a line for \n

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

We should consolidate the special case logic in a single method. Looks good otherwise! Feel free to commit with this change and a try run.

::: testing/mozbase/mozprocess/mozprocess/processhandler.py
@@ +841,5 @@
>  
>          def _readWithTimeout(self, f, timeout):
>              if timeout is None:
>                  # shortcut to allow callers to pass in "None" for no timeout.
> +                # Adb on Windows returns \r\r\n at the end of each line

let's put this into a helper method above called:

@staticmethod
_normalize_newline(line):
    # adb on windows returns \r\r\n at the end of each line, to get around
    # this normalize all newlines to have a unix-style '\n'
    # http://src.chromium.org/viewvc/chrome/trunk/src/build/android/pylib/android_commands.py#l1944
    return re.sub(r'\r+\n?$', '\n', line)

Then you should be able to just call it like:

return (self._normalize_newline(f.readline()), False)

This removes the need to have the same logic and comments repeated twice.

Comment 20

[Armen [:armenzg]]

So green: https://tbpl.mozilla.org/?tree=Try&rev=71fdf45e59a7
Here's with the code with the static method: https://hg.mozilla.org/try/rev/71fdf45e59a7

I will land to m-i in the morning and request to bump the version.

Comment 21

[Armen [:armenzg]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/735394aa3813

Comment 22

[Armen [:armenzg]]

Hi vasanth, could you please verify that mozdevice 0.38 and mozprocess 0.20 (just released) resolves your issue?

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Backed out for almost-certainly being the cause of mass Windows bustage.
https://hg.mozilla.org/integration/mozilla-inbound/rev/1e0fd78becce

https://tbpl.mozilla.org/php/getParsedLog.php?id=45541260&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=45543725&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=45544159&tree=Mozilla-Inbound

Why in the world was this landed in a DONTBUILD push?

Comment 24

[William Lachance (:wlach)]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #21)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/735394aa3813

This patch was not the same one that went through try. It contains a bug, you're calling an undefined method called _normalize, not _normalize_newline as you should.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

This also appears to have caused every Windows build slave unfortunate enough to have attempted a build with this patch in the tree to get hung up and unable to take further jobs, contributing to an all-day tree closure.

Comment 26

[Armen [:armenzg]]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #22)
> Hi vasanth, could you please verify that mozdevice 0.38 and mozprocess 0.20
> (just released) resolves your issue?

I landed the wrong patch. I will have to push again and bump the version of mozprocess.
I will ask you to check again on Monday.

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #23)
> Backed out for almost-certainly being the cause of mass Windows bustage.
> https://hg.mozilla.org/integration/mozilla-inbound/rev/1e0fd78becce
> 
> Why in the world was this landed in a DONTBUILD push?

DONTBUILD was not for this patch but for the other one in bug 1046380. I just forgot that tbpl listens to the message of the last changeset:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=735394aa3813

My apologies that this caused such a mess.

Comment 27

[Armen [:armenzg]]

This time the right patch:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2e0e4d841f0f

Comment 28

[Armen [:armenzg]]

(In reply to Armen Zambrano [:armenzg] (EDT/UTC-4) from comment #22)
> Hi vasanth, could you please verify that mozdevice 0.38 and mozprocess 0.20
> (just released) resolves your issue?

The new version of mozprocess is 0.21. I just released it.

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2e0e4d841f0f

Comment 30

[Armen [:armenzg]]

vasanth, let us know if this is not fixed and we can re-open it and investigate it.

I'm marking it fixed as far as we know.

Comment 31

[vasanth]

This issue is resolved in mozprocess 0.21. thanks Armen!

Comment 32

[vasanth]

[Blocking Requested - why for this release]: 
We are using this for our automation running on 2.0. Can we please uplift this?

Comment 33

[bhavana bajaj [:bajaj]]

(Didn't need to block this, could have gone approval route, but given armen is out and we want this in 2.0, blocking here)

Comment 34

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/98ef4027b295