Closed Bug 1046087 Opened 8 years ago Closed 7 years ago

mozdevice devicemanagerADB stopped working in windows

Categories

(Testing :: Mozbase, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

(blocking-b2g:2.0+, firefox32 wontfix, firefox33 wontfix, firefox34 fixed, b2g-v2.0 fixed, b2g-v2.1 fixed)

RESOLVED FIXED
mozilla34
blocking-b2g 2.0+
Tracking Status
firefox32 --- wontfix
firefox33 --- wontfix
firefox34 --- fixed
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: vasanth, Assigned: armenzg)

References

Details

Attachments

(1 file, 3 obsolete files)

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
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?
Flags: needinfo?(armenzg)
I will look at it this afternoon.
Flags: needinfo?(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.
Assignee: nobody → 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
(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.
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)
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.
Attachment #8468044 - Flags: review?(ahalberstadt)
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.
Attachment #8468044 - Flags: review?(ahalberstadt) → review+
This is breaking cpp unit tests: [1]
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/armenzg@mozilla.com-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).
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.
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
Attachment #8468044 - Attachment is obsolete: true
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
Attachment #8468772 - Flags: review?(wlachance)
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
Attachment #8468772 - Flags: review?(wlachance)
I found out that adb for Windows appends "\r\r\n" at the end of each line. Gotta love it.
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")
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
Attached patch replace \r\r\n for \n (obsolete) — Splinter Review
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.
Attachment #8469504 - Flags: review?(wlachance)
Attachment #8468772 - Attachment is obsolete: true
Attachment #8469504 - Attachment is obsolete: true
Attachment #8469504 - Flags: review?(wlachance)
Attachment #8469532 - Flags: review?(wlachance)
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.
Attachment #8469532 - Flags: review?(wlachance) → review+
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.
Blocks: 1050756
Hi vasanth, could you please verify that mozdevice 0.38 and mozprocess 0.20 (just released) resolves your issue?
Flags: needinfo?(vasanth)
Whiteboard: [leave open]
(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.
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.
(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.
Flags: needinfo?(vasanth)
Flags: needinfo?(armenzg)
Depends on: 1051799
(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.
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.
Status: NEW → RESOLVED
Closed: 7 years ago
Flags: needinfo?(vasanth)
Resolution: --- → FIXED
This issue is resolved in mozprocess 0.21. thanks Armen!
Flags: needinfo?(vasanth)
[Blocking Requested - why for this release]: 
We are using this for our automation running on 2.0. Can we please uplift this?
blocking-b2g: --- → 2.0?
(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)
blocking-b2g: 2.0? → 2.0+
You need to log in before you can comment on or make changes to this bug.