test_logging test_race failed with PermissionError

[ned-deily]

BPO	19690
Nosy	@vsajip, @vstinner, @ned-deily

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2013-11-22.07:31:15.913>
labels = ['type-bug', 'tests']
title = 'test_logging test_race failed with PermissionError'
updated_at = <Date 2014-09-18.03:21:06.562>
user = 'https://github.com/ned-deily'

bugs.python.org fields:

activity = <Date 2014-09-18.03:21:06.562>
actor = 'berker.peksag'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Tests']
creation = <Date 2013-11-22.07:31:15.913>
creator = 'ned.deily'
dependencies = []
files = []
hgrepos = []
issue_num = 19690
keywords = []
message_count = 7.0
messages = ['203727', '205112', '205113', '205536', '213694', '226334', '226338']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'vstinner', 'ned.deily', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = None
stage = 'needs patch'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue19690'
versions = ['Python 3.4', 'Python 3.5']

[ned-deily]

http://buildbot.python.org/all/builders/AMD64%20Snow%20Leop%203.x/builds/568/steps/test/logs/stdio

======================================================================
ERROR: test_race (test.test_logging.HandlerTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/test/test_logging.py", line 613, in test_race
    h.handle(r)
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/logging/__init__.py", line 835, in handle
    self.emit(record)
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/logging/handlers.py", line 468, in emit
    self.stream = self._open()
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/logging/__init__.py", line 1005, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
PermissionError: [Errno 1] Operation not permitted: '/tmp/test_logging-3-i5haxx_n.log'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/test/test_logging.py", line 616, in test_race
    h.close()
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/logging/__init__.py", line 990, in close
    self.flush()
  File "/Users/buildbot/buildarea/3.x.murray-snowleopard/build/Lib/logging/__init__.py", line 937, in flush
    self.stream.flush()
ValueError: I/O operation on closed file.

The test passed when rerun by regrtest. This looks similar to the failures in bpo-14632.

[vsajip]

Unfortunately, the race condition can't be removed completely - it was reduced by the patch in bpo-14632 but could not be eliminated altogether. So this test can fail sporadically - tweaking the timeouts might give some temporary respite, but doesn't guarantee the issue won't return when e.g. machines are unusually heavily loaded.

I'll add some diagnostics for now and see what they show.

[python-dev]

New changeset 8fe3022af4b3 by Vinay Sajip in branch 'default':
Added some diagnostics to help with bpo-19690.
http://hg.python.org/cpython/rev/8fe3022af4b3

[vsajip]

I'll close this for now as the failures seem to have stopped. Though I only added some diagnostics, that might have changed the relative timings enough so the race doesn't surface (for now).

[ned-deily]

I've just seen another instance of this failure, this time using a 3.4.0 release test OS X installer build (non-debug, built on and running on OS X 10.5). The added diagnostics show up:

[186/389/1] test_logging
Deleted at 1394930826.466016, opened at 1394930826.456779
test test_logging failed -- Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/test/test_logging.py", line 618, in test_race
    h.handle(r)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/logging/__init__.py", line 837, in handle
    self.emit(record)
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/logging/handlers.py", line 468, in emit
    self.stream = self._open()
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/logging/__init__.py", line 1007, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
PermissionError: [Errno 1] Operation not permitted: '/tmp/test_logging-3-92xfhrsa.log'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/test/test_logging.py", line 626, in test_race
    h.close()
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/logging/__init__.py", line 992, in close
    self.flush()
  File "/Library/Frameworks/Python.framework/Versions/3.4/lib/python3.4/logging/__init__.py", line 939, in flush
    self.stream.flush()
ValueError: I/O operation on closed file.

[vstinner]

What is the status of this issue? The failure is still common on the buildbot:

http://buildbot.python.org/all/builders/AMD64%20Snow%20Leop%203.4/builds/458/steps/test/logs/stdio

======================================================================
ERROR: test_race (test.test_logging.HandlerTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/Users/buildbot/buildarea/3.4.murray-snowleopard/build/Lib/test/test_logging.py", line 618, in test_race
    h.handle(r)
  File "/Users/buildbot/buildarea/3.4.murray-snowleopard/build/Lib/logging/__init__.py", line 852, in handle
    self.emit(record)
  File "/Users/buildbot/buildarea/3.4.murray-snowleopard/build/Lib/logging/handlers.py", line 468, in emit
    self.stream = self._open()
  File "/Users/buildbot/buildarea/3.4.murray-snowleopard/build/Lib/logging/__init__.py", line 1029, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
PermissionError: [Errno 1] Operation not permitted: '/tmp/test_logging-3-vrpj_wts.log'

[vsajip]

What is the status of this issue?

Sorry, it's been off my radar - I wonder if it has become more common recently. It's hard to reproduce, and tweaking timeouts might make it disappear, but it's a trial-and-error situation because I can hardly ever get the error to occur. The base race condition can't be eliminated, unfortunately.

[kumaraditya303]

Closing as the failures seem to have stopped.