1005856 - [mozinstall] Missing failure details for exceptions when (un)installing Firefox: "mozinstall.mozinstall.UninstallError: Failed to uninstall"

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Andrei Eftimie]

We've had 2 testruns fail to delete the installation folder, both on mm-win-8-32-2:
http://mm-ci-master.qa.scl3.mozilla.com:8080/job/mozilla-aurora_functional/24103/
http://mm-ci-master.qa.scl3.mozilla.com:8080/job/mozilla-esr24_addons/2014/

Relevant part of the log:
> 05:31:12 RESULTS | Passed: 93
> 05:31:12 RESULTS | Failed: 0
> 05:31:12 RESULTS | Skipped: 15
> 05:31:12 Report document created at 'http://mozauto.iriscouch.com/mozmill-daily/0bd22723d1fdbb446269f765b91714d3'
> 05:31:12 *** Removing profile: c:\jenkins\workspace\mozilla-aurora_functional\data\profile
> 05:31:12 *** Uninstalling build: c:\jenkins\workspace\mozilla-aurora_functional\data\binary\2014-05-03-00-40-03-mozilla-aurora-firefox-31
> 05:35:59 Traceback (most recent call last):
> 05:35:59   File "c:\jenkins\workspace\mozilla-aurora_functional\mozmill-env-windows\python\Scripts\testrun_functional-script.py", line 9, in <module>
> 05:35:59     load_entry_point('mozmill-automation==2.0.6.1', 'console_scripts', 'testrun_functional')()
> 05:35:59   File "c:\jenkins\workspace\mozilla-aurora_functional\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 786, in functional_cli
> 05:35:59     exec_testrun(FunctionalTestRun)
> 05:35:59   File "c:\jenkins\workspace\mozilla-aurora_functional\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 769, in exec_testrun
> 05:35:59     cls().run()
> 05:35:59   File "c:\jenkins\workspace\mozilla-aurora_functional\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 360, in run
> 05:35:59     mozinstall.uninstall(self._folder)
> 05:35:59   File "c:\jenkins\workspace\mozilla-aurora_functional\mozmill-env-windows\python\lib\site-packages\mozinstall\mozinstall.py", line 196, in uninstall
> 05:35:59     raise Exception('Failure removing uninstall folder.')
> 05:35:59 mozinstall.mozinstall.UninstallError: Failed to uninstall c:\jenkins\workspace\mozilla-aurora_functional\data\binary\2014-05-03-00-40-03-mozilla-aurora-firefox-31
> 05:36:00 Build step 'Invoke XShell command' marked build as failure

Nothing in the machine logs.

Not sure. Might have been a permission or file lock issue under Windows...
To make sure I've removed the Jenkins folder and rebooted the machine.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Why infrastructure? This is a mozbase/mozinstall issue not correctly handling a specific situation. Would be good to know what it is in detail.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Maybe it would already help to add more details for the failure in the exception message.

Comment 3

[Andrei Eftimie]

