SIP SIMPLE Client SDK

= SIPIT 29 =

== Sending BYE exception when using TCP transport ==

The problem occurs when proxy is stateless and is requesting authorization for the BYE.

The problem happens with every in-dialog request that gets challenged.

{{{

SENDING: Packet 188, +0:14:23.287009

2011-10-24 11:35:51.825513: 132.177.252.163:51280 -(SIP over tls)-> 132.177.253.22:5061

INVITE sip:ag02@cisco.sipit.net SIP/2.0

Via: SIP/2.0/tls 132.177.252.163:51280;rport;branch=z9hG4bKPjGqaVmgy6QI4hqusA17.VmYbSEjEn1S-y

Max-Forwards: 70

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>

Contact: <sip:doszpemb@132.177.252.163:51544;transport=tls>

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4485 INVITE

Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER

Supported: 100rel, replaces, norefersub

User-Agent: Blink Pro 1.3.1 (MacOSX)

Proxy-Authorization: Digest username="cisco", realm="h1.cisco.sipit.net", nonce="5f8327823b80b7c1ad635e68c6ab5ef8b1ac0010d74c76ea30d139be4b0e", uri="sip:ag02@cisco.sipit.net", response="02829cb450bd6f420e8f980f80dec000", algorithm=MD5, cnonce="WMYZEu5MhMBRJr97hlz3Nxqd9pidFkvZ", opaque="AQAAANXGRIqnJLpaa2+oaGI3teAaoA95", qop=auth, nc=00000001

Content-Type: application/sdp

Content-Length:   269

v=0

o=- 3528437751 3528437751 IN IP4 132.177.252.163

s=Blink Pro 1.3.1 (MacOSX)

c=IN IP4 132.177.252.163

t=0 0

m=audio 50004 RTP/AVP 9 0 101

a=rtcp:50005

a=rtpmap:9 G722/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=sendrecv

RECEIVED: Packet 189, +0:14:23.333731

2011-10-24 11:35:51.872235: 132.177.253.22:5061 -(SIP over tls)-> 132.177.252.163:51280

SIP/2.0 100 Trying

Via: SIP/2.0/tls 132.177.252.163:51280;branch=z9hG4bKPjGqaVmgy6QI4hqusA17.VmYbSEjEn1S-y;received=132.177.252.163;rport=51280;ingress-zone=DefaultZone

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4485 INVITE

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>

Server: TANDBERG/4103 (X7.1PreAlpha29 (TEST SW))

Content-Length: 0

RECEIVED: Packet 190, +0:14:23.380310

2011-10-24 11:35:51.918814: 132.177.253.22:5061 -(SIP over tls)-> 132.177.252.163:51280

SIP/2.0 180 Ringing

Via: SIP/2.0/tls 132.177.252.163:51280;rport=51280;received=132.177.252.163;branch=z9hG4bKPjGqaVmgy6QI4hqusA17.VmYbSEjEn1S-y;ingress-zone=DefaultZone

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4485 INVITE

Contact: <sip:qwbivsgz@132.177.252.111:60868>

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Record-Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5060;transport=udp;lr>

Record-Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5061;transport=tls;lr>

Allow: SUBSCRIBE,NOTIFY,PRACK,INVITE,ACK,BYE,CANCEL,UPDATE,MESSAGE,REFER

Server: Blink Pro 1.3.1 (MacOSX)

Content-Length: 0

RECEIVED: Packet 191, +0:14:28.691178

2011-10-24 11:35:57.229682: 132.177.253.22:5061 -(SIP over tls)-> 132.177.252.163:51280

SIP/2.0 200 OK

Via: SIP/2.0/tls 132.177.252.163:51280;rport=51280;received=132.177.252.163;branch=z9hG4bKPjGqaVmgy6QI4hqusA17.VmYbSEjEn1S-y;ingress-zone=DefaultZone

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4485 INVITE

Contact: <sip:qwbivsgz@132.177.252.111:60868>

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Record-Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5060;transport=udp;lr>

Record-Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5061;transport=tls;lr>

Allow: SUBSCRIBE,NOTIFY,PRACK,INVITE,ACK,BYE,CANCEL,UPDATE,MESSAGE,REFER

Server: Blink Pro 1.3.1 (MacOSX)

Supported: 100rel,replaces,norefersub

Content-Type: application/sdp

Content-Length: 255

v=0

o=- 3528437757 3528437758 IN IP4 132.177.252.111

s=Blink Pro 1.3.1 (MacOSX)

c=IN IP4 132.177.252.111

b=AS:384

t=0 0

m=audio 50018 RTP/AVP 9 101

a=rtcp:50019

a=rtpmap:9 G722/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

a=sendrecv

SENDING: Packet 192, +0:14:28.691472

2011-10-24 11:35:57.229976: 132.177.252.163:51280 -(SIP over tls)-> 132.177.253.22:5061

ACK sip:qwbivsgz@132.177.252.111:60868 SIP/2.0

Via: SIP/2.0/tls 132.177.252.163:51280;rport;branch=z9hG4bKPjydOyhHyq82C92apBgV97cGE2r.G2e4GO

Max-Forwards: 70

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4485 ACK

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5061;transport=tls;lr>

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5060;transport=udp;lr>

User-Agent: Blink Pro 1.3.1 (MacOSX)

Content-Length:  0

SENDING: Packet 193, +0:14:32.184140

2011-10-24 11:36:00.722644: 132.177.252.163:51280 -(SIP over tls)-> 132.177.253.22:5061

BYE sip:qwbivsgz@132.177.252.111:60868 SIP/2.0

Via: SIP/2.0/tls 132.177.252.163:51280;rport;branch=z9hG4bKPjqWIKkD-f1CW8BystKkNHu3QQ.HhB920m

Max-Forwards: 70

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4486 BYE

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5061;transport=tls;lr>

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5060;transport=udp;lr>

User-Agent: Blink Pro 1.3.1 (MacOSX)

Content-Length:  0

RECEIVED: Packet 194, +0:14:32.185918

2011-10-24 11:36:00.724422: 132.177.253.22:5061 -(SIP over tls)-> 132.177.252.163:51280

SIP/2.0 407 Proxy Authentication Required

Via: SIP/2.0/tls 132.177.252.163:51280;branch=z9hG4bKPjqWIKkD-f1CW8BystKkNHu3QQ.HhB920m;received=132.177.252.163;rport=51280

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4486 BYE

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Server: TANDBERG/4103 (X7.1PreAlpha29 (TEST SW))

Proxy-Authenticate: Digest realm="h1.cisco.sipit.net", nonce="ecf10cc969b2858a1f46ce145b58ba291426098f076e4fa29924531f706e", opaque="AQAAANXGRIqnJLpaa2+oaGI3teAaoA95", stale=FALSE, algorithm=MD5, qop="auth"

Content-Length: 0

SENDING: Packet 195, +0:14:32.186342

2011-10-24 11:36:00.724846: 132.177.252.163:51280 -(SIP over tls)-> 132.177.253.22:5061

BYE sip:qwbivsgz@132.177.252.111:60868 SIP/2.0

Via: SIP/2.0/tls 132.177.252.163:51280;rport;branch=z9hG4bKPj7LZjnOhpR57.YTxGAv42MyoF7RSBupjk

Max-Forwards: 70

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4487 BYE

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5061;transport=tls;lr>

Route: <sip:proxy-call-id=9041af5c-fe23-11e0-8ac1-000c29ab0f7b@132.177.253.22:5060;transport=udp;lr>

User-Agent: Blink Pro 1.3.1 (MacOSX)

Proxy-Authorization: Digest username="cisco", realm="h1.cisco.sipit.net", nonce="ecf10cc969b2858a1f46ce145b58ba291426098f076e4fa29924531f706e", uri="sip:qwbivsgz@132.177.252.111:60868", response="6ed728af6b1b5443c953ec89d17151c6", algorithm=MD5, cnonce="WMYZEu5MhMBRJr97hlz3Nxqd9pidFkvZ", opaque="AQAAANXGRIqnJLpaa2+oaGI3teAaoA95", qop=auth, nc=00000001

Content-Length:  0

RECEIVED: Packet 196, +0:14:32.203260

2011-10-24 11:36:00.741764: 132.177.253.22:5061 -(SIP over tls)-> 132.177.252.163:51280

SIP/2.0 200 OK

Via: SIP/2.0/tls 132.177.252.163:51280;rport=51280;received=132.177.252.163;branch=z9hG4bKPj7LZjnOhpR57.YTxGAv42MyoF7RSBupjk;ingress-zone=DefaultZone

Call-ID: wm-ihLWnDBKwk743UftUCoP-H5qoETv-

CSeq: 4487 BYE

From: "Adrian Georgescu" <sip:ag01@cisco.sipit.net>;tag=tG4TWxTurelH-rGZRnivbJ96jCHFsQS8

To: <sip:ag02@cisco.sipit.net>;tag=nkEDOGe3nL5K7PwTs1-DzrwUmbdzAYUy

Server: Blink Pro 1.3.1 (MacOSX)

Content-Length: 0

2011-10-24 11:36:12.346891: DNS lookup A h1.cisco.sipit.net succeeded, ttl=600: 132.177.253.22

}}}

