Saturday, August 1, 2009

Okay, so that's done... but we're stuck with a hanging thread [HALP!]

The full TCP exchange of 3-way-handshake, data transfer (with acknowledgement) and active-close (Established -> Fin Wait 1 -> Fin Wait 2 -> Time Wait) has been successfully tested, and works fine.

Here's the script, and subsequent output:

import testconfig
from tcpstatemachine import *
from threading import Thread
from testserver import runServer
from multiprocessing import Process

def test():
t = TcpStateMachine()
t.die = False

serverProcess = Process(target=runServer)
serverProcess.start()

t.open()
t.send('COOOOOOOL!')
t.close()

serverProcess.terminate()

>>> import test
2009-08-01 17:35:18,212 - tcpFilter - INFO - Opened lo0
>>> test.test()
2009-08-01 17:35:19,867 - TcpStateMachine - DEBUG - __init__ - (('127.0.0.3', 31765), ('127.0.0.1', 32261))
2009-08-01 17:35:19,870 - tcpFilter - DEBUG - openInterface - Tried to re-open same interface: lo0
2009-08-01 17:35:19,870 - tcpFilter - INFO - Opened lo0
2009-08-01 17:35:19,870 - TcpStateMachine - INFO - Local host: 127.0.0.3:31765
2009-08-01 17:35:19,871 - TcpStateMachine - INFO - Remote host: 127.0.0.1:32261
~~~~~ In runServer
~~~~~ Listening on 127.0.0.1:32261
~~~~~ Waiting for accepted connection
2009-08-01 17:35:19,950 - TcpStateMachine - DEBUG - open - In valid state to open connection
2009-08-01 17:35:19,967 - TcpStateMachine - DEBUG - open - Generated ISS: 1036344287
2009-08-01 17:35:19,969 - TcpStateMachine - DEBUG - open - Sending SYN packet
2009-08-01 17:35:19,975 - TcpStateMachine - STATE - Setting state from Closed to Syn-Sent
2009-08-01 17:35:19,976 - TcpRecvDaemon - INFO - Starting receive thread for object TcpStateMachine( (127.0.0.3,31765), (127.0.0.1,32261) )
2009-08-01 17:35:19,977 - TcpSendDaemon - INFO - Starting send thread for object TcpStateMachine( (127.0.0.3,31765), (127.0.0.1,32261) )
2009-08-01 17:35:19,980 - TcpStateMachine - DEBUG - open - Waiting for state == ESTABLISHED... Outbound Sequenes: segmentBuffer(limit=4294967296,base=1036344287,copyList=['[SYN]']+[])
2009-08-01 17:35:20,047 - TcpSendDaemon - DEBUG - sendThread - Sending items 1036344287 to 1036345633 in ['[SYN]']
2009-08-01 17:35:20,049 - TcpSendDaemon - DEBUG - sendThread - Sending sequences 1036344287 to 1036344288: ['[SYN]']
2009-08-01 17:35:20,050 - TcpSendDaemon - DEBUG - sendThread - Haz a SYN!
2009-08-01 17:35:20,054 - TcpStateMachine - SENT - [<class tcp Seq: 1036344287, 31765->32261, [S], reserved: 0, checksum: 7711, offset: 5, window: 65535L>,
<class payload {payload: ''}>]
2009-08-01 17:35:20,484 - TcpStateMachine - INFO - Segment arrived!
2009-08-01 17:35:20,485 - TcpStateMachine - RECVD - [<class tcp Seq: 1883201111, 32261->31765, [AS], reserved: 0, checksum: 65058, offset: 6, window: 65535, ack_number: 1036344288>]
2009-08-01 17:35:20,487 - TcpStateMachine - DEBUG - debugWithState - [Syn-Sent] IN SYN_SENT
2009-08-01 17:35:20,489 - TcpStateMachine - DEBUG - debugWithState - [Syn-Sent] Has ACK
2009-08-01 17:35:20,490 - TcpStateMachine - DEBUG - debugWithState - [Syn-Sent] Accepted ACK
2009-08-01 17:35:20,492 - TcpStateMachine - DEBUG - debugWithState - [Syn-Sent] Has SYN and either good ACK or no ACK
2009-08-01 17:35:20,492 - TcpStateMachine - STATE - Setting state from Syn-Sent to Established
Sending ack: {seq: 1036344288, ack: 1, ack#: 1883201112}
2009-08-01 17:35:20,497 - TcpStateMachine - SENT - [<class tcp Seq: 1036344288, 31765->32261, [A], reserved: 0, checksum: 20344, offset: 5, window: 65535L, ack_number: 1883201112L>]
~~~~~ Connected
~~~~~ Waiting on Data
2009-08-01 17:35:20,499 - TcpStateMachine - DEBUG - open - Established
2009-08-01 17:35:20,507 - TcpSendDaemon - DEBUG - sendThread - Sending items 1036344288 to 1036345634 in ['C', 'O', 'O', 'O', 'O', 'O', 'O', 'O', 'L', '!', 'C', 'O', 'O', 'O', 'O', 'O', 'O', 'O', 'L', '!']
2009-08-01 17:35:20,508 - TcpSendDaemon - DEBUG - sendThread - Sending sequences 1036344288 to 1036344308: ['C', 'O', 'O', 'O', 'O', 'O', 'O', 'O', 'L', '!', 'C', 'O', 'O', 'O', 'O', 'O', 'O', 'O', 'L', '!']
2009-08-01 17:35:20,511 - TcpStateMachine - SENT - [<class tcp Seq: 1036344288, 31765->32261, [A], reserved: 0, checksum: 21671, offset: 5, window: 65535L, ack_number: 1883201112L>,
<class payload {payload: 'COOOOOOOL!COOOOOOOL!'}>]
Received Data: COOOOOOOL!COOOOOOOL!
~~~~~ Waiting on Data
2009-08-01 17:35:21,008 - TcpStateMachine - INFO - Segment arrived!
2009-08-01 17:35:21,009 - TcpStateMachine - RECVD - [<class tcp Seq: 1883201112, 32261->31765, [A], reserved: 0, checksum: 65054, offset: 5, window: 65535, ack_number: 1036344308>]
2009-08-01 17:35:21,009 - TcpStateMachine - ERROR - This point should never be reached!
2009-08-01 17:35:21,059 - TcpStateMachine - STATE - Setting state from Established to Fin-Wait-1
2009-08-01 17:35:22,021 - TcpSendDaemon - DEBUG - sendThread - Sending items 1036344308 to 1036345654 in ['[FIN]']
2009-08-01 17:35:22,023 - TcpSendDaemon - DEBUG - sendThread - Sending sequences 1036344308 to 1036344309: ['[FIN]']
2009-08-01 17:35:22,024 - TcpSendDaemon - DEBUG - sendThread - Haz an FIN!
2009-08-01 17:35:22,028 - TcpStateMachine - SENT - [<class tcp Seq: 1036344308, 31765->32261, [AF], reserved: 0, checksum: 20323, offset: 5, window: 65535L, ack_number: 1883201112L>,
<class payload {payload: ''}>]
Received Data:
~~~~~ No more data
2009-08-01 17:35:23,016 - TcpStateMachine - INFO - Segment arrived!
2009-08-01 17:35:23,017 - TcpStateMachine - RECVD - [<class tcp Seq: 1883201112, 32261->31765, [A], reserved: 0, checksum: 65054, offset: 5, window: 65535, ack_number: 1036344309>]
2009-08-01 17:35:23,019 - TcpStateMachine - DEBUG - debugWithState - [Fin-Wait-1] Our FIN is ACKed
2009-08-01 17:35:23,019 - TcpStateMachine - STATE - Setting state from Fin-Wait-1 to Fin-Wait-2
2009-08-01 17:35:23,020 - TcpStateMachine - ERROR - This point should never be reached!
2009-08-01 17:35:23,023 - TcpStateMachine - INFO - Segment arrived!
2009-08-01 17:35:23,024 - TcpStateMachine - RECVD - [<class tcp Seq: 1883201112, 32261->31765, [AF], reserved: 0, checksum: 65054, offset: 5, window: 65535, ack_number: 1036344309>]
2009-08-01 17:35:23,025 - TcpStateMachine - DEBUG - debugWithState - [Fin-Wait-2] connection closing
2009-08-01 17:35:23,027 - TcpStateMachine - DEBUG - debugWithState - [Fin-Wait-2] sending ACK of FIN
Sending ack: {seq: 1036344309, ack: 1, ack#: 1883201113}
2009-08-01 17:35:23,029 - TcpStateMachine - SENT - [<class tcp Seq: 1036344309, 31765->32261, [A], reserved: 0, checksum: 20322, offset: 5, window: 65535L, ack_number: 1883201113L>]
2009-08-01 17:35:23,030 - TcpStateMachine - STATE - Setting state from Fin-Wait-2 to Time-Wait
2009-08-01 17:35:23,031 - TcpStateMachine - DEBUG - debugWithState - [Time-Wait] Starting TIME_WAIT timer
2009-08-01 17:35:24,035 - TcpSendDaemon - DEBUG - sendThread - Quitting send thread
2009-08-01 17:35:33,032 - TcpStateMachine - STATE - Setting state from Time-Wait to Closed

It's a bit more verbose than it needs to be, and there's a few things that will be taken out (i.e. "Haz a SYN!") but overall I'm pleased with the way it works.

However, the only remaining problem before the real-real test-writing gets going is that the call to retrieve the next packet from PCAP is a blocking call that's performed by a Python thread (which has no terminate() or equivalent method).

Looking into the issue a bit, pypcap has a "setnonblock(nonblock=True)" method, but due to the way everything is done, this isn't quite so easy to work with (there are also some bug reports that say that this functionality doesn't necessarily work as expected).


Read more...

No comments:

Post a Comment

Followers