pytest is eating the middle of stdout in tracebacks

[bcl]

At least I think it is pytest. I'm not 100% sure since I couldn't fix it.
When the tools/test/test_depsolve.py failed when running osbuild_depsolve_dnf5 it would print the contents of the subprocess variables, including stdout which includes a traceback (from osbuild_depsolve_dnf5) wrapped in json. The string is a bit long, and something is chopping out the middle and replacing it with '...'
If I manually trigger failures in the script the json wrapped traceback is fine.
If I run pytest tools manually it is missing the middle part, which ends up being the part telling you what line failed :)
I tried running pytest with --tb=long or --full-traceback and didn't get any more of the output.
So I'm currently stumped as to what's replacing that part of the string with ...

[mvo5]

Thanks for the issue.

I tried to (artificially) reproduce this with:

diff --git a/tools/osbuild-depsolve-dnf b/tools/osbuild-depsolve-dnf
index adfc4040..79d65e01 100755
--- a/tools/osbuild-depsolve-dnf
+++ b/tools/osbuild-depsolve-dnf
@@ -62,6 +62,9 @@ class Solver():
         self.base.conf.persistdir = persistdir
         self.base.conf.cachedir = cache_dir
         self.base.conf.substitutions['arch'] = arch
+        for i in range(1000):
+            print(10*f"{i}", file=sys.stderr)
+        xxx
         self.base.conf.substitutions['basearch'] = dnf.rpm.basearch(arch)
         self.base.conf.substitutions['releasever'] = releasever
         if proxy:

and get the full output of stderr via:

$ pytest './tools/test/test_depsolve.py::test_depsolve[test_case0]'
----------------------------- Captured stderr call -----------------------------
0000000000
...
999999999999999999999999999999
Traceback (most recent call last):
  File "/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf", line 488, in <module>
    main()
  File "/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf", line 480, in main
    result, err = solve(request, cachedir)
                  ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf", line 371, in solve
    solver = Solver(request, persistdir, cache_dir)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf", line 67, in __init__
    xxx
NameError: name 'xxx' is not defined
=========================== short test summary info ============================
FAILED tools/test/test_depsolve.py::test_depsolve[test_case0] - subprocess.CalledProcessError: Command '['./tools/osbuild-depsolve-dnf']' r...

But then I noticed that this already includes f892351 so I reverted that and now I can see:

tools/test/test_depsolve.py:45: in depsolve
    p = sp.run([command], input=json.dumps(req).encode(), check=True, stdout=sp.PIPE, stderr=sp.PIPE)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

input = b'{"command": "depsolve", "arch": "x86_64", "module_platform_id": "platform:el9", "releasever": "9", "cachedir": "/tmp... ["-----BEGIN PGP PUBLIC KEY BLOCK-----\\nTEST KEY\\ncustom"]}], "transactions": [{"package-specs": ["filesystem"]}]}}'
capture_output = False, timeout = None, check = True
popenargs = (['./tools/osbuild-depsolve-dnf'],)
kwargs = {'stderr': -1, 'stdin': -1, 'stdout': -1}
process = <Popen: returncode: 1 args: ['./tools/osbuild-depsolve-dnf']>
stdout = b''
stderr = b'0000000000\n1111111111\n2222222222\n3333333333\n4444444444\n5555555555\n6666666666\n7777777777\n8888888888\n99999999...osbuild/osbuild/./tools/osbuild-depsolve-dnf", line 67, in __init__\n    xxx\nNameError: name \'xxx\' is not defined\n'
retcode = 1
....

which I assume is what you also see? This is set in https://github.com/pytest-dev/pytest/blob/main/src/_pytest/_io/saferepr.py#L95 and afaict there is no way to override this for this level, it is called from https://github.com/pytest-dev/pytest/blob/8.1.x/src/_pytest/_code/code.py#L841 without an maxsize. It seems there is/as some discussion in pytest-dev/pytest#11387 but nothing concrete. Wiring this up shouldn't be too hard, something like
0001-add-verylong-traceback-style.patch.txt might work, not sure if it's worth perusing with upstream though.

Which is slightly sad.

[bcl]

That's similar, but it is in stdout, not stderr. To reproduce it edit osbuild-depsolve-dnf5 to revert the exclude-specs fix:

diff --git a/tools/osbuild-depsolve-dnf5 b/tools/osbuild-depsolve-dnf5
index 64afd199..7b577318 100755
--- a/tools/osbuild-depsolve-dnf5
+++ b/tools/osbuild-depsolve-dnf5
@@ -105,7 +105,7 @@ class Solver():
         transactions = arguments.get("transactions") or []
         for t in transactions:
             # Return an empty list when 'exclude-specs' key is missing or when it is None