{{{

2011-10-24 10:42:21.419 Blink Pro[1668:a0f] [Session with ag02@cisco.sipit.net] Ending session with audio stream

2011-10-24 10:42:21.457 Blink Pro[1668:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/coros.py", line 253, in _do_acquire

    waiter.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 1904, in end

    TimestampedNotificationData(originator='local', method='BYE', code=notification.data.code, reason=notification.data.reason))

AttributeError: 'NotificationData' object has no attribute 'code'

2011-10-24 10:42:21.474 Blink Pro[1668:a0f] [Session with ag02@cisco.sipit.net] Session will end (local)

2011-10-24 10:42:21.643 Blink Pro[1668:a0f] [Session with ag02@cisco.sipit.net] Audio stream ended

}}}

{{{

2011-10-24 10:31:00.239837: Notification name=SIPInvitationChangedState

sender=<sipsimple.core._core.Invitation object at 0x18c5ab10>

data=NotificationData(originator='local', body=None, prev_sub_state='normal',

timestamp=datetime.datetime(2011, 10, 24, 10, 31, 0, 232073), headers={'Via':

[FrozenViaHeader('tls', '132.177.252.163', 50951, frozendict({'rport': 0,

'branch': 'z9hG4bKPj5bKvhluLSr5OxNTM0vdb4umkCpVNtox8'}))], 'From':

FrozenFromHeader(FrozenSIPURI('cisco.sipit.net', 'ag01', None, None, False,

frozendict({}), frozendict({})), u'Adrian Georgescu', frozendict({'tag':

'kfOPAVWAfIHorykAJBu31vAmIZif780n'})), 'Route':

[FrozenRouteHeader(FrozenSIPURI('132.177.253.22',

'proxy-call-id=844482fa-fe1a-11e0-bd41-000c29ab0f7b', None, 5061, False,

frozendict({'lr': 1, 'transport': 'tls'}), frozendict({})), None,

frozendict({})), FrozenRouteHeader(FrozenSIPURI('132.177.253.22',

'proxy-call-id=844482fa-fe1a-11e0-bd41-000c29ab0f7b', None, 5061, False,

frozendict({'lr': 1, 'transport': 'tls'}), frozendict({})), None,

frozendict({}))], 'User-Agent': FrozenHeader('User-Agent', 'Blink Pro 1.3.1

(MacOSX)'), 'To': FrozenToHeader(FrozenSIPURI('cisco.sipit.net', 'ag02', None,

None, False, frozendict({}), frozendict({})), None, frozendict({'tag':

'-9Gm-krVFw154HwQh5W.UsZY12oHT9di'})), 'CSeq': (8401, 'BYE'), 'Call-ID':

FrozenHeader('Call-ID', 'JzYfmKI6hZg0iBD9t4WdpKNhW6SyQzlm'), 'Max-Forwards':

70}, state='disconnecting', prev_state='connected', method='BYE',

request_uri=FrozenSIPURI('132.177.252.111', 'qwbivsgz', None, 51564, False,

frozendict({'transport': 'tls'}), frozendict({})))

2011-10-24 10:31:00.259586: Notification name=SIPInvitationChangedState

sender=<sipsimple.core._core.Invitation object at 0x18c5ab10>

data=NotificationData(originator='local', disconnect_reason='user request',

state='disconnected', prev_state='disconnecting',

timestamp=datetime.datetime(2011, 10, 24, 10, 31, 0, 250102))

}}}

