thread vs threading -- Unexpected Results

[CK]

I am a "newbie" to python and today I had the need to
write a program which generated a lot of tcp connections
to a range of addresses (10.34.32.0/22) in order to
troubleshoot a problem with a switch. I also wanted
to get familiar with threads under python and so I
thought I could do both at the same time. I wrote
two programs - one using thread and one using threading
but the results between the two were unexpected and quite
different. I was hoping that someone could shed some
light on why there is such a difference.

Program A - thread example

#!/usr/local/bin/python

import socket
import time
import thread

def tcp_connect(dst_ip,dst_port):
print "%s Connecting to %s on port %d" %
(time.asctime(),dst_ip,dst_port)
s = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
try:
s.connect((dst_ip,dst_port))
except:
pass
s.close()
print "%s Disconnecting from %s on port %d" %
(time.asctime(),dst_ip,dst_port)

for x in range(0,2):
for octet3 in range(32,36):
for octet4 in range(0,256):
ip_addr = "10.34."+str(octet3)+"."+str(octet4)
thread.start_new_thread(tcp_connect,(ip_addr,135))

produces the following output

pus-bin[49]% ./tcp_connector.py
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.0 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.5 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.10 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.15 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.20 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.25 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.24 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.23 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.22 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.21 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.19 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.18 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.17 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.16 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.14 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.13 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.12 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.11 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.9 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.8 on port 135
Wed Dec 3 21:36:01 2003 Connecting to 10.34.32.7 on port 135
....etc...

At most I see only 2 Disconnecting prints. I would have
expected to see Disconnect prints intermingled in the output.
In fact I don't see any Disconnecting prints (other than the two).
Why is this?

And now for something completely different....

Program B - threading example

#!/usr/local/bin/python

import socket
import time
import threading

class connector(threading.Thread):
def __init__(self,dst_ip,dst_port):
self.dst_ip = dst_ip
self.dst_port = dst_port
threading.Thread.__init__(self)
def run(self):
print "%s Connecting to %s on port %d" %
(time.asctime(),self.dst_ip,self.dst_port)
self.s = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
try:
self.s.connect((dst_ip,dst_port))
except:
pass
self.s.close()
print "%s Disconnecting from %s on port %d" %
(time.asctime(),self.dst_ip,self.dst_port)

threadlist = []
for x in range(0,4):
for octet3 in range(32,36):
for octet4 in range(0,256):
ip_addr = "10.34."+str(octet3)+"."+str(octet4)
thread = connector(ip_addr,135)
thread.start()
threadlist.append(thread)

for thread in threadlist:
thread.join()

print "Main thread exitting"

which produces the following output...

Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.0 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.0 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.1 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.1 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.2 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.2 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.3 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.3 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.4 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.4 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.5 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.5 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.6 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.6 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.7 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.7 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.8 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.8 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.9 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.9 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.10 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.10 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.11 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.11 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.12 on port 135
Wed Dec 3 21:56:42 2003 Disconnecting from 10.34.32.12 on port 135
Wed Dec 3 21:56:42 2003 Connecting to 10.34.32.13 on port 135
..... etc ...

Now in the threading example I have Connect / Disconnect pairs for the
whole cycle. I would have expected multiple Connects here and there
and multiple Disconnects appearing here and there but it looks like
at most only two threads are ever active (main + one). Why don't
I see multiple Connects / Disconnects??

Thanks.
../CK

 

[Krzysztof Stachlewski]

Program A - thread example

#!/usr/local/bin/python

import socket
import time
import thread

def tcp_connect(dst_ip,dst_port):
print "%s Connecting to %s on port %d" %
(time.asctime(),dst_ip,dst_port)
s = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
try:
s.connect((dst_ip,dst_port))
except:
pass
s.close()
print "%s Disconnecting from %s on port %d" %
(time.asctime(),dst_ip,dst_port)

for x in range(0,2):
for octet3 in range(32,36):
for octet4 in range(0,256):
ip_addr = "10.34."+str(octet3)+"."+str(octet4)
thread.start_new_thread(tcp_connect,(ip_addr,135))

After the loop completes, the main thread terminates
and so your whole program. You don't wait for the threads
to finish.

Program B - threading example
[...]
for thread in threadlist:
thread.join()

print "Main thread exitting"

And in this program you wait for the threads.

