classification
Title: test_logging failure in test_rollover
Type: behavior Stage: needs patch
Components: Tests Versions: Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: pitrou, python-dev, vinay.sajip
Priority: high Keywords:

Created on 2011-05-12 22:02 by pitrou, last changed 2011-05-30 09:44 by vinay.sajip. This issue is now closed.

Messages (5)
msg135874 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-05-12 22:02
This has started popping up on several buildbots:


======================================================================
FAIL: test_rollover (test.test_logging.TimedRotatingFileHandlerTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/test/test_logging.py", line 3529, in test_rollover
    self.assertTrue(found, msg=msg)
AssertionError: False is not true : No rotated files found, went back 1 seconds

(http://www.python.org/dev/buildbot/all/builders/x86%20Gentoo%203.x/builds/101/steps/test/logs/stdio)
msg135898 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-13 11:16
New changeset 660a4a6dc2cd by Vinay Sajip in branch 'default':
Issue #12068: Fix appears to have worked; added more diagnostics for rare failures.
http://hg.python.org/cpython/rev/660a4a6dc2cd
msg136252 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-05-18 16:42
Still happens sometimes:

http://www.python.org/dev/buildbot/all/builders/x86%20Gentoo%203.x/builds/133/steps/test/logs/stdio

----------------------------------------
Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 582, in process_request_thread
    self.finish_request(request, client_address)
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 323, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 641, in __init__
    self.finish()
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 713, in finish
    self.socket.sendto(self.wfile.getvalue(), self.client_address)
socket.error: [Errno 9] Bad file descriptor
test test_logging failed -- Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/test/test_logging.py", line 2525, in test_listen_config_10_ok
    ], stream=output)
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/test/test_logging.py", line 162, in assert_log_lines
    '%s vs. %s' % (actual_lines, expected_values))
AssertionError: 4 != 2 : ["Exception happened during processing of request from ('192.168.0.106', 33509)", '----------------------------------------', 'WARNING ++ 1', 'ERROR ++ 4'] vs. [('WARNING', '1'), ('ERROR', '4')]

----------------------------------------
Exception happened during processing of request from ('192.168.0.106', 33512)
Traceback (most recent call last):
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 582, in process_request_thread
    self.finish_request(request, client_address)
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 323, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 641, in __init__
    self.finish()
  File "/var/lib/buildslave/3.x.murray-gentoo/build/Lib/socketserver.py", line 713, in finish
    self.socket.sendto(self.wfile.getvalue(), self.client_address)
socket.error: [Errno 9] Bad file descriptor
----------------------------------------
msg136269 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-19 09:13
It's not the same error, but there's no point opening another issue for it. The earlier error occurred more frequently, and was specifically due to some changes I made, whereas this error hasn't occurred before and appears to be due to some sort of network glitch. On the same buildbot, later revisions have run without errors, with no changes to test_logging:

162ed9841f147f37d2077a1848eb9aff130b71fb
05836e84e584d3c529e74fba4b99da95df17ef24
c45e92bd4d81713603b7271cc7f61b7457296563

I'll mark as pending and keep an eye on it, but if the failure doesn't recur in the next week or so I'll close the issue again.
msg137251 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-05-30 09:44
There appear to have been no test_logging failures on the buildbots for around a week, so closing this issue. A change to ignore socket errors when the server was closed appears to have done the trick.
History
Date User Action Args
2011-05-30 09:44:42vinay.sajipsetstatus: pending -> closed
resolution: fixed
messages: + msg137251
2011-05-19 09:13:56vinay.sajipsetstatus: open -> pending
resolution: fixed -> (no value)
messages: + msg136269
2011-05-18 16:42:01pitrousetstatus: closed -> open

messages: + msg136252
2011-05-13 18:55:27vinay.sajipsetresolution: duplicate -> fixed
2011-05-13 18:55:11vinay.sajipsetstatus: open -> closed
resolution: duplicate
2011-05-13 11:16:11python-devsetnosy: + python-dev
messages: + msg135898
2011-05-12 22:02:11pitroucreate