Work on moving stdout / stderr redirection from desispec to desiutil

[tskisner]

The unit tests are not yet working, since redirecting stdout actually breaks the unit test runner (which has a persistent handle to sys.stdout). I am working on a unit test that runs the redirection in a subprocess.

[tskisner]

The MPI test script cannot be spawned from within the unit test runner, so I simply print out the command to run.

[araichoor]

I've run two checks (no MPI).
One on a small piece of code which produces an error, and one on a typical call of fba_cmx, with an (intentional) error.
Both work fine, the error message is printed in the log file (and also on the prompt).

[tskisner]

There is one transient test failure unrelated to this PR, but the rest seems to be working. After this work is merged we can use this in fiberassign and switch desispec over to this version of the redirection.

[weaverba137]

This is a very complex module, and I will probably need to take more time than this to fully digest it. So this first review is just to catch the obvious things. I'll do a second review after the first round is addressed.

[tskisner]

I'll go wrap the libc handle fetching in a function. Just for the record, although this is "complicated" code, it is a minor reworking of code that has been used in desispec for a long time:

https://github.com/desihub/desispec/blob/master/py/desispec/parallel.py#L292

This version of the code has been improved to be more resilient against the wrapped code raising an exception. And this version of the code now has explicit unit tests, unlike the desispec version.

[weaverba137]

OK, but again, we are not using setup.py for tests now. pytest is used instead. I am pretty sure that the travis tests already reflect this. Where are the remaining tests being run that still use python setup.py test?

[weaverba137]

@sbailey, I'd like your review here. We're getting bogged down in changes to Travis tests that I feel are not necessary, but we have not come to a consensus. I also don't know how urgent this is, and because of the test issue, I have not had time to review the module really thoroughly for other problems. Could you please chime in?

[tskisner]

@weaverba137 , do you understand at least why I need to install the package first? I really am not trying to make more work for myself just for fun. The python unittest module keeps a persistent handle to stdout. It is not possible to redirect stdout from inside a unittest. Thus the need to run an external script.

Just to reiterate- a messier version of this code (with no unit tests at all) is already in use in desispec. This PR was an effort to put the code in a common place and clean it up and make some tests.

[weaverba137]

@tskisner, honestly, no, I do not understand that, in part because I haven't had time to dig into the details of the module itself. Without delving into that, I don't know whether there is a more clever way to manipulate unittest to do what we need.

[sbailey]

Wearing my manager hat, summarizing my understanding of this PR:

• @tskisner is adding code that has been in use in desispec without problems for a couple of years.
• Moving it to desiutil allows it to be used by other desi products without introducing dependency loops or new desi package cross dependencies (good!)
• At the same time, he is adding unit tests (good!); it was not previously unit-tested in desispec.
• The unittest module keeps a persistent handle to stdout, which conflicts with the new functionality of redirecting stdout, so the new tests spawn a script to work around this while still testing the new functionality. However, that test script needs desiutil to be installed so that it can import desiutil.redirect.
  • For reasons I don't completely understand, "python setup.py test" does a more complete test installation environment than "pytest" does, such that if desiutil is not installed prior to testing, the tests in this branch work with "python setup.py test" but not "pytest".
  • however, testing via setup.py / setuptools is deprecated by the Python gods (not by us), thus the motivation to move to pytest or other.
• I don't think it was explicitly stated here, but my memory of previous conversations is that the motivation for being able to test a package without installing it is so that you can catch any errors specific to your local system prior to installing potentially broken code. So the objection to the new "install before testing" requirement isn't just "but we haven't needed that before so why do we need it now", but rather that there are specific motivations for being able to test first.
• At the same time, purity of testing is getting in the way of actually having useful code put in place where it can be used, and including automated tests on it.
• And having Travis install before testing checks the installation process itself, which in other packages has occasionally been problematic, so that can be viewed as a feature not a bug, even if it is a step backwards on testing a different case.

