1410723 - Intermittent DistutilsFileError: cannot copy tree

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Testing, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=138730283&repo=mozilla-central

https://queue.taskcluster.net/v1/task/fFKL89L5QIyY5ZIdpzJHjQ/runs/0/artifacts/public/logs/live_backing.log

[task 2017-10-22T11:02:06.969Z] 11:02:06     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetryScalars.js
[task 2017-10-22T11:02:13.012Z] 11:02:13     INFO -  mozdevice killProcess failed force-stop of xpcshell
[task 2017-10-22T11:02:13.032Z] 11:02:13     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryScalars.js | took 6063ms
[task 2017-10-22T11:02:13.065Z] 11:02:13     INFO -  Following exceptions were raised:
[task 2017-10-22T11:02:13.066Z] 11:02:13     INFO -  Traceback (most recent call last):
[task 2017-10-22T11:02:13.066Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 181, in run
[task 2017-10-22T11:02:13.067Z] 11:02:13     INFO -      self.run_test()
[task 2017-10-22T11:02:13.068Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 792, in run_test
[task 2017-10-22T11:02:13.068Z] 11:02:13     INFO -      if self.checkForCrashes(self.tempDir, self.symbolsPath, test_name=name):
[task 2017-10-22T11:02:13.069Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 181, in checkForCrashes
[task 2017-10-22T11:02:13.069Z] 11:02:13     INFO -      self.device.getDirectory(self.remoteMinidumpDir, dumpDir)
[task 2017-10-22T11:02:13.070Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/devicemanagerADB.py", line 541, in getDirectory
[task 2017-10-22T11:02:13.070Z] 11:02:13     INFO -      dir_util.copy_tree(localDir, originalLocal)
[task 2017-10-22T11:02:13.071Z] 11:02:13     INFO -    File "/usr/lib/python2.7/distutils/dir_util.py", line 128, in copy_tree
[task 2017-10-22T11:02:13.071Z] 11:02:13     INFO -      "cannot copy tree '%s': not a directory" % src
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -  DistutilsFileError: cannot copy tree '/tmp/tmps55NSj/minidumps': not a directory
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -  Traceback (most recent call last):
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 625, in <module>
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -      main()
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 620, in main
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -      mobileArgs=xpcsh.mobileArgs):
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 1385, in runTests
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -      mobileArgs, **kwargs)
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 1580, in runTestList
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -      raise exceptions[0]
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -  distutils.errors.DistutilsFileError: cannot copy tree '/tmp/tmps55NSj/minidumps': not a directory
[task 2017-10-22T11:02:13.114Z] 11:02:13    ERROR - Return code: 1

Comment 1

[Intermittent Failures Robot]

2 failures in 864 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 2

Platform breakdown:
* android-4-3-armv7-api16: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 2

[Intermittent Failures Robot]

3 failures in 912 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1
* mozilla-central: 1
* autoland: 1

Platform breakdown:
* android-4-3-armv7-api16: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 3

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=138730283&lineNumber=2140

[task 2017-10-22T11:02:06.969Z] 11:02:06     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetryScalars.js
[task 2017-10-22T11:02:13.012Z] 11:02:13     INFO -  mozdevice killProcess failed force-stop of xpcshell
[task 2017-10-22T11:02:13.032Z] 11:02:13     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryScalars.js | took 6063ms
[task 2017-10-22T11:02:13.065Z] 11:02:13     INFO -  Following exceptions were raised:
[task 2017-10-22T11:02:13.066Z] 11:02:13     INFO -  Traceback (most recent call last):
[task 2017-10-22T11:02:13.066Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 181, in run
[task 2017-10-22T11:02:13.067Z] 11:02:13     INFO -      self.run_test()
[task 2017-10-22T11:02:13.068Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 792, in run_test
[task 2017-10-22T11:02:13.068Z] 11:02:13     INFO -      if self.checkForCrashes(self.tempDir, self.symbolsPath, test_name=name):
[task 2017-10-22T11:02:13.069Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 181, in checkForCrashes
[task 2017-10-22T11:02:13.069Z] 11:02:13     INFO -      self.device.getDirectory(self.remoteMinidumpDir, dumpDir)
[task 2017-10-22T11:02:13.070Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/devicemanagerADB.py", line 541, in getDirectory
[task 2017-10-22T11:02:13.070Z] 11:02:13     INFO -      dir_util.copy_tree(localDir, originalLocal)
[task 2017-10-22T11:02:13.071Z] 11:02:13     INFO -    File "/usr/lib/python2.7/distutils/dir_util.py", line 128, in copy_tree
[task 2017-10-22T11:02:13.071Z] 11:02:13     INFO -      "cannot copy tree '%s': not a directory" % src
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -  DistutilsFileError: cannot copy tree '/tmp/tmps55NSj/minidumps': not a directory
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -  Traceback (most recent call last):
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 625, in <module>
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -      main()
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/remotexpcshelltests.py", line 620, in main
[task 2017-10-22T11:02:13.072Z] 11:02:13     INFO -      mobileArgs=xpcsh.mobileArgs):
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 1385, in runTests
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -      mobileArgs, **kwargs)
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -    File "/builds/worker/workspace/build/tests/xpcshell/runxpcshelltests.py", line 1580, in runTestList
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -      raise exceptions[0]
[task 2017-10-22T11:02:13.073Z] 11:02:13     INFO -  distutils.errors.DistutilsFileError: cannot copy tree '/tmp/tmps55NSj/minidumps': not a directory
[task 2017-10-22T11:02:13.114Z] 11:02:13    ERROR - Return code: 1
[task 2017-10-22T11:02:13.114Z] 11:02:13    ERROR - No tests run or test summary not found

Bug 1328301 updated getDirectory(), but that is conditional on using a modern adb. In automation, we were using an older adb until I updated it in bug 1409057.

Comment 4

[Intermittent Failures Robot]

5 failures in 857 pushes (0.006 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 3
* mozilla-inbound: 2

Platform breakdown:
* android-4-3-armv7-api16: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 5

[Geoff Brown [:gbrown]]

I haven't quite figured out what is going wrong here or how to fix it, and probably won't get to it for at least a few days. :bc, checking with you to see if you have come across this, and/or if you want to take it?? (No pressure -- nothing urgent here afaik.)

Comment 6

[Bob Clary [:bc] (inactive)]

Yes, I have seen it in autophone. It is common but not that frequent. I would like to take a look some time but it is really low on my priorities. The main issue I'd like to tackle now is disabling the tests which time out since they result in dramatic reductions in throughput. If someone would like to investigate that would be great. Otherwise, I'll get to it when I have the time. Thanks for the heads up though. I had thought this was Autophone specific. It must lie in devicemanager somewhere.

Comment 7

[Intermittent Failures Robot]

4 failures in 849 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2
* autoland: 2

Platform breakdown:
* android-4-4-armv7-api16: 2
* android-4-3-armv7-api16: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-11-06&endday=2017-11-12&tree=all

Comment 8

[Intermittent Failures Robot]

5 failures in 762 pushes (0.007 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1

Platform breakdown:
* android-4-3-armv7-api16: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-11-13&endday=2017-11-19&tree=all

Comment 9

[Intermittent Failures Robot]

6 failures in 744 pushes (0.008 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 3
* autoland: 2
* mozilla-inbound: 1

Platform breakdown:
* android-4-3-armv7-api16: 4
* android-api-16-gradle: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-11-20&endday=2017-11-26&tree=all

Comment 10

[Geoff Brown [:gbrown]]

Attachment: better diagnostics on getDirectory failure

I don't understand how/why that directory is not there after the pull. Rather than pull my hair out, here's a patch to improve the error message -- hopefully that will help me understand the problem.

Comment 11

[Bob Clary [:bc] (inactive)]

Comment on attachment 8933153 [details] [diff] [review]
better diagnostics on getDirectory failure

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

Let's chat on irc.

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +538,5 @@
>                  localDir = os.path.join(tempParent, remoteName)
>              else:
>                  localDir = '/'.join(localDir.rstrip('/').split('/')[:-1])
> +        cmd = ["pull", remoteDir, localDir]
> +        proc = self._runCmd(cmd)

The way _runCmd is written, proc will be None if _runCmd times out. At first I thought we needed the wait() but it seems _runCmd will guarantee that it is called if proc is not None.

@@ +543,1 @@
>          if copyRequired:

Maybe handle no proc by:

    if not proc:
        raise Exception("getDirectory() _runCmd %s failed" % str(cmd))
    try:
        ...

But really, the caller's of _runCmd seem to expect proc to be returned regardless of the timeout. Perhaps we should make _runCmd always return proc even if it does timeout. Then we would need the proc.wait().

Comment 12

[Geoff Brown [:gbrown]]

Attachment: better diagnostics on getDirectory failure

Thanks. I like the idea of always returning proc from _runCmd, since many existing callers assume a non-None return value. Also added some warnings to _runCmd to give us more info about retries. Let's see how that works.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ba362d7944eba488a31d41e2c64fa56c8d24138f

Comment 13

[Bob Clary [:bc] (inactive)]

Comment on attachment 8933354 [details] [diff] [review]
better diagnostics on getDirectory failure

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

Minor style comments. Looks good to me. r+

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +544,5 @@
> +            try:
> +                dir_util.copy_tree(localDir, originalLocal)
> +                mozfile.remove(tempParent)
> +            except:
> +                self._logger.error("getDirectory() failed after %s" % str(cmd))

Since we have proc now, what do you think of adding proc.returncode to the error message?

@@ +696,5 @@
>                  retries += 1
>              else:
>                  return proc
> +        self._logger.warning("_runCmd exceeded all retries")
> +        return proc

Personal style issue. Feel free to ignore.

proc = None
while retries < retryLimit:
    proc = ProcessHandler(finalArgs, storeOutput=True,
                          processOutputLine=self._log, onTimeout=_timeout)
    proc.returncode = proc.wait()
    if proc.returncode is not None:
        break
    proc.kill()
    self._logger.warning("_runCmd failed for '%s'" % ' '.join(finalArgs))
    retries += 1
if retries >= retryLimit:
    self._logger.warning("_runCmd exceeded all retries")
return proc

Comment 14

[Geoff Brown [:gbrown]]

Great suggestions -- will incorporate both on landing.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0e3f8ec51869
Improve diagnostics when Android devicemanager getDirectory fails; r=bc

Comment 16

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/0e3f8ec51869

Comment 17

[Intermittent Failures Robot]

3 failures in 792 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 3

Platform breakdown:
* android-api-16-gradle: 2
* android-4-3-armv7-api16: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-11-27&endday=2017-12-03&tree=all

Comment 18

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=149266366&lineNumber=1875

[task 2017-12-02T08:41:40.533Z] 08:41:40     INFO -  mozdevice getDirectory() failed after ['pull', '/storage/sdcard/tests/xpc/minidumps', '/tmp/tmp8XVf2s/minidumps']
[task 2017-12-02T08:41:40.533Z] 08:41:40     INFO -  mozdevice rc=1 out=['adb: error: failed to get feature set: no devices/emulators found']
...
[task 2017-12-02T08:41:40.545Z] 08:41:40     INFO -  DistutilsFileError: cannot copy tree '/tmp/tmp8XVf2s/minidumps': not a directory

Comment 26

[Geoff Brown [:gbrown]]

Attachment: use _checkCmd instead of _runCmd for getDirectory

All the recent failures with extra diagnostics show the same error message, as in comment 18: The emulator is suddenly unresponsive. That's a common intermittent problem with the emulator, usually handled by retrying the task whenever a DMError is seen. From that perspective, the only problem here is that getDirectory fails to throw DMError in this case; using _checkCmd should rectify that.

Comment 27

[Geoff Brown [:gbrown]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=85d3338678c333b5c8f297172c6ac8673d480985

Comment 28

[Bob Clary [:bc] (inactive)]

Comment on attachment 8934718 [details] [diff] [review]
use _checkCmd instead of _runCmd for getDirectory

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

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +539,4 @@
>              else:
>                  localDir = '/'.join(localDir.rstrip('/').split('/')[:-1])
>          cmd = ["pull", remoteDir, localDir]
> +        proc = self._checkCmd(cmd)

_checkCmd returns the returncode of the process.

Comment 29

[Geoff Brown [:gbrown]]

Attachment: throw DMError when a bad emulator is suspected

It looks like 'adb pull' will return non-zero for other conditions -- an empty directory, or a directory that doesn't exist, so I think it is necessary to parse the output to decide if throwing a DMError and triggering a task retry is reasonable.

Here I check for the "no devices/emulators found" message as an explicit indication that the emulator is down, but also allow for other conditions: if adb pull failed and didn't report any of the expected messages:

 0 files pulled
 1 file pulled
 <remote dir> does not exist


Doesn't break the common cases: https://treeherder.mozilla.org/#/jobs?repo=try&revision=60e69ae6e6892d809f1c5833a7d6ac19cf399c7f

Comment 30

[Bob Clary [:bc] (inactive)]

Comment on attachment 8935133 [details] [diff] [review]
throw DMError when a bad emulator is suspected

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

r+. Feel free to ignore the style comment.

::: testing/mozbase/mozdevice/mozdevice/devicemanagerADB.py
@@ +544,5 @@
> +            # Raise a DMError when the device is missing, but not when the
> +            # directory is empty or missing.
> +            if ("no devices/emulators found" in proc.output or
> +                not ("pulled" in proc.output or
> +                     "does not exist" in proc.output)):

A comment on style. I find I need to concentrate a bit to make sure this does what we expect. What do you think of?

        if ("no devices/emulators found" in proc.output or
            "pulled" not in proc.output and
            "does not exist" not in proc.output):

or with parens which aren't absolutely necessary but do provide a 1 char indent of the raise from the condition?

        if ("no devices/emulators found" in proc.output or
            ("pulled" not in proc.output and
             "does not exist" not in proc.output)):

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1a48edb857f3
Throw DMError when getDirectory() fails suspiciously; r=bc

Comment 32

[Dorel Luca [:dluca]]

Backed out changeset 1a48edb857f3 (bug 1410723) for autophone mass failures r=backout on a CLOSED TREE

https://treeherder.mozilla.org/logviewer.html#?job_id=150341938&repo=mozilla-inbound

https://hg.mozilla.org/integration/mozilla-inbound/rev/70fd148133435d20416262be28f51ee4c430a6f6

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=1a48edb857f33c02e23104d9d1f7b6e1e5c42a75&selectedJob=150341938

Comment 33

[Geoff Brown [:gbrown]]

I forgot that proc.output is a []. This should fix it up:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ece6d35061a391956e9c11c12953a6a826f57e5f

Comment 35

[Geoff Brown [:gbrown]]

autophone passes on try, with a simple modification to account for [] output.

Comment 36

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5115d6bc9009
Throw DMError when getDirectory() fails suspiciously; r=bc

Comment 37

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/5115d6bc9009

Comment 38

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/888df7563642
https://hg.mozilla.org/releases/mozilla-beta/rev/c7a07000546a

Comment 39

[Geoff Brown [:gbrown]]

Confirmation this is working: https://treeherder.mozilla.org/logviewer.html#?job_id=150809794&repo=mozilla-inbound&lineNumber=1884

Comment 40

[Intermittent Failures Robot]

6 failures in 889 pushes (0.007 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 3
* autoland: 2
* mozilla-central: 1

Platform breakdown:
* android-api-16-gradle: 4
* android-4-4-armv7-api16: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1410723&startday=2017-12-04&endday=2017-12-10&tree=all

Comment 41

[Intermittent Failures Robot]

1 failures in 655 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* android-4-3-armv7-api16: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1410723&startday=2018-05-28&endday=2018-06-03&tree=trunk