Bug 253264 - urllib2 http timeouts
urllib2 http timeouts
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: python (Show other bugs)
5.0
All Linux
low Severity low
: ---
: ---
Assigned To: James Antill
Brock Organ
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2007-08-17 12:47 EDT by daryl herzmann
Modified: 2008-08-02 19:40 EDT (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-02-08 10:16:42 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
test.py script to do a simple query against the cam (2.07 KB, text/x-python)
2007-08-17 12:47 EDT, daryl herzmann
no flags Details
wireshark trace from a simple HTTP GET / (1.74 KB, text/plain)
2007-08-17 12:48 EDT, daryl herzmann
no flags Details
the real test.py, oye (353 bytes, text/plain)
2007-08-17 12:52 EDT, daryl herzmann
no flags Details
wireshark log from working RHEL4 client (2.92 KB, text/plain)
2007-08-17 15:53 EDT, daryl herzmann
no flags Details
wireshark log from non-working RHEL5 python script. (1.90 KB, text/plain)
2007-08-17 16:12 EDT, daryl herzmann
no flags Details

  None (edit)
Description daryl herzmann 2007-08-17 12:47:06 EDT
Since RHEL3, I have written a python library now using urllib2 to communicate
with a network of Canon VB-C10 and VB-C50i internet cameras.  On RHEL5, I can't
communicate with a handful of them and almost every time get timeouts.  Now, I
am not sure that the issue is with python, since Firefox has the same issue on
RHEL5.  But the python reproducer is easy and it does work on rhel4.

I'll attach a script that can be run against on of these webcams.  It times out
on RHEL5 and works on RHEL4.  I have had a number of friends reproduce this as
well on their systems. 

I appologize if this is a goose chase or if this should be filed against another
component.  I'm about to wits end :)  Another user sort of confirmed this
problem on the rhelv5 list:

http://www.redhat.com/archives/rhelv5-list/2007-August/msg00063.html

I'll also attach a wireshark trace.

thanks so much!
  daryl
Comment 1 daryl herzmann 2007-08-17 12:47:06 EDT
Created attachment 161754 [details]
test.py script to do a simple query against the cam
Comment 2 daryl herzmann 2007-08-17 12:48:33 EDT
Created attachment 161755 [details]
wireshark trace from a simple HTTP GET /

Here is a wireshark trace  showing this problem.
Comment 3 daryl herzmann 2007-08-17 12:52:43 EDT
Created attachment 161756 [details]
the real test.py, oye
Comment 4 James Antill 2007-08-17 15:47:58 EDT
 So the wireshark trace is from firefox?
 Does the camera respond correctly when given an unauthenticated http request?
 The TCP trace shows that the remote host got the firefox request fine, but then
the response didn't make it back. Can we get a trace from a working (RHEL4) machine.
Comment 5 daryl herzmann 2007-08-17 15:53:26 EDT
Created attachment 161764 [details]
wireshark log from working RHEL4 client
Comment 6 daryl herzmann 2007-08-17 16:12:29 EDT
Created attachment 161769 [details]
wireshark log from non-working RHEL5 python script.

There is one stray packet, sorry didn't know how to remove it from the dump.
Comment 7 daryl herzmann 2007-08-17 16:18:14 EDT
Hi,  Thanks for the help.

Yeah, the trace was from firefox.  I've attached two now from python

Turning off access control doesn't help.  Good test tho.

thanks!
Comment 8 daryl herzmann 2007-08-30 10:55:10 EDT
Were you able to reproduce this bug by running the script on EL4 and then EL5?
Just curious if it is something on my end or you are seeing it to...

thanks!
  daryl
Comment 9 Brad Scalio 2007-09-19 18:11:33 EDT
Greetings

Did this go anywhere, we just updated to 2.6.9-55.0.2.ELsmp and are experiencing
TIME_WAIT connections on port 80 as well, which eventuall cripple the system ...
the ephermeral ports aren't getting recycled/closed ... we were running
2.6.9-42.19.ELsmp before this and had no problems, so it was between the upgrade
from those two kerneles, I think 42.19 is RHEL4u2 and 55.0.2 is RHEL4u5 but I
may be mistaken as I don't know the corrosponding release versions to kernel
versions.

Anyway -- some pertinent info we seem to always see it on the httpd port80 when
it connects to a NAS device, we have seen this now on three servers, and with
only port 80

THANKS


Sep 19 18:04:28 px1-ehu portmap[19396]: connect from 10.0.5.4 to
callit(ypserv): request from unauthorized host
Sep 19 18:04:59 px1-ehu sshd(pam_unix)[19738]: session opened for user
root by (uid=0)
Sep 19 18:05:24 px1-ehu pam_rhosts_auth[20601]: allowed to fxa@px1f-ehu
as fxa
Sep 19 18:05:24 px1-ehu rsh(pam_unix)[20601]: session opened for user
fxa by (uid=0)
Sep 19 18:05:25 px1-ehu rsh(pam_unix)[20601]: session closed for user fxa
Sep 19 18:05:48 px1-ehu heartbeat[20737]: info: Checking status of
STONITH device [external STONITH device]
Sep 19 18:05:48 px1-ehu heartbeat[23428]: info: Exiting STONITH-stat
process 20737 returned rc 0.
Sep 19 18:06:07 px1-ehu portmap[21398]: connect from 10.0.4.2 to
callit(ypserv): request from unauthorized host
Sep 19 18:07:32 px1-ehu sshd(pam_unix)[22247]: session opened for user
root by (uid=0)
Sep 19 18:07:53 px1-ehu portmap[22325]: connect from 10.0.5.2 to
callit(ypserv): request from unauthorized host
Sep 19 18:08:01 px1-ehu portmap[22334]: connect from 10.0.5.3 to
callit(ypserv): request from unauthorized host


Sep 19 17:19:27 px1-ehu portmap[9850]: connect from 10.0.5.4 to
callit(ypserv): request from unauthorized host
Sep 19 17:20:00 px1-ehu kernel: RPC: Can't bind to reserved port (98).
Sep 19 17:20:00 px1-ehu kernel: RPC: can't bind to reserved port.
Sep 19 17:20:01 px1-ehu kernel: RPC: error 5 connecting to server nas1
Sep 19 17:20:01 px1-ehu kernel: nfs_statfs: statfs error = 5
Sep 19 17:20:01 px1-ehu kernel: RPC: Can't bind to reserved port (98).
Sep 19 17:20:01 px1-ehu kernel: RPC: can't bind to reserved port.
Sep 19 17:20:01 px1-ehu kernel: RPC: error 5 connecting to server nas1
Sep 19 17:20:01 px1-ehu kernel: nfs_statfs: statfs error = 5
Sep 19 17:20:01 px1-ehu kernel: RPC: Can't bind to reserved port (98).
Sep 19 17:20:01 px1-ehu kernel: RPC: can't bind to reserved port.
Sep 19 17:20:01 px1-ehu kernel: RPC: error 5 connecting to server nas1
Sep 19 17:20:01 px1-ehu kernel: nfs_statfs: statfs error = 5

Sep 19 16:27:47 px1-ehu xinetd: xinetd -HUP succeeded
Sep 19 16:27:48 px1-ehu xinetd[2500]: Swapping defaults
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service auth
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service printer
A
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service exec
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service login
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service shell
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service rsync
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service telnet
Sep 19 16:27:48 px1-ehu xinetd[2500]: readjusting service tftp
Sep 19 16:27:48 px1-ehu xinetd[2500]: Reconfigured: new=0 old=8
dropped=0 (services)
Sep 19 16:30:02 px1-ehu heartbeat[4837]: info: Checking status of
STONITH device [external STONITH device]
Sep 19 16:30:02 px1-ehu heartbeat[25009]: info: Exiting STONITH-stat
process 4837 returned rc 0.
Sep 19 16:31:22 px1-ehu xinetd[2500]: Starting reconfiguration
Sep 19 16:31:22 px1-ehu xinetd: xinetd -HUP succeeded
Sep 19 16:31:23 px1-ehu xinetd[2500]: Swapping defaults
Sep 19 16:31:23 px1-ehu xinetd[2500]: readjusting service auth
Sep 19 16:31:23 px1-ehu xinetd[2500]: readjusting service printer
Sep 19 16:31:23 px1-ehu xinetd[2500]: readjusting service exec
Sep 19 16:31:23 px1-ehu xinetd[2500]: readjusting service login
Sep 19 16:31:23 px1-ehu xinetd[2500]: readjusting service shell
-- INSERT --                                                          
                                                               
4290151,2     99%



==========================================================
NETSTAT -TUNAPE OUTPUT ===================================
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35105  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35106  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35107  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35108  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35109  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35110  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35111  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35112  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35113  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35114  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35115  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35116  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35117  TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.63:35118  TIME_WAIT   0          0          -       
         
tcp        0    352 ::ffff:165.92.219.7:22    
::ffff:165.92.219.1:49107   ESTABLISHED 0          170630     16478/1 
         
tcp        0      0 ::ffff:165.92.219.7:35087 
::ffff:165.92.219.65:5432   TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36219 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36218 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36217 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36216 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36223 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36222 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36221 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36220 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36211 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36215 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36214 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36213 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36212 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36243 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36242 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36241 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36240 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36244 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36235 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36234 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36233 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36232 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36239 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36238 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36237 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36236 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36227 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36226 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36225 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36224 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36231 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36230 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36229 TIME_WAIT   0          0          -       
         
tcp        0      0 ::ffff:165.92.219.63:80   
::ffff:165.92.219.100:36228 TIME_WAIT   0          0          -            

[root@px1-ehu log]# cat /etc/services | grep 80
http            80/tcp          www www-http    # WorldWideWeb HTTP
http            80/udp          www www-http    # HyperText Transfer
Comment 10 daryl herzmann 2007-11-09 09:57:39 EST
Same issue on RHEL5.1 , any word on if this script reproduces the bug at red
hat? thanks! 
daryl
Comment 11 daryl herzmann 2007-12-05 14:45:31 EST
I keep trying to figure out what is happening and continue to see flaky
behaviour.  The reproducing script will work every once in a while and fail
about 80% of the time.  Does it fail for you as well?
Comment 12 James Antill 2008-02-08 09:01:46 EST
 So the two differences I see between comment#5 and comment#6 are:

1. HTTP/1.1 vs. HTTP/1.0
2. Accept-Encoding: identity is passed in RHEL-5.

...#2 really shouldn't affect anything, although real life can be weird. Can you
try telnet'ing to the HTTP port on the remote host and Doing the HTTP request
that RHEL-4 does?

 My guess is that this is some network stack problem, and doing the exact same
request will fail. 
Comment 13 daryl herzmann 2008-02-08 09:37:25 EST
Good day,

Thanks for your help.  Augh, I can't reproduce this error now.  It seems to be
working just fine this morning.

I think your guess about the network stack is correct, as the same issue was
happening in Firefox and when I would test with telnet.  

Sorry, this appears to have been a wild goose chase :(

daryl
Comment 14 James Antill 2008-02-08 10:16:42 EST
 No problem.

Note You need to log in before you can comment on or make changes to this bug.