(In reply to Henrik Skupin (:whimboo) from comment #1)
> Why infrastructure? This is a mozbase/mozinstall issue not correctly
> handling a specific situation. Would be good to know what it is in detail.

Well infra if the specific situation is/was a machine issue (not sure if this is the case or not).

Comment 4

[Sambuddha Basu [:sambuddhabasu1]]

I am interested to work on this bug. Please assign it to me.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Thanks Sam. Let me know if you have questions. First please see the URL in how to get started on mozbase hacking.

Comment 6

[Mike Hoye [:mhoye]]

(In reply to Sambuddha Basu from comment #4)
> I am interested to work on this bug. Please assign it to me.

Hi, Sambudddha - Are things moving along for you? Do you have any questions?

Comment 7

[Mihaela Velimiroviciu (:mihaelav)]

Failed again today in http://mm-ci-master.qa.scl3.mozilla.com:8080/job/mozilla-central_update/12932/ :

06:58:44 TEST-END | testUpdate.js | finished in 816ms
06:58:45 RESULTS | Passed: 4
06:58:45 RESULTS | Failed: 0
06:58:45 RESULTS | Skipped: 0
06:58:45 Report document created at 'http://mozauto.iriscouch.com/mozmill-daily/46dbc8f622b855f9ec017c8a6075b3a5'
06:58:45 *** Removing profile: c:\jenkins\workspace\mozilla-central_update\data\profile
06:58:46 *** Uninstalling build: c:\jenkins\workspace\mozilla-central_update\data\binary\2014-11-02-03-02-04-mozilla-central-firefox-36
06:59:46 Traceback (most recent call last):
06:59:46   File "c:\jenkins\workspace\mozilla-central_update\mozmill-env-windows\python\Scripts\testrun_update-script.py", line 9, in <module>
06:59:46     load_entry_point('mozmill-automation==2.0.8.1', 'console_scripts', 'testrun_update')()
06:59:46   File "c:\jenkins\workspace\mozilla-central_update\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 792, in update_cli
06:59:46     exec_testrun(UpdateTestRun)
06:59:46   File "c:\jenkins\workspace\mozilla-central_update\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 764, in exec_testrun
06:59:46     cls().run()
06:59:46   File "c:\jenkins\workspace\mozilla-central_update\mozmill-env-windows\python\lib\site-packages\mozmill_automation\testrun.py", line 364, in run
06:59:46     mozinstall.uninstall(self._folder)
06:59:46   File "c:\jenkins\workspace\mozilla-central_update\mozmill-env-windows\python\lib\site-packages\mozinstall\mozinstall.py", line 196, in uninstall
06:59:46     raise Exception('Failure removing uninstall folder.')
06:59:46 mozinstall.mozinstall.UninstallError: Failed to uninstall c:\jenkins\workspace\mozilla-central_update\data\binary\2014-11-02-03-02-04-mozilla-central-firefox-36
06:59:46 Build step 'Invoke XShell command' marked build as failure

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

How does the affected machine look like? Is there a Firefox version still installed?

Comment 9

[Mihaela Velimiroviciu (:mihaelav)]

No, it isn't.

Comment 10

[Ujjwal Wahi [:ujjwal]]

I would like to on this

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Thanks for your interest Ujjwal! The first thing we should do here for a fix is to update the code for the failure output, so that we can see the real underlying exception message. We perfectly hide that at the moment.

Comment 12

[Ujjwal Wahi [:ujjwal]]

From what I understand 'Failure removing uninstall folder.' exception is raised when uninstall timeout has been reached but uninstall folder still exist. It seems that uninstaller is executing but not completing its task.
If there is someway we can know exactly what happened with execution of uninstaller we can output that as exception message

Please provide some more details and correct me if I understood things differently

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

I can think of a few things that might help out:
1) trap the exception and print it out, this will let us know what type of error code and exception it is, that might help us see the root cause
2) if we fail to delete the directory, there is probably a specific file or two which is causing troubles.  Could we list all files and subfolders and delete them one by one, then print out which specific file is causing a timeout.  Of course this would only be a needed action when we hit an error deleting the first time.
3) maybe there are other flags or parameters to send to the delete folder command.

I am sure while looking at the code there are other safeguarding things that can be done.

:whimboo, can you weigh in here?

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: test.py

The problematic lines are those:
http://mxr.mozilla.org/mozilla-central/source/testing/mozbase/mozinstall/mozinstall/mozinstall.py#216

As you can see we catch the exception and re-throw an UninstallError exception. Sadly we loose the original exception message, which contains the actual problem. That's what I tried to say in comment 11.

Here you have a simple testcase to run, which exactly shows what we should have and what is currently implemented.

Fixing the broken exception message is maybe the only thing we could do here. It would be good to also check other lines of code in this file while working on it. Maybe we also miss it there.

Comment 15

[Ujjwal Wahi [:ujjwal]]

Attachment: bug1005856_fix_exception_message.diff

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Comment on attachment 8544580 [details] [diff] [review]
bug1005856_fix_exception_message.diff

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

::: testing/mozbase/mozinstall/mozinstall/mozinstall.py
@@ +217,2 @@
>                  cls, exc, trbk = sys.exc_info()
> +                error = UninstallError('Failed to uninstall %s : %s' % install_folder, str(ex))

This looks fine. But maybe we should put the underlying error message in rounded brackets instead of separating with a colon.

As talked on IRC please also fix the other instances in that file.

Comment 17

[Ujjwal Wahi [:ujjwal]]

Attachment: Include original error message when re-throw an exception

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Comment on attachment 8545956 [details] [diff] [review]
Include original error message when re-throw an exception

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

The patch looks fine and should not cause a test failure under mozbase. But for safety I triggered a try build:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=ddb5522ebb36

I will land the patch when unit tests are all passing.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+1]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e44fa14f6a51

Thank you Ujjwal for your contribution! If you want to continue with something else please let me know.

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e44fa14f6a51