thread vs threading -- Unexpected Results

Discussion in 'Python' started by CK, Dec 4, 2003.

  1. CK

    CK Guest

    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
     
    CK, Dec 4, 2003
    #1
    1. Advertising

  2. "CK" <> wrote in message
    news:...

    > 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
     
    Krzysztof Stachlewski, Dec 4, 2003
    #2
    1. Advertising

  3. CK

    CK Guest

    "Krzysztof Stachlewski" <> wrote in message news:<bqn9no$qp6$>...
    > "CK" <> wrote in message
    > news:...
    >
    > > Program A - thread example
    > >

    .... 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"



    > > Program B - threading example

    .....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, Dec 5, 2003
    #3
  4. CK

    CK Guest

    (CK) wrote in message news:<>...
    > "Krzysztof Stachlewski" <> wrote in message news:<bqn9no$qp6$>...
    > > "CK" <> wrote in message

    ....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
     
    CK, Dec 6, 2003
    #4
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. Scott Lander

    Re: unexpected results

    Scott Lander, Jul 7, 2003, in forum: Perl
    Replies:
    0
    Views:
    1,751
    Scott Lander
    Jul 7, 2003
  2. Dave
    Replies:
    1
    Views:
    349
    Leor Zolman
    Apr 8, 2004
  3. =?Utf-8?B?QXJ0?=

    Page inherting from .master - unexpected results

    =?Utf-8?B?QXJ0?=, May 26, 2006, in forum: ASP .Net
    Replies:
    0
    Views:
    372
    =?Utf-8?B?QXJ0?=
    May 26, 2006
  4. Jerry Sievers

    thread, threading; how to kill a thread?

    Jerry Sievers, Nov 17, 2004, in forum: Python
    Replies:
    12
    Views:
    1,184
    Mustafa Demirhan
    Nov 19, 2004
  5. Steven D'Aprano

    Unexpected timing results

    Steven D'Aprano, Feb 23, 2006, in forum: Python
    Replies:
    7
    Views:
    417
    Steven D'Aprano
    Feb 24, 2006
Loading...

Share This Page