Log output rewriting causes issues when running conda-build in a python subprocess

[JeanChristopheMorinPerso]

Checklist

• I added a descriptive title
• I searched open reports and couldn't find a duplicate

What happened?

conda-build has a rather annoying (at least to me) feature where it rewrites all logs coming from builds to replace any known paths with their matching environment variable.

For example, during a cmake build, we can see things like

-- The C compiler identification is Clang 14.0.6
-- The CXX compiler identification is Clang 14.0.6
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
-- Check for working C compiler: $BUILD_PREFIX/bin/arm64-apple-darwin20.0.0-clang - skipped
-- Detecting C compile features
-- Detecting C compile features - done
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: $BUILD_PREFIX/bin/arm64-apple-darwin20.0.0-clang++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Configuring ensmallen 2.19.1
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Success
-- Found Threads: TRUE  
-- Found Armadillo: $PREFIX/lib/libarmadillo.dylib (found suitable version "12.6.6", minimum required is "9.800.0") 
-- Armadillo libraries: $PREFIX/lib/libarmadillo.dylib
-- Configuring done (2.2s)
-- Generating done (0.0s)

In this example, we can see that conda-build replaced some paths with $PREFIX and $BUILD_PREFIX.

This process happens in

conda-build/conda_build/utils.py

Lines 214 to 441 in aefdab6

	def _setup_rewrite_pipe(env):
	"""Rewrite values of env variables back to $ENV in stdout
	Takes output on the pipe and finds any env value
	and rewrites it as the env key
	Useful for replacing "~/conda/conda-bld/pkg_<date>/_h_place..." with "$PREFIX"
	Returns an FD to be passed to Popen(stdout=...)
	"""
	# replacements is the env dict reversed,
	# ordered by the length of the value so that longer replacements
	# always occur first in case of common prefixes
	replacements = OrderedDict()
	for k, v in sorted(env.items(), key=lambda kv: len(kv[1]), reverse=True):
	replacements[v] = k
	r_fd, w_fd = os.pipe()
	r = os.fdopen(r_fd, "rt")
	if sys.platform == "win32":
	replacement_t = "%{}%"
	else:
	replacement_t = "${}"
	def rewriter():
	while True:
	try:
	line = r.readline()
	if not line:
	# reading done
	r.close()
	os.close(w_fd)
	return
	for s, key in replacements.items():
	line = line.replace(s, replacement_t.format(key))
	sys.stdout.write(line)
	except UnicodeDecodeError:
	try:
	txt = os.read(r, 10000)
	sys.stdout.write(txt or "")
	except TypeError:
	pass
	t = Thread(target=rewriter)
	t.daemon = True
	t.start()
	return w_fd
	class PopenWrapper:
	# Small wrapper around subprocess.Popen to allow memory usage monitoring
	# copied from ProtoCI, https://github.com/ContinuumIO/ProtoCI/blob/59159bc2c9f991fbfa5e398b6bb066d7417583ec/protoci/build2.py#L20 # NOQA
	def __init__(self, *args, **kwargs):
	self.elapsed = None
	self.rss = 0
	self.vms = 0
	self.returncode = None
	self.disk = 0
	self.processes = 1
	self.out, self.err = self._execute(*args, **kwargs)
	def _execute(self, *args, **kwargs):
	try:
	import psutil
	psutil_exceptions = (
	psutil.NoSuchProcess,
	psutil.AccessDenied,
	psutil.NoSuchProcess,
	)
	except ImportError as e:
	psutil = None
	psutil_exceptions = (OSError, ValueError)
	log = get_logger(__name__)
	log.warn(f"psutil import failed. Error was {e}")
	log.warn(
	"only disk usage and time statistics will be available. Install psutil to "
	"get CPU time and memory usage statistics."
	)
	# The polling interval (in seconds)
	time_int = kwargs.pop("time_int", 2)
	disk_usage_dir = kwargs.get("cwd", sys.prefix)
	# Create a process of this (the parent) process
	parent = psutil.Process(os.getpid()) if psutil else DummyPsutilProcess()
	cpu_usage = defaultdict(dict)
	# Using the convenience Popen class provided by psutil
	start_time = time.time()
	_popen = (
	psutil.Popen(*args, **kwargs)
	if psutil
	else subprocess.Popen(*args, **kwargs)
	)
	try:
	while self.returncode is None:
	# We need to get all of the children of our process since our
	# process spawns other processes. Collect all of the child
	# processes
	rss = 0
	vms = 0
	processes = 0
	# We use the parent process to get mem usage of all spawned processes
	for child in parent.children(recursive=True):
	child_cpu_usage = cpu_usage.get(child.pid, {})
	try:
	mem = child.memory_info()
	rss += mem.rss
	vms += mem.rss
	# listing child times are only available on linux, so we don't use them.
	# we are instead looping over children and getting each individually.
	# https://psutil.readthedocs.io/en/latest/#psutil.Process.cpu_times
	cpu_stats = child.cpu_times()
	child_cpu_usage["sys"] = cpu_stats.system
	child_cpu_usage["user"] = cpu_stats.user
	cpu_usage[child.pid] = child_cpu_usage
	except psutil_exceptions:
	# process already died. Just ignore it.
	continue
	processes += 1
	# Sum the memory usage of all the children together (2D columnwise sum)
	self.rss = max(rss, self.rss)
	self.vms = max(vms, self.vms)
	self.cpu_sys = sum(child["sys"] for child in cpu_usage.values())
	self.cpu_user = sum(child["user"] for child in cpu_usage.values())
	self.processes = max(processes, self.processes)
	# Get disk usage
	self.disk = max(directory_size(disk_usage_dir), self.disk)
	time.sleep(time_int)
	self.elapsed = time.time() - start_time
	self.returncode = _popen.poll()
	except KeyboardInterrupt:
	_popen.kill()
	raise
	self.disk = max(directory_size(disk_usage_dir), self.disk)
	self.elapsed = time.time() - start_time
	return _popen.stdout, _popen.stderr
	def __repr__(self):
	return str(
	{
	"elapsed": self.elapsed,
	"rss": self.rss,
	"vms": self.vms,
	"disk": self.disk,
	"processes": self.processes,
	"cpu_user": self.cpu_user,
	"cpu_sys": self.cpu_sys,
	"returncode": self.returncode,
	}
	)
	def _func_defaulting_env_to_os_environ(func, *popenargs, **kwargs):
	if "env" not in kwargs:
	kwargs = kwargs.copy()
	env_copy = os.environ.copy()
	kwargs.update({"env": env_copy})
	kwargs["env"] = {str(key): str(value) for key, value in kwargs["env"].items()}
	_args = []
	if "stdin" not in kwargs:
	kwargs["stdin"] = subprocess.PIPE
	for arg in popenargs:
	# arguments to subprocess need to be bytestrings
	if sys.version_info.major < 3 and hasattr(arg, "encode"):
	arg = arg.encode(codec)
	elif sys.version_info.major >= 3 and hasattr(arg, "decode"):
	arg = arg.decode(codec)
	_args.append(str(arg))
	stats = kwargs.get("stats")
	if "stats" in kwargs:
	del kwargs["stats"]
	rewrite_stdout_env = kwargs.pop("rewrite_stdout_env", None)
	if rewrite_stdout_env:
	kwargs["stdout"] = _setup_rewrite_pipe(rewrite_stdout_env)
	out = None
	if stats is not None:
	proc = PopenWrapper(_args, **kwargs)
	if func == "output":
	out = proc.out.read()
	if proc.returncode != 0:
	raise subprocess.CalledProcessError(proc.returncode, _args)
	stats.update(
	{
	"elapsed": proc.elapsed,
	"disk": proc.disk,
	"processes": proc.processes,
	"cpu_user": proc.cpu_user,
	"cpu_sys": proc.cpu_sys,
	"rss": proc.rss,
	"vms": proc.vms,
	}
	)
	else:
	if func == "call":
	subprocess.check_call(_args, **kwargs)
	else:
	if "stdout" in kwargs:
	del kwargs["stdout"]
	out = subprocess.check_output(_args, **kwargs)
	return out
	def check_call_env(popenargs, **kwargs):
	return _func_defaulting_env_to_os_environ("call", *popenargs, **kwargs)
	def check_output_env(popenargs, **kwargs):
	return _func_defaulting_env_to_os_environ(
	"output", stdout=subprocess.PIPE, *popenargs, **kwargs
	).rstrip()

