classification
Title: IMAP4_SSL spin because of SSLSocket.suppress_ragged_eofs
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.1, Python 3.2, Python 2.7, Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: r.david.murray Nosy List: barry, benjamin.peterson, janssen, kevinwatters, ncoghlan, r.david.murray, rhettinger, rmore, rtucker, scott.dial
Priority: high Keywords: patch

Created on 2009-05-06 15:45 by kevinwatters, last changed 2009-12-12 18:47 by r.david.murray. This issue is now closed.

Files
File name Uploaded Description Edit
imaplib-r76683.patch scott.dial, 2009-12-06 02:59 corrects the handling of EOF in readline() and _get_line()
test_imaplib_issue5949-3.patch scott.dial, 2009-12-07 16:30 PEP8ified tests
test_imaplib_issue5949-py26.patch scott.dial, 2009-12-09 17:26 tests backported for 2.6
socketserver_issue_6267.patch scott.dial, 2009-12-09 18:34 backport for py26 of SocketServer patch from r73638
test_imaplib_issue5949_py3k.patch r.david.murray, 2009-12-09 18:49
Messages (38)
msg87337 - (view) Author: Kevin Watters (kevinwatters) Date: 2009-05-06 15:45
I cannot reproduce this locally yet, but I have several bug reports from users showing 
that IMAP4_SSL connections can get stuck in an infinite loop during logout()

  File "imaplib.pyo", line 529, in logout
  File "imaplib.pyo", line 1059, in _simple_command
  File "imaplib.pyo", line 889, in _command_complete
  File "imaplib.pyo", line 990, in _get_tagged_response
  File "imaplib.pyo", line 907, in _get_response
  File "imaplib.pyo", line 1000, in _get_line
  File "imaplib.pyo", line 1170, in readline
  File "ssl.pyo", line 136, in read

IMAP4_SSL uses ssl.wrap_socket and should probably be passing 
suppress_ragged_eofs=False. Without this, self.sslobj.read() may return '' forever, and 
both IMAP4_SSL.read() and IMAP4_SSL.readline() will spin. With 
suppress_ragged_eofs=False, calling logout() may raise an SSLError instead.

Thoughts?
msg87359 - (view) Author: Rod Morehead (rmore) Date: 2009-05-07 04:24
Isn't the call to read(1) blocking in this case?

If so the only reason it should spin would be if it returned an empty 
string representing EOF.

Couldn't we just add a check for an empty string and, if found, raise an 
EOF exception?
msg87410 - (view) Author: Kevin Watters (kevinwatters) Date: 2009-05-07 21:31
I wasn't sure--the docs for SSLSocket.read 
(http://docs.python.org/library/ssl.html#ssl.SSLSocket.read) say

  "Reads up to nbytes bytes from the SSL-encrypted channel and returns 
them."

With that "up to" I wasn't sure that an empty string would necessarily 
mean EOF--I'm not familiar enough with _ssl.c to say either way.
msg91663 - (view) Author: Ryan Tucker (rtucker) Date: 2009-08-17 13:09
I can reproduce this problem with Python 2.6.  It manifests itself as a
lengthy iteration through an IMAP SSL mailbox locking up after a long
while and the interpreter consuming all available system memory.

I suspect this to be the combination of doom:

imaplib.py:
   1166         def readline(self):
   1167             """Read line from remote."""
   1168             line = []
   1169             while 1:
   1170                 char = self.sslobj.read(1)
   1171                 line.append(char)
   1172                 if char == "\n": return ''.join(line)

ssl.py:
    130     def read(self, len=1024):
    131 
    132         """Read up to LEN bytes and return them.
    133         Return zero-length string on EOF."""
    134 
    135         try:
    136             return self._sslobj.read(len)
    137         except SSLError, x:
    138             if x.args[0] == SSL_ERROR_EOF and
self.suppress_ragged_eofs:
    139                 return ''
    140             else:
    141                 raise

After setting suppress_ragged_eofs=False, I now get:

ssl.SSLError: [Errno 8] _ssl.c:1325: EOF occurred in violation of protocol

... instead of an explosion.  This I can trap and handle much more
easily than an infinite loop appending '' to a list on each iteration :-)