Now in the threading example I have Connect / Disconnect pairs for the
whole cycle. I would have expected multiple Connects here and there
and multiple Disconnects appearing here and there but it looks like
at most only two threads are ever active (main + one). Why don't
I see multiple Connects / Disconnects??

In your threads' code you put the s.close() immediately after s.connect().
The connections are closed very quickly. This time is so short
that the scheduler did not switched tasks.
Why you see a different pattern of calls I cannot tell.
Probably an artefact of the task scheduler?
I would not worry about this. All of your
operations completed within one second.
Try to put something - at least a delay - between
connect() and close() and see how it works.

Stach

 

[CK]

.... snip ...

After the loop completes, the main thread terminates
and so your whole program. You don't wait for the threads
to finish.

Good point. I added code to check for this (a la Programming
Python by Mark Lutz) but the results are really strange. All I see are
Connecting messages and never a disconnecting message and
so now the whole program hangs waiting for these "hung"
threads to wake up.

Here is the revised "thread" code

#!/usr/local/bin/python

import socket
import time
import thread

threadlist = [0] * 2048
threadId = -1
def tcp_connect(dst_ip,dst_port,thisId):
print "%s Connecting to %s on port %d ThreadId=%d" % (time.asctime(),dst_ip,d
st_port,thisId)
s = socket.socket(socket.AF_INET,socket.SOCK_STREAM)
try:
s.connect((dst_ip,dst_port))
except:
pass
s.close()
threadlist[thisId] = 1
print "%s Disconnecting from %s on port %d" % (time.asctime(),dst_ip,dst_port)

for x in range(0,2):
for octet3 in range(32,36):
for octet4 in range(0,256):
threadId = threadId + 1
ip_addr = "10.34."+str(octet3)+"."+str(octet4)
thread.start_new_thread(tcp_connect,(ip_addr,135,threadId))

while 0 in threadlist:
time.sleep(2)

print "Main thread exitting"

and here is some sample output....

Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.0 on port 135 ThreadId=0
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.5 on port 135 ThreadId=5
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.6 on port 135 ThreadId=6
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.7 on port 135 ThreadId=7
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.8 on port 135 ThreadId=8
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.9 on port 135 ThreadId=9
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.10 on port 135 ThreadId=10
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.11 on port 135 ThreadId=11
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.12 on port 135 ThreadId=12
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.13 on port 135 ThreadId=13
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.14 on port 135 ThreadId=14
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.15 on port 135 ThreadId=15
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.16 on port 135 ThreadId=16
....

Never see a Disconnecting message, never see "Main thread exitting"

.....snip....
The connections are closed very quickly. This time is so short
that the scheduler did not switched tasks.
Why you see a different pattern of calls I cannot tell.
Probably an artefact of the task scheduler?
I would not worry about this. All of your
operations completed within one second.
Try to put something - at least a delay - between
connect() and close() and see how it works.

You are correct on this one. I added a time.sleep(2) just
before the close and I got results that one would expect.

I don't know what I am doing wrong in the 'thread' example
but the 'threading' example works just fine.

Thank you for your help Stach.

../CK

 

[CK]

....snip

Good point. I added code to check for this (a la Programming
Python by Mark Lutz) but the results are really strange. All I see are
Connecting messages and never a disconnecting message and
so now the whole program hangs waiting for these "hung"
threads to wake up.
....snip

and here is some sample output....

Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.0 on port 135 ThreadId=0
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.5 on port 135 ThreadId=5
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.6 on port 135 ThreadId=6
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.7 on port 135 ThreadId=7
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.8 on port 135 ThreadId=8
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.9 on port 135 ThreadId=9
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.10 on port 135 ThreadId=10
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.11 on port 135 ThreadId=11
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.12 on port 135 ThreadId=12
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.13 on port 135 ThreadId=13
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.14 on port 135 ThreadId=14
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.15 on port 135 ThreadId=15
Fri Dec 5 06:54:12 2003 Connecting to 10.34.32.16 on port 135 ThreadId=16
...

Never see a Disconnecting message, never see "Main thread exitting"

Well it turns out that if I wait long enough (namely 4 minutes) all
the Disconnecting messages come out at once. I seem to recall that
4 minutes has something to do with the TCP/IP Maximum Segment Life
or something like that. I don't know why sockets under 'thread'
work differently from sockets under 'threading'. The code used to
generate the socket connections is the same in both instances.

Quite odd.

../CK