Roundup Tracker - Issues

Issue 2550750

classification
Title: Handling of socket timeouts
Type: behavior Severity: normal
Components: Web interface Versions: devel
process
Status: new Resolution:
Dependencies: Superseder:
Assigned To: rouilj Nosy List: ber, jerrykan, joseph_myers, rouilj
Priority: normal Keywords: patch

Created on 2012-03-18 21:30 by joseph_myers, last changed 2016-06-19 03:25 by rouilj.

Files
File name Uploaded Description Edit Remove
no-timeout-mail-patch joseph_myers, 2012-03-18 21:30 patch to socket error handling
Messages
msg4518 Author: [hidden] (joseph_myers) Date: 2012-03-18 21:30
Roundup tries to detect certain network errors and not report them to
the tracker admin (roundup/cgi/client.py, IGNORE_NET_ERRORS).  This does
not work reliably for timeouts, which produce the socket.timeout
exception rather than socket.error with ETIMEDOUT.

The attached patch deals with this by checking for socket.timeout before
socket.error.
msg4519 Author: [hidden] (ber) Date: 2012-03-19 08:28
Joseph,
thanks for the report and the patch.
Next step would be to get another person to confirm both.

Do you know an easy way to reproduce the issue for testing?
Bernhard
msg4520 Author: [hidden] (joseph_myers) Date: 2012-03-19 09:10
I don't have a way of reproducing timeouts on demand.  I generally 
observed the timeout exceptions being reported for large static images 
served through Roundup (and empirically observed that the exception emails 
did not appear for a month of having the patch installed, having been 
quite frequent before then).
msg5596 Author: [hidden] (rouilj) Date: 2016-06-12 00:36
I tried a few ways to get the timeout to trigger (suspending wget in the
middle of an attachment or page download etc.) with no luck.

Per:

    https://docs.python.org/2/library/socket.html

=====
 exception socket.timeout
    This exception is raised when a timeout occurs on a socket which has
had timeouts enabled via a prior call to settimeout(). The accompanying
value is a string whose value is currently always “timed out”.
[...]
Some notes on socket blocking and timeouts: A socket object can be in
one of three modes: blocking, non-blocking, or timeout. Sockets are
always created in blocking mode. In blocking mode, operations block
until complete or the system returns an error (such as connection timed
out). In non-blocking mode, 
====

I can't find a call to settimeout anywhere in the roundup code. The fact
that blocking mode can return a timeout seems well wrong.

However checking out the code in hg as of: 2012-08-27 also shows no
settimeout, so .... However settimeout was new in python 2.3. I don't
know if something changed in python that would make this patch obsolete.
msg5597 Author: [hidden] (joseph_myers) Date: 2016-06-12 00:47
The timeout is from the socket.setdefaulttimeout(60) call in 
roundup_server.py.
msg5599 Author: [hidden] (rouilj) Date: 2016-06-12 01:43
Thanks to Joseph's pointer I changed the default timeout to 0.05 and
ran demo.py. I also added print statements to all the exception code
near the patch.

When downloading a 25MB file (loaded prior to changing the timeout)

I now see:

  In handler socket.error
  timed out
  raising exception

indicating that the timeout exception is re-raised by the existing
code. The "timed out" is from printing the exception (print err).

I applied patch (with a mod to define err) and I get:

  In handler socket.timeout
  timed out

Note that I am not seeing any attempt to send email in either case
(the tracker is configured with MAIL_DEBUG=log.email.txt). So I am not
sure if something else is broken. But if raising the socket.error does
generate email, this patch does seem to stop it.

Bernhard is this a good enough investigation to let the patch proceed?

-- rouilj
msg5600 Author: [hidden] (ber) Date: 2016-06-13 08:23
Hi John,
good work on succeeding to get this reproduced at your side.

My knowledge on how this networking should work regarding
timeouts is limited. If you are saying that ignoring this timeout
is fine, please commit. My suggestion is to add a comment 
with a bit of explanation why it is the wanted behaviour.

Thanks,
Bernhard
History
Date User Action Args
2016-06-19 03:25:39rouiljsetassignee: rouilj
2016-06-13 08:23:48bersetmessages: + msg5600
2016-06-12 01:43:11rouiljsetmessages: + msg5599
2016-06-12 00:47:38joseph_myerssetmessages: + msg5597
2016-06-12 00:36:42rouiljsetnosy: + rouilj
messages: + msg5596
2012-08-28 03:48:08jerrykansetnosy: + jerrykan
2012-03-19 09:10:28joseph_myerssetmessages: + msg4520
2012-03-19 08:28:54bersetpriority: normal
nosy: + ber
messages: + msg4519
keywords: + patch
2012-03-18 21:30:57joseph_myerscreate