Skip to content

Commit 0348c71

Browse files
fix: avoid a potential feedback loop in output redirection (#367)
#### Description of changes The current stderr redirect can lead to a feedback loop (i.e. log to stderr, we redirect and log to both file and stderr). This change breaks the loop, but keeps behavior unchanged otherwise. The loop occurs when introducing a custom mlflow run. Not 100% sure on the underlying cause though. E.g. logging to `logging.StreamHandler(sys.stderr)` also causes repeated outputs, but only if mlflow is also active (???). At the same time, `print` to `sys.stderr` seems to always be fine... #### Testing done Local testing --------- Co-authored-by: Alessandro Angioi <alessandro.angioi@simulation.science>
1 parent 80974ef commit 0348c71

2 files changed

Lines changed: 94 additions & 2 deletions

File tree

tesseract_core/runtime/mpa.py

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -251,9 +251,13 @@ def redirect_stdio(logfile: Union[str, Path]) -> Generator[None, None, None]:
251251
with ExitStack() as stack:
252252
f = stack.enter_context(open(logfile, "w"))
253253

254-
orig_stderr = sys.stderr
254+
# Duplicate the original stderr file descriptor before any redirection
255+
orig_stderr_fd = os.dup(sys.stderr.fileno())
256+
orig_stderr_file = os.fdopen(orig_stderr_fd, "w")
257+
stack.callback(orig_stderr_file.close)
258+
255259
# Use `print` instead of `.write` so we get appropriate newlines and flush behavior
256-
write_to_stderr = lambda msg: print(msg, file=orig_stderr, flush=True)
260+
write_to_stderr = lambda msg: print(msg, file=orig_stderr_file, flush=True)
257261
write_to_file = lambda msg: print(msg, file=f, flush=True)
258262
pipe_fd = stack.enter_context(LogPipe(write_to_stderr, write_to_file))
259263

tests/endtoend_tests/test_endtoend.py

Lines changed: 88 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -883,6 +883,94 @@ def test_logging_tesseract_serve(
883883
assert "Hello from apply!" == log_content.strip()
884884

885885

886+
@pytest.fixture(scope="module")
887+
def logging_with_mlflow_test_image(
888+
tmpdir_factory, dummy_tesseract_location, docker_cleanup_module
889+
):
890+
tesseract_api = dedent(
891+
"""
892+
from pydantic import BaseModel
893+
import mlflow
894+
import sys
895+
896+
class InputSchema(BaseModel):
897+
pass
898+
899+
class OutputSchema(BaseModel):
900+
pass
901+
902+
def apply(inputs: InputSchema) -> OutputSchema:
903+
sys.__stderr__.write("DUMMY_STDERR_OUTPUT\\n")
904+
mlflow.start_run()
905+
return OutputSchema()
906+
"""
907+
)
908+
909+
workdir = tmpdir_factory.mktemp("logging_with_mlflow_test_image")
910+
911+
# Write the API file
912+
with open(workdir / "tesseract_api.py", "w") as f:
913+
f.write(tesseract_api)
914+
# Add mlflow dependency
915+
with open(workdir / "tesseract_requirements.txt", "w") as f:
916+
f.write("mlflow\n")
917+
918+
shutil.copy(
919+
dummy_tesseract_location / "tesseract_config.yaml",
920+
workdir / "tesseract_config.yaml",
921+
)
922+
923+
cli_runner = CliRunner(mix_stderr=False)
924+
925+
# Build the Tesseract
926+
result = cli_runner.invoke(
927+
app,
928+
[
929+
"--loglevel",
930+
"debug",
931+
"build",
932+
str(workdir),
933+
"--tag",
934+
"logging_with_mlflow_test_image",
935+
],
936+
catch_exceptions=False,
937+
)
938+
assert result.exit_code == 0, result.stderr
939+
940+
img_tag = json.loads(result.stdout)[0]
941+
docker_cleanup_module["images"].append(img_tag)
942+
return img_tag
943+
944+
945+
def test_logging_with_mlflow(logging_with_mlflow_test_image, tmpdir):
946+
# This test covers a bug where mlflow would mess with stderr capturing
947+
# We ensure that stderr output from the Tesseract is captured exactly once
948+
# in stderr output and log file, even when mlflow is used.
949+
run_res = subprocess.run(
950+
[
951+
"tesseract",
952+
"run",
953+
logging_with_mlflow_test_image,
954+
"apply",
955+
'{"inputs": {}}',
956+
"--output-path",
957+
tmpdir,
958+
],
959+
capture_output=True,
960+
text=True,
961+
)
962+
assert run_res.returncode == 0, run_res.stderr
963+
assert run_res.stderr.count("DUMMY_STDERR_OUTPUT") == 1, run_res.stderr
964+
965+
log_file = Path(tmpdir) / "logs" / "tesseract.log"
966+
assert log_file.exists()
967+
968+
with open(log_file) as f:
969+
log_content = f.read()
970+
971+
assert log_content.count("DUMMY_STDERR_OUTPUT") == 1, log_content
972+
973+
886974
@pytest.fixture(scope="module")
887975
def mpa_test_image(dummy_tesseract_location, tmpdir_factory, docker_cleanup_module):
888976
tesseract_api = dedent(

0 commit comments

Comments
 (0)