Executive decision:

• Keep the install before testing change in this PR for Travis so that this new code can be included in the automated testing
• Add an import check to the test so that it doesn't break the ability to test the rest of desiutil prior to installation (I just added that, tested at NERSC on a git clone of this branch without desiutil installed).
  • Note that if you are using "pytest" to test prior to installing on some system, it skips testing this new code, but that is no worse than the previous state which didn't test it at all anywhere, and at least for awhile longer "python setup.py test" does the full suite of tests including desiutil.redirect even if desiutil isn't installed.
  • Caveat: if you have a working installed copy of desiutil, and then have a new branch that has broken desiutil.redirect but that somehow got through Travis, and you are trying to test that prior to replacing your current installation, I'm not entirely sure what would happen. However, that seems like such a theoretical corner case that I don't think it warrants blocking the other benefits of getting this code in here with automated travis testing.

[weaverba137]

@sbailey, thank you. I also remember now that we had issues in the past along the lines of "is this testing the bare git clone, or code that is installed somewhere else".

I will take one more look at the module itself this afternoon, and I will approve and merge after that.

I added desiutil.redirect to the API documentation and updated the change log.

[weaverba137]

Is the function get_libc() intended to be part of the public API, or is it used only internally by the redirect module? If the latter, I'd recommend calling it _get_libc().

[weaverba137]

                _c_stdout = ctypes.c_void_p.in_dll(_libc, '__stdoutp')
                _c_stderr = ctypes.c_void_p.in_dll(_libc, '__stdoutp')

Is this really the correct calling sequence for MacOS/Darwin? Stdout and stderr have exactly the same names?

[weaverba137]

        if sys.version_info[0] < 3:
            sys.stdout = os.fdopen(fd_out, "wb")
            sys.stderr = os.fdopen(fd_err, "wb")
        else:
            # Python 3 case
            sys.stdout = io.TextIOWrapper(os.fdopen(fd_out, 'wb'))
            sys.stderr = io.TextIOWrapper(os.fdopen(fd_err, 'wb'))

I'm pretty sure we don't need to support Python 2 in this module.

[weaverba137]

    def _open_redirect(filename):
        # Open python file, which creates low-level POSIX file
        # descriptor.
        file_handle = open(filename, "w")
        # ...

In most other places, files are opened "wb" (binary write). Is this file handle deliberately meant to be opened "w" (text write)?

[weaverba137]

log.info("Begin log redirection to %s at %s", to, time.asctime())

Since you're using desiutil.log, a timestamp is already provided by the log. Is it important to log two separate timestamps?

[weaverba137]

Why are there so many calls to log = get_logger()? You only need one.

[weaverba137]

Now that I've finally looked over the module in detail, there are several more points to address before this can be merged. Hopefully these can be done quickly.

[tskisner]

I made these changes:

• fix typo stdoutp --> stderrp on Darwin (I can't test this, but it sure looks like a typo)
• remove timestamps in log messages
• remove python2 check
• open files in wb mode

I am intentionally getting a new log handle each time I need it, since I recall problems with this in past. Likely something to do with the redirect modifying the logger.

[weaverba137]

I verified that ctypes.c_void_p.in_dll(_libc, "__stderrp") does give a valid result on MacOS/Darwin. Merge when ready.

[tskisner]

Thanks @sbailey . Looks like travis may never run, so merge if you are happy with it.

[sbailey]

Two updates:

• fixed _get_libc vs. get_libc typo (missing _ when using it)
• logger only prints a timestamp if specifically requested via get_logger(timestamp=True), so I added that to the get_logger calls for beginning and ending the redirect which are where we most want the timing statements.

Travis is completely bogged down (tests aren't getting through on multiple repos), but I verified that they pass on my laptop (Mac) and at NERSC so I'll merge anyway without Travis so that we can proceed with a new tag. This will flag that PR as failing tests, but ok.