Bug 2183519

Summary:	%pyproject_buildrequires swamped with "ValueError: I/O operation on closed file."s with setuptools 67.5.1
Product:	[Fedora] Fedora	Reporter:	Miro Hrončok <mhroncok>
Component:	pyproject-rpm-macros	Assignee:	Miro Hrončok <mhroncok>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	cstratak, maxwell, mhroncok, pviktori, python-packagers-sig
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	pyproject-rpm-macros-1.7.0-1.fc39	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2023-04-18 09:10:15 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	2144132

Description Miro Hrončok 2023-03-31 13:19:50 UTC

Output from building https://src.fedoraproject.org/rpms/pyproject-rpm-macros/blob/rawhide/f/tests/python-pytest.spec

Executing(%generate_buildrequires): ...
...
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib64/python3.11/logging/__init__.py", line 1113, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/usr/lib/rpm/redhat/pyproject_buildrequires.py", line 550, in <module>
    main(sys.argv[1:])
  File "/usr/lib/rpm/redhat/pyproject_buildrequires.py", line 532, in main
    generate_requires(
  File "/usr/lib/rpm/redhat/pyproject_buildrequires.py", line 444, in generate_requires
    generate_run_requirements(backend, requirements, build_wheel=build_wheel, wheeldir=wheeldir)
  File "/usr/lib/rpm/redhat/pyproject_buildrequires.py", line 354, in generate_run_requirements
    generate_run_requirements_hook(backend, requirements)
  File "/usr/lib/rpm/redhat/pyproject_buildrequires.py", line 310, in generate_run_requirements_hook
    dir_basename = prepare_metadata('.')
  File "/usr/lib/python3.11/site-packages/setuptools/build_meta.py", line 377, in prepare_metadata_for_build_wheel
    self.run_setup()
  File "/usr/lib/python3.11/site-packages/setuptools/build_meta.py", line 335, in run_setup
    exec(code, locals())
  File "<string>", line 4, in <module>
  File "/usr/lib/python3.11/site-packages/setuptools/__init__.py", line 108, in setup
    return distutils.core.setup(**attrs)
  File "/usr/lib/python3.11/site-packages/setuptools/_distutils/core.py", line 185, in setup
    return run_commands(dist)
  File "/usr/lib/python3.11/site-packages/setuptools/_distutils/core.py", line 201, in run_commands
    dist.run_commands()
  File "/usr/lib/python3.11/site-packages/setuptools/_distutils/dist.py", line 969, in run_commands
    self.run_command(cmd)
  File "/usr/lib/python3.11/site-packages/setuptools/dist.py", line 1221, in run_command
    super().run_command(command)
  File "/usr/lib/python3.11/site-packages/setuptools/_distutils/dist.py", line 985, in run_command
    log.info("running %s", command)
Message: 'running %s'
Arguments: ('dist_info',)
[The traceback is repeated for all logged messages.]

pyproject-rpm-macros-1.6.3-1.fc39
python3-setuptools-67.5.1-1.fc39


This might be related to the fix of bz2166888 -- https://src.fedoraproject.org/rpms/pyproject-rpm-macros/c/85fc41174dbdbc26fd3b456c08d6c15dc623e91e?branch=rawhide


It's not happening with python3-setuptools-65.5.1-2.fc38, but I recall setuptools/distutils changed the way they handle logging:

https://setuptools.pypa.io/en/latest/history.html#v65-6-0

Comment 1 Miro Hrončok 2023-03-31 13:27:05 UTC

Reverting https://src.fedoraproject.org/rpms/pyproject-rpm-macros/c/85fc41174dbdbc26fd3b456c08d6c15dc623e91e?branch=rawhide seems to make it work, but that's not the desired outcome.

Comment 2 Miro Hrončok 2023-03-31 15:49:50 UTC

I think I know where the problem is.

First, we call get_requires_for_build_wheel hook in hook_call() and setuptools stores a reference to our faked stdout in the logger.
At the end of this hook_call(), our faked stdout is closed.

Later, we call prepare_metadata_for_build_wheel hook in another hook_call() and setuptools attempts to log to the faked stdout stored in the logger. That is however the already closed faked stdout from the previous hook_call() invocation.



Sharing one faked stdout across multiple hook_call()s seems to do the trick, but I need to figure out how to do that nicely.

Comment 3 Petr Viktorin (pviktori) 2023-03-31 16:17:24 UTC

At this point it might be worth it to switch to writing to file, and use `>&2` & `cat` in the macro.

Comment 4 Miro Hrončok 2023-03-31 16:22:47 UTC

I actually have a fix ready, testing it.

Comment 5 Miro Hrončok 2023-03-31 16:31:32 UTC

Here is my proposed fix: https://src.fedoraproject.org/rpms/pyproject-rpm-macros/pull-request/369



But yeah, switching to writing to file, and use `>&2` & `cat` in the macro is still an option.

Comment 6 Miro Hrončok 2023-03-31 17:00:32 UTC

And here is the alternative with >&2 and cat: https://src.fedoraproject.org/rpms/pyproject-rpm-macros/pull-request/370

Comment 7 Fedora Update System 2023-04-18 09:08:58 UTC

FEDORA-2023-28b5d794fc has been submitted as an update to Fedora 39. https://bodhi.fedoraproject.org/updates/FEDORA-2023-28b5d794fc

Comment 8 Fedora Update System 2023-04-18 09:10:15 UTC

FEDORA-2023-28b5d794fc has been pushed to the Fedora 39 stable repository.
If problem still persists, please make note of it in this bug report.