Make unittest's output more reasonable

[tngreene]

Because our unit test is complicated

1. Start test runner
2. Open Blender process with its own stdout and stderr
3. Blender process runs test script for us
4. unittest prints to stdout as well
5. XPlane2Blender has print statements, asserts, and exceptions
6. unittest prints those same failures (sometimes)
7. Blender reports those same failures (sometimes)
8. test runner explains what happened

It can leave a very jumbled mess and long output.

It would be very nice if it could be cleaned up and organized, including ignoring Blender's inane debugging messages. See tests.py's effort to ignore stuff like "read_libblock: unknown id code 'PY'"

[tngreene]

See also #369.

[tngreene]

So, in debugging the meshes_split_materials_copied test I would try and understand this again. Here is the reduced output, with portions summarized by > Bunch of stuff here

BEGIN TESTRUNNER
/*=== Running file ./tests\converter\materials\meshes_split_materials_copied.test.py {{{
BEGIN BLENDER subprocess
END BLENDER subprocess
BEGIN out
    > Bunch of Blender startup stuff, including warnings about our datablocks - aka file is loaded
    > Bunch of XPlane2Blender updater stuff - aka file load hooks are running
BEGIN UNITTEST
    > Bunch of Converter Log Stuff, including all the print statements for debugging the splitting algorithm
    ======================================================================
    ERROR: test_diffuse_and_specularity_copied (__main__.TestMeshesSplitMaterialsCopied)
    ----------------------------------------------------------------------
    Traceback (most recent call last):
      File "C:\Users\Ted\XPlane2Blender\./tests\converter\materials\meshes_split_materials_copied.test.py", line 101, in test_diffuse_and_specularity_copied
        print(1/0)
    ZeroDivisionError: division by zero (purposefully induced)

    ----------------------------------------------------------------------
    Ran 4 tests in 0.052s

    FAILED (errors=1)
> A bunch more of converter log stuff, including all the print statements for debugging the splitting algorithm!
...
> End of unit test "RESULT: After 4 tests got 1 errors, 0 failures, and 0 skipped"
END UNITTEST
> Blender quit
END out
An uncaught exception occurred in test './tests\converter\materials\meshes_split_materials_copied.test.py'
./tests\converter\materials\meshes_split_materials_copied.test.py FAILED
===========================================================================}}}*/
FINAL RESULTS: 4 tests cases completed, 2 errors, 0 failures, 0 skipped. Finished in 1.7769 seconds
END TESTRUNNER

Having the assertionErrror appear instead of divide by zero results in the same thing: unittest's output is appearing in the middle of the exporter's output! Very confusing!

I have no idea why this happens

[tngreene]

WARNING: NEXT-STEPS: Check the Export Type of 249_ROOT_07
RESULT: After 7 tests got 6 errors, 0 failures, and 0 skipped
Read blend: C:\Users\Ted\XPlane2Blender\./tests\converter\materials\global_attributes_applied.test.blend
2.66 versioning fix: replacing black sky with premultiplied alpha for scene BlendGlass
2.66 versioning fix: replacing black sky with premultiplied alpha for scene GlobalCockpitLit
2.66 versioning fix: replacing black sky with premultiplied alpha for scene GlobalNoBlend
2.66 versioning fix: replacing black sky with premultiplied alpha for scene GlobalShadowBlend
2.66 versioning fix: replacing black sky with premultiplied alpha for scene GlobalSpecular
2.66 versioning fix: replacing black sky with premultiplied alpha for scene GlobalTint

Blender quit
===========================================================================}}}*/
FINAL RESULTS: 43 tests cases completed, 7 errors, 0 failures, 0 skipped. Finished in 18.7183 seconds
END TESTRUNNER

Here Blender's beginning output is at the bottom. I guess it is still very irregular.

My test is a cmd.exe instance inside of Minicmd on Windows, btw.

[tngreene]

Adding sys.stdout = os.fdopen(sys.stdout.fileno(), 'w') helped this, I think. I thought it was something more interesting than a buffering issue due to the complex set up we've got here.

Closed with 3d8261f2be

[tngreene]

Reverted and re-opened. Turns out it doesn't like it when sys.stdout is repeatedly reassigned.

I also tried setting PYTHONUNBUFFERED to "x" in a variety of ways (In cmd, in test runner before opening the subprocess), but it doesn't do anything. I confirm that os.environ["PYTHONUNBUFFERED"] == "x" is in there but still there is buffering.

I couldn't find a way to pass -u into Blender's copy of Python before it starts up, and I'm not sure that would have done anything either.

Maybe there is another way of doing this... maybe there is a way to reassign sys.stdout only once (if that actually did anything and it wasn't just my eyes glazing over or getting lucky)

[tngreene]

--python-use-system-env may be relevant now. See https://blender.stackexchange.com/questions/172421/pythonpath-ignored for this person's experience with other environment variables