Logging done late enough might happen when capture already stopped. #4487

s0undt3ch · 2018-11-30T23:19:06Z

22:56:26,997 [pytestsalt.utils:206 ][INFO    ][1024] Stopping process psutil.Process(pid=1228, name='/home/vampas/.d', started='22:55:17') and respective children: [psutil.Process(pid=1245, name='/home/vampas/.d', started='22:55:18'), psut
il.Process(pid=1262, name='/home/vampas/.d', started='22:55:19'), psutil.Process(pid=1263, name='/home/vampas/.d', started='22:55:19')]                                                                                                        
Error in atexit._run_exitfuncs:                                                                                                                                                                                                                
Traceback (most recent call last):                                                                                                                                                                                                             
  File "/home/vampas/.dotfiles/.ext/pyenv/versions/3.5.4/lib/python3.5/logging/__init__.py", line 861, in handle                                                                                                                               
    self.emit(record)                                                                                                                                                                                                                          
  File "/home/vampas/.dotfiles/.ext/pyenv/versions/3.5.4/envs/Salt-3.5.4-Develop/lib/python3.5/site-packages/_pytest/logging.py", line 625, in emit                                                                                            
    logging.StreamHandler.emit(self, record)
  File "/home/vampas/.dotfiles/.ext/pyenv/versions/3.5.4/lib/python3.5/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/home/vampas/.dotfiles/.ext/pyenv/versions/3.5.4/envs/Salt-3.5.4-Develop/lib/python3.5/site-packages/_pytest/capture.py", line 167, in global_and_fixture_disabled
    self.resume_global_capture()
  File "/home/vampas/.dotfiles/.ext/pyenv/versions/3.5.4/envs/Salt-3.5.4-Develop/lib/python3.5/site-packages/_pytest/capture.py", line 120, in resume_global_capture
    self._global_capturing.resume_capturing()
AttributeError: 'NoneType' object has no attribute 'resume_capturing'

Create a new changelog file in the changelog folder, with a name like <ISSUE NUMBER>.<TYPE>.rst. See changelog/README.rst for details.
Target the master branch for bug fixes, documentation updates and trivial changes.

nicoddemus

Hi @s0undt3ch, thanks a lot for the PR.

Could you provide a simple integration test which reproduces the problem? It is important to avoid future regressions in case of a refactoring (for example).

src/_pytest/capture.py

s0undt3ch · 2018-12-01T19:07:18Z

@nicoddemus believe me, I tried, for sure not long enough or there would be a test case. Anyway, I wasn't able to reproduce this in a test case :\

nicoddemus · 2018-12-01T19:21:13Z

Hmm I see, thanks. I've tried here myself as well using atexit, but without success.

IMHO we can get this in as it makes the code more consistent with suspend_global_capture anyway. If anybody wants to give this a try to produce a reproducible test please post a comment so we mark this PR as WIP.

changelog/4487.bugfix

codecov · 2018-12-01T19:27:56Z

Codecov Report

Merging #4487 into master will decrease coverage by 53.36%.
The diff coverage is 50%.

@@             Coverage Diff             @@
##           master    #4487       +/-   ##
===========================================
- Coverage    95.9%   42.54%   -53.37%     
===========================================
  Files         111       92       -19     
  Lines       25085    20844     -4241     
  Branches     2447     2337      -110     
===========================================
- Hits        24059     8868    -15191     
- Misses        724    11383    +10659     
- Partials      302      593      +291

Flag	Coverage Δ
#docs	`29.19% <50%> (-0.83%)`	⬇️
#doctesting	`29.19% <50%> (-0.83%)`	⬇️
#linting	`29.19% <50%> (-0.83%)`	⬇️
#linux	`42.54% <50%> (-53.2%)`	⬇️
#nobyte	`?`
#numpy	`41.01% <50%> (-52.46%)`	⬇️
#pexpect	`41.01% <50%> (-0.88%)`	⬇️
#py27	`41.01% <50%> (-53.04%)`	⬇️
#py34	`?`
#py35	`?`
#py36	`?`
#py37	`?`
#trial	`41.01% <50%> (-52.46%)`	⬇️
#windows	`?`
#xdist	`?`

Impacted Files	Coverage Δ
src/_pytest/capture.py	`71.49% <50%> (-21.94%)`	⬇️
testing/test_pastebin.py	`0% <0%> (-100%)`	⬇️
testing/test_resultlog.py	`0% <0%> (-100%)`	⬇️
testing/test_entry_points.py	`0% <0%> (-100%)`	⬇️
testing/test_doctest.py	`0% <0%> (-100%)`	⬇️
testing/test_runner_xunit.py	`0% <0%> (-100%)`	⬇️
testing/test_pathlib.py	`0% <0%> (-100%)`	⬇️
testing/test_nodes.py	`0% <0%> (-100%)`	⬇️
testing/deprecated_test.py	`0% <0%> (-100%)`	⬇️
testing/test_stepwise.py	`0% <0%> (-100%)`	⬇️
... and 91 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update d8e00c9...f792cc4. Read the comment docs.

nicoddemus · 2018-12-01T19:41:50Z

@RonnyPfannschmidt @asottile @blueyed any objections to get this in without an acceptance test?

blueyed

Not sure how difficult a test would be, but it certainly would be great to have for corner cases like this.

blueyed · 2018-12-01T19:55:22Z

changelog/4487.bugfix.rst