200 OK rdata seems to be none for received 200OK for the sent out BYE

=== UDP trace that works ===

{{{

2011-10-24 10:46:07.277414: Notification name=SIPInvitationChangedState

sender=<sipsimple.core._core.Invitation object at 0x18c5abf8>

data=NotificationData(originator='local', body=None, prev_sub_state='normal',

timestamp=datetime.datetime(2011, 10, 24, 10, 46, 7, 268879), headers={'Via':

[FrozenViaHeader('UDP', '132.177.252.163', 60653, frozendict({'rport': 0,

'branch': 'z9hG4bKPjVWjI8ftu8DW7rR5WhnOsbgpAWQFpbFYT'}))], 'From':

FrozenFromHeader(FrozenSIPURI('cisco.sipit.net', 'ag01', None, None, False,

frozendict({}), frozendict({})), u'Adrian Georgescu', frozendict({'tag':

'M5uaZcSknKymRnkGTjRG88C8DG99m5Hy'})), 'Route':

[FrozenRouteHeader(FrozenSIPURI('132.177.253.22',

'proxy-call-id=99e57f04-fe1c-11e0-ba17-000c29ab0f7b', None, 5060, False,

frozendict({'lr': 1, 'transport': 'udp'}), frozendict({})), None,

frozendict({})), FrozenRouteHeader(FrozenSIPURI('132.177.253.22',

'proxy-call-id=99e57f04-fe1c-11e0-ba17-000c29ab0f7b', None, 5060, False,

frozendict({'lr': 1, 'transport': 'tcp'}), frozendict({})), None,

frozendict({}))], 'User-Agent': FrozenHeader('User-Agent', 'Blink Pro 1.3.1

(MacOSX)'), 'To': FrozenToHeader(FrozenSIPURI('cisco.sipit.net', 'ag02', None,

None, False, frozendict({}), frozendict({})), None, frozendict({'tag':

'hNd9U3UKc.VP-1WWYP-S8MegH2yeRc5e'})), 'CSeq': (28697, 'BYE'), 'Call-ID':

FrozenHeader('Call-ID', '41QYdm0-Eny2uHKzgETWx57HhGq47xPl'), 'Max-Forwards':

70}, state='disconnecting', prev_state='connected', method='BYE',

request_uri=FrozenSIPURI('132.177.252.111', 'qwbivsgz', None, 51252, False,

frozendict({'transport': 'tcp'}), frozendict({})))

2011-10-24 10:46:07.293137: Notification name=SIPInvitationChangedState

sender=<sipsimple.core._core.Invitation object at 0x18c5abf8>

data=NotificationData(originator='remote', body=None, code=200,

disconnect_reason='user request', timestamp=datetime.datetime(2011, 10, 24, 10,

46, 7, 287860), state='disconnected', headers={'Content-Length': 0, 'Via':

[FrozenViaHeader('UDP', '132.177.252.163', 60653, frozendict({'received':

'132.177.252.163', 'ingress-zone': 'DefaultSubZone', 'rport': 60653, 'branch':

'z9hG4bKPjB6pOFsn58EsyG4sXhsB.72oClDLkXjEW'}))], 'From':

FrozenFromHeader(FrozenSIPURI('cisco.sipit.net', 'ag01', None, None, False,

frozendict({}), frozendict({})), u'Adrian Georgescu', frozendict({'tag':

'M5uaZcSknKymRnkGTjRG88C8DG99m5Hy'})), 'Server': FrozenHeader('Server', 'Blink

Pro 1.3.1 (MacOSX)'), 'To': FrozenToHeader(FrozenSIPURI('cisco.sipit.net',

'ag02', None, None, False, frozendict({}), frozendict({})), None,

frozendict({'tag': 'hNd9U3UKc.VP-1WWYP-S8MegH2yeRc5e'})), 'CSeq': (28698,

'BYE'), 'Call-ID': FrozenHeader('Call-ID', '41QYdm0-Eny2uHKzgETWx57HhGq47xPl')},

reason='OK', prev_state='disconnecting')

}}}

