[Blink] Fwd: Attended transfer - Replaces Invite not reaching Blink

Peter Flowers pflowers at mergecom.co.nz
Tue May 8 04:14:04 CEST 2012


Hi Saul

Core log file attached.

I have also attached two SIP traces.  One is for the original call and the
second is the actual Refer request trace.  Both are from the point of view
of the proxy.

regards

On 7 May 2012 19:54, Saúl Ibarra Corretgé <saul at ag-projects.com> wrote:

> Hi Peter,
>
> On May 5, 2012, at 8:30 AM, Peter Flowers wrote:
>
> > Hi
> >
> > I have discovered that when trying to do an attended transfer to Blink
> the Replaces Invite from the proxy arrives on the interface of my Mac but
> does not get to Blink. As a consequence the proxy times out the refer.
> >
> > There are two files attached.  One is a Wireshark capture file of the
> attempted attended transfer. The other is the Blink SIP log for the same
> call. Frames 11, 12, etc do not appear in the log.
> >
>
> By looking at the trace I don't see an obvious reason. Can you please
> enable Core Engine logging and send me the file? (You can enable Core
> Engine tracing on Blink Preferences -> Advanced -> File Logging, the file
> will be in ~/Library/Application Support /Blink Pro/logs/pjsip_trace.txt
>
>
> Regards,
>
> --
> Saúl Ibarra Corretgé
> AG Projects
>
>
>
> _______________________________________________
> Blink mailing list
> Blink at lists.ag-projects.com
> http://lists.ag-projects.com/mailman/listinfo/blink
>



-- 
Peter Flowers
www.mergecom.co.nz
www.facebook.com/mergecom
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ag-projects.com/pipermail/blink/attachments/20120508/9e2867a6/attachment.html>
-------------- next part --------------
SIP trace on proxy 161.29.126.70 for session 1465201887-5064-47 at BJC.BGI.B.BDB
--

Packet 1 at 2012-05-08 13:57:16 from 121.72.137.118 to 161.29.126.70 (in)

INVITE sip:209000492 at mergecom.net.nz SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK488940881;rport
Route: <sip:sip.mergecom.net.nz:5060;lr>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 460 INVITE
Contact: "Refer Tester1" <sip:209000491 at 192.168.1.131:5064>
X-Grandstream-PBX: true
Max-Forwards: 69
User-Agent: Grandstream GXP2100 1.0.3.30
Privacy: none
P-Preferred-Identity: "Refer Tester1" <sip:209000491 at mergecom.net.nz>
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   358

v=0
o=209000491 8003 8000 IN IP4 192.168.1.131
s=SIP Call
c=IN IP4 192.168.1.131
t=0 0
m=audio 5016 RTP/AVP 9 0 8 18 97 101
a=sendrecv
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

---
Packet 2 at 2012-05-08 13:57:16 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK488940881;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=7b31eeef4cbd20c7e99948edfba7651f.52e7
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 460 INVITE
Proxy-Authenticate: Digest realm="mergecom.net.nz", nonce="4fa87d9a0000cdd7bb5b3a697d061d77ce9dfc23cd9166b5"
Server: OpenSIPS XS 1.8.0
Content-Length: 0


---
Packet 3 at 2012-05-08 13:57:17 from 121.72.137.118 to 161.29.126.70 (in)

INVITE sip:209000492 at mergecom.net.nz SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK511486006;rport
Route: <sip:sip.mergecom.net.nz:5060;lr>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 461 INVITE
Contact: "Refer Tester1" <sip:209000491 at 192.168.1.131:5064>
Proxy-Authorization: Digest username="209000491", realm="mergecom.net.nz", nonce="4fa87d9a0000cdd7bb5b3a697d061d77ce9dfc23cd9166b5", uri="sip:209000492 at mergecom.net.nz", response="cdca5cc6a0c832ded8ff7af7407ec167", algorithm=MD5
X-Grandstream-PBX: true
Max-Forwards: 69
User-Agent: Grandstream GXP2100 1.0.3.30
Privacy: none
P-Preferred-Identity: "Refer Tester1" <sip:209000491 at mergecom.net.nz>
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   358

v=0
o=209000491 8003 8000 IN IP4 192.168.1.131
s=SIP Call
c=IN IP4 192.168.1.131
t=0 0
m=audio 5016 RTP/AVP 9 0 8 18 97 101
a=sendrecv
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

---
Packet 4 at 2012-05-08 13:57:17 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK511486006;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 461 INVITE
Server: OpenSIPS XS 1.8.0
Content-Length: 0


---
Packet 5 at 2012-05-08 13:57:17 from 161.29.126.70 to 121.72.137.118 (out)

INVITE sip:txhjnqmv at 192.168.1.134:56980 SIP/2.0
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK7e23.99f413d6.0
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK511486006;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 461 INVITE
Contact: "Refer Tester1" <sip:209000491 at 121.72.137.118:50441>
X-Grandstream-PBX: true
Max-Forwards: 69
User-Agent: Grandstream GXP2100 1.0.3.30
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length: 359
Privacy: none
P-Asserted-Identity: <sip:6449749905 at mergecom.net.nz>
Remote-Party-ID: <sip:6449749905 at mergecom.net.nz>;party=calling;id-type=subscriber;privacy=off;screen=yes

v=0
o=209000491 8003 8000 IN IP4 192.168.1.131
s=SIP Call
c=IN IP4 161.29.126.69
t=0 0
m=audio 52838 RTP/AVP 9 0 8 18 97 101
a=sendrecv
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

---
Packet 6 at 2012-05-08 13:57:17 from 121.72.137.118 to 161.29.126.70 (in)

SIP/2.0 100 Trying
Via: SIP/2.0/UDP 161.29.126.70;received=161.29.126.70;branch=z9hG4bK7e23.99f413d6.0
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK511486006
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>
CSeq: 461 INVITE
Server: Blink Pro 1.8.1 (MacOSX)
Content-Length:  0


---
Packet 7 at 2012-05-08 13:57:17 from 121.72.137.118 to 161.29.126.70 (in)

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 161.29.126.70;received=161.29.126.70;branch=z9hG4bK7e23.99f413d6.0
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK511486006
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 461 INVITE
Server: Blink Pro 1.8.1 (MacOSX)
Contact: <sip:txhjnqmv at 192.168.1.134:56980>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Content-Length:  0


---
Packet 8 at 2012-05-08 13:57:17 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK511486006
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 461 INVITE
Server: Blink Pro 1.8.1 (MacOSX)
Contact: <sip:txhjnqmv at 121.72.137.118:50976>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Content-Length:  0


---
Packet 9 at 2012-05-08 13:57:21 from 121.72.137.118 to 161.29.126.70 (in)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 161.29.126.70;received=161.29.126.70;branch=z9hG4bK7e23.99f413d6.0
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK511486006
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 461 INVITE
Server: Blink Pro 1.8.1 (MacOSX)
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Contact: <sip:txhjnqmv at 192.168.1.134:56980>
Supported: 100rel, replaces, norefersub, gruu
Content-Type: application/sdp
Content-Length:   241

v=0
o=- 3545431041 3545431042 IN IP4 192.168.1.134
s=Blink Pro 1.8.1 (MacOSX)
c=IN IP4 192.168.1.134
t=0 0
m=audio 50000 RTP/AVP 9 101
a=rtcp:50001
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv

---
Packet 10 at 2012-05-08 13:57:21 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK511486006
Record-Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 461 INVITE
Server: Blink Pro 1.8.1 (MacOSX)
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Contact: <sip:txhjnqmv at 121.72.137.118:50976>
Supported: 100rel, replaces, norefersub, gruu
Content-Type: application/sdp
Content-Length:   241

v=0
o=- 3545431041 3545431042 IN IP4 192.168.1.134
s=Blink Pro 1.8.1 (MacOSX)
c=IN IP4 161.29.126.69
t=0 0
m=audio 52836 RTP/AVP 9 101
a=rtcp:52837
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv

---
Packet 11 at 2012-05-08 13:57:22 from 121.72.137.118 to 161.29.126.70 (in)

ACK sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK187904555;rport
Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 461 ACK
Contact: <sip:209000491 at 192.168.1.131:5064>
Proxy-Authorization: Digest username="209000491", realm="mergecom.net.nz", nonce="4fa87d9a0000cdd7bb5b3a697d061d77ce9dfc23cd9166b5", uri="sip:209000492 at mergecom.net.nz", response="cdca5cc6a0c832ded8ff7af7407ec167", algorithm=MD5
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 12 at 2012-05-08 13:57:22 from 161.29.126.70 to 121.72.137.118 (out)

ACK sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK7e23.99f413d6.2
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK187904555;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 461 ACK
Contact: <sip:209000491 at 121.72.137.118:50441>
Proxy-Authorization: Digest username="209000491", realm="mergecom.net.nz", nonce="4fa87d9a0000cdd7bb5b3a697d061d77ce9dfc23cd9166b5", uri="sip:209000492 at mergecom.net.nz", response="cdca5cc6a0c832ded8ff7af7407ec167", algorithm=MD5
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 13 at 2012-05-08 13:57:24 from 121.72.137.118 to 161.29.126.70 (in)

INVITE sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK75882757;rport
Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 462 INVITE
Contact: <sip:209000491 at 192.168.1.131:5064>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   352

v=0
o=209000491 8003 8001 IN IP4 192.168.1.131
s=SIP Call
c=IN IP4 0.0.0.0
t=0 0
m=audio 5016 RTP/AVP 9 0 8 18 97 101
a=sendonly
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

---
Packet 14 at 2012-05-08 13:57:24 from 161.29.126.70 to 121.72.137.118 (out)

INVITE sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK4e23.95baf9e1.0
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK75882757;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 462 INVITE
Contact: <sip:209000491 at 121.72.137.118:50441>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length: 353

v=0
o=209000491 8003 8001 IN IP4 192.168.1.131
s=SIP Call
c=IN IP4 0.0.0.0
t=0 0
m=audio 52838 RTP/AVP 9 0 8 18 97 101
a=sendonly
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

---
Packet 15 at 2012-05-08 13:57:24 from 121.72.137.118 to 161.29.126.70 (in)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 161.29.126.70;received=161.29.126.70;branch=z9hG4bK4e23.95baf9e1.0
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK75882757
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 462 INVITE
Contact: <sip:txhjnqmv at 192.168.1.134:56980>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
Server: Blink Pro 1.8.1 (MacOSX)
Content-Type: application/sdp
Content-Length:   241

v=0
o=- 3545431041 3545431043 IN IP4 192.168.1.134
s=Blink Pro 1.8.1 (MacOSX)
c=IN IP4 192.168.1.134
t=0 0
m=audio 50000 RTP/AVP 9 101
a=rtcp:50001
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly

---
Packet 16 at 2012-05-08 13:57:24 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK75882757
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 462 INVITE
Contact: <sip:txhjnqmv at 121.72.137.118:50976>
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER
Supported: 100rel, replaces, norefersub, gruu
Server: Blink Pro 1.8.1 (MacOSX)
Content-Type: application/sdp
Content-Length:   241

v=0
o=- 3545431041 3545431043 IN IP4 192.168.1.134
s=Blink Pro 1.8.1 (MacOSX)
c=IN IP4 161.29.126.69
t=0 0
m=audio 52836 RTP/AVP 9 101
a=rtcp:52837
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=recvonly

---
Packet 17 at 2012-05-08 13:57:24 from 121.72.137.118 to 161.29.126.70 (in)

ACK sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK858690361;rport
Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 462 ACK
Contact: <sip:209000491 at 192.168.1.131:5064>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 18 at 2012-05-08 13:57:24 from 161.29.126.70 to 121.72.137.118 (out)

ACK sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK4e23.95baf9e1.2
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK858690361;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 462 ACK
Contact: <sip:209000491 at 121.72.137.118:50441>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 19 at 2012-05-08 13:57:44 from 121.72.137.118 to 161.29.126.70 (in)

BYE sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.131:5064;branch=z9hG4bK92428215;rport
Route: <sip:161.29.126.70;lr;ftag=214138694;did=20a.5fed41d2>
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 463 BYE
Contact: <sip:209000491 at 192.168.1.131:5064>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 20 at 2012-05-08 13:57:44 from 161.29.126.70 to 121.72.137.118 (out)

BYE sip:txhjnqmv at 121.72.137.118:50976 SIP/2.0
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK5e23.be470c87.0
Via: SIP/2.0/UDP 192.168.1.131:5064;received=121.72.137.118;branch=z9hG4bK92428215;rport=50441
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
CSeq: 463 BYE
Contact: <sip:209000491 at 121.72.137.118:50441>
X-Grandstream-PBX: true
Max-Forwards: 69
Supported: replaces, path, timer
User-Agent: Grandstream GXP2100 1.0.3.30
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


---
Packet 21 at 2012-05-08 13:57:44 from 121.72.137.118 to 161.29.126.70 (in)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 161.29.126.70;received=161.29.126.70;branch=z9hG4bK5e23.be470c87.0
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK92428215
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 463 BYE
Server: Blink Pro 1.8.1 (MacOSX)
Content-Length:  0


---
Packet 22 at 2012-05-08 13:57:44 from 161.29.126.70 to 121.72.137.118 (out)

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.131:5064;rport=50441;received=121.72.137.118;branch=z9hG4bK92428215
Record-Route: <sip:161.29.126.70;lr;ftag=214138694>
Call-ID: 1465201887-5064-47 at BJC.BGI.B.BDB
From: "Refer Tester1" <sip:209000491 at mergecom.net.nz>;tag=214138694
To: <sip:209000492 at mergecom.net.nz>;tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8
CSeq: 463 BYE
Server: Blink Pro 1.8.1 (MacOSX)
Content-Length:  0


---
-------------- next part --------------
SIP trace on proxy 161.29.126.70 for session B2B.21.5954592
--

Packet 1 at 2012-05-08 13:57:27 from 161.29.126.80 to 161.29.126.70 (in)

INVITE sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694 SIP/2.0
Via: SIP/2.0/UDP 161.29.126.80;branch=z9hG4bK3a07.ed3e6b94.0
To: sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694
From: <sip:6445653949 at 202.180.114.49>;tag=d0300e7492b0491a072105696734dbf3-56ee
CSeq: 4 INVITE
Call-ID: B2B.21.5954592
Max-Forwards: 69
Content-Length: 325
User-Agent: OpenSIPS (1.8.0-beta-notls (i386/linux))
Content-Type: application/sdp
Supported: replaces
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Contact: <sip:161.29.126.80:5060>
Replaces: 1465201887-5064-47 at BJC.BGI.B.BDB;to-tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8;from-tag=214138694 

v=0
o=root 5220 5222 IN IP4 161.29.126.80
s=session
c=IN IP4 161.29.126.80
t=0 0
m=audio 54812 RTP/AVP 0 8 3 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=nortpproxy:yes

---
Packet 2 at 2012-05-08 13:57:27 from 161.29.126.70 to 161.29.126.80 (out)

SIP/2.0 100 Trying
Via: SIP/2.0/UDP 161.29.126.80;branch=z9hG4bK3a07.ed3e6b94.0
To: sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694
From: <sip:6445653949 at 202.180.114.49>;tag=d0300e7492b0491a072105696734dbf3-56ee
CSeq: 4 INVITE
Call-ID: B2B.21.5954592
Server: OpenSIPS XS 1.8.0
Content-Length: 0


---
Packet 3 at 2012-05-08 13:57:27 from 161.29.126.70 to 121.72.137.118 (out)

INVITE sip:txhjnqmv at 192.168.1.134:56980 SIP/2.0
Record-Route: <sip:161.29.126.70;lr;ftag=d0300e7492b0491a072105696734dbf3-56ee;did=17.8f99c1d2>
Via: SIP/2.0/UDP 161.29.126.70;branch=z9hG4bK3a07.59157b05.0
Via: SIP/2.0/UDP 161.29.126.80;branch=z9hG4bK3a07.ed3e6b94.0
To: sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694
From: <sip:6445653949 at 202.180.114.49>;tag=d0300e7492b0491a072105696734dbf3-56ee
CSeq: 4 INVITE
Call-ID: B2B.21.5954592
Max-Forwards: 69
Content-Length: 325
User-Agent: OpenSIPS (1.8.0-beta-notls (i386/linux))
Content-Type: application/sdp
Supported: replaces
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Contact: <sip:161.29.126.80:5060>
Replaces: 1465201887-5064-47 at BJC.BGI.B.BDB;to-tag=RumqGl0vq1oH7Kv79d1f1um2TbwcXAR8;from-tag=214138694 

v=0
o=root 5220 5222 IN IP4 161.29.126.80
s=session
c=IN IP4 161.29.126.68
t=0 0
m=audio 52642 RTP/AVP 0 8 3 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=nortpproxy:yes

---
Packet 4 at 2012-05-08 13:57:41 from 161.29.126.70 to 161.29.126.80 (out)

SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 161.29.126.80;branch=z9hG4bK3a07.ed3e6b94.0
To: sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694;tag=16f13714a0c9e1a76791193128dc021d-d3cf
From: <sip:6445653949 at 202.180.114.49>;tag=d0300e7492b0491a072105696734dbf3-56ee
CSeq: 4 INVITE
Call-ID: B2B.21.5954592
Server: OpenSIPS XS 1.8.0
Content-Length: 0


---
Packet 5 at 2012-05-08 13:57:41 from 161.29.126.80 to 161.29.126.70 (in)

ACK sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694 SIP/2.0
Via: SIP/2.0/UDP 161.29.126.80;branch=z9hG4bK3a07.ed3e6b94.0
From: <sip:6445653949 at 202.180.114.49>;tag=d0300e7492b0491a072105696734dbf3-56ee
Call-ID: B2B.21.5954592
To: sip:209000492 at mergecom.net.nz?Replaces=1465201887-5064-47%40BJC.BGI.B.BDB%3Bto-tag%3DRumqGl0vq1oH7Kv79d1f1um2TbwcXAR8%3Bfrom-tag%3D214138694;tag=16f13714a0c9e1a76791193128dc021d-d3cf
CSeq: 4 ACK
Max-Forwards: 69
User-Agent: OpenSIPS (1.8.0-beta-notls (i386/linux))
Content-Length: 0


---
-------------- next part --------------
2012-05-08 13:56:39.182000 [Blink Pro 42865] (4) os_core_unix.c: pjlib 1.0.3-trunk for POSIX initialized
2012-05-08 13:56:39.215000 [Blink Pro 42865] (4)      pasound.c: PortAudio sound library initialized, status=0
2012-05-08 13:56:39.215000 [Blink Pro 42865] (4)      pasound.c: PortAudio host api count=1
2012-05-08 13:56:39.215000 [Blink Pro 42865] (4)      pasound.c: Sound device count=3
2012-05-08 13:56:39.218000 [Blink Pro 42865] (4)          pjlib: select() I/O Queue created (0x127d014)
2012-05-08 13:56:39.218000 [Blink Pro 42865] (5) sip_endpoint.c: Creating endpoint instance...
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4)          pjlib: select() I/O Queue created (0x12e3614)
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-msg-print" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (5) sip_transport.: Transport manager created.
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-tsx-layer" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-stateful-util" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-ua" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-evsub" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-100rel" registered
2012-05-08 13:56:39.219000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-invite" registered
2012-05-08 13:56:39.223000 [Blink Pro 42865] (4) sip_transport_: Error setting SO_RCVBUF: No buffer space available [120055]
2012-05-08 13:56:39.223000 [Blink Pro 42865] (4) sip_transport_: Error setting SO_SNDBUF: No buffer space available [120055]
2012-05-08 13:56:39.223000 [Blink Pro 42865] (4)    udp0xd52000: SIP UDP transport started, published address is 192.168.1.134:56980
2012-05-08 13:56:39.224000 [Blink Pro 42865] (4)   tcplis:53695: SIP TCP listener ready for incoming connections at 192.168.1.134:53695
2012-05-08 13:56:39.224000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-core" registered
2012-05-08 13:56:39.224000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-core-sip-trace" registered
2012-05-08 13:56:39.224000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-core-ua-tag" registered
2012-05-08 13:56:39.224000 [Blink Pro 42865] (4) sip_endpoint.c: Module "mod-core-events" registered
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "conference" registered by mod-core-events
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "message-summary" registered by mod-core-events
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "presence" registered by mod-core-events
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "presence.winfo" registered by mod-core-events
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "xcap-diff" registered by mod-core-events
2012-05-08 13:56:39.224000 [Blink Pro 42865] (5)        evsub.c: Event pkg "refer" registered by mod-core-events
2012-05-08 13:56:39.226000 [Blink Pro 42865] (5)   tls0x1270064: TLS CA file successfully loaded from '/Users/mcl/Library/Application Support/Blink Pro/tls/ca.crt'
2012-05-08 13:56:39.227000 [Blink Pro 42865] (5)   tls0x1270064: TLS certificate successfully loaded from '/Applications/Blink.app/Contents/Resources/default.crt'
2012-05-08 13:56:39.227000 [Blink Pro 42865] (5)   tls0x1270064: TLS private key successfully loaded from '/Applications/Blink.app/Contents/Resources/default.crt'
2012-05-08 13:56:39.227000 [Blink Pro 42865] (5)   tls0x1270064: TLS verification mode set to 0
2012-05-08 13:56:39.228000 [Blink Pro 42865] (4)   tls0x1270064: SIP TLS listener ready for incoming connections at 192.168.1.134:53696
2012-05-08 13:56:39.228000 [Blink Pro 42865] (5)   conference.c: Creating conference bridge with 255 ports
2012-05-08 13:56:39.228000 [Blink Pro 42865] (5)   conference.c: Sound device successfully created for port 0
2012-05-08 13:56:39.296000 [Blink Pro 42865] (5)      pasound.c: Opened device ADDCOM(Core Audio)/ADDCOM(Core Audio) for recording and playback, sample rate=16000, ch=1, bits=16, 320 samples per frame, input latency=0 ms, output latency=20 ms
2012-05-08 13:56:39.296000 [Blink Pro 42865] (5)      pasound.c: Starting ADDCOM stream..
2012-05-08 13:56:39.473000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:56:39.477000 [Blink Pro 42865] (5)   ec0x184e9170: Creating WEBRTC AEC
2012-05-08 13:56:39.478000 [Blink Pro 42865] (4)   ec0x184e9170: WEBRTC AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=15 ms, latency=20 ms
2012-05-08 13:56:40.577000 [Blink Pro 42865] (5)      pasound.c: Stopping stream..
2012-05-08 13:56:40.777000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:56:41.788000 [Blink Pro 42865] (5)      pasound.c: Closing ADDCOM: 0 underflow, 0 overflow
2012-05-08 13:56:41.790000 [Blink Pro 42865] (5)   conference.c: Creating conference bridge with 255 ports
2012-05-08 13:56:41.790000 [Blink Pro 42865] (5)   conference.c: Sound device successfully created for port 0
2012-05-08 13:56:41.791000 [Blink Pro 42865] (5)      pasound.c: Opened device 1: Built-in Output(Core Audio) for playing, sample rate=16000, ch=1, bits=16, 320 samples per frame, latency=0 ms
2012-05-08 13:56:41.791000 [Blink Pro 42865] (5)      pasound.c: Starting Built-in Output stream..
2012-05-08 13:56:42.612000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:56:43.623000 [Blink Pro 42865] (5)      pasound.c: Stopping stream..
2012-05-08 13:56:43.723000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:56:44.735000 [Blink Pro 42865] (5)      pasound.c: Closing Built-in Output: 0 underflow, 0 overflow
2012-05-08 13:56:44.965000 [Blink Pro 42865] (5) natck0x1397600: Local address is 192.168.1.134:60854
2012-05-08 13:56:44.965000 [Blink Pro 42865] (5) natck0x1397600: Server set to 192.168.1.140:3478
2012-05-08 13:56:44.965000 [Blink Pro 42865] (5) natck0x1397600: Performing Test I: Binding request to 192.168.1.140:3478
2012-05-08 13:56:44.965000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN client transaction created
2012-05-08 13:56:44.965000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=1)
2012-05-08 13:56:45.079000 [Blink Pro 42865] (5) natck0x1397600: Performing Test II: Binding request with change address and port request to 192.168.1.140:3478
2012-05-08 13:56:45.079000 [Blink Pro 42865] (5) stuntsx0x13829: STUN client transaction created
2012-05-08 13:56:45.079000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=1)
2012-05-08 13:56:45.079000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=2)
2012-05-08 13:56:45.080000 [Blink Pro 42865] (5)       endpoint: Request msg REGISTER/cseq=1 (tdta0x13af600) created.
2012-05-08 13:56:45.080000 [Blink Pro 42865] (5)   tsx0x13b0664: Transaction created for Request msg REGISTER/cseq=1 (tdta0x13af600)
2012-05-08 13:56:45.080000 [Blink Pro 42865] (5)   tsx0x13b0664: Sending Request msg REGISTER/cseq=1 (tdta0x13af600) in state Null
2012-05-08 13:56:45.080000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.080000 [Blink Pro 42865] (5)   tsx0x13b0664: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  dlg0x1680ae64: UAC dialog created
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  dlg0x1680ae64: Session count inc to 1 by mod-core
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  dlg0x1680ae64: Module mod-evsub added as dialog usage, data=0x168467b4
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5) evsub0x168ca81: UAC subscription created, using dialog dlg0x1680ae64
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  dlg0x1680ae64: Session count inc to 3 by mod-evsub
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)       endpoint: Request msg SUBSCRIBE/cseq=3720 (tdta0x168bfe00) created.
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  dlg0x1680ae64: Sending Request msg SUBSCRIBE/cseq=3720 (tdta0x168bfe00)
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  tsx0x1689fe64: Transaction created for Request msg SUBSCRIBE/cseq=3719 (tdta0x168bfe00)
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  tsx0x1689fe64: Sending Request msg SUBSCRIBE/cseq=3719 (tdta0x168bfe00) in state Null
2012-05-08 13:56:45.098000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.099000 [Blink Pro 42865] (5)  tsx0x1689fe64: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.099000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1689fe64 state changed to Calling
2012-05-08 13:56:45.099000 [Blink Pro 42865] (4) evsub0x168ca81: Subscription state changed NULL --> SENT
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: UAC dialog created
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: Session count inc to 1 by mod-core
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: Module mod-evsub added as dialog usage, data=0xecfdb4
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  evsub0xedaa14: UAC subscription created, using dialog dlg0x168f1c64
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: Session count inc to 3 by mod-evsub
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)       endpoint: Request msg SUBSCRIBE/cseq=25996 (tdta0x16912400) created.
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: Sending Request msg SUBSCRIBE/cseq=25996 (tdta0x16912400)
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  tsx0x168f2464: Transaction created for Request msg SUBSCRIBE/cseq=25995 (tdta0x16912400)
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  tsx0x168f2464: Sending Request msg SUBSCRIBE/cseq=25995 (tdta0x16912400) in state Null
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  tsx0x168f2464: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.100000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x168f2464 state changed to Calling
2012-05-08 13:56:45.100000 [Blink Pro 42865] (4)  evsub0xedaa14: Subscription state changed NULL --> SENT
2012-05-08 13:56:45.101000 [Blink Pro 42865] (5)       endpoint: Request msg REGISTER/cseq=1 (tdta0x16913400) created.
2012-05-08 13:56:45.101000 [Blink Pro 42865] (5)  tsx0x1692be64: Transaction created for Request msg REGISTER/cseq=1 (tdta0x16913400)
2012-05-08 13:56:45.101000 [Blink Pro 42865] (5)  tsx0x1692be64: Sending Request msg REGISTER/cseq=1 (tdta0x16913400) in state Null
2012-05-08 13:56:45.101000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.101000 [Blink Pro 42865] (5)  tsx0x1692be64: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.136000 [Blink Pro 42865] (5) natck0x1397600: Performing Test III: Binding request with change port request to 192.168.1.140:3478
2012-05-08 13:56:45.136000 [Blink Pro 42865] (5) stuntsx0x16908: STUN client transaction created
2012-05-08 13:56:45.136000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=1)
2012-05-08 13:56:45.180000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=2)
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 401/REGISTER/cseq=1 (rdata0x16878214)
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)   tsx0x13b0664: Incoming Response msg 401/REGISTER/cseq=1 (rdata0x16878214) in state Calling
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)   tsx0x13b0664: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)  tsx0x168f2c64: Transaction created for Request msg REGISTER/cseq=2 (tdta0x13af600)
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)  tsx0x168f2c64: Sending Request msg REGISTER/cseq=2 (tdta0x13af600) in state Null
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.184000 [Blink Pro 42865] (5)  tsx0x168f2c64: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.193000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 407/SUBSCRIBE/cseq=3719 (rdata0x16878214)
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  tsx0x1689fe64: Incoming Response msg 407/SUBSCRIBE/cseq=3719 (rdata0x16878214) in state Calling
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  tsx0x1689fe64: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  dlg0x1680ae64: Received Response msg 407/SUBSCRIBE/cseq=3719 (rdata0x16878214)
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1689fe64 state changed to Completed
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  dlg0x1680ae64: Sending Request msg SUBSCRIBE/cseq=3719 (tdta0x168bfe00)
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  tsx0x1694fa64: Transaction created for Request msg SUBSCRIBE/cseq=3720 (tdta0x168bfe00)
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  tsx0x1694fa64: Sending Request msg SUBSCRIBE/cseq=3720 (tdta0x168bfe00) in state Null
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  tsx0x1694fa64: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.194000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1694fa64 state changed to Calling
2012-05-08 13:56:45.205000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 407/SUBSCRIBE/cseq=25995 (rdata0x16878214)
2012-05-08 13:56:45.205000 [Blink Pro 42865] (5)  tsx0x168f2464: Incoming Response msg 407/SUBSCRIBE/cseq=25995 (rdata0x16878214) in state Calling
2012-05-08 13:56:45.205000 [Blink Pro 42865] (5)  tsx0x168f2464: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.205000 [Blink Pro 42865] (5)  dlg0x168f1c64: Received Response msg 407/SUBSCRIBE/cseq=25995 (rdata0x16878214)
2012-05-08 13:56:45.205000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x168f2464 state changed to Completed
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)  dlg0x168f1c64: Sending Request msg SUBSCRIBE/cseq=25995 (tdta0x16912400)
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)   tsx0x13b9a64: Transaction created for Request msg SUBSCRIBE/cseq=25996 (tdta0x16912400)
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)   tsx0x13b9a64: Sending Request msg SUBSCRIBE/cseq=25996 (tdta0x16912400) in state Null
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.206000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x13b9a64 state changed to Calling
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 401/REGISTER/cseq=1 (rdata0x16878214)
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)  tsx0x1692be64: Incoming Response msg 401/REGISTER/cseq=1 (rdata0x16878214) in state Calling
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)  tsx0x1692be64: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)   tsx0x13b5664: Transaction created for Request msg REGISTER/cseq=2 (tdta0x16913400)
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)   tsx0x13b5664: Sending Request msg REGISTER/cseq=2 (tdta0x16913400) in state Null
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:0' type=Unspecified resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.216000 [Blink Pro 42865] (5)   tsx0x13b5664: State changed from Null to Calling, event=TX_MSG
2012-05-08 13:56:45.236000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=2)
2012-05-08 13:56:45.279000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=3)
2012-05-08 13:56:45.282000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 200/REGISTER/cseq=2 (rdata0x13f3014)
2012-05-08 13:56:45.282000 [Blink Pro 42865] (5)  tsx0x168f2c64: Incoming Response msg 200/REGISTER/cseq=2 (rdata0x13f3014) in state Calling
2012-05-08 13:56:45.282000 [Blink Pro 42865] (5)  tsx0x168f2c64: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 200/SUBSCRIBE/cseq=3720 (rdata0x13f3014)
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  tsx0x1694fa64: Incoming Response msg 200/SUBSCRIBE/cseq=3720 (rdata0x13f3014) in state Calling
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  tsx0x1694fa64: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  dlg0x1680ae64: Received Response msg 200/SUBSCRIBE/cseq=3720 (rdata0x13f3014)
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  dlg0x1680ae64: Route-set updated
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  dlg0x1680ae64: Route-set frozen
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1694fa64 state changed to Completed
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5) evsub0x168ca81: Will refresh in 3595 seconds
2012-05-08 13:56:45.292000 [Blink Pro 42865] (5) evsub0x168ca81: Timer UAC_REFRESH scheduled in 3595 seconds
2012-05-08 13:56:45.292000 [Blink Pro 42865] (4) evsub0x168ca81: Subscription state changed SENT --> ACCEPTED
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=1 (rdata0x13f3014)
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)  dlg0x1680ae64: Received Request msg NOTIFY/cseq=1 (rdata0x13f3014)
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)   tsx0x13bd264: Transaction created for Request msg NOTIFY/cseq=1 (rdata0x13f3014)
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)   tsx0x13bd264: Incoming Request msg NOTIFY/cseq=1 (rdata0x13f3014) in state Null
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)   tsx0x13bd264: State changed from Null to Trying, event=RX_MSG
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x13bd264 state changed to Trying
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5) evsub0x168ca81: Will refresh in 3595 seconds
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5) evsub0x168ca81: Updating UAC_REFRESH timer
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5) evsub0x168ca81: Timer UAC_REFRESH scheduled in 3595 seconds
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)       endpoint: Response msg 200/NOTIFY/cseq=1 (tdta0x13b2600) created
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)  dlg0x1680ae64: Sending Response msg 200/NOTIFY/cseq=1 (tdta0x13b2600)
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)   tsx0x13bd264: Sending Response msg 200/NOTIFY/cseq=1 (tdta0x13b2600) in state Trying
2012-05-08 13:56:45.297000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.298000 [Blink Pro 42865] (5)   tsx0x13bd264: State changed from Trying to Completed, event=TX_MSG
2012-05-08 13:56:45.298000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x13bd264 state changed to Completed
2012-05-08 13:56:45.298000 [Blink Pro 42865] (4) evsub0x168ca81: Subscription state changed ACCEPTED --> ACTIVE
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 200/SUBSCRIBE/cseq=25996 (rdata0x16953014)
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)   tsx0x13b9a64: Incoming Response msg 200/SUBSCRIBE/cseq=25996 (rdata0x16953014) in state Calling
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Received Response msg 200/SUBSCRIBE/cseq=25996 (rdata0x16953014)
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Route-set updated
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Route-set frozen
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x13b9a64 state changed to Completed
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  evsub0xedaa14: Will refresh in 3595 seconds
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  evsub0xedaa14: Timer UAC_REFRESH scheduled in 3595 seconds
2012-05-08 13:56:45.306000 [Blink Pro 42865] (4)  evsub0xedaa14: Subscription state changed SENT --> ACCEPTED
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=1 (rdata0x16953014)
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Received Request msg NOTIFY/cseq=1 (rdata0x16953014)
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  tsx0x16950264: Transaction created for Request msg NOTIFY/cseq=1 (rdata0x16953014)
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  tsx0x16950264: Incoming Request msg NOTIFY/cseq=1 (rdata0x16953014) in state Null
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  tsx0x16950264: State changed from Null to Trying, event=RX_MSG
2012-05-08 13:56:45.306000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x16950264 state changed to Trying
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  evsub0xedaa14: Will refresh in 3595 seconds
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  evsub0xedaa14: Updating UAC_REFRESH timer
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  evsub0xedaa14: Timer UAC_REFRESH scheduled in 3595 seconds
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)       endpoint: Response msg 200/NOTIFY/cseq=1 (tdta0x13da800) created
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  dlg0x168f1c64: Sending Response msg 200/NOTIFY/cseq=1 (tdta0x13da800)
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  tsx0x16950264: Sending Response msg 200/NOTIFY/cseq=1 (tdta0x13da800) in state Trying
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  tsx0x16950264: State changed from Trying to Completed, event=TX_MSG
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x16950264 state changed to Completed
2012-05-08 13:56:45.307000 [Blink Pro 42865] (4)  evsub0xedaa14: Subscription state changed ACCEPTED --> ACTIVE
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Response msg 200/REGISTER/cseq=2 (rdata0x140de14)
2012-05-08 13:56:45.307000 [Blink Pro 42865] (5)   tsx0x13b5664: Incoming Response msg 200/REGISTER/cseq=2 (rdata0x140de14) in state Calling
2012-05-08 13:56:45.308000 [Blink Pro 42865] (5)   tsx0x13b5664: State changed from Calling to Completed, event=RX_MSG
2012-05-08 13:56:45.380000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=3)
2012-05-08 13:56:45.437000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=3)
2012-05-08 13:56:45.679000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=4)
2012-05-08 13:56:45.780000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=4)
2012-05-08 13:56:45.838000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=4)
2012-05-08 13:56:46.480000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=5)
2012-05-08 13:56:46.580000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=5)
2012-05-08 13:56:46.639000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=5)
2012-05-08 13:56:48.080000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=6)
2012-05-08 13:56:48.181000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=6)
2012-05-08 13:56:48.240000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=6)
2012-05-08 13:56:50.184000 [Blink Pro 42865] (5)   tsx0x13b0664: Timeout timer event
2012-05-08 13:56:50.184000 [Blink Pro 42865] (5)   tsx0x13b0664: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.184000 [Blink Pro 42865] (5)   tsx0x13b0664: Timeout timer event
2012-05-08 13:56:50.184000 [Blink Pro 42865] (5)   tsx0x13b0664: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.184000 [Blink Pro 42865] (5)   tsx0x13b0664: Transaction destroyed!
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  tsx0x1689fe64: Timeout timer event
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  tsx0x1689fe64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1689fe64 state changed to Terminated
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  tsx0x1689fe64: Timeout timer event
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  tsx0x1689fe64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.197000 [Blink Pro 42865] (5)  tsx0x1689fe64: Transaction destroyed!
2012-05-08 13:56:50.209000 [Blink Pro 42865] (5)  tsx0x168f2464: Timeout timer event
2012-05-08 13:56:50.209000 [Blink Pro 42865] (5)  tsx0x168f2464: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.209000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x168f2464 state changed to Terminated
2012-05-08 13:56:50.212000 [Blink Pro 42865] (5)  tsx0x168f2464: Timeout timer event
2012-05-08 13:56:50.212000 [Blink Pro 42865] (5)  tsx0x168f2464: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.212000 [Blink Pro 42865] (5)  tsx0x168f2464: Transaction destroyed!
2012-05-08 13:56:50.218000 [Blink Pro 42865] (5)  tsx0x1692be64: Timeout timer event
2012-05-08 13:56:50.218000 [Blink Pro 42865] (5)  tsx0x1692be64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.218000 [Blink Pro 42865] (5)  tsx0x1692be64: Timeout timer event
2012-05-08 13:56:50.218000 [Blink Pro 42865] (5)  tsx0x1692be64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.218000 [Blink Pro 42865] (5)  tsx0x1692be64: Transaction destroyed!
2012-05-08 13:56:50.286000 [Blink Pro 42865] (5)  tsx0x168f2c64: Timeout timer event
2012-05-08 13:56:50.286000 [Blink Pro 42865] (5)  tsx0x168f2c64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.286000 [Blink Pro 42865] (5)  tsx0x168f2c64: Timeout timer event
2012-05-08 13:56:50.286000 [Blink Pro 42865] (5)  tsx0x168f2c64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.286000 [Blink Pro 42865] (5)  tsx0x168f2c64: Transaction destroyed!
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  tsx0x1694fa64: Timeout timer event
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  tsx0x1694fa64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x1694fa64 state changed to Terminated
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  tsx0x1694fa64: Timeout timer event
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  tsx0x1694fa64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5) tdta0x168bfe00: Destroying txdata Request msg SUBSCRIBE/cseq=3720 (tdta0x168bfe00)
2012-05-08 13:56:50.295000 [Blink Pro 42865] (5)  tsx0x1694fa64: Transaction destroyed!
2012-05-08 13:56:50.309000 [Blink Pro 42865] (5)   tsx0x13b9a64: Timeout timer event
2012-05-08 13:56:50.309000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.309000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x13b9a64 state changed to Terminated
2012-05-08 13:56:50.309000 [Blink Pro 42865] (5)   tsx0x13b5664: Timeout timer event
2012-05-08 13:56:50.309000 [Blink Pro 42865] (5)   tsx0x13b5664: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:56:50.310000 [Blink Pro 42865] (5)   tsx0x13b9a64: Timeout timer event
2012-05-08 13:56:50.310000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.310000 [Blink Pro 42865] (5) tdta0x16912400: Destroying txdata Request msg SUBSCRIBE/cseq=25996 (tdta0x16912400)
2012-05-08 13:56:50.310000 [Blink Pro 42865] (5)   tsx0x13b9a64: Transaction destroyed!
2012-05-08 13:56:50.314000 [Blink Pro 42865] (5)   tsx0x13b5664: Timeout timer event
2012-05-08 13:56:50.314000 [Blink Pro 42865] (5)   tsx0x13b5664: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:56:50.314000 [Blink Pro 42865] (5)   tsx0x13b5664: Transaction destroyed!
2012-05-08 13:56:51.280000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN sending message (transmit count=7)
2012-05-08 13:56:51.328000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=1 (rdata0x140de14)
2012-05-08 13:56:51.329000 [Blink Pro 42865] (5)       endpoint: Response msg 405/NOTIFY/cseq=1 (tdta0x1265c00) created
2012-05-08 13:56:51.329000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:56:51.329000 [Blink Pro 42865] (5)  tdta0x1265c00: Destroying txdata Response msg 405/NOTIFY/cseq=1 (tdta0x1265c00)
2012-05-08 13:56:51.382000 [Blink Pro 42865] (5) stuntsx0x13829: STUN sending message (transmit count=7)
2012-05-08 13:56:51.440000 [Blink Pro 42865] (5) stuntsx0x16908: STUN sending message (transmit count=7)
2012-05-08 13:56:52.880000 [Blink Pro 42865] (4) stuntsx0x139d1: STUN timeout waiting for response
2012-05-08 13:56:52.880000 [Blink Pro 42865] (5) natck0x1397600: Completed Test I: Binding request, status=370004
2012-05-08 13:56:52.982000 [Blink Pro 42865] (4) stuntsx0x13829: STUN timeout waiting for response
2012-05-08 13:56:52.982000 [Blink Pro 42865] (5) natck0x1397600: Completed Test II: Binding request with change address and port request, status=370004
2012-05-08 13:56:53.041000 [Blink Pro 42865] (4) stuntsx0x16908: STUN timeout waiting for response
2012-05-08 13:56:53.041000 [Blink Pro 42865] (5) natck0x1397600: Completed Test III: Binding request with change port request, status=370004
2012-05-08 13:56:53.045000 [Blink Pro 42865] (5) stuntsx0x16908: STUN client transaction destroyed
2012-05-08 13:56:53.045000 [Blink Pro 42865] (5) stuntsx0x13829: STUN client transaction destroyed
2012-05-08 13:56:53.045000 [Blink Pro 42865] (5) stuntsx0x139d1: STUN client transaction destroyed
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg INVITE/cseq=461 (rdata0x140de14)
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: Transaction created for Request msg INVITE/cseq=461 (rdata0x140de14)
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: Incoming Request msg INVITE/cseq=461 (rdata0x140de14) in state Null
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Null to Trying, event=RX_MSG
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13b9a64 state changed to Trying
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   dlg0x13b5664: UAS dialog created
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   dlg0x13b5664: Module mod-invite added as dialog usage, data=0x13b3cec
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   dlg0x13b5664: Session count inc to 2 by mod-invite
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   inv0x13b5664: UAS invite session created for dialog dlg0x13b5664
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)       endpoint: Response msg 100/INVITE/cseq=461 (tdta0x137a000) created
2012-05-08 13:57:17.181000 [Blink Pro 42865] (5)   dlg0x13b5664: Initial answer Response msg 100/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:17.187000 [Blink Pro 42865] (5)   inv0x13b5664: Sending Response msg 100/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:17.187000 [Blink Pro 42865] (5)   dlg0x13b5664: Sending Response msg 100/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:17.187000 [Blink Pro 42865] (5)   tsx0x13b9a64: Sending Response msg 100/INVITE/cseq=461 (tdta0x137a000) in state Trying
2012-05-08 13:57:17.187000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:57:17.188000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Trying to Proceeding, event=TX_MSG
2012-05-08 13:57:17.188000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13b9a64 state changed to Proceeding
2012-05-08 13:57:17.191000 [Blink Pro 42865] (5)      pasound.c: Opened device ADDCOM(Core Audio)/ADDCOM(Core Audio) for recording and playback, sample rate=16000, ch=1, bits=16, 320 samples per frame, input latency=0 ms, output latency=20 ms
2012-05-08 13:57:17.191000 [Blink Pro 42865] (5)      pasound.c: Starting ADDCOM stream..
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)   tsx0x13bd264: Timeout timer event
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)   tsx0x13bd264: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)  dlg0x1680ae64: Transaction tsx0x13bd264 state changed to Terminated
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)   tsx0x13bd264: Timeout timer event
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)   tsx0x13bd264: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)  tdta0x13b2600: Destroying txdata Response msg 200/NOTIFY/cseq=1 (tdta0x13b2600)
2012-05-08 13:57:17.298000 [Blink Pro 42865] (5)   tsx0x13bd264: Transaction destroyed!
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tsx0x16950264: Timeout timer event
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tsx0x16950264: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  dlg0x168f1c64: Transaction tsx0x16950264 state changed to Terminated
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tsx0x16950264: Timeout timer event
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tsx0x16950264: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tdta0x13da800: Destroying txdata Response msg 200/NOTIFY/cseq=1 (tdta0x13da800)
2012-05-08 13:57:17.308000 [Blink Pro 42865] (5)  tsx0x16950264: Transaction destroyed!
2012-05-08 13:57:17.364000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:57:17.364000 [Blink Pro 42865] (5)   ec0x17827820: Creating WEBRTC AEC
2012-05-08 13:57:17.364000 [Blink Pro 42865] (4)   ec0x17827820: WEBRTC AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=15 ms, latency=20 ms
2012-05-08 13:57:17.364000 [Blink Pro 42865] (4)   conference.c: Port 2 (mixer-port) transmitting to port 0 (Master/sound)
2012-05-08 13:57:17.364000 [Blink Pro 42865] (4)   conference.c: Port 0 (Master/sound) transmitting to port 1 (mixer-port)
2012-05-08 13:57:17.370000 [Blink Pro 42865] (5)   inv0x13b5664: Sending Response msg 180/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:17.370000 [Blink Pro 42865] (5)   dlg0x13b5664: Sending Response msg 180/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:17.370000 [Blink Pro 42865] (5)   tsx0x13b9a64: Sending Response msg 180/INVITE/cseq=461 (tdta0x137a000) in state Proceeding
2012-05-08 13:57:17.371000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Proceeding to Proceeding, event=TX_MSG
2012-05-08 13:57:17.371000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13b9a64 state changed to Proceeding
2012-05-08 13:57:17.372000 [Blink Pro 42865] (4)   wav_player.c: File player '/Applications/Blink.app/Contents/Resources/ring_inbound.wav' created: samp.rate=44100, ch=1, bufsize=4KB, filesize=110KB
2012-05-08 13:57:17.372000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=44100/16000
2012-05-08 13:57:17.372000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=16000/44100
2012-05-08 13:57:17.461000 [Blink Pro 42865] (5)      pasound.c: Recorder thread started
2012-05-08 13:57:17.461000 [Blink Pro 42865] (5)   ec0x17827820: Prefetching..
2012-05-08 13:57:17.461000 [Blink Pro 42865] (4) os_core_unix.c: Info: possibly re-registering existing thread
2012-05-08 13:57:17.461000 [Blink Pro 42865] (5)      pasound.c: Player thread started
2012-05-08 13:57:17.483000 [Blink Pro 42865] (5)   ec0x17827820: Prefetching..
2012-05-08 13:57:17.483000 [Blink Pro 42865] (5)   ec0x17827820: Latency bufferring complete
2012-05-08 13:57:17.734000 [Blink Pro 42865] (5)      pasound.c: Opened device 1: Built-in Output(Core Audio) for playing, sample rate=16000, ch=1, bits=16, 320 samples per frame, latency=0 ms
2012-05-08 13:57:17.734000 [Blink Pro 42865] (5)      pasound.c: Starting Built-in Output stream..
2012-05-08 13:57:18.545000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:57:18.545000 [Blink Pro 42865] (4)   conference.c: Port 1 (/Applications/Blink.app/Contents/Resources/ring_inbound.wav) transmitting to port 0 (Master/sound)
2012-05-08 13:57:18.551000 [Blink Pro 42865] (5)      pasound.c: Player thread started
2012-05-08 13:57:19.811000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/ring_inbound.wav EOF
2012-05-08 13:57:20.825000 [Blink Pro 42865] (5)      pasound.c: Stopping stream..
2012-05-08 13:57:20.925000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:57:21.929000 [Blink Pro 42865] (5)      pasound.c: Closing Built-in Output: 0 underflow, 0 overflow
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   inv0x13b5664: SDP negotiation done, status=0
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   inv0x13b5664: Sending Response msg 200/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   dlg0x13b5664: Sending Response msg 200/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   tsx0x13b9a64: Sending Response msg 200/INVITE/cseq=461 (tdta0x137a000) in state Proceeding
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Proceeding to Completed, event=TX_MSG
2012-05-08 13:57:21.934000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13b9a64 state changed to Completed
2012-05-08 13:57:21.940000 [Blink Pro 42865] (5)          rtp.c: pjmedia_rtp_session_init: ses=0x136b084, default_pt=9, ssrc=0x36d33246
2012-05-08 13:57:21.940000 [Blink Pro 42865] (5)          rtp.c: pjmedia_rtp_session_init: ses=0x136b6a8, default_pt=9, ssrc=0x36d33246
2012-05-08 13:57:21.940000 [Blink Pro 42865] (5)       stream.c: Stream strm0x169166b4 created
2012-05-08 13:57:21.940000 [Blink Pro 42865] (4) strm0x169166b4: Encoder stream started
2012-05-08 13:57:21.940000 [Blink Pro 42865] (4) strm0x169166b4: Decoder stream started
2012-05-08 13:57:21.940000 [Blink Pro 42865] (5)   ec0x17827820: Delay buffer is reset
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4) echo_webrtc_ae: WebRTC AEC reset succeeded
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   sound_port.c: EC reset
2012-05-08 13:57:21.941000 [Blink Pro 42865] (5)   ec0x17827820: Delay buffer is reset
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4) echo_webrtc_ae: WebRTC AEC reset succeeded
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   sound_port.c: EC reset
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   conference.c: Port 2 (mixer-port) transmitting to port 3 (strm0x169166b4)
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   conference.c: Port 3 (strm0x169166b4) transmitting to port 1 (mixer-port)
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   conference.c: Port 0 (Master/sound) transmitting to port 3 (strm0x169166b4)
2012-05-08 13:57:21.941000 [Blink Pro 42865] (4)   conference.c: Port 3 (strm0x169166b4) transmitting to port 0 (Master/sound)
2012-05-08 13:57:21.946000 [Blink Pro 42865] (5)   ec0x17827820: Prefetching..
2012-05-08 13:57:21.946000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=0)
2012-05-08 13:57:21.946000 [Blink Pro 42865] (5) strm0x169166b4: Start talksprut..
2012-05-08 13:57:21.960000 [Blink Pro 42865] (5)   ec0x17827820: Prefetching..
2012-05-08 13:57:21.960000 [Blink Pro 42865] (5)   ec0x17827820: Latency bufferring complete
2012-05-08 13:57:22.177000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg ACK/cseq=461 (rdata0x140de14)
2012-05-08 13:57:22.177000 [Blink Pro 42865] (5)   dlg0x13b5664: Received Request msg ACK/cseq=461 (rdata0x140de14)
2012-05-08 13:57:22.177000 [Blink Pro 42865] (5)   tsx0x13b9a64: Request to terminate transaction
2012-05-08 13:57:22.177000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Completed to Terminated, event=USER
2012-05-08 13:57:22.177000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13b9a64 state changed to Terminated
2012-05-08 13:57:22.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: Timeout timer event
2012-05-08 13:57:22.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:57:22.181000 [Blink Pro 42865] (5)  tdta0x137a000: Destroying txdata Response msg 200/INVITE/cseq=461 (tdta0x137a000)
2012-05-08 13:57:22.181000 [Blink Pro 42865] (5)   tsx0x13b9a64: Transaction destroyed!
2012-05-08 13:57:22.288000 [Blink Pro 42865] (5) strm0x169166b4: RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
2012-05-08 13:57:22.386000 [Blink Pro 42865] (4)       stream.c: G722 codec used, remote samples per frame detected = 160
2012-05-08 13:57:22.447000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=0)
2012-05-08 13:57:22.505000 [Blink Pro 42865] (5) strm0x169166b4: jb updated(2), prefetch=2, size=1
2012-05-08 13:57:22.621000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=2)
2012-05-08 13:57:22.802000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=2)
2012-05-08 13:57:23.724000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=2)
2012-05-08 13:57:24.660000 [Blink Pro 42865] (5) strm0x169166b4: Jitter buffer empty (prefetch=2)
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg INVITE/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   dlg0x13b5664: Received Request msg INVITE/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   tsx0x13daa64: Transaction created for Request msg INVITE/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   tsx0x13daa64: Incoming Request msg INVITE/cseq=462 (rdata0x140de14) in state Null
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   tsx0x13daa64: State changed from Null to Trying, event=RX_MSG
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13daa64 state changed to Trying
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   inv0x13b5664: Got SDP offer in Request msg INVITE/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)       endpoint: Response msg 100/INVITE/cseq=462 (tdta0x137a000) created
2012-05-08 13:57:24.730000 [Blink Pro 42865] (5)   dlg0x13b5664: Initial answer Response msg 100/INVITE/cseq=462 (tdta0x137a000)
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   inv0x13b5664: SDP negotiation done, status=0
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   inv0x13b5664: Sending Response msg 200/INVITE/cseq=462 (tdta0x137a000)
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   dlg0x13b5664: Sending Response msg 200/INVITE/cseq=462 (tdta0x137a000)
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   tsx0x13daa64: Sending Response msg 200/INVITE/cseq=462 (tdta0x137a000) in state Trying
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   tsx0x13daa64: State changed from Trying to Completed, event=TX_MSG
2012-05-08 13:57:24.736000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13daa64 state changed to Completed
2012-05-08 13:57:24.841000 [Blink Pro 42865] (5)   ec0x17827820: Delay buffer is reset
2012-05-08 13:57:24.841000 [Blink Pro 42865] (4) echo_webrtc_ae: WebRTC AEC reset succeeded
2012-05-08 13:57:24.841000 [Blink Pro 42865] (4)   sound_port.c: EC reset
2012-05-08 13:57:24.841000 [Blink Pro 42865] (4)   ec0x17827820: Underflow, buf_cnt=0, will generate 1 frame
2012-05-08 13:57:24.841000 [Blink Pro 42865] (5)   ec0x17827820: Latency bufferring complete
2012-05-08 13:57:24.845000 [Blink Pro 42865] (4)   wav_player.c: File player '/Applications/Blink.app/Contents/Resources/hold_tone.wav' created: samp.rate=32000, ch=1, bufsize=4KB, filesize=32KB
2012-05-08 13:57:24.845000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=32000/16000
2012-05-08 13:57:24.845000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=16000/32000
2012-05-08 13:57:24.845000 [Blink Pro 42865] (4)   conference.c: Port 4 (/Applications/Blink.app/Contents/Resources/hold_tone.wav) transmitting to port 0 (Master/sound)
2012-05-08 13:57:24.953000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg ACK/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.953000 [Blink Pro 42865] (5)   dlg0x13b5664: Received Request msg ACK/cseq=462 (rdata0x140de14)
2012-05-08 13:57:24.953000 [Blink Pro 42865] (5)   tsx0x13daa64: Request to terminate transaction
2012-05-08 13:57:24.953000 [Blink Pro 42865] (5)   tsx0x13daa64: State changed from Completed to Terminated, event=USER
2012-05-08 13:57:24.953000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x13daa64 state changed to Terminated
2012-05-08 13:57:24.956000 [Blink Pro 42865] (5)   tsx0x13daa64: Timeout timer event
2012-05-08 13:57:24.956000 [Blink Pro 42865] (5)   tsx0x13daa64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:57:24.956000 [Blink Pro 42865] (5)  tdta0x137a000: Destroying txdata Response msg 200/INVITE/cseq=462 (tdta0x137a000)
2012-05-08 13:57:24.956000 [Blink Pro 42865] (5)   tsx0x13daa64: Transaction destroyed!
2012-05-08 13:57:25.364000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hold_tone.wav EOF
2012-05-08 13:57:25.385000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hold_tone.wav EOF
2012-05-08 13:57:25.400000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hold_tone.wav EOF
2012-05-08 13:57:25.422000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hold_tone.wav EOF
2012-05-08 13:57:25.443000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hold_tone.wav EOF
2012-05-08 13:57:30.182000 [Blink Pro 42865] (4)   sound_port.c: EC suspended because of inactivity
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg BYE/cseq=463 (rdata0x140de14)
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Received Request msg BYE/cseq=463 (rdata0x140de14)
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Transaction created for Request msg BYE/cseq=463 (rdata0x140de14)
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Incoming Request msg BYE/cseq=463 (rdata0x140de14) in state Null
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   tsx0x1420c64: State changed from Null to Trying, event=RX_MSG
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x1420c64 state changed to Trying
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)       endpoint: Response msg 200/BYE/cseq=463 (tdta0x13c7c00) created
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Sending Response msg 200/BYE/cseq=463 (tdta0x13c7c00)
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Sending Response msg 200/BYE/cseq=463 (tdta0x13c7c00) in state Trying
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   tsx0x1420c64: State changed from Trying to Completed, event=TX_MSG
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x1420c64 state changed to Completed
2012-05-08 13:57:44.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Session count dec to 3 by mod-invite
2012-05-08 13:57:44.744000 [Blink Pro 42865] (4)   wav_player.c: File player '/Applications/Blink.app/Contents/Resources/hangup_tone.wav' created: samp.rate=32000, ch=1, bufsize=4KB, filesize=32KB
2012-05-08 13:57:44.744000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=32000/16000
2012-05-08 13:57:44.744000 [Blink Pro 42865] (5)     resample.c: resample created: high qualiy, large filter, in/out rate=16000/32000
2012-05-08 13:57:44.744000 [Blink Pro 42865] (4)   conference.c: Port 1 (/Applications/Blink.app/Contents/Resources/hangup_tone.wav) transmitting to port 0 (Master/sound)
2012-05-08 13:57:44.766000 [Blink Pro 42865] (5)   ec0x17827820: Delay buffer is reset
2012-05-08 13:57:44.766000 [Blink Pro 42865] (4) echo_webrtc_ae: WebRTC AEC reset succeeded
2012-05-08 13:57:44.766000 [Blink Pro 42865] (4)   sound_port.c: EC activated
2012-05-08 13:57:44.780000 [Blink Pro 42865] (5)   ec0x17827820: Prefetching..
2012-05-08 13:57:44.780000 [Blink Pro 42865] (5)   ec0x17827820: Latency bufferring complete
2012-05-08 13:57:45.259000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hangup_tone.wav EOF
2012-05-08 13:57:45.281000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hangup_tone.wav EOF
2012-05-08 13:57:45.303000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hangup_tone.wav EOF
2012-05-08 13:57:45.325000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hangup_tone.wav EOF
2012-05-08 13:57:45.339000 [Blink Pro 42865] (5)   wav_player.c: File port /Applications/Blink.app/Contents/Resources/hangup_tone.wav EOF
2012-05-08 13:57:46.375000 [Blink Pro 42865] (5)      pasound.c: Stopping stream..
2012-05-08 13:57:46.575000 [Blink Pro 42865] (5)      pasound.c: Done, status=0
2012-05-08 13:57:47.587000 [Blink Pro 42865] (5)      pasound.c: Closing ADDCOM: 0 underflow, 0 overflow
2012-05-08 13:58:11.410000 [Blink Pro 42865] (5) sip_endpoint.c: Processing incoming message: Request msg NOTIFY/cseq=1 (rdata0x140de14)
2012-05-08 13:58:11.410000 [Blink Pro 42865] (5)       endpoint: Response msg 405/NOTIFY/cseq=1 (tdta0x1431200) created
2012-05-08 13:58:11.410000 [Blink Pro 42865] (5)  sip_resolve.c: Target '161.29.126.70:5060' type=UDP resolved to '161.29.126.70:5060' type=UDP (UDP transport)
2012-05-08 13:58:11.410000 [Blink Pro 42865] (5)  tdta0x1431200: Destroying txdata Response msg 405/NOTIFY/cseq=1 (tdta0x1431200)
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Timeout timer event
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   tsx0x1420c64: State changed from Completed to Terminated, event=TIMER
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Transaction tsx0x1420c64 state changed to Terminated
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   dlg0x13b5664: Dialog destroyed
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Timeout timer event
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   tsx0x1420c64: State changed from Terminated to Destroyed, event=TIMER
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)  tdta0x13c7c00: Destroying txdata Response msg 200/BYE/cseq=463 (tdta0x13c7c00)
2012-05-08 13:58:16.731000 [Blink Pro 42865] (5)   tsx0x1420c64: Transaction destroyed!


More information about the Blink mailing list