I can reliably reproduce this against my gmail mailbox, although it does
take some number of hours.  I am not sure if this would be an imaplib
bug or a ssl bug; I'd think ssl, because it is Not the Python Way to
bury an exception like this.
msg93392 - (view) Author: Scott Dial (scott.dial) Date: 2009-10-01 07:37
It would seem the logical patch would be to return the line when the
empty string is returned. This would fall in line with the behavior of
other objects with a readline() in python. In following with that, the
patch I have attached returns a truncated line. Therein, the _get_line()
implementation needs to actually check for the correct termination of
the line (it's arguably a bug as it is, just chucking away the last two
characters blindly).
msg93401 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2009-10-01 11:07
Probably too late for 2.6.3 - assigning to Barry to check anyway.
msg93402 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2009-10-01 12:20
I'm afraid so.  Please consider this for landing after 2.6.3 is released.
msg93621 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2009-10-05 21:24
Can this go into 2.6.4?
msg93708 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2009-10-07 18:08
Sorry, 2.6.4 will be solely to remove the brown paper bag of 2.6.3 from
our heads.  This can go in 2.6.5 though.
msg95424 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2009-11-18 12:06
Unassigned from Barry since this isn't an RM review issue anymore
msg96010 - (view) Author: Benjamin Peterson (benjamin.peterson) * (Python committer) Date: 2009-12-05 22:01
.endswith() is a good alternative to [-2:] ==
msg96017 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-06 02:59
Alright, I am attaching a new patch to correct the brain-fart
inefficiency of slicing versus endswith().

I don't understand why this is so difficult to review. I don't think
Janssen is the right person to have been assigned to this. While it is
related to SSL, I don't think the IMAP module is even on his radar.
Whereas, I use this module everyday, every 10 minutes every day to fetch
my email (via getmail), and can assure you that the 110 character change
is correct.
msg96018 - (view) Author: Benjamin Peterson (benjamin.peterson) * (Python committer) Date: 2009-12-06 03:26
Rest assured it has little to do with the difficultly of reviewing it.
Rather we are all volunteers. Do you think a test would be easy to write
for this?
msg96019 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-06 04:19
Ben, I understand that we are all volunteers here. My frustration in the
lack of a de facto owner of the imaplib module and not with you
personally or any other committer for that matter.

As it is, there is no unittests for the imaplib module, and I am not in
a position to provide a complete implementation of an IMAP server.
However, I have attached a simple script demonstrating the issue. An
unpatched trunk will infinite loop, consuming memory, and a patched
version will throw a Traceback immediately.
msg96020 - (view) Author: Benjamin Peterson (benjamin.peterson) * (Python committer) Date: 2009-12-06 04:29
2009/12/5 Scott Dial <report@bugs.python.org>:
>
> Scott Dial <scott@scottdial.com> added the comment:
>
> Ben, I understand that we are all volunteers here. My frustration in the
> lack of a de facto owner of the imaplib module and not with you
> personally or any other committer for that matter.\

Unfortunately imaplib predates the focus for stability in Python.

>
> As it is, there is no unittests for the imaplib module, and I am not in
> a position to provide a complete implementation of an IMAP server.

There is a stub in test_imaplib.py. I wouldn't expect a complete test
suite, but merely a test exposing the bug you are fixing. Every step
counts.

> However, I have attached a simple script demonstrating the issue. An
> unpatched trunk will infinite loop, consuming memory, and a patched
> version will throw a Traceback immediately.
msg96021 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-06 07:21
I found myself in the mood to code, so in the spirit of "every step
counts", I have attached a patch that updates test_imaplib accordingly.
The construction of the test framework is based loosely on test_ssl and
test_socketserver. If someone felt so moved to add more test cases, then
one would could simply extend SimpleIMAPHandler to handle more IMAP
commands.

FYI, as previously noted, on an unpatch trunk test_issue5949() is an
infinite loop.
msg96025 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 16:23
With just the test patch applied, test_imaplib passes for me on trunk
r76687.
msg96027 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 16:25
Ah, your new test isn't being run, that's why test_impalib passes.  Let
me figure out why your test isn't run.
msg96028 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-06 16:31
The test requires regrtest.py be run with network support and the python
instance be built with threads.

$ ./python Lib/test/regrtest.py -u network test_imaplib

Without network support, it just skips those test (which is the same way
test_ssl). That seemed a bit fishy to me, but I was just emulating what
I saw.
msg96029 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 16:32
OK, after adding ThreadedNetworkedTests to the 'tests' list in
test_main, the new tests ran and did hang.  After applying the imaplib
patch, the new tests completed.  However, afterward I got the following
traceback:

Exception in thread Thread-6 (most likely raised during interpreter
shutdown):
Traceback (most recent call last):
  File "/home/rdmurray/python/trunk/Lib/threading.py", line 526, in