== MSRP Error (Solved) ==

Incoming session is cancelled by remote before we have the chance to initialize msrp media stream.

{{{

2011-10-24 13:24:24.311 Blink Pro[3997:a0f] [Session with ag02@cisco.sipit.net] Session ended

2011-10-24 13:25:07.452 Blink Pro[3997:6527] Account('ag01@cisco.sipit.net') registered contact "sip:ohwvastb@132.177.252.163:52017;transport=tls" at 132.177.253.22:5061;transport=tls for 93 seconds

2011-10-24 13:26:10.570 Blink Pro[3997:6527] Account('ag01@cisco.sipit.net') registered contact "sip:ohwvastb@132.177.252.163:52017;transport=tls" at 132.177.253.22:5061;transport=tls for 93 seconds

2011-10-24 13:26:43.250 Blink Pro[3997:a0f] Incoming session request from GES <ges@georgescu.info> with chat streams

2011-10-24 13:27:13.688 Blink Pro[3997:6527] Account('ag01@cisco.sipit.net') registered contact "sip:ohwvastb@132.177.252.163:52017;transport=tls" at 132.177.253.22:5061;transport=tls for 93 seconds

2011-10-24 13:27:21.438 Blink Pro[3997:a0f] Accepting session to ges@georgescu.info

2011-10-24 13:27:21.440 Blink Pro[3997:a0f] [Session with ges@georgescu.info] Handling incoming chat stream

2011-10-24 13:27:21.730 Blink Pro[3997:6527] Starting factory <eventlet.twistedutil.protocol.GreenInstanceFactory instance at 0x1885c620>

2011-10-24 13:27:21.740 Blink Pro[3997:6527] /etc/resolv.conf changed, reparsing

2011-10-24 13:27:21.740 Blink Pro[3997:6527] Resolver added ('132.177.252.2', 53) to server list

2011-10-24 13:27:21.742 Blink Pro[3997:6527] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 54952

2011-10-24 13:27:21.742 Blink Pro[3997:6527] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x18c0a490>

2011-10-24 13:27:21.939 Blink Pro[3997:6527] (Port 54952 Closed)

2011-10-24 13:27:21.940 Blink Pro[3997:6527] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x18c0a490>

2011-10-24 13:27:23.978 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/hubs/twistedr.py", line 159, in call_if_greenlet_alive

    return func(*args1, **kwargs1)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/streams/msrp.py", line 260, in end

    notification_center.remove_observer(self, sender=self)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/application/notification.py", line 164, in remove_observer

    raise KeyError("observer %r not registered for %r events from %r" % (observer, name, sender))

KeyError: 'observer <sipsimple.streams.msrp.ChatStream object at 0x1860cfd0> not registered for Any events from <sipsimple.streams.msrp.ChatStream object at 0x1860cfd0>'

}}}

