classification
Title: test_logging: SMTPHandlerTest.test_basic() fails randomly on x86 Gentoo Refleaks 3.7
Type: Stage: resolved
Components: Tests Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: vstinner
Priority: normal Keywords: patch

Created on 2018-07-11 09:45 by vstinner, last changed 2018-07-11 13:56 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 8245 merged vstinner, 2018-07-11 09:51
PR 8247 merged miss-islington, 2018-07-11 10:36
PR 8249 merged vstinner, 2018-07-11 10:44
Messages (7)
msg321423 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 09:45
https://buildbot.python.org/all/#builders/114/builds/163

1:26:51 load avg: 4.83 [117/415/1] test_logging failed -- running: test_multiprocessing_forkserver (8 min 18 sec)
beginning 6 repetitions
123456
.--- Logging error ---
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 387, in getreply
    line = self.file.readline(_MAXLINE + 1)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/socket.py", line 589, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/logging/handlers.py", line 1007, in emit
    smtp = smtplib.SMTP(self.mailhost, port, timeout=self.timeout)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 251, in __init__
    (code, msg) = self.connect(host, port)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 338, in connect
    (code, msg) = self.getreply()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 391, in getreply
    + str(e))
smtplib.SMTPServerDisconnected: Connection unexpectedly closed: timed out
Call stack:
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/regrtest.py", line 50, in <module>
    _main()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/regrtest.py", line 46, in _main
    main()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 584, in main
    Regrtest().main(tests=tests, **kwargs)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 531, in main
    self._main(tests, kwargs)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 547, in _main
    run_tests_slave(self.ns.slaveargs)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest_mp.py", line 68, in run_tests_slave
    result = runtest(ns, testname)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 140, in runtest
    result = runtest_inner(ns, test, display_failure=not ns.verbose)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 177, in runtest_inner
    refleak = dash_R(the_module, test, test_runner, ns.huntrleaks)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/refleak.py", line 69, in dash_R
    indirect_test()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1606, in inner
    return func(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/test_logging.py", line 4641, in test_main
    support.run_unittest(*tests)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1972, in run_unittest
    _run_suite(suite)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1882, in _run_suite
    result = runner.run(suite)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1781, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 663, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 615, in run
    testMethod()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/test_logging.py", line 988, in test_basic
    h.handle(r)
Message: 'Hello ✓'
Arguments: ()
test test_logging failed -- Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/test_logging.py", line 991, in test_basic
    self.assertTrue(self.handled.is_set())
AssertionError: False is not true

(...)

test_basic (test.test_logging.SMTPHandlerTest) ... --- Logging error ---
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 387, in getreply
    line = self.file.readline(_MAXLINE + 1)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/socket.py", line 589, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/logging/handlers.py", line 1007, in emit
    smtp = smtplib.SMTP(self.mailhost, port, timeout=self.timeout)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 251, in __init__
    (code, msg) = self.connect(host, port)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 338, in connect
    (code, msg) = self.getreply()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/smtplib.py", line 391, in getreply
    + str(e))
smtplib.SMTPServerDisconnected: Connection unexpectedly closed: timed out
Call stack:
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/__main__.py", line 2, in <module>
    main()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 584, in main
    Regrtest().main(tests=tests, **kwargs)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 531, in main
    self._main(tests, kwargs)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 570, in _main
    self.rerun_failed_tests()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/main.py", line 286, in rerun_failed_tests
    ok = runtest(self.ns, test)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 140, in runtest
    result = runtest_inner(ns, test, display_failure=not ns.verbose)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/runtest.py", line 177, in runtest_inner
    refleak = dash_R(the_module, test, test_runner, ns.huntrleaks)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/libregrtest/refleak.py", line 69, in dash_R
    indirect_test()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1606, in inner
    return func(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/test_logging.py", line 4641, in test_main
    support.run_unittest(*tests)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1972, in run_unittest
    _run_suite(suite)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/support/__init__.py", line 1882, in _run_suite
    result = runner.run(suite)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/runner.py", line 176, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/suite.py", line 122, in run
    test(result)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 663, in __call__
    return self.run(*args, **kwds)
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/unittest/case.py", line 615, in run
    testMethod()
  File "/buildbot/buildarea/cpython/3.7.ware-gentoo-x86.refleak/build/Lib/test/test_logging.py", line 988, in test_basic
    h.handle(r)
Message: 'Hello ✓'
Arguments: ()
FAIL
msg321424 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 09:47
bpo-14314 added a timeout of 5 seconds in the test:

-        self.handled.wait()p
+        self.handled.wait(5.0)  # 14314: don't wait forever

commit 17160fd6d6d7850294a9a465a3e5e399e5028bb6
Author: Vinay Sajip <vinay_sajip@yahoo.co.uk>
Date:   Thu Mar 15 12:02:08 2012 +0000

    Fixes #14314: Improved SMTP timeout handling.


The timeout has been increased to 8 seconds by:

commit 827f5d35e592c21e4bb82afb702c6496cf77c2ad
Author: Vinay Sajip <vinay_sajip@yahoo.co.uk>
Date:   Tue Dec 3 11:28:55 2013 +0000

    Issue #19665: Increased timeout for SMTPHandler test.


I suggest to just increase the timeout to 60 seconds.
msg321426 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 09:52
Python 2.7 is not affected: it has no test for the SMTPHandler.
msg321433 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 10:35
New changeset 31b50b8cbfbf49d5fc17c612cf0dfaa4d0c24983 by Victor Stinner in branch 'master':
bpo-34092, test_logging: increase SMTPHandlerTest timeout (GH-8245)
https://github.com/python/cpython/commit/31b50b8cbfbf49d5fc17c612cf0dfaa4d0c24983
msg321443 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 11:14
New changeset d68cb9d62c3671dd9aee5cdecb02fcb3268dacf0 by Victor Stinner in branch '3.6':
bpo-34092, test_logging: increase SMTPHandlerTest timeout (GH-8245) (GH-8249)
https://github.com/python/cpython/commit/d68cb9d62c3671dd9aee5cdecb02fcb3268dacf0
msg321444 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 11:15
I hope that the issue was just that the buildbot was slow, and that the failure didn't hide a real bug.
msg321451 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 13:56
New changeset 0a1db32949b4813e9ac04e672fcb5bc97072a428 by Victor Stinner (Miss Islington (bot)) in branch '3.7':
bpo-34092, test_logging: increase SMTPHandlerTest timeout (GH-8245) (GH-8247)
https://github.com/python/cpython/commit/0a1db32949b4813e9ac04e672fcb5bc97072a428
History
Date User Action Args
2018-07-11 13:56:49vstinnersetmessages: + msg321451
2018-07-11 11:15:11vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg321444

stage: patch review -> resolved
2018-07-11 11:14:39vstinnersetmessages: + msg321443
2018-07-11 10:44:26vstinnersetpull_requests: + pull_request7781
2018-07-11 10:36:49miss-islingtonsetpull_requests: + pull_request7778
2018-07-11 10:35:41vstinnersetmessages: + msg321433
2018-07-11 09:52:36vstinnersetmessages: + msg321426
versions: + Python 3.6, Python 3.8
2018-07-11 09:51:18vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request7776
2018-07-11 09:47:33vstinnersetmessages: + msg321424
2018-07-11 09:45:45vstinnercreate