@@ -0,0 +1 @@
+During teardown of the python process, capture attributes are None'd. On rare occasions global capture could be attempted to resume while is't already reset.


s/is't/it's/

and probably ``None`` as well

s/are None'd/that are ``None``/ ?

``None``'d I think is correct

nicoddemus · 2018-12-01T20:00:45Z

Not sure how difficult a test would be, but it certainly would be great to have for corner cases like this.

Definitely, would you like to give this a try? I've tried for a few minutes to get this error to blow up with atexit, but no dice.

blueyed · 2018-12-01T21:28:12Z

@nicoddemus
Ok, I trust you and @s0undt3ch then on that it is difficult.. 👍

s0undt3ch · 2018-12-01T21:41:17Z

Comment and changelog entry reworded.

blueyed · 2018-12-02T11:10:04Z

Thanks!

s0undt3ch · 2018-12-02T19:08:38Z

Anytime, and Thanks!

RonnyPfannschmidt · 2018-12-03T11:34:22Z

@s0undt3ch i believe someone found a minimal test in #4500

s0undt3ch · 2018-12-03T11:48:30Z

Awesome!

s0undt3ch · 2018-12-03T12:18:52Z

#4501

Test case for #4500 and respective fix #4487

nicoddemus requested changes Dec 1, 2018

View reviewed changes

asottile reviewed Dec 1, 2018

View reviewed changes

src/_pytest/capture.py Outdated Show resolved Hide resolved

s0undt3ch force-pushed the master branch from bb1717c to 87a4c17 Compare December 1, 2018 19:11

nicoddemus requested changes Dec 1, 2018

View reviewed changes

changelog/4487.bugfix Outdated Show resolved Hide resolved

s0undt3ch force-pushed the master branch from 87a4c17 to 81033da Compare December 1, 2018 19:26

nicoddemus approved these changes Dec 1, 2018

View reviewed changes

blueyed reviewed Dec 1, 2018

View reviewed changes

s0undt3ch added 2 commits December 1, 2018 21:40

Logging done late enough might happen when capture already stopped.

f4d3ec6

Add changelog entry

f792cc4

s0undt3ch force-pushed the master branch from 6f02941 to f792cc4 Compare December 1, 2018 21:40

blueyed merged commit ecc5c84 into pytest-dev:master Dec 2, 2018

RonnyPfannschmidt mentioned this pull request Dec 3, 2018

Logging after yield causes a crash #4500

Closed

s0undt3ch added a commit to s0undt3ch/pytest that referenced this pull request Dec 3, 2018

Test case for pytest-dev#4500 bug and respective fix pytest-dev#4487

2ae077e

s0undt3ch added a commit to s0undt3ch/pytest that referenced this pull request Dec 3, 2018

Test case for pytest-dev#4500 bug and respective fix pytest-dev#4487

14024c7

asottile added a commit that referenced this pull request Dec 3, 2018

Merge pull request #4501 from s0undt3ch/master

99d3fe2

Test case for #4500 and respective fix #4487

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging done late enough might happen when capture already stopped. #4487

Logging done late enough might happen when capture already stopped. #4487

s0undt3ch commented Nov 30, 2018 •

edited

Loading

nicoddemus left a comment

s0undt3ch commented Dec 1, 2018

nicoddemus commented Dec 1, 2018

codecov bot commented Dec 1, 2018 •

edited

Loading

nicoddemus commented Dec 1, 2018

blueyed left a comment

blueyed Dec 1, 2018

asottile Dec 1, 2018

blueyed Dec 1, 2018 •

edited

Loading

asottile Dec 1, 2018

nicoddemus commented Dec 1, 2018

blueyed commented Dec 1, 2018

s0undt3ch commented Dec 1, 2018

blueyed commented Dec 2, 2018

s0undt3ch commented Dec 2, 2018

RonnyPfannschmidt commented Dec 3, 2018

s0undt3ch commented Dec 3, 2018

s0undt3ch commented Dec 3, 2018

		@@ -0,0 +1 @@
		During teardown of the python process, capture attributes are None'd. On rare occasions global capture could be attempted to resume while is't already reset.

Logging done late enough might happen when capture already stopped. #4487

Logging done late enough might happen when capture already stopped. #4487

Conversation

s0undt3ch commented Nov 30, 2018 • edited Loading

nicoddemus left a comment

Choose a reason for hiding this comment

s0undt3ch commented Dec 1, 2018

nicoddemus commented Dec 1, 2018

codecov bot commented Dec 1, 2018 • edited Loading

Codecov Report

nicoddemus commented Dec 1, 2018

blueyed left a comment

Choose a reason for hiding this comment

blueyed Dec 1, 2018

Choose a reason for hiding this comment

asottile Dec 1, 2018

Choose a reason for hiding this comment

blueyed Dec 1, 2018 • edited Loading

Choose a reason for hiding this comment

asottile Dec 1, 2018

Choose a reason for hiding this comment

nicoddemus commented Dec 1, 2018

blueyed commented Dec 1, 2018

s0undt3ch commented Dec 1, 2018

blueyed commented Dec 2, 2018

s0undt3ch commented Dec 2, 2018

RonnyPfannschmidt commented Dec 3, 2018

s0undt3ch commented Dec 3, 2018

s0undt3ch commented Dec 3, 2018

s0undt3ch commented Nov 30, 2018 •

edited

Loading

codecov bot commented Dec 1, 2018 •

edited

Loading

blueyed Dec 1, 2018 •

edited

Loading