__bootstrap_inner
  File "/home/rdmurray/python/trunk/Lib/threading.py", line 479, in run
  File "/home/rdmurray/python/trunk/Lib/SocketServer.py", line 583, in
process_request_thread
  File "/home/rdmurray/python/trunk/Lib/test/test_imaplib.py", line 82,
in handle_error
  File "/home/rdmurray/python/trunk/Lib/SocketServer.py", line 434, in
server_close
  File "/home/rdmurray/python/trunk/Lib/socket.py", line 192, in close
<type 'exceptions.TypeError'>: 'NoneType' object is not callable
msg96030 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 16:33
Ah, my mistake, I misread the code, sorry.

Yes, if I supply -uall to regrtest the tests run correctly.
msg96031 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-06 17:05
Thanks for giving it a try. I believe the issue is that I am raising an
exception in the middle of run_server, which was not a pattern tested in
the other modules I looked at. Thus, the threads for those do not get
reaped correctly.

I have rewrote the test to ensure all of the spawned threads and servers
are shutdown correctly.
msg96038 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 20:41
The traceback I posted was a spurious result of my misunderstanding your
test code.  With -uall it worked fine.  Sorry that I didn't make that clear.

Thanks for doing the work of putting the extended test framework
together.  Without that, this would probably have remained stuck.

I don't think the test_socketserver code is a particularly good example
of unittest code, though, so I refactored what you did into something I
like better.  I may be wrong, so feedback welcome.

Alternative test_imaplib patch attached.

Note that in looking at this I discovered that the test suite as a whole
does not currently handle --without-threads cleanly.  I've opened issue
7449 for this.  Since test_imaplib currently only has one
non-thread-dependent test, I've written my version of the patch so that
the whole test is skipped if threading is not available (this skip will
come with an appropriate message in the test output).

Note also that my code generates a traceback analogous to the one I
posted but only when run under -R.  I'll have to look in to that.
msg96039 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-06 20:42
Patch actually attached this time.
msg96050 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-07 14:22
The design of your patch makes a lot of sense. I found that your patch
uncovered a problem with using the ThreadingMixin (which is ultimately
not necessary as long as the whole SocketServer is in its own thread). I
rewrote the SimpleIMAPHandler to timeout in a timely manner and for the
reap_server() to actually ensure that all threads have been shutdown.

I ended up rewriting my patch in steps towards yours before I uncovered
why I was getting threads alive at shutdown. In that vein, the patch I
am attaching uses the "with reaped_server(hdlr) as server:" technique,
but it could be converted to use an attribute instead. I find using
"with" easier to read and less error prone (failing shutdown the server
and thread because human error or an uncaught exception).
msg96052 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-07 14:48
IMO the context manager approach is much better than what I had.  I'm
still not used to using those :)

One request: I imported test_support as support because that's what it
is named in py3k, and doing it that way will make porting the patch to
py3k simpler.  It would also be nice to pep8ify the spacing by putting
two blank lines between classes (yeah, I know, a lot of the test source
is not PEP 8 compliant...but we try to keep any new code compliant, and
fix old code as we touch it).

Oh, and the reason I moved SocketServer below the import_module for
threading is that SocketServer will die on import if threading is not
available, so it seemed better to me to make the explicit check for
threading first.  Probably instead that import_module should be moved to
the top of the import list, since if it fails the module is skipped.
msg96061 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-07 16:30
I actually thought I was complying with PEP8.. yikes. I guess my
personal rules are slightly different. I think the latest attached patch
is PEP8 compliant now. And, I moved the import_module() to the top as
you suggested.
msg96170 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-09 15:31
Applied to trunk in r76276.  However, when I tried to backport it to
2.6, the tests hang in test_connect for the SSL version.  The hang isn't
interruptible by ctl-C.  Perhaps there's some SSL fix that hasn't been
backported, and if so it would be nice to figure out if it can be
backported.  (Note, to backport the tests I removed the 'reap_threads'
context manager calls and replaced it with a reap_children call at the
end of test_main).
msg96172 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-09 16:42
Added skipping of the SSL tests if ssl is not available in r76727.
msg96174 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-09 17:26
I have attached a proper backport for the 2.6 maintenance branch. There
were some features (not bugfixes) of the trunk that the tests depended
on, which are not backported.

However, the tests still hang, because there are changes to
SocketServer.py that were not backported to 2.6. The changes are needed
to properly call close() on the underlying socket of the SecureTCPServer
and thus trigger the EOF. To avoid the backporting of bits in
SocketServer, I hacked the necessary bits into this version of the tests.
msg96176 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-09 18:08
Do you know which patches?  It's possible they just haven't been
evaluated for backport yet, and if that's so I'll see if I can take care
of it.
msg96177 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-09 18:24
I tracked the necessary change to r73638 and issue6267. However, I am
not sure it is in scope to backport all of that.