== Multiple reconnect for MSRP and cancel (when clicking cancel and reconnect like there is no tomorrow)==

{{{

2011-10-24 15:31:07.196 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Initiating DNS Lookup of Account('31208005169@ag-projects.com') to sip:agp@conference.sip2sip.info

2011-10-24 15:31:07.205 Blink Pro[3997:a0f] Starting DNS Lookup for sip:agp@conference.sip2sip.info via proxy of account 31208005169@ag-projects.com

2011-10-24 15:31:07.212 Blink Pro[3997:6527] DNS Lookup for sip:agp@conference.sip2sip.info succeeded: 85.17.186.7:5060 (UDP), 81.23.228.129:5060 (UDP)

2011-10-24 15:31:07.248 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Connecting session

2011-10-24 15:31:07.262 Blink Pro[3997:a0f] Starting Outgoing Session to agp@conference.sip2sip.info with ['chat']

2011-10-24 15:31:07.287 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Ending session with chat stream

2011-10-24 15:31:07.317 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Session cancelled

2011-10-24 15:31:07.364 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:31:07.414 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Initiating DNS Lookup of Account('31208005169@ag-projects.com') to sip:agp@conference.sip2sip.info

2011-10-24 15:31:07.423 Blink Pro[3997:a0f] Starting DNS Lookup for sip:agp@conference.sip2sip.info via proxy of account 31208005169@ag-projects.com

2011-10-24 15:31:07.430 Blink Pro[3997:6527] DNS Lookup for sip:agp@conference.sip2sip.info succeeded: 85.17.186.7:5060 (UDP), 81.23.228.129:5060 (UDP)

2011-10-24 15:31:07.470 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Connecting session

2011-10-24 15:31:07.473 Blink Pro[3997:a0f] Starting Outgoing Session to agp@conference.sip2sip.info with ['chat']

2011-10-24 15:31:07.501 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Ending session with chat stream

2011-10-24 15:31:07.532 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Session cancelled

2011-10-24 15:31:07.625 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:31:07.696 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 239, in _spawn

    g.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2175, in handle_notification

    handler(notification)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2310, in _NH_SIPInvitationChangedState

    elif notification.data.state == 'connected' and notification.data.sub_state == 'normal' and notification.data.prev_sub_state == 'received_proposal':

AttributeError: 'NotificationData' object has no attribute 'prev_sub_state'

2011-10-24 15:31:07.696 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Initiating DNS Lookup of Account('31208005169@ag-projects.com') to sip:agp@conference.sip2sip.info

2011-10-24 15:31:07.706 Blink Pro[3997:a0f] Starting DNS Lookup for sip:agp@conference.sip2sip.info via proxy of account 31208005169@ag-projects.com

2011-10-24 15:31:07.714 Blink Pro[3997:6527] DNS Lookup for sip:agp@conference.sip2sip.info succeeded: 85.17.186.7:5060 (UDP), 81.23.228.129:5060 (UDP)

2011-10-24 15:31:07.775 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Connecting session

2011-10-24 15:31:07.782 Blink Pro[3997:a0f] Starting Outgoing Session to agp@conference.sip2sip.info with ['chat']

2011-10-24 15:31:07.804 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Ending session with chat stream

2011-10-24 15:31:08.075 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 239, in _spawn

    g.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2175, in handle_notification

    handler(notification)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2310, in _NH_SIPInvitationChangedState

    elif notification.data.state == 'connected' and notification.data.sub_state == 'normal' and notification.data.prev_sub_state == 'received_proposal':

AttributeError: 'NotificationData' object has no attribute 'prev_sub_state'

2011-10-24 15:31:08.477 Blink Pro[3997:6527] *** __NSAutoreleaseNoPool(): Object 0x1e5e4af0 of class NSCFString autoreleased with no pool in place - just leaking

2011-10-24 15:31:08.551 Blink Pro[3997:6527] *** attempt to pop an unknown autorelease pool (0x24d0e00)

2011-10-24 15:31:08.760 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Session cancelled

2011-10-24 15:31:08.775 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Chat stream ended

2011-10-24 15:31:17.812 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 239, in _spawn

    g.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2175, in handle_notification

    handler(notification)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2328, in _NH_SIPInvitationChangedState

    for stream in self.streams:

TypeError: 'NoneType' object is not iterable

2011-10-24 15:31:18.005 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 239, in _spawn

    g.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2175, in handle_notification

    handler(notification)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 2328, in _NH_SIPInvitationChangedState

    for stream in self.streams:

TypeError: 'NoneType' object is not iterable

2011-10-24 15:32:02.401 Blink Pro[3997:6527] Account('ag01@cisco.sipit.net') registered contact "sip:ohwvastb@132.177.252.163:52016;transport=tcp" at 132.177.253.22:5060;transport=tcp for 93 seconds

2011-10-24 15:32:14.921 Blink Pro[3997:a0f] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:32:14.922 Blink Pro[3997:a0f] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:32:14.970 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Initiating DNS Lookup of Account('31208005169@ag-projects.com') to sip:agp@conference.sip2sip.info

2011-10-24 15:32:14.981 Blink Pro[3997:a0f] Starting DNS Lookup for sip:agp@conference.sip2sip.info via proxy of account 31208005169@ag-projects.com

2011-10-24 15:32:15.465 Blink Pro[3997:6527] DNS Lookup for sip:agp@conference.sip2sip.info succeeded: 81.23.228.129:5060 (UDP), 81.23.228.150:5060 (UDP), 85.17.186.7:5060 (UDP)

2011-10-24 15:32:15.501 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Connecting session

2011-10-24 15:32:15.512 Blink Pro[3997:a0f] Starting Outgoing Session to agp@conference.sip2sip.info with ['chat']

2011-10-24 15:32:15.772 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Ending session with chat stream

2011-10-24 15:32:26.048 Blink Pro[3997:6527] Traceback (most recent call last):

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/twisted/internet/base.py", line 757, in runUntilCurrent

    call.func(*call.args, **call.kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/coros.py", line 253, in _do_acquire

    waiter.switch()

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/eventlet/api.py", line 235, in _spawn_startup

    return cb(*args, **kw)

  File "/Users/adigeo/work/blink/build/Release/Blink Pro.app/Contents/Resources/lib/sipsimple/session.py", line 1898, in end

    TimestampedNotificationData(originator='local', method='INVITE', code=notification.data.code, reason=notification.data.reason))

AttributeError: 'NotificationData' object has no attribute 'code'

2011-10-24 15:32:26.057 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Chat stream ended

2011-10-24 15:32:28.717 Blink Pro[3997:a0f] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:32:28.718 Blink Pro[3997:a0f] Re-establishing session to agp@conference.sip2sip.info

2011-10-24 15:32:28.762 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Proposing chat stream

2011-10-24 15:32:28.763 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] IllegalStateError: cannot call add_stream in terminated state

2011-10-24 15:32:41.751 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] Cancelling proposal

2011-10-24 15:32:41.752 Blink Pro[3997:a0f] [Session with agp@conference.sip2sip.info] IllegalStateError: cannot call cancel_proposal in terminated state

2011-10-24 15:33:05.520 Blink Pro[3997:6527] Account('ag01@cisco.sipit.net') registered contact "sip:ohwvastb@132.177.252.163:52016;transport=tcp" at 132.177.253.22:5060;transport=tcp for 93 seconds

}}}

== Problem if hold request is received with direction "inactive" ==

 * 200 OK is correct

 * Another INVITE is sent with same SDP, possibly confusing session state