classification
Title: test_nntplib: sporadic failures, test_article_head_body()
Type: behavior Stage: patch review
Components: Tests Versions: Python 3.6, Python 3.5
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: berker.peksag, koobs, martin.panter, mcepl, vstinner
Priority: normal Keywords: buildbot, patch

Created on 2013-11-15 17:30 by vstinner, last changed 2019-05-21 12:34 by mcepl.

Files
File name Uploaded Description Edit
koobs-freebsd-10-python-3x-build-4682.txt koobs, 2016-07-27 00:58
ending-dot.patch martin.panter, 2016-07-27 03:17 review
ending-dot.v2.patch martin.panter, 2016-07-27 03:35 review
Messages (18)
msg202961 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2013-11-15 17:30
http://buildbot.python.org/all/builders/AMD64%20Ubuntu%20LTS%203.x/builds/3024/steps/test/logs/stdio

======================================================================
ERROR: test_article_head_body (test.test_nntplib.NetworkedNNTP_SSLTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/opt/python/3.x.langa-ubuntu/build/Lib/test/test_nntplib.py", line 251, in wrapped
    meth(self)
  File "/opt/python/3.x.langa-ubuntu/build/Lib/test/test_nntplib.py", line 178, in test_article_head_body
    self.check_article_resp(resp, body, art_num)
  File "/opt/python/3.x.langa-ubuntu/build/Lib/test/test_nntplib.py", line 158, in check_article_resp
    self.assertNotIn(article.lines[-1], (b".", b".\n", b".\r\n"))
IndexError: list index out of range

(...)
Re-running failed tests in verbose mode
Re-running test 'test_nntplib' in verbose mode
(...)
test_article_head_body (test.test_nntplib.NetworkedNNTPTests) ... ok
msg224475 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2014-08-01 09:02
The last five builds have been successful so can this be closed as "out of date"?
msg224476 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-08-01 09:13
> The last five builds have been successful so can this be closed as "out of date"?

Really? I saw a lot of test_nntplib failures this week, on Windows buildbots for example.
msg224481 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-08-01 10:34
Well, it's not exactly the same error, but it's still "sporadic failure" of test_nntp. Example:

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


======================================================================
ERROR: test_zlogin (test.test_nntplib.NetworkedNNTPTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_nntplib.py", line 251, in wrapped
    meth(self)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_nntplib.py", line 229, in test_zlogin
    user=baduser, password=badpw, usenetrc=False)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\unittest\case.py", line 704, in assertRaises
    return context.handle('assertRaises', callableObj, args, kwargs)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\unittest\case.py", line 162, in handle
    callable_obj(*args, **kwargs)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\nntplib.py", line 963, in login
    resp = self._shortcmd('authinfo user ' + user)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\nntplib.py", line 512, in _shortcmd
    return self._getresp()
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\nntplib.py", line 450, in _getresp
    resp = self._getline()
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\nntplib.py", line 433, in _getline
    line = self.file.readline(_MAXLINE +1)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\socket.py", line 514, in readinto
    raise OSError("cannot read from timed out object")
OSError: cannot read from timed out object
msg245538 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-06-20 01:44
The timed out case seems to be similar to Issue 19756.
msg268972 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-06-21 06:07
I presume the original report was due to testing when the server happened to return an article with an empty body. The failing test is

# XXX this could exceptionally happen...
self.assertNotIn(article.lines[-1], (b".", b".\n", b".\r\n"))

The test code already admits that what it is testing cannot be guaranteed (an article body could end with a full stop). And we have found another case where the test is not valid (an article with zero lines). I say remove this part of the test, at least when testing the article() and body() methods.
msg271423 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2016-07-27 00:58
This just failed on 3.x (default) on koobs-freebsd{9,10} bots:

======================================================================
FAIL: test_article_head_body (test.test_nntplib.NetworkedNNTP_SSLTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd10/build/Lib/test/test_nntplib.py", line 240, in wrapped
    meth(self)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd10/build/Lib/test/test_nntplib.py", line 185, in test_article_head_body
    self.check_article_resp(resp, body, art_num)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd10/build/Lib/test/test_nntplib.py", line 165, in check_article_resp
    self.assertNotIn(article.lines[-1], (b".", b".\n", b".\r\n"))
AssertionError: b'.' unexpectedly found in (b'.', b'.\n', b'.\r\n')

----------------------------------------------------------------------

Full log attached
msg271426 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-07-27 02:43
A few other buildbots shared this failure. It would be nice to see what the article is that is causing the failure, but I’m fairly confident we should just remove this part of the test.
msg271428 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-07-27 03:17
I played with the server and group that is apparently used in the test:

>>> server = NNTP_SSL("nntp.aioe.org")
>>> [_, _, first, last, _] = server.group("fr.comp.lang.python")
>>> first
2900
>>> last
2915
>>> server.body(last)[1].lines[-1]
b''
>>> server.body(first)[1].lines[-1]
b'Merci'
>>> server.body(last - 1)[1].lines[-1]
b'Kevin'

I tried all articles from 2900–2915, and none of them end with a dot on its own line, so I don’t actually know what caused the failure.

However looking again at the _getlongresp() implementation, I cannot imagine how the test failure can occur except for a genuine body that ends with a dot on its own line (encoded as b".." and then converted to b"."). Here is a quick patch to alter the test cases.
msg271429 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-07-27 03:32
This version actually works :P
msg297134 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-06-28 01:45
Sorry, I lost track of this issue. What is the status?

@Martin: Do you want to convert your latest patch into a PR?
msg297529 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2017-07-03 00:34
It looks like I was fairly confident about my patch, but it was all theoretical and I was never able to analyze the failure myself.

Sorry but I am unlikely to spend much time on this or open a pull request any time soon.
msg306936 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2017-11-25 02:51
Victor opened Issue 32128 with the same complaint. I think I found the offending article:

>>> server = NNTP_SSL("nntp.aioe.org")
>>> [response, count, first, last, name] = server.group("comp.lang.python")
>>> last
199267
>>> pprint(server.article(199265)[1].lines)
[. . .
 b'Date: Fri, 24 Nov 2017 15:44:26 -0800 (PST)',
 . . .
 b'Message-ID: <dcaddc9c-a7b7-4120-bd30-304f58566d3d@googlegroups.com>',
 b'Subject: Re: Python loop and web server (bottle) in the same script (Posting',
 b'     On Python-List Prohibited)',
 . . .
 b'Content-Transfer-Encoding: quoted-printable',
 . . .
 b'If processing is I/O bound and not CPU bound, then asyncio should work fine=',
 b'.']

The body uses Quoted-printable encoding, and the previous line ends with an equals sign “=”, meaning a soft line break. So the full stop is on its own because the encoder didn’t want to fit it on the previous line. This is valid (albeit quirky) encoding, and not a problem with the NNTP library.
msg325829 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-09-19 23:31
I suggest to close the issue since the bug didn't show up recently.
msg325921 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2018-09-20 19:05
The test_article_head_body test is now skipped unconditionally:

    @unittest.skipIf(True, "FIXME: see bpo-32128")

I don't think we should close this issue without re-enabling that test.
msg325923 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-09-20 19:21
>  I don't think we should close this issue without re-enabling that test.

The fact is that nobody cares of test_nntplib: this issue is open for 5 years. I don't see how leaving the issue open which helps. It's fine to skip a test if nobody is available to fix it.
msg325924 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2018-09-20 19:36
Well, no one is going to notice it if we close this issue. I don't see why the age of the issue matters here. We close issues when we fix them. It may take 20 minutes, 5 years or a decade.

I understand closing an issue as "out of date" when we couldn't find the root of the problem, but in this case the problem is obvious and there is already a patch that tries to fix it.
msg343039 - (view) Author: Matej Cepl (mcepl) * Date: 2019-05-21 12:34
Could anybody make a PR from these patches? @vstinner, would you make me a review if I do it?
History
Date User Action Args
2019-05-21 12:34:45mceplsetnosy: + mcepl
messages: + msg343039
2019-04-12 10:30:33martin.panterlinkissue36600 superseder
2018-09-20 19:36:41berker.peksagsetmessages: + msg325924
2018-09-20 19:21:53vstinnersetmessages: + msg325923
2018-09-20 19:05:11berker.peksagsetnosy: + berker.peksag
messages: + msg325921
2018-09-19 23:31:14vstinnersetmessages: + msg325829
2017-11-25 02:51:54martin.pantersetmessages: + msg306936
2017-07-03 00:34:59martin.pantersetmessages: + msg297529
2017-06-28 01:45:52vstinnersetmessages: + msg297134
2016-07-27 03:35:15martin.pantersetfiles: + ending-dot.v2.patch
2016-07-27 03:34:14martin.pantersetfiles: - ending-dot.v2.patch
2016-07-27 03:32:13martin.pantersetfiles: + ending-dot.v2.patch

messages: + msg271429
2016-07-27 03:17:04martin.pantersetfiles: + ending-dot.patch
versions: - Python 3.4
messages: + msg271428

keywords: + patch
stage: needs patch -> patch review
2016-07-27 02:43:20martin.pantersetmessages: + msg271426
stage: needs patch
2016-07-27 01:01:09koobssetversions: + Python 3.6
2016-07-27 00:58:35koobssetfiles: + koobs-freebsd-10-python-3x-build-4682.txt

nosy: + koobs
messages: + msg271423

keywords: + buildbot
2016-06-21 13:45:11BreamoreBoysetnosy: - BreamoreBoy
2016-06-21 06:07:52martin.pantersetmessages: + msg268972
2015-06-20 01:44:28martin.pantersetnosy: + martin.panter
messages: + msg245538
2014-08-01 10:34:29vstinnersetmessages: + msg224481
2014-08-01 09:13:04vstinnersetmessages: + msg224476
2014-08-01 09:02:07BreamoreBoysetversions: + Python 3.5
nosy: + BreamoreBoy

messages: + msg224475

type: behavior
2013-11-15 17:30:45vstinnercreate