The only changed actually needed from this set to make SocketServer
behave correctly with a SSLSocket is:

     def close_request(self, request):
         """Called to clean up an individual request."""
+        #explicitly shutdown.  socket.close() merely releases
+        #the socket and waits for GC to perform the actual close.
+        request.shutdown(socket.SHUT_WR)
         request.close()

Hence in my py26 patch, I have made a call to shutdown() within the
handler. I would call this a bug, but nobody seems to have noticed but
me, so I defer to you about the best solution.
msg96178 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-09 18:34
I've revised my opinion. If you extract out only the changes to
SocketServer and ignore the others, then I would consider it a good
backport (fixes bugs only). I have attached such a patch.

BTW, with this patch, you can remove the shutdown() call in the
test_imaplib patch.
msg96179 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-09 18:49
I'll take a look at the socketserver issue, but probably not today.

In the meantime, can you take a look at this port of the tests to py3k
when you get a chance?  The tests pass without changes to imaplib, but
the imaplib code is a bit different in py3k.  I'd like your opinion on
whether the fact that _get_line unconditionally chomps the last two
bytes is a bug waiting to happen in some other context, even though it
doesn't happen in this particular one in py3k.
msg96180 - (view) Author: Scott Dial (scott.dial) Date: 2009-12-09 19:49
It seems that on the py3k branch, the EOF situation is handled roughly
in the same manner (the broken line is returned) and ultimately the
IMAP4.abort exception is raised because b'* ' is an invalid response
(the 'OK' having been dropped). IOW, it passes the EOF test only because
trimming broke the welcome message format. If it got an EOF in the
middle of a more complicated response, it would go undetected or cause a
broken response.