The main issue is that _setup_rewrite_pipe creates a thread (

conda-build/conda_build/utils.py

Line 257 in aefdab6

t = Thread(target=rewriter)

) and only stdout is being processed by that thread, as shown in

conda-build/conda_build/utils.py

Line 402 in aefdab6

kwargs["stdout"] = _setup_rewrite_pipe(rewrite_stdout_env)

This creates an issue where stdout and stderr are not synchronized anymore (if that's the right term).

When running conda-build from a python subprocess, the output from the build itself gets scrambled. Log lines are not outputted in the right order. This is pretty frustrating and it makes it super hard to debug anything. We are hitting that problem on a daily basis (read in all our builds) in our Anaconda build system.

Conda Info

active environment : base
    active env location : /Users/jcmorin/miniconda
            shell level : 1
       user config file : /Users/jcmorin/.condarc
 populated config files : /Users/jcmorin/.condarc
          conda version : 23.10.0
    conda-build version : 3.27.0
         python version : 3.11.5.final.0
       virtual packages : __archspec=1=m2
                          __osx=13.6=0
                          __unix=0=0
       base environment : /Users/jcmorin/miniconda  (writable)
      conda av data dir : /Users/jcmorin/miniconda/etc/conda
  conda av metadata url : None
           channel URLs : https://repo.anaconda.com/pkgs/main/osx-arm64
                          https://repo.anaconda.com/pkgs/main/noarch
                          https://repo.anaconda.com/pkgs/r/osx-arm64
                          https://repo.anaconda.com/pkgs/r/noarch
          package cache : /Users/jcmorin/miniconda/pkgs
                          /Users/jcmorin/.conda/pkgs
       envs directories : /Users/jcmorin/miniconda/envs
                          /Users/jcmorin/.conda/envs
               platform : osx-arm64
             user-agent : conda/23.10.0 requests/2.31.0 CPython/3.11.5 Darwin/22.6.0 OSX/13.6 solver/libmamba conda-libmamba-solver/23.11.0 libmambapy/1.5.3
                UID:GID : 502:20
             netrc file : None
           offline mode : False

Conda Config

==> /Users/jcmorin/.condarc <==
report_errors: False
solver: libmamba
conda-build: {}

Conda list

# packages in environment at /Users/jcmorin/miniconda:
#
# Name                    Version                   Build  Channel
archspec                  0.2.1              pyhd3eb1b0_0    defaults
backports                 1.1                pyhd3eb1b0_0    defaults
backports.functools_lru_cache 1.6.4              pyhd3eb1b0_0    defaults
backports.tempfile        1.0                pyhd3eb1b0_1    defaults
backports.weakref         1.0.post1                  py_1    defaults
beautifulsoup4            4.12.2          py311hca03da5_0    defaults
boltons                   23.0.0          py311hca03da5_0    defaults
brotli-python             1.0.9           py311h313beb8_7    defaults
brotlipy                  0.7.0           py311h80987f9_1002    defaults
bzip2                     1.0.8                h620ffc9_4    defaults
c-ares                    1.19.1               h80987f9_0    defaults
ca-certificates           2023.08.22           hca03da5_0    defaults
cctools                   949.0.1             hc179dcd_25    defaults
cctools_osx-arm64         949.0.1             h332cad3_25    defaults
certifi                   2023.7.22       py311hca03da5_0    defaults
cffi                      1.15.1          py311h80987f9_3    defaults
chardet                   4.0.0           py311hca03da5_1003    defaults
charset-normalizer        2.0.4              pyhd3eb1b0_0    defaults
click                     8.1.7           py311hca03da5_0    defaults
conda                     23.10.0         py311hca03da5_0    defaults
conda-build               3.27.0          py311hca03da5_0    defaults
conda-content-trust       0.2.0           py311hca03da5_0    defaults
conda-index               0.3.0           py311hca03da5_0    defaults
conda-libmamba-solver     23.11.0         py311hca03da5_0    defaults
conda-package-handling    2.2.0           py311hca03da5_0    defaults
conda-package-streaming   0.9.0           py311hca03da5_0    defaults
conda-verify              3.4.2                      py_1    defaults
cryptography              41.0.3          py311hd4332d6_0    defaults
darts                     0.25.0                   pypi_0    pypi
filelock                  3.9.0           py311hca03da5_0    defaults
fmt                       9.1.0                h48ca7d4_0    defaults
future                    0.18.3          py311hca03da5_0    defaults
glob2                     0.7                pyhd3eb1b0_0    defaults
icu                       73.1                 h313beb8_0    defaults
idna                      3.4             py311hca03da5_0    defaults
jinja2                    3.1.2           py311hca03da5_0    defaults
jsonpatch                 1.32               pyhd3eb1b0_0    defaults
jsonpointer               2.1                pyhd3eb1b0_0    defaults
krb5                      1.20.1               hf3e1bf2_1    defaults
ld64                      530                 hb29bf3f_25    defaults
ld64_osx-arm64            530                 h001ce53_25    defaults
ldid                      2.1.5                h20b2a84_3    defaults
libarchive                3.6.2                h62fee54_2    defaults
libcurl                   8.4.0                h3e2b118_0    defaults
libcxx                    14.0.6               h848a8c0_0    defaults
libedit                   3.1.20221030         h80987f9_0    defaults
libev                     4.33                 h1a28f6b_1    defaults
libffi                    3.4.4                hca03da5_0    defaults
libiconv                  1.16                 h1a28f6b_2    defaults
liblief                   0.12.3               h313beb8_0    defaults
libllvm14                 14.0.6               h7ec7a93_3    defaults
libmamba                  1.5.3                h15e39b3_0    defaults
libmambapy                1.5.3           py311h1c5506f_0    defaults
libnghttp2                1.57.0               h62f6fdd_0    defaults
libsolv                   0.7.24               h514c7bf_0    defaults
libssh2                   1.10.0               h02f6b3c_2    defaults
libxml2                   2.10.4               h0dcf63f_1    defaults
lz4-c                     1.9.4                h313beb8_0    defaults
markupsafe                2.1.1           py311h80987f9_0    defaults
more-itertools            8.12.0             pyhd3eb1b0_0    defaults
ncurses                   6.4                  h313beb8_0    defaults
openssl                   3.0.12               h1a28f6b_0    defaults
packaging                 23.1            py311hca03da5_0    defaults
patch                     2.7.6             h1a28f6b_1001    defaults
pcre2                     10.42                hb066dcc_0    defaults
pip                       23.3            py311hca03da5_0    defaults
pkginfo                   1.9.6           py311hca03da5_0    defaults
pluggy                    1.0.0           py311hca03da5_1    defaults
psutil                    5.9.0           py311h80987f9_0    defaults
py-lief                   0.12.3          py311h313beb8_0    defaults
pybind11-abi              4                    hd3eb1b0_1    defaults
pycosat                   0.6.6           py311h80987f9_0    defaults
pycparser                 2.21               pyhd3eb1b0_0    defaults
pyopenssl                 23.2.0          py311hca03da5_0    defaults
pysocks                   1.7.1           py311hca03da5_0    defaults
python                    3.11.5               hb885b13_0    defaults
python-libarchive-c       2.9                pyhd3eb1b0_1    defaults
python.app                3               py311h80987f9_0    defaults
pytz                      2023.3.post1    py311hca03da5_0    defaults
pyyaml                    6.0.1           py311h80987f9_0    defaults
readline                  8.2                  h1a28f6b_0    defaults
reproc                    14.2.4               hc377ac9_1    defaults
reproc-cpp                14.2.4               hc377ac9_1    defaults
requests                  2.31.0          py311hca03da5_0    defaults
ruamel.yaml               0.17.21         py311h80987f9_0    defaults
ruamel.yaml.clib          0.2.7           py311h80987f9_0    defaults
setuptools                68.0.0          py311hca03da5_0    defaults
six                       1.16.0             pyhd3eb1b0_1    defaults
soupsieve                 2.5             py311hca03da5_0    defaults
sqlite                    3.41.2               h80987f9_0    defaults
tapi                      1100.0.11            h8754e6a_1    defaults
tk                        8.6.12               hb8d0fd4_0    defaults
tomli                     2.0.1           py311hca03da5_0    defaults
toolz                     0.12.0          py311hca03da5_0    defaults
tqdm                      4.65.0          py311hb6e6a13_0    defaults
truststore                0.8.0           py311hca03da5_0    defaults
tzdata                    2023c                h04d1e81_0    defaults
urllib3                   1.26.18         py311hca03da5_0    defaults
wheel                     0.41.2          py311hca03da5_0    defaults
xz                        5.4.2                h80987f9_0    defaults
yaml                      0.2.5                h1a28f6b_0    defaults
yaml-cpp                  0.8.0                h313beb8_0    defaults
zlib                      1.2.13               h5a0b063_0    defaults
zstandard                 0.19.0          py311h80987f9_0    defaults
zstd                      1.5.5                hd90d995_0    defaults

Additional Context

No response

[travishathaway]

One way to solve this problem could be by implementing a proper queue: https://docs.python.org/3/library/queue.html

[github-actions]

Hi there, thank you for your contribution!

This issue has been automatically marked as stale because it has not had recent activity. It will be closed automatically if no further activity occurs.

If you would like this issue to remain open please:

1. Verify that you can still reproduce the issue at hand
2. Comment that the issue is still reproducible and include:
   - What OS and version you reproduced the issue on
   - What steps you followed to reproduce the issue

NOTE: If this issue was closed prematurely, please leave a comment.

Thanks!