1003412 - Mozbase unit test mozlog/tests/test_structured.py fails on windows slaves when run from test package.

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Dan Minor [:dminor]]

Relevant portion of log:
13:31:42     INFO -  ERROR: test_setup_logging (test_structured.TestCommandline)
13:31:42     INFO -  ----------------------------------------------------------------------
13:31:42     INFO -  Traceback (most recent call last):
13:31:42     INFO -    File "C:\slave\test\build\tests\mozbase\mozlog\tests\test_structured.py", line 194, in test_setup_logging
13:31:42     INFO -      args = parser.parse_args(["--log-raw=/tmp/foo"])
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 1688, in parse_args
13:31:42     INFO -      args, argv = self.parse_known_args(args, namespace)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 1720, in parse_known_args
13:31:42     INFO -      namespace, args = self._parse_known_args(args, namespace)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 1926, in _parse_known_args
13:31:42     INFO -      start_index = consume_optional(start_index)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 1866, in consume_optional
13:31:42     INFO -      take_action(action, args, option_string)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 1778, in take_action
13:31:42     INFO -      argument_values = self._get_values(action, argument_strings)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 2204, in _get_values
13:31:42     INFO -      value = self._get_value(action, arg_string)
13:31:42     INFO -    File "c:\mozilla-build\python27\Lib\argparse.py", line 2233, in _get_value
13:31:42     INFO -      result = type_func(arg_string)
13:31:42     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\commandline.py", line 26, in log_file
13:31:42     INFO -      return open(name, "w")
13:31:42     INFO -  IOError: [Errno 2] No such file or directory: '/tmp/foo'

Looks like '/tmp' doesn't exist on our windows test slaves.

Comment 1

[Julien Pagès (:parkouss)]

Attachment: fix log file creation on windows and delete it at the end of the test

Comment 2

[Dan Minor [:dminor]]

Thanks, this looks good!

I'm going to give this a run on our try server [1] before finishing the review just to make sure nothing unexpected shows up.

[1] https://tbpl.mozilla.org/?tree=Try&rev=8d665a95052b

Comment 3

[Dan Minor [:dminor]]

Comment on attachment 8419713 [details] [diff] [review]
fix log file creation on windows and delete it at the end of the test

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

Unfortunately, this doesn't work as expected on Windows. The filename of the NamedTemporaryFile can't be used to reopen the file on Windows while the file is still open [1], which leads to error at [2].

I think what we need to do is to set the delete parameter to false, close the file right away, and then delete the file manually at the end of the test, which is kind of hacky. If you have a cleaner way, let me know. Thanks for looking at this!

[1] https://docs.python.org/2/library/tempfile.html#tempfile.NamedTemporaryFile
[2] https://tbpl.mozilla.org/php/getParsedLog.php?id=39356983&tree=Try&full=1#error4

Comment 4

[Julien Pagès (:parkouss)]

I'm sorry for the mistake(s). I didn't test on windows and I didn't read the python doc which clearly indicate the behaviour ;).

I will send another patch where I followed your recommendations as I don't see a better solution. I currently can't test on windows but I think this new patch will work.

Thanks for the feedback!

Comment 5

[Julien Pagès (:parkouss)]

Attachment: fix the temp file reopening on windows

Comment 6

[Dan Minor [:dminor]]

Thanks, don't worry about it! I don't have a windows machine either, so I'll have to kick off another try server run.

Comment 7

[Dan Minor [:dminor]]

Try job here: https://tbpl.mozilla.org/?tree=Try&rev=f46654df2c70

Comment 8

[Julien Pagès (:parkouss)]

Well !

I saw the error log, and found [1] as a possible explanation and solution for this issue. I'm sorry I have to bother you again to launch a build on the try server, but this is my first bug and I don't have yet a mozilla hg account level 1 - so I'm not able to launch it myself.

I'll post a new patch soon, and I'll hope this one will work:) Thanks for the support.

Comment 9

[Julien Pagès (:parkouss)]

Attachment: try to make the temporary log file removed correctly on windows

Comment 10

[Dan Minor [:dminor]]

(In reply to j.parkouss from comment #8)
> Well !
> 
> I saw the error log, and found [1] as a possible explanation and solution
> for this issue. I'm sorry I have to bother you again to launch a build on
> the try server, but this is my first bug and I don't have yet a mozilla hg
> account level 1 - so I'm not able to launch it myself.
> 
> I'll post a new patch soon, and I'll hope this one will work:) Thanks for
> the support.
Don't worry about it, I'm happy you're interested in contributing! Latest try run is here:
https://tbpl.mozilla.org/?tree=Try&rev=a40f68024d4e

Comment 11

[Julien Pagès (:parkouss)]

The best solution I can see now is to use NamedTemporaryFile this way:

temp_fname = tempfile.NamedTemporaryFile(delete=False).name
try:
    # do something, maybe opening the file
    # open(temp_fname, 'w')
finally:
    os.unlink(temp_fname)

This way the file is automatically created then closed properly, and we may reopen it - but in case of a test failure, the file existed anyway so the finally will always success.

I tested it on a windows xp os today and it's working. i'll send you a patch as soon as I have the time.

Comment 12

[Dan Minor [:dminor]]

(In reply to j.parkouss from comment #11)
> The best solution I can see now is to use NamedTemporaryFile this way:
> 
> temp_fname = tempfile.NamedTemporaryFile(delete=False).name
> try:
>     # do something, maybe opening the file
>     # open(temp_fname, 'w')
> finally:
>     os.unlink(temp_fname)
> 
> This way the file is automatically created then closed properly, and we may
> reopen it - but in case of a test failure, the file existed anyway so the
> finally will always success.
> 
> I tested it on a windows xp os today and it's working. i'll send you a patch
> as soon as I have the time.

Thanks for your persistence! Looking forward to the patch.

Comment 13

[Julien Pagès (:parkouss)]

Attachment: 1003412.patch

Comment 14

[Dan Minor [:dminor]]

I think your missing part of your patch - what is there just adds the import for tempfile :)

Comment 15

[Julien Pagès (:parkouss)]

Hmm I don't think so - I clicked on the following link [1] and scrolled down with the mouse and there is more than the import. But I applied instructions from here [2] this time in order to create the patch and I don't know well mercurial, maybe I have done something wrong ?

[1] https://bugzilla.mozilla.org/attachment.cgi?id=8421104&action=edit
[2] https://developer.mozilla.org/en-US/docs/Mercurial_FAQ#How_can_I_generate_a_patch_for_somebody_else_to_check-in_for_me.3F

Comment 16

[Dan Minor [:dminor]]

Oh, sorry, not sure how I missed that! New try run here: https://tbpl.mozilla.org/?tree=Try&rev=4d9208982141

Comment 17

[Julien Pagès (:parkouss)]

It's hard to debug when I can't reproduce it! Anyway, I found that on the last try build the preceeding test log some lines like this one:

remove() failed for "('c:\\users\\cltbld\\appdata\\local\\temp\\tmpvcib92\\foo\\bar.txt',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...

I looked at this test ([1]), and there is a call to mozfile.remove at the end of the test. I looked at the implementation, and there is a retry mecanism in case of a Windows OS [2].

I think this is the solution. Replace os.unlink with mozfile.remove. I hope mozfile is accessible through this test - I will test when I have the time and send another patch.

I read in some post (I can't remember which one right now) that it may be so because of various reasons, for example an antivirus analysing the file while we're trying to delete it.

[1] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozversion/tests/test_b2g.py#30
[2] http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozfile/mozfile/mozfile.py#133

Comment 18

[Julien Pagès (:parkouss)]

Attachment: 1003412.patch

This one should work on windows. I used mozfile.remove to handle previous errors when deleting a file opened by another process.

This is OK if the inclusion of the mozfile package is accepted here - and I suppose it is.

Comment 19

[Dan Minor [:dminor]]

Still no luck: https://tbpl.mozilla.org/?tree=Try&rev=464a860aaa04

At this point, I think it might end up being better to try something simpler. It looks like using a filename of '-' will cause the log to go to stdout instead of to a file, which seems to be fine (at least on linux.)

If you want to update your patch to do this we can get it landed and find you a more interesting bug to work on.

Comment 20

[Julien Pagès (:parkouss)]

Attachment: fix log file creation on windows

Thank you for the solution - I hope this will work !

Comment 21

[Dan Minor [:dminor]]

Thanks for your persistence! The patch looks fine - you just need to update your commit comment for the logs. Use something like:

"Bug 1003412 - Fix Mozbase unit test mozlog/tests/test_structured.py on windows; r=dminor"

You need the bug number, what the patch does and the reviewer. Almost there!

If you're interested in looking at another bug, Bug 1003405 is another straightforward one. After that, maybe we can look at Bug 1003408.

Comment 22

[Julien Pagès (:parkouss)]

Attachment: Bug 1003412 - Fix Mozbase unit test mozlog/tests/test_structured.py on windows; r=dminor

Thanks for all the workflow process infos :)

Comment 23

[Dan Minor [:dminor]]

Comment on attachment 8423829 [details] [diff] [review]
Bug 1003412 - Fix Mozbase unit test mozlog/tests/test_structured.py on windows; r=dminor

Looks good, thank you!

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/5bdeb198f7ce

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/5bdeb198f7ce