-            exclude_pkgs.extend(t.get("exclude-specs") or [])
+            exclude_pkgs.extend(t.get("exclude-specs", []))
 
         if not exclude_pkgs:
             exclude_pkgs = []

and then run pytest. I don't see a proper traceback at all, other than one from subprocess.CalledProcessError

[mvo5]

That's similar, but it is in stdout, not stderr. To reproduce it edit osbuild-depsolve-dnf5 to revert the exclude-specs fix:

diff --git a/tools/osbuild-depsolve-dnf5 b/tools/osbuild-depsolve-dnf5
index 64afd199..7b577318 100755
--- a/tools/osbuild-depsolve-dnf5
+++ b/tools/osbuild-depsolve-dnf5
@@ -105,7 +105,7 @@ class Solver():
         transactions = arguments.get("transactions") or []
         for t in transactions:
             # Return an empty list when 'exclude-specs' key is missing or when it is None
-            exclude_pkgs.extend(t.get("exclude-specs") or [])
+            exclude_pkgs.extend(t.get("exclude-specs", []))
 
         if not exclude_pkgs:
             exclude_pkgs = []

and then run pytest. I don't see a proper traceback at all, other than one from subprocess.CalledProcessError

Thank @bcl ! That helped a lot, I can reproduce it now in the same way and most of what I wrote above is bogus (sorry!).

I opened pytest-dev/pytest#12241 on pytest to see if they are open for a tweak here, with that patch I get:

$ pytest -s -vvv './tools/test/test_depsolve.py::test_depsolve[./tools/osbuild-depsolve-dnf5-has_dnf5-test_case3]'
============================= test session starts ==============================
platform linux -- Python 3.12.2, pytest-7.4.3, pluggy-1.3.0 -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /home/mvogt/devel/osbuild/osbuild
collected 1 item                                                               

tools/test/test_depsolve.py::test_depsolve[./tools/osbuild-depsolve-dnf5-has_dnf5-test_case3] error traceback
TypeError: 'NoneType' object is not iterable
FAILED
...
tools/test/test_depsolve.py:51: in depsolve
    p = sp.run([command], input=json.dumps(req), check=True, stdout=sp.PIPE, stderr=sys.stderr, text=True)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

input = ('{"command": "depsolve", "arch": "x86_64", "module_platform_id": '
 '"platform:el9", "releasever": "9", "cachedir": '
 '"/tmp/pytest-of-mvogt/pytest-57/cache0", "arguments": {"root_dir": '
 '"/tmp/pytest-of-mvogt/pytest-57/test_depsolve___tools_osbuild_0/tmprvckca15", '
 '"repos": [{"id": "baseos", "name": "baseos", "baseurl": '
 '"http://localhost:47925", "check_gpg": false, "ignoressl": true, "rhsm": '
 'false, "gpgkeys": ["-----BEGIN PGP PUBLIC KEY BLOCK-----\\nTEST '
 'KEY\\nbaseos"]}, {"id": "custom", "name": "custom", "baseurl": '
 '"http://localhost:38443", "check_gpg": false, "ignoressl": true, "rhsm": '
 'false, "gpgkeys": ["-----BEGIN PGP PUBLIC KEY BLOCK-----\\nTEST '
 'KEY\\ncustom"]}], "transactions": [{"package-specs": ["tmux", '
 '"pkg-with-no-deps"], "exclude-specs": null}]}}')
capture_output = False, timeout = None, check = True
popenargs = (['./tools/osbuild-depsolve-dnf5'],)
kwargs = {'stderr': <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>,
 'stdin': -1,
 'stdout': -1,
 'text': True}
process = <Popen: returncode: 1 args: ['./tools/osbuild-depsolve-dnf5']>
stdout = ('{"kind": "TypeError", "reason": "\'NoneType\' object is not iterable", '
 '"traceback": "Traceback (most recent call last):\\n  File '
 '\\"/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf5\\", line '
 '512, in solve\\n    solver = Solver(request, persistdir, '
 'cache_dir)\\n             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\\n  File '
 '\\"/home/mvogt/devel/osbuild/osbuild/./tools/osbuild-depsolve-dnf5\\", line '
 '108, in __init__\\n    exclude_pkgs.extend(t.get(\\"exclude-specs\\", '
 '[]))\\nTypeError: \'NoneType\' object is not iterable\\n"}\n')
stderr = None, retcode = 1

which is more useful.