test_logging failure in test_rollover

[pitrou]

BPO	12068
Nosy	@vsajip, @pitrou

^{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 = 'https://github.com/vsajip'
closed_at = <Date 2011-05-30.09:44:42.303>
created_at = <Date 2011-05-12.22:02:11.699>
labels = ['type-bug', 'tests']
title = 'test_logging failure in test_rollover'
updated_at = <Date 2011-05-30.09:44:42.302>
user = 'https://github.com/pitrou'

bugs.python.org fields:

activity = <Date 2011-05-30.09:44:42.302>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2011-05-30.09:44:42.303>
closer = 'vinay.sajip'
components = ['Tests']
creation = <Date 2011-05-12.22:02:11.699>
creator = 'pitrou'
dependencies = []
files = []
hgrepos = []
issue_num = 12068
keywords = []
message_count = 5.0
messages = ['135874', '135898', '136252', '136269', '137251']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'pitrou', 'python-dev']
pr_nums = []
priority = 'high'
resolution = 'fixed'
stage = 'needs patch'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue12068'
versions = ['Python 3.3']

[pitrou]

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)

[python-dev]

New changeset 660a4a6dc2cd by Vinay Sajip in branch 'default':
Issue bpo-12068: Fix appears to have worked; added more diagnostics for rare failures.
http://hg.python.org/cpython/rev/660a4a6dc2cd

[pitrou]

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

---

[vsajip]

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.

[vsajip]

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.