Capture Fortran-C level outputs to stdout (#65)

The fortran model produces copious outputs that make it challenging to
debug. This code refactors some functionality from fv3net for capturing
the stdout stream from the fortran model, and remitting it as a debug
level python logging statements.


Here is a sample of the output for `level=logging.DEBUG`:
```
INFO:fv3gfs(0):NOTE from PE     0: Potential error in diag_manager_end: snowwat NOT available, check if output interval > runlength. Netcdf fill_values are written
INFO:fv3gfs(0):NOTE from PE     0: Potential error in diag_manager_end: graupel NOT available, check if output interval > runlength. Netcdf fill_values are written
DEBUG:fv3gfs(0): MPP_DOMAINS_STACK high water mark=       37800
DEBUG:fv3gfs(0):Tabulating mpp_clock statistics across      6 PEs...
DEBUG:fv3gfs(0):                                          tmin          tmax          tavg          tstd  tfrac grain pemin pemax
DEBUG:fv3gfs(0):Total runtime                        11.250342     11.250344     11.250343      0.000000  1.000     0     0     5
DEBUG:fv3gfs(0):Initialization                        1.142568      1.142690      1.142652      0.000042  0.102     0     0     5
DEBUG:fv3gfs(0):FV dy-core                            0.433355      3.979878      1.885681      1.464813  0.168    11     0     5
DEBUG:fv3gfs(0):FV subgrid_z                          0.000504      0.000735      0.000657      0.000086  0.000    11     0     5
DEBUG:fv3gfs(0):FV Diag                               0.011109      0.016041      0.014311      0.002226  0.001    11     0     5
DEBUG:fv3gfs(0):GFS Step Setup                        5.819388      9.333302      7.864650      1.474163  0.699     1     0     5
DEBUG:fv3gfs(0):GFS Radiation                         0.135066      0.339031      0.213256      0.070167  0.019     1     0     5
DEBUG:fv3gfs(0):GFS Physics                           0.035783      0.059737      0.050340      0.010068  0.004     1     0     5
DEBUG:fv3gfs(0):Dynamics get state                    0.002524      0.004121      0.003575      0.000596  0.000     1     0     5
DEBUG:fv3gfs(0):Dynamics update state                 0.023314      3.501858      1.422214      1.453081  0.126     1     0     5
DEBUG:fv3gfs(0):FV3 Dycore                            0.453250      3.993675      1.903505      1.463173  0.169     1     0     5
DEBUG:fv3gfs(0):Main loop                            10.056789     10.056795     10.056791      0.000002  0.894     0     0     5
DEBUG:fv3gfs(0):Termination                           0.046836      0.046848      0.046843      0.000004  0.004     0     0     5
DEBUG:fv3gfs(0): MPP_STACK high water mark=           0
WARNING:fv3gfs(0):WARNING from PE     0: MPP_OPEN: File RESTART/coupler.res opened WRONLY already exists!
```
NOTE, WARNING, and FATAL are logged as INFO, WARNING, and CRITICAL python logging levels. Note that, because errors from fortran are not currently caught by python, this feature will not display any outputs in a subroutine calls the `exit` or `stop` OS routines.

Partial fix to ai2cm/fv3net#246 #32

fv3util/__init__.py

@@ -39,6 +39,7 @@
 from .units import ensure_equal_units, units_are_equal, UnitsError
 from .communicator import TileCommunicator, CubedSphereCommunicator, Communicator
 from ._xarray import to_dataset
+from ._capture_stream import capture_stream
 from . import testing
 
 __version__ = "0.4.1"

fv3util/_capture_stream.py

@@ -0,0 +1,25 @@
+import contextlib
+import tempfile
+import os
+import io
+
+
+@contextlib.contextmanager
+def capture_stream(stream):
+
+    out_stream = io.BytesIO()
+
+    # parent process:
+    # close the reading end, we won't need this
+    orig_file_handle = os.dup(stream.fileno())
+
+    with tempfile.NamedTemporaryFile() as out:
+        # overwrite the streams fileno with a the pipe to be read by the forked
+        # process below
+        os.dup2(out.fileno(), stream.fileno())
+        yield out_stream
+        # restore the original file handle
+        os.dup2(orig_file_handle, stream.fileno())
+        # print logging info
+        out.seek(0)
+        out_stream.write(out.read())

tests/test__capture_stream.py

@@ -0,0 +1,36 @@
+import sys
+import pytest
+import os
+import ctypes
+
+from fv3util import capture_stream
+
+
+def get_libc():
+    if os.uname().sysname == "Linux":
+        return ctypes.cdll.LoadLibrary("libc.so.6")
+    else:
+        pytest.skip()
+
+
+def printc(fd, text):
+    libc = get_libc()
+    b = bytes(text + "\n", "UTF-8")
+    libc.write(fd, b, len(b))
+
+
+def printpy(_, text):
+    print(text)
+
+
+@pytest.mark.parametrize("print_", [printc, printpy])
+def test_capture_stream_python_print(capfdbinary, print_):
+    text = "hello world"
+
+    # This test interacts in a confusing with pytests output capturing
+    # sys.stdout.fileno() is usually 1, but not here.
+    fd = sys.stdout.fileno()
+    with capture_stream(sys.stdout) as out:
+        print_(fd, text)
+
+    assert out.getvalue().decode("UTF-8") == text + "\n"