Fix #9481: fix invalid output during environment initialization

[yashhere]

Earlier the logger was emitting an empty JSON file for errors during
environment initialization. Now the mozlog shutdown() method is called
if the environment initialization fails to ensure that the generated report
file contains valid JSON object. The suite_end() method functionality
has been moved to the shutdown function to avoid redundancy.

---

This change is 

[w3c-bots]

Build PASSED

Started: 2018-03-09 14:49:06
Finished: 2018-03-09 15:07:09

View more information about this build on:

• WPT PR Status
• TravisCI

[jgraham]

I think the changes in formatters.py make sense, but the way that we are ensuring that the logger is shutdown doesn't really work.

[jgraham]

So, I don't think this is going to work. Sometimes we (hackily?) run multiple session with the same logger (e.g. for stability checking). I think you need to look for all the places in the code where we call setup_logging and ensure that each of those places has a corresponding call to logger.shutdown() once the logger is no longer in use.

[yashhere]

But don't you think that if a command, like mentioned in original issue, is going to fail, then the control will never return to the place, where I have called setup_logging, so even if I define the shutdown function at each place, the logger will not shut down properly and nothing will be written to the log file. The command fails at the environment variable initialization part in the wptrunner.py file, and that was the reason that the suite_end() function was never called. Also, I could not understand what you want to say when you mention about run multiple session with the same logger? If you could provide a command which gives such scenario, that would be a great help for testing.

[yashhere]

I think that you want to change the call in wptlogging.py for successful calls only. When the tests fail, the call in wptrunner.py will call the shutdown() method and write to the file correctly. But when the test cases succeed, the control will reach the end, and hence the shutdown() calls will also execute. If this is what you want me to do, then I think, I agree with you here. I'll do the necessary changes. If not, please elaborate your opinion about the problem.

[jgraham]

So when there's an exception the stack will unwind, but we'll still have the oppertunty to execute exception handlers and finally cluases in each calling function.

The way that the logger is used isn't ideal because we tend to call setup_logging and set a global, but it's quite possible to ensure that we have a try/finally block enclosing the scope over which the logger is actually used, and calling shotdown if we exit that scope even via an exception.

[yashhere]

Hi, sorry for the delay. I have updated the code to wrap all the setup_logging calls in try/finally blocks. I have kept my previous logic of calling shutdown() in wptlogging.py's CaptureIO class as without that nothing was being written to the empty.json file. Please review and give suggestions.

[jgraham]

I think the way this works in run.py is more or less right, but there are a couple of other places that will break without similar changes. In wptrunner.py itself the main function sets up a mozlog logger. In tools/ci/check_stability.py we create a logger in run. There are a few other places you can see in the search at https://github.com/w3c/web-platform-tests/search?utf8=%E2%9C%93&q=setup_logging&type=

In all these cases we need to ensure that the shutdown method is being called when the logger's no longer in use.

[jgraham]

I don't think this change is right; we certainly want to still call suite_end.

[jgraham]

This should be in a finally block.

[yashhere]

How do I test these changes? Can you tell some particular test cases, where these changes might fail? Or shall I run the complete test suite?

[jgraham]

So if you run e.g. wpt run --log-wptreport=file.json firefox infrastructure, that should work. Then there are a few other cases that are less common. You can source _venv/bin./activate to activate the wpt virtualenv and then run wptrunner directly by installing it cd tools/wptrunner && pip install -e ./ and running it somethingn like wptrunner --log-wptreport=file.json infrastructure. The stability checking script is harder to test since it depends on travis but it also doesn't depend on wptreport.json files at present, so I think we can rely on code inspection in that case.

[jgraham]

OK, I think this is good now, thanks. Let's merge it and find out if anything unexpectedly breaks.

[rakuco]

This seems to have broken Travis: see https://travis-ci.org/w3c/web-platform-tests/jobs/352369551 and https://travis-ci.org/w3c/web-platform-tests/jobs/352369562, for example.

Traceback (most recent call last):
  File "./wpt", line 5, in <module>
    wpt.main()
  File "/home/travis/build/w3c/web-platform-tests/tools/wpt/wpt.py", line 132, in main
    rv = script(*args, **kwargs)
  File "/home/travis/build/w3c/web-platform-tests/tools/ci/check_stability.py", line 383, in run
    logger.shutdown()
AttributeError: 'Logger' object has no attribute 'shutdown'

[yashhere]

How did my changes pass Travis test, in this case? @jgraham shall I push more commits to fix this, or do I need to create a new pull request?

[rakuco]

I don't think you can push more commits and reopen this PR, so could you please create a new pull request?

[yashhere]

How do I check if there are issues at other places also? Tox passes without showing any errors.

[jgraham]

Sorry, that's my fault. It looks like the logger in check_stability.py isn't a mozlog logger; it's wpt_logger that is. If you open another PR with the same changes, but calling shutdown on wpt_logger in check_stability instead, and in a separate commit make a change to a test (e.g. add some whitespace to infrastructure/Ahem.html) and we can check that this works.

[gsnedders]

@jgraham why did the automatic running of infrastructure/ not catch this?

[jgraham]

Because that doesn't run in the stability checker, just using normal wpt run.

[gsnedders]

@jgraham what would it take to have some unit tests for the stability checker?