I propose adding the following test case:

    @reap_threads
    def test_line_termination(self):

        class BadNewlineHandler(SimpleIMAPHandler):

            def cmd_CAPABILITY(self, tag, args):
                self._send(b'* CAPABILITY IMAP4rev1 AUTH\n')
                self._send('{} OK CAPABILITY
completed\r\n'.format(tag).encode('ASCII'))

        with self.reaped_server(BadNewlineHandler) as server:
            self.assertRaises(imaplib.IMAP4.abort,
                              self.imap_class, *server.server_address)

Which silently misreads the CAPABILITY response as including "AUT" and
not "AUTH". It would be a perversely broken server, but I think this
test case demonstrates why an explicit check and exception should be
thrown always.
msg96186 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-10 01:13
Unfortunately, the SocketServer patches introduced other issues (see for
example issue 6381).  So I'm reluctant to backport those changes, since
as you say no one had reported problems.  It seems like the chance of
inadvertently breaking someone's working 2.6 code is too high given the
absence of any actual bug report that we'd be fixing.

So I'm inclined to go with your revised test for the 2.6 backport of
this bugfix.
msg96187 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-10 02:09
Committed to py3k in r76730 with the suggested additional test.
msg96300 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-12-12 18:47
Patch modified to skip ssl tests if ssl not available in r76727 in
trunk; that changeset included in all merges.  p3k merge in r76730 as
stated.  2.6 merge in r76761, using the 2.6 patch provided by Scott. 
3.1 merge in r76762.
History
Date User Action Args
2010-06-17 13:03:57r.david.murraylinkissue9010 superseder
2009-12-12 18:47:24r.david.murraysetstatus: open -> closed
resolution: fixed
messages: + msg96300

stage: commit review -> resolved
2009-12-10 02:09:11r.david.murraysetmessages: + msg96187
2009-12-10 01:13:56r.david.murraysetmessages: + msg96186
2009-12-09 19:49:12scott.dialsetmessages: + msg96180
2009-12-09 18:49:44r.david.murraysetfiles: + test_imaplib_issue5949_py3k.patch

messages: + msg96179
2009-12-09 18:34:46scott.dialsetfiles: + socketserver_issue_6267.patch

messages: + msg96178
2009-12-09 18:24:45scott.dialsetmessages: + msg96177
2009-12-09 18:08:00r.david.murraysetmessages: + msg96176
2009-12-09 17:26:58scott.dialsetfiles: - test_imaplib_issue5949-py26.patch
2009-12-09 17:26:49scott.dialsetfiles: + test_imaplib_issue5949-py26.patch

messages: + msg96174
2009-12-09 17:06:02scott.dialsetfiles: - test_imaplib_issue5949-py26.patch
2009-12-09 17:05:56scott.dialsetfiles: + test_imaplib_issue5949-py26.patch
2009-12-09 16:47:02scott.dialsetfiles: + test_imaplib_issue5949-py26.patch
2009-12-09 16:42:43r.david.murraysetmessages: + msg96172
2009-12-09 15:31:43r.david.murraysetmessages: + msg96170
stage: patch review -> commit review
2009-12-07 17:15:04scott.dialsetfiles: - imaplib-eof-test.py
2009-12-07 17:14:56scott.dialsetfiles: - test_imaplib_issue5949-2.patch
2009-12-07 17:14:52scott.dialsetfiles: - test_imaplib-r76683-2.patch
2009-12-07 17:14:44scott.dialsetfiles: - test_imaplib-r76683.patch
2009-12-07 17:13:06r.david.murraysetfiles: - test_imaplib_issue5949.patch
2009-12-07 16:30:21scott.dialsetfiles: + test_imaplib_issue5949-3.patch

messages: + msg96061
2009-12-07 14:48:11r.david.murraysetmessages: + msg96052
2009-12-07 14:22:19scott.dialsetfiles: + test_imaplib_issue5949-2.patch

messages: + msg96050
2009-12-06 20:42:40r.david.murraysetfiles: + test_imaplib_issue5949.patch

messages: + msg96039
2009-12-06 20:41:45r.david.murraysetassignee: r.david.murray
messages: + msg96038
2009-12-06 17:05:10scott.dialsetfiles: + test_imaplib-r76683-2.patch

messages: + msg96031
2009-12-06 16:33:41r.david.murraysetmessages: + msg96030
2009-12-06 16:32:08r.david.murraysetmessages: + msg96029
2009-12-06 16:31:18scott.dialsetmessages: + msg96028
2009-12-06 16:25:20r.david.murraysetmessages: + msg96027
2009-12-06 16:23:12r.david.murraysetnosy: + r.david.murray
messages: + msg96025
2009-12-06 07:25:39scott.dialsetfiles: - test_imaplib-r76683.patch
2009-12-06 07:25:34scott.dialsetfiles: + test_imaplib-r76683.patch
2009-12-06 07:23:59scott.dialsetfiles: - test_imaplib-r76683.patch
2009-12-06 07:23:53scott.dialsetfiles: + test_imaplib-r76683.patch
2009-12-06 07:22:05scott.dialsetfiles: + test_imaplib-r76683.patch

messages: + msg96021
2009-12-06 04:29:00benjamin.petersonsetmessages: + msg96020
2009-12-06 04:19:45scott.dialsetfiles: + imaplib-eof-test.py

messages: + msg96019
2009-12-06 03:26:54benjamin.petersonsetassignee: janssen -> (no value)
messages: + msg96018
2009-12-06 02:59:31scott.dialsetfiles: - imaplib-r75166.patch
2009-12-06 02:59:22scott.dialsetfiles: + imaplib-r76683.patch

messages: + msg96017
2009-12-05 22:01:31benjamin.petersonsetnosy: + benjamin.peterson
messages: + msg96010
2009-11-18 20:29:32pitrousetassignee: janssen
versions: + Python 3.2, - Python 3.0

nosy: + janssen
stage: patch review
2009-11-18 12:06:26ncoghlansetpriority: high
2009-11-18 12:06:17ncoghlansetassignee: barry -> (no value)
messages: + msg95424
2009-10-07 18:08:40barrysetmessages: + msg93708
2009-10-05 21:24:43rhettingersetassignee: barry

messages: + msg93621
nosy: + rhettinger
2009-10-01 12:20:27barrysetassignee: barry -> (no value)
messages: + msg93402
2009-10-01 11:07:15ncoghlansetassignee: barry

messages: + msg93401
nosy: + barry, ncoghlan
2009-10-01 07:41:49scott.dialsetfiles: + imaplib-r75166.patch
2009-10-01 07:41:36scott.dialsetfiles: - imaplib-r75166.patch
2009-10-01 07:37:15scott.dialsetfiles: + imaplib-r75166.patch

nosy: + scott.dial
messages: + msg93392

keywords: + patch
2009-08-17 13:09:30rtuckersetnosy: + rtucker
messages: + msg91663
2009-05-07 21:31:25kevinwatterssetmessages: + msg87410
2009-05-07 04:24:13rmoresetnosy: + rmore
messages: + msg87359
2009-05-06 15:45:39kevinwatterscreate