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

RESOLVED FIXED in mozilla32

Status

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: dminor, Assigned: parkouss)

Tracking

Trunk
mozilla32
x86_64
Linux
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [good first bug][mentor=dminor][lang=python])

Attachments

(1 attachment, 6 obsolete attachments)

Reporter

Description

5 years ago
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.
Reporter

Comment 2

5 years ago
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
Assignee: nobody → j.parkouss
Status: NEW → ASSIGNED
Reporter

Comment 3

5 years ago
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
Attachment #8419713 - Flags: review?(dminor) → review-
Assignee

Comment 4

5 years ago
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!
Assignee

Comment 5

5 years ago
Attachment #8419713 - Attachment is obsolete: true
Attachment #8420187 - Flags: review?(dminor)
Reporter

Comment 6

5 years ago
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.
Assignee

Comment 8

5 years ago
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.
Assignee

Comment 9

5 years ago
Attachment #8420187 - Attachment is obsolete: true
Attachment #8420187 - Flags: review?(dminor)
Attachment #8420510 - Flags: review?(dminor)
Reporter

Comment 10

5 years ago
(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
Assignee

Comment 11

5 years ago
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.
Reporter

Comment 12

5 years ago
(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.
Assignee

Comment 13

5 years ago
Posted patch 1003412.patch (obsolete) — Splinter Review
Attachment #8420510 - Attachment is obsolete: true
Attachment #8420510 - Flags: review?(dminor)
Attachment #8421104 - Flags: review?(dminor)
Reporter

Comment 14

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

Comment 15

5 years ago
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
Reporter

Comment 16

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

Comment 17

5 years ago
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
Assignee

Comment 18

5 years ago
Posted patch 1003412.patch (obsolete) — Splinter Review
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.
Attachment #8421104 - Attachment is obsolete: true
Attachment #8421104 - Flags: review?(dminor)
Attachment #8422380 - Flags: review?(dminor)
Reporter

Comment 19

5 years ago
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.
Reporter

Updated

5 years ago
Attachment #8422380 - Flags: review?(dminor)
Assignee

Comment 20

5 years ago
Thank you for the solution - I hope this will work !
Attachment #8422380 - Attachment is obsolete: true
Attachment #8423664 - Flags: review?(dminor)
Reporter

Comment 21

5 years ago
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.
Assignee

Comment 22

5 years ago
Thanks for all the workflow process infos :)
Attachment #8423664 - Attachment is obsolete: true
Attachment #8423664 - Flags: review?(dminor)
Attachment #8423829 - Flags: review?(dminor)
Reporter

Comment 23

5 years ago
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!
Attachment #8423829 - Flags: review?(dminor) → review+
Reporter

Updated

5 years ago
Keywords: checkin-needed
https://hg.mozilla.org/integration/fx-team/rev/5bdeb198f7ce
Keywords: checkin-needed
Whiteboard: [good first bug][mentor=dminor][lang=python] → [good first bug][mentor=dminor][lang=python][fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/5bdeb198f7ce
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [good first bug][mentor=dminor][lang=python][fixed-in-fx-team] → [good first bug][mentor=dminor][lang=python]
Target Milestone: --- → mozilla32
You need to log in before you can comment on or make changes to this bug.