test_nntplib: sporadic failures, network isses? server down?

[vstinner]

BPO	19756
Nosy	@pitrou, @vstinner, @berkerpeksag, @vadmium, @miss-islington
PRs	bpo-19756: Prevent test failures due to EADDRNOTAVAIL #9446 [3.7] bpo-19756: Prevent test failures due to EADDRNOTAVAIL (GH-9446) #9447 [3.6] bpo-19756: Prevent test failures due to EADDRNOTAVAIL (GH-9446) #9448 [2.7] bpo-19756: Prevent test failures due to EADDRNOTAVAIL (GH-9446) #9450 bpo-19756: Change remote NNTP server to localhost server for most tests #9461
Files	test_nntplib_logs.txt nntp-server.patch: Custom local server original-order.diff: Smaller diff representing above changes multi-connect.patch: Each test creates new connection

^{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-24.18:07:31.280>
labels = ['3.7', '3.8', 'type-bug', 'tests']
title = 'test_nntplib: sporadic failures, network isses? server down?'
updated_at = <Date 2020-05-22.21:28:12.797>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2020-05-22.21:28:12.797>
actor = 'chris.jerdonek'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Tests']
creation = <Date 2013-11-24.18:07:31.280>
creator = 'vstinner'
dependencies = []
files = ['43441', '43464', '43478', '46018']
hgrepos = []
issue_num = 19756
keywords = ['patch', 'buildbot']
message_count = 25.0
messages = ['204248', '204262', '223333', '245587', '268742', '268745', '268841', '268882', '283915', '292451', '297123', '325821', '325857', '325861', '325873', '325875', '325878', '325885', '325887', '325889', '325893', '325896', '325917', '325931', '369650']
nosy_count = 5.0
nosy_names = ['pitrou', 'vstinner', 'berker.peksag', 'martin.panter', 'miss-islington']
pr_nums = ['9446', '9447', '9448', '9450', '9461']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue19756'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[vstinner]

http://buildbot.python.org/all/builders/AMD64%20FreeBSD%209.x%203.x/builds/692/steps/test/logs/stdio

======================================================================
ERROR: test_capabilities (test.test_nntplib.NetworkedNNTP_SSLTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/test/test_nntplib.py", line 251, in wrapped
    meth(self)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/test/test_nntplib.py", line 201, in test_capabilities
    resp, caps = self.server.capabilities()
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/nntplib.py", line 558, in capabilities
    resp, lines = self._longcmdstring("CAPABILITIES")
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/nntplib.py", line 525, in _longcmdstring
    resp, list = self._getlongresp(file)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/nntplib.py", line 476, in _getlongresp
    resp = self._getresp()
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/nntplib.py", line 449, in _getresp
    resp = self._getline()
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/nntplib.py", line 432, in _getline
    line = self.file.readline(_MAXLINE +1)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd9/build/Lib/socket.py", line 368, in readinto
    raise OSError("cannot read from timed out object")
OSError: cannot read from timed out object

http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.x/builds/7147/steps/test/logs/stdio

======================================================================
ERROR: setUpClass (test.test_nntplib.NetworkedNNTP_SSLTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_nntplib.py", line 298, in setUpClass
    cls.server = cls.NNTP_CLASS(cls.NNTP_HOST, timeout=TIMEOUT, usenetrc=False)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 1071, in __init__
    readermode=readermode, timeout=timeout)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 334, in __init__
    self.getcapabilities()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 390, in getcapabilities
    resp, caps = self.capabilities()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 558, in capabilities
    resp, lines = self._longcmdstring("CAPABILITIES")
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 525, in _longcmdstring
    resp, list = self._getlongresp(file)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 476, in _getlongresp
    resp = self._getresp()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 449, in _getresp
    resp = self._getline()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/nntplib.py", line 437, in _getline
    if not line: raise EOFError
EOFError

[pitrou]

The third-party server isn't extremely reliable indeed. Ideally, we would run our own NNTP server, but that's a lot more work.

[BreamoreBoy]

Are these sporadic failures still happening? I've glanced over the logs and only found failures due to recent code changes.

[vadmium]

See bpo-1186900 about the NNTP client raising EOFError.

As for the “cannot read from timed out object” errors (also reported in bpo-19613), I think the test classes are bad. The test logs don’t seem to be available, but I reckon that the previous test to the failing test would have been skipped due to the transient Internet handler. The test classes are essentially coded like this:

class NetworkedNNTP_SSLTests(TestCase):
    @classmethod
    def setUpClass(cls):
        with support.transient_internet(cls.NNTP_HOST):
            cls.server = NNTP_SSL(cls.NNTP_HOST, timeout=TIMEOUT)
    
    def test_that_triggered_the_failure(self):
        with support.transient_internet(self.NNTP_HOST):
            ...  # Suppose this timed out and the test was skipped
    
    def test_capabilities(self):
        # Now this is reusing the existing connection, left in a broken state by
        # the previous test
        self.server.capabilities()

Either the server connection should be freshly made for each individual test case (not once per class), or all the test cases grouped by setUpClass() should be skipped if the transient Internet handler kicks in. I’m not sure if it is practical to do the second option with the standard unittest module. Perhaps the method wrapping stage could add some extra checks to see if the test should be skipped.

[berkerpeksag]

I just saw the same test failures at http://buildbot.python.org/all/builders/AMD64%20Debian%20root%203.5/builds/998/steps/test/logs/stdio

I'm attaching the test logs for future reference.

[vadmium]

Thanks Berker. In this case the previous tests using the same NNTP connection object were skipped. First run:

test_unknown_command (test.test_nntplib.NetworkedNNTPTests) ... ok
test_welcome (test.test_nntplib.NetworkedNNTPTests) ... ok
test_with_statement (test.test_nntplib.NetworkedNNTPTests) ... skipped "Resource 'news.trigofacile.com' is not available"
test_xhdr (test.test_nntplib.NetworkedNNTPTests) ... skipped "Resource 'news.trigofacile.com' is not available"
test_xover (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_zlogin (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_zzquit (test.test_nntplib.NetworkedNNTPTests) ... ERROR

Subsequent retry:

test_xover (test.test_nntplib.NNTPv2Tests) ... ok
test_article_head_body (test.test_nntplib.NetworkedNNTPTests) ... skipped "Resource 'news.trigofacile.com' is not available"
test_capabilities (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_date (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_description (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_descriptions (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_group (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_help (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_list (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_list_active (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_newgroups (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_over (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_unknown_command (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_welcome (test.test_nntplib.NetworkedNNTPTests) ... ok
test_with_statement (test.test_nntplib.NetworkedNNTPTests) ... ok
test_xhdr (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_xover (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_zlogin (test.test_nntplib.NetworkedNNTPTests) ... ERROR
test_zzquit (test.test_nntplib.NetworkedNNTPTests) ... ERROR

Test_with_statement() is a special case because it starts a fresh NNTP connection, rather than reusing self.server. Test_welcome() is also different because it does not send any new commands to the server. But I presume the other tests all try to reuse the old timed-out self.server object. The skipped messages are evidence of this.

The easy solution which I mentioned above would be to change setUpClass() to setUp(), although this might slow the tests down a bit, reconnecting to the remote server for each test method.

The solution that I prefer would be as Antoine suggested, to run our own server. I think expanding the server I created in bpo-25859 with more commands would be good enough.

[vadmium]

Here is a patch that changes all affected tests to use a custom server running on localhost:

• Local server is based on the existing NNTPv2Handler class, and the LocalServerTests class
• Reintegrate test_starttls() back into NetworkedNNTPTestsMixin
• Only test_with_statement() talks to the remote NNTP_HOST now (not affected by this bug)
• Make tests in NetworkedNNTPTestsMixin stricter, because the server responses are predetermined now
• Add mock comp.lang.python support to NNTPv1Handler.handle_GROUP()
• Add support for rejecting passwords in NNTPv1Handler.handle_AUTHINFO()
• New message number with non-UTF-8 message body for ARTICLE, HEAD, BODY, and non-UTF-8 subject for OVER, XOVER

[vadmium]

Here is a diff that shows my changes better. I temporarily moved some classes back to their original positions to reduce the diff size, though it won’t work in practice because Python needs the classes defined before using them.

[vadmium]

Multi-connect.patch is a smaller patch that changes setUpClass() → setUp(), so that each test method creates a new NNTP connection. The downside is all the reconnecting slows the test execution from 42 s down to 115 s, which is why I would like to move the testing to a local server.

[vstinner]

ERROR: setUpClass (test.test_nntplib.NetworkedNNTP_SSLTests)

I wrote an obvious fix for this one: issue bpo-30188.

[vstinner]

Any progress on this issue?

Martin: Can you please convert your latest patch into a Pull Request?

[vstinner]

I didn't see test_nntplib failing recently, so I close the issue as outdated.