Strange behavior when making a call (format fix)

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi Bill,
?
Turned out it was not linked to the o= line but to the contact field in the SIP message I receive.
I tried to resolve the name to the IP address of the outbound proxy and it seems to work.


Thank you for your help in assisting me to find a solution!


Mathieu

?

Sent:?Thursday, February 26, 2015 at 9:45 PM
From:?"Bill Gardner" <billg at wavearts.com>
To:?pjsip at lists.pjsip.org
Subject:?Re: [pjsip] Strange behavior when making a call (format fix)
Hi Mathieu,

The o= is the IP address of the originator of the RTP session, c= is the
IP address of the RTP endpoint. I don't know why o= is included or why
pjsip is trying to resolve the IP address. I note your outgoing SDP
contains local IP addresses 192.168.x.x which will be meaningless to the
other endpoint. Provided the other endpoint supplies public IP in its
SDP and pjsip sends to it, the other endpoint will likely reply to the
proper IP address. Your contact address is also a local address, the
other endpoint is able to reply because of the "rport" modifier in the
Via header. The topic of SIP through NATs is complicated. You can
experiment with using --ip-addr option, stun, or preferably, ice and
turn, to properly traverse NATs. I don't know if NAT issues are causing
problems with your call experiment, but you may run into NAT problems
eventually.

Regards,

Bill



On 2/26/2015 3:12 PM, Mathieu Trinc wrote:
> Hi Bill,
>
> I found out the reason of the different behavior in XLite, they do not support PRACK.
> If I disable 100rel/PRACK in pjsua I receive the 183 and 180 messages.
>
> When the connection is established I get 200 OK but the Ack is not sent as pcgw-0005.imsgroup0-000.xxx.xxx.org cannot be resolved...
> I noticed there is an IP address in the c= line in the SDP, is it related to the hostname in the o= line?
>
>
> Thank you,
>
> Mathieu
>
>
> Sent: Thursday, February 26, 2015 at 7:37 PM
> From: "Bill Gardner" <billg@xxxxxxxxxxxx>
> To: pjsip at lists.pjsip.org
> Subject: Re: Strange behavior when making a call (format fix)
> Hi Mathieu,
>
> The problematic address is coming from the origin o= line in the SDP:
>
> Failed to resolve 'pcgw-0005.imsgroup0-000.xxx.xxx.org'
>
> To compare with XLite, you could do a wireshark trace of XLite call and
> capture the outgoing invite and compare that to the invite from pjsip.
> It might offer some clues.
>
> Regards,
>
> Bill
>
> On 2/26/2015 11:29 AM, Mathieu Trinc wrote:
>> Hi Bill,
>>
>> Thank you for your help.
>>
>> I cannot resolve this hostname on my machine but I am not sure this is an issue.
>> With a different SIP stack (XLite is based on reSIProcate if I am correct) no PRACK is sent and the 183 is immediately followed by 180 Ringing.
>>
>> I rebuild PJSIP with PJ_LOG_MAX_LEVEL set to 6 and I got a much more verbose log. I removed the Mutex / Semaphore / Pool stuff to keep it somewhat short.
>> The scenario is: Register - Make a call - When established wait a few seconds and hang up - Unregister.
>>
>> 16:17:56.356 sip_endpoint.c .Module "mod-pjsua-log" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-tsx-layer" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-stateful-util" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-ua" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-100rel" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-pjsua" registered
>> 16:17:56.356 sip_endpoint.c .Module "mod-invite" registered
>> 16:17:56.376 wmme_dev.c ..WMME found 4 devices:
>> 16:17:56.376 wmme_dev.c .. dev_id 0: Wave mapper (in=2, out=2)
>> 16:17:56.376 wmme_dev.c .. dev_id 1: CABLE Output (VB-Audio Virtual (in=2, out=0)
>> 16:17:56.376 wmme_dev.c .. dev_id 2: Haut-parleurs (Realtek High Def (in=0, out=2)
>> 16:17:56.376 wmme_dev.c .. dev_id 3: CABLE Input (VB-Audio Virtual C (in=0, out=2)
>> 16:17:56.376 wmme_dev.c ..WMME initialized
>> 16:17:56.377 pjlib ..select() I/O Queue created (00391F34)
>> 16:17:56.377 conference.c ..Creating conference bridge with 254 ports
>> 16:17:56.378 Master/sound ..Using delay buffer with WSOLA.
>> 16:17:56.379 sip_endpoint.c .Module "mod-evsub" registered
>> 16:17:56.379 sip_endpoint.c .Module "mod-presence" registered
>> 16:17:56.379 evsub.c .Event pkg "presence" registered by mod-presence
>> 16:17:56.379 sip_endpoint.c .Module "mod-mwi" registered
>> 16:17:56.379 evsub.c .Event pkg "message-summary" registered by mod-mwi
>> 16:17:56.379 sip_endpoint.c .Module "mod-refer" registered
>> 16:17:56.379 evsub.c .Event pkg "refer" registered by mod-refer
>> 16:17:56.379 sip_endpoint.c .Module "mod-pjsua-pres" registered
>> 16:17:56.379 sip_endpoint.c .Module "mod-pjsua-im" registered
>> 16:17:56.379 sip_endpoint.c .Module "mod-pjsua-options" registered
>> 16:17:56.379 pjsua_core.c .1 SIP worker threads created
>> 16:17:56.379 pjsua_core.c .pjsua version 2.3 for win32-6.1/i386/msvc-18.0 initialized
>> 16:17:56.379 pjsua_core.c .PJSUA state changed: CREATED --> INIT
>> 16:17:56.379 sip_endpoint.c Module "mod-default-handler" registered
>> 16:17:56.381 pjsua_core.c SIP UDP socket reachable at 192.168.1.25:5060
>> 16:17:56.381 udp00397478 SIP UDP transport started, published address is 192.168.1.25:5060
>> 16:17:56.381 pjsua_acc.c Adding account: id=<sip:192.168.1.25:5060>
>> 16:17:56.382 pjsua_acc.c .Account <sip:192.168.1.25:5060> added with id 0
>> 16:17:56.382 pjsua_acc.c Modifying accunt 0
>> 16:17:56.382 pjsua_acc.c Acc 0: setting online status to 1..
>> 16:17:56.383 tcplis:5060 SIP TCP listener ready for incoming connections at 192.168.1.25:5060
>> 16:17:56.383 pjsua_acc.c Adding account: id=<sip:192.168.1.25:5060;transport=TCP>
>> 16:17:56.383 pjsua_acc.c .Account <sip:192.168.1.25:5060;transport=TCP> added with id 1
>> 16:17:56.383 pjsua_acc.c Modifying accunt 1
>> 16:17:56.383 pjsua_acc.c Acc 1: setting online status to 1..
>> 16:17:56.383 pjsua_acc.c Adding account: id=sip:USERID at DOMAIN
>> 16:17:56.383 pjsua_acc.c .Account sip:USERID at DOMAIN added with id 2
>> 16:17:56.383 pjsua_acc.c .Acc 2: setting registration..
>> 16:17:56.383 endpoint ..Request msg REGISTER/cseq=28616 (tdta003AE538) created.
>> 16:17:56.384 tsx003AF5A4 ..tsx_key=c$REGISTER$z9hG4bKPj1caae52047514465bbbb37b048652f7f
>> 16:17:56.384 tsx003AF5A4 ...Transaction created for Request msg REGISTER/cseq=28617 (tdta003AE538)
>> 16:17:56.384 tsx003AF5A4 ..Sending Request msg REGISTER/cseq=28617 (tdta003AE538) in state Null
>> 16:17:56.384 sip_resolve.c ...DNS resolver not available, target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified will be resolved with getaddrinfo()
>> 16:17:56.384 sip_resolve.c ...Target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified resolved to 'OUTBOUNDPROXY_IP:5060' type=UDP (UDP transport)
>> 16:17:56.384 pjsua_core.c ...TX 661 bytes Request msg REGISTER/cseq=28617 (tdta003AE538) to UDP OUTBOUNDPROXY_IP:5060:
>> REGISTER sip:DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPj1caae52047514465bbbb37b048652f7f
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Max-Forwards: 70
>> From: <sip:USERID@DOMAIN>;tag=eb783c90ea264adeba0df424b03d9ed8
>> To: <sip:USERID at DOMAIN>
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> CSeq: 28617 REGISTER
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Contact: <sip:USERID at 192.168.1.25:5060;ob>
>> Expires: 300
>> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:17:56.384 tsx003AF5A4 ...State changed from Null to Calling, event=TX_MSG
>> 16:17:56.384 pjsua_acc.c ..Acc 2: Registration sent
>> 16:17:56.384 pjsua_acc.c Acc 2: setting online status to 1..
>> 16:17:56.384 pjsua_core.c PJSUA state changed: INIT --> STARTING
>> 16:17:56.384 sip_endpoint.c .pjsip_endpt_schedule_timer(entry=01423638, delay=300.0)
>> 16:17:56.384 sip_endpoint.c .Module "mod-unsolicited-mwi" registered
>> 16:17:56.384 pjsua_core.c .PJSUA state changed: STARTING --> RUNNING
>> 16:17:56.384 main.c Ready: Success
>> 16:17:56.759 sip_endpoint.c Processing incoming message: Response msg 401/REGISTER/cseq=28617 (rdata003A6214)
>> 16:17:56.759 pjsua_core.c .RX 715 bytes Response msg 401/REGISTER/cseq=28617 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 401 Unauthorized
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj1caae52047514465bbbb37b048652f7f;rport=5060
>> To: <sip:USERID at DOMAIN>;tag=54596245-54ef38b957bcfb4
>> From: <sip:USERID@DOMAIN>;tag=eb783c90ea264adeba0df424b03d9ed8
>> CSeq: 28617 REGISTER
>> Date: Thu, 26 Feb 2015 15:16:09 GMT
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> WWW-Authenticate: Digest realm="REALM",
>> nonce="xxx",
>> opaque="ALU:xxx",
>> algorithm=MD5,
>> qop="auth"
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:17:56.759 tsx003AF5A4 .Incoming Response msg 401/REGISTER/cseq=28617 (rdata003A6214) in state Calling
>> 16:17:56.759 tsx003AF5A4 ..State changed from Calling to Completed, event=RX_MSG
>> 16:17:56.760 tsx003B1CF4 ...tsx_key=c$REGISTER$z9hG4bKPje41f2d4140fd47d1835769e90ac88ffa
>> 16:17:56.760 tsx003B1CF4 ....Transaction created for Request msg REGISTER/cseq=28618 (tdta003AE538)
>> 16:17:56.760 tsx003B1CF4 ...Sending Request msg REGISTER/cseq=28618 (tdta003AE538) in state Null
>> 16:17:56.760 endpoint ....Request msg REGISTER/cseq=28618 (tdta003AE538): skipping target resolution because address is already set
>> 16:17:56.760 pjsua_core.c ....TX 1056 bytes Request msg REGISTER/cseq=28618 (tdta003AE538) to UDP OUTBOUNDPROXY_IP:5060:
>> REGISTER sip:DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPje41f2d4140fd47d1835769e90ac88ffa
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Max-Forwards: 70
>> From: <sip:USERID@DOMAIN>;tag=eb783c90ea264adeba0df424b03d9ed8
>> To: <sip:USERID at DOMAIN>
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> CSeq: 28618 REGISTER
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Contact: <sip:USERID at 192.168.1.25:5060;ob>
>> Expires: 300
>> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
>> Authorization: Digest username="AUTHNAME", realm="REALM", nonce="xxx", uri="sip:DOMAIN", response="xxx", algorithm=MD5, cnonce="xxx", opaque="ALU:xxx", qop=auth, nc=00000001
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:17:56.760 tsx003B1CF4 ....State changed from Null to Calling, event=TX_MSG
>> 16:17:56.873 sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=28618 (rdata003A6214)
>> 16:17:56.873 pjsua_core.c .RX 792 bytes Response msg 200/REGISTER/cseq=28618 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 200 OK
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPje41f2d4140fd47d1835769e90ac88ffa;rport=5060
>> To: <sip:USERID at DOMAIN>;tag=54596245-54ef38b9c28301d
>> From: <sip:USERID@DOMAIN>;tag=eb783c90ea264adeba0df424b03d9ed8
>> CSeq: 28618 REGISTER
>> Allow-Events: reg
>> Contact: <sip:USERID at 192.168.1.25:5060;ob;transport=udp>;expires=300
>> Date: Thu, 26 Feb 2015 15:16:09 GMT
>> Path: <sip:pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;lr;ottag=ue_term;bidx=6201093;access-type=ADSL>
>> P-Associated-URI: <sip:USERID at DOMAIN>
>> P-Associated-URI: <tel:USERID>
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:17:56.873 tsx003B1CF4 .Incoming Response msg 200/REGISTER/cseq=28618 (rdata003A6214) in state Calling
>> 16:17:56.873 tsx003B1CF4 ..State changed from Calling to Completed, event=RX_MSG
>> 16:17:56.873 sip_endpoint.c ...pjsip_endpt_schedule_timer(entry=003AC76C, delay=295.0)
>> 16:17:56.874 pjsua_acc.c ....SIP outbound status for acc 2 is not active
>> 16:17:56.874 pjsua_acc.c ....sip:USERID at DOMAIN: registration success, status=200 (OK), will re-register in 300 seconds
>> 16:17:56.874 sip_endpoint.c ....pjsip_endpt_schedule_timer(entry=013DA2B4, delay=15.0)
>> 16:17:56.874 pjsua_acc.c ....Keep-alive timer started for acc 2, destination:OUTBOUNDPROXY_IP:5060, interval:15s
>> 16:18:01.761 tsx003AF5A4 Timeout timer event
>> 16:18:01.761 tsx003AF5A4 .State changed from Completed to Terminated, event=TIMER
>> 16:18:01.761 tsx003AF5A4 Timeout timer event
>> 16:18:01.761 tsx003AF5A4 .State changed from Terminated to Destroyed, event=TIMER
>> 16:18:01.761 tsx003AF5A4 Transaction destroyed!
>> 16:18:01.875 tsx003B1CF4 Timeout timer event
>> 16:18:01.875 tsx003B1CF4 .State changed from Completed to Terminated, event=TIMER
>> 16:18:01.875 tsx003B1CF4 Timeout timer event
>> 16:18:01.875 tsx003B1CF4 .State changed from Terminated to Destroyed, event=TIMER
>> 16:18:01.875 tdta003AE538 ..Destroying txdata Request msg REGISTER/cseq=28618 (tdta003AE538)
>> 16:18:01.875 tsx003B1CF4 Transaction destroyed!
>> 16:18:07.342 pjsua_call.c Making call with acc #2 to sip:01xxxxxxxx at DOMAIN
>> 16:18:07.342 pjsua_aud.c .Set sound device: capture=-1, playback=-2
>> 16:18:07.342 pjsua_app.c ..Turning sound device ON
>> 16:18:07.342 pjsua_aud.c ..Opening sound device PCM at 16000/1/20ms
>> 16:18:07.376 wmme_dev.c ... WaveAPI Sound player "Wave mapper" initialized (format=PCM, clock_rate=16000, channel_count=1, samples_per_frame=320 (20ms))
>> 16:18:07.387 wmme_dev.c ... WaveAPI Sound recorder "Wave mapper" initialized (format=PCM, clock_rate=16000, channel_count=1, samples_per_frame=320 (20ms))
>> 16:18:07.388 ec003C2680 ...Creating AEC
>> 16:18:07.388 ec003C2680 ...AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=200 ms, latency=0 ms
>> 16:18:07.388 wmme_dev.c ...WMME playback stream started
>> 16:18:07.388 wmme_dev.c ...WMME capture stream started
>> 16:18:07.389 dlg003F40FC .UAC dialog created
>> 16:18:07.389 dlg003F40FC ..Session count inc to 2 by mod-pjsua
>> 16:18:07.389 pjsua_media.c .Call 0: initializing media..
>> 16:18:07.392 pjsua_media.c ..RTP socket reachable at 192.168.1.25:4000
>> 16:18:07.392 pjsua_media.c ..RTCP socket reachable at 192.168.1.25:4001
>> 16:18:07.392 pjsua_media.c ..Media index 0 selected for audio call 0
>> 16:18:07.392 dlg003F40FC ..Session count dec to 2 by mod-pjsua
>> 16:18:07.393 dlg003F40FC .Module mod-invite added as dialog usage, data=003A93BC
>> 16:18:07.393 dlg003F40FC ..Session count inc to 4 by mod-invite
>> 16:18:07.393 dlg003F40FC .Module mod-100rel added as dialog usage, data=003A99DC
>> 16:18:07.393 dlg003F40FC .100rel module attached
>> 16:18:07.393 inv003F40FC .UAC invite session created for dialog dlg003F40FC
>> 16:18:07.393 endpoint .Request msg INVITE/cseq=27953 (tdta003F9070) created.
>> 16:18:07.393 inv003F40FC ..Sending Request msg INVITE/cseq=27953 (tdta003F9070)
>> 16:18:07.393 dlg003F40FC ...Sending Request msg INVITE/cseq=27953 (tdta003F9070)
>> 16:18:07.393 tsx003FB084 ...tsx_key=c$z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36
>> 16:18:07.393 tsx003FB084 ....Transaction created for Request msg INVITE/cseq=27952 (tdta003F9070)
>> 16:18:07.393 tsx003FB084 ...Sending Request msg INVITE/cseq=27952 (tdta003F9070) in state Null
>> 16:18:07.393 sip_resolve.c ....DNS resolver not available, target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified will be resolved with getaddrinfo()
>> 16:18:07.394 sip_resolve.c ....Target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified resolved to 'OUTBOUNDPROXY_IP:5060' type=UDP (UDP transport)
>> 16:18:07.394 pjsua_core.c ....TX 1238 bytes Request msg INVITE/cseq=27952 (tdta003F9070) to UDP OUTBOUNDPROXY_IP:5060:
>> INVITE sip:01xxxxxxxx at DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36
>> Max-Forwards: 70
>> From: sip:USERID@DOMAIN;tag=1162169bb9034eac9d245678948fabfc
>> To: sip:01xxxxxxxx at DOMAIN
>> Contact: <sip:USERID at 192.168.1.25:5060;ob>
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> CSeq: 27952 INVITE
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
>> Supported: replaces, 100rel, timer, norefersub
>> Session-Expires: 1800
>> Min-SE: 90
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Content-Type: application/sdp
>> Content-Length: 473
>>
>> v=0
>> o=- 3633956287 3633956287 IN IP4 192.168.1.25
>> s=pjmedia
>> b=AS:84
>> t=0 0
>> a=X-nat:0
>> m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96
>> c=IN IP4 192.168.1.25
>> b=TIAS:64000
>> a=rtcp:4001 IN IP4 192.168.1.25
>> a=sendrecv
>> a=rtpmap:98 speex/16000
>> a=rtpmap:97 speex/8000
>> a=rtpmap:99 speex/32000
>> a=rtpmap:104 iLBC/8000
>> a=fmtp:104 mode=30
>> a=rtpmap:3 GSM/8000
>> a=rtpmap:0 PCMU/8000
>> a=rtpmap:8 PCMA/8000
>> a=rtpmap:9 G722/8000
>> a=rtpmap:96 telephone-event/8000
>> a=fmtp:96 0-16
>>
>> --end msg--
>> 16:18:07.394 tsx003FB084 ....State changed from Null to Calling, event=TX_MSG
>> 16:18:07.394 dlg003F40FC .....Transaction tsx003FB084 state changed to Calling
>> 16:18:07.394 pjsua_app.c .......Call 0 state changed to CALLING
>> 16:18:07.419 speex warning: discarded first playback frame
>> 16:18:07.448 speex warning: Auto-filling the buffer (your application is buggy and/or got xruns)
>> 16:18:07.448 sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:07.448 pjsua_core.c .RX 469 bytes Response msg 100/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 100 Trying
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Date: Thu, 26 Feb 2015 15:16:19 GMT
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:07.448 tsx003FB084 .Incoming Response msg 100/INVITE/cseq=27952 (rdata003A6214) in state Calling
>> 16:18:07.449 tsx003FB084 ..State changed from Calling to Proceeding, event=RX_MSG
>> 16:18:07.449 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:07.449 dlg003F40FC ...Received Response msg 100/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:07.449 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:10.337 sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:10.338 pjsua_core.c .RX 1097 bytes Response msg 183/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 183 Session Progress
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Require: 100rel
>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>> Contact: <sip:lucentNGFS-007410 at pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFFR0VFNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>> Content-Type: application/sdp
>> RSeq: 1
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 247
>>
>> v=0
>> o=LucentPCSF 600759623 600759623 IN IP4 imsgroup0-000.xxx.xxx.org
>> s=-
>> c=IN IP4 X.X.X.X
>> t=0 0
>> m=audio 37794 RTP/AVP 8 101
>> a=rtpmap:101 telephone-event/8000
>> a=sendrecv
>> a=ptime:20
>> a=maxptime:30
>> a=silenceSupp:off - - - -
>>
>> --end msg--
>> 16:18:10.338 tsx003FB084 .Incoming Response msg 183/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:10.338 tsx003FB084 ..State changed from Proceeding to Proceeding, event=RX_MSG
>> 16:18:10.338 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:10.338 dlg003F40FC ...Received Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:10.338 dlg003F40FC ....Route-set updated
>> 16:18:10.338 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:10.338 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>> 16:18:10.338 inv003F40FC ....Got SDP answer in Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:10.338 inv003F40FC ....SDP negotiation done, status=0
>> 16:18:10.338 pjsua_call.c .....Call 0: remote NAT type is 0 (Unknown)
>> 16:18:10.338 pjsua_media.c .....Call 0: updating media..
>> 16:18:10.338 pjsua_aud.c ......Audio channel update..
>> 16:18:10.338 mtx004067B4 .......Mutex created
>> 16:18:10.339 strm00405D94 .......VAD temporarily disabled
>> 16:18:10.339 rtp.c .......pjmedia_rtp_session_init: ses=00407C40, default_pt=8, ssrc=0x33ed08d6
>> 16:18:10.339 rtp.c .......pjmedia_rtp_session_init: ses=004082C8, default_pt=8, ssrc=0x33ed08d6
>> 16:18:10.339 stream.c .......Stream strm00405D94 created
>> 16:18:10.339 strm00405D94 .......Encoder stream started
>> 16:18:10.339 strm00405D94 .......Decoder stream started
>> 16:18:10.339 resample.c .......resample created: high qualiy, large filter, in/out rate=8000/16000
>> 16:18:10.339 resample.c .......resample created: high qualiy, large filter, in/out rate=16000/8000
>> 16:18:10.339 pjsua_media.c ......Audio updated, stream #0: PCMA (sendrecv)
>> 16:18:10.339 sip_endpoint.c .....pjsip_endpt_schedule_timer(entry=013DE684, delay=0.0)
>> 16:18:10.339 pjsua_app.c .....Call 0 media 0 [type=audio], status is Active
>> 16:18:10.339 pjsua_aud.c .....Conf connect: 3 --> 0
>> 16:18:10.339 conference.c ......Port 3 (sip:01xxxxxxxx at DOMAIN) transmitting to port 0 (Wave mapper)
>> 16:18:10.339 pjsua_aud.c .....Conf connect: 0 --> 3
>> 16:18:10.339 conference.c ......Port 0 (Wave mapper) transmitting to port 3 (sip:01xxxxxxxx at DOMAIN)
>> 16:18:10.339 endpoint ....Request msg PRACK/cseq=27954 (tdta00409890) created.
>> 16:18:10.339 dlg003F40FC .....Sending Request msg PRACK/cseq=27954 (tdta00409890)
>> 16:18:10.339 glck003AA7F8 .....Mutex created
>> 16:18:10.339 tsx0040A8FC .....Mutex created
>> 16:18:10.339 tsx0040A8FC .....tsx_key=c$PRACK$z9hG4bKPj4a9207e3ef1a444fa25f77a436b0662a
>> 16:18:10.339 tsx0040A8FC ......Transaction created for Request msg PRACK/cseq=27953 (tdta00409890)
>> 16:18:10.339 tsx0040A8FC .....Sending Request msg PRACK/cseq=27953 (tdta00409890) in state Null
>> 16:18:10.339 sip_resolve.c ......DNS resolver not available, target 'pcgw-0005.imsgroup0-000.xxx.xxx.org:5060' type=Unspecified will be resolved with getaddrinfo()
>> 16:18:10.340 sip_resolve.c ......Failed to resolve 'pcgw-0005.imsgroup0-000.xxx.xxx.org'. Err=70018 (gethostbyname() has returned error (PJ_ERESOLVE))
>> 16:18:10.340 tsx0040A8FC ......Failed to send Request msg PRACK/cseq=27953 (tdta00409890)! err=70018 (gethostbyname() has returned error (PJ_ERESOLVE))
>> 16:18:10.340 tsx0040A8FC ......State changed from Null to Terminated, event=TRANSPORT_ERROR
>> 16:18:10.340 dlg003F40FC .......Transaction tsx0040A8FC state changed to Terminated
>> 16:18:10.341 tsx0040A8FC Timeout timer event
>> 16:18:10.341 tsx0040A8FC .State changed from Terminated to Destroyed, event=TIMER
>> 16:18:10.341 tdta00409890 ..Destroying txdata Request msg PRACK/cseq=27953 (tdta00409890)
>> 16:18:10.341 tsx0040A8FC Transaction destroyed!
>> 16:18:10.358 strm00405D94 Jitter buffer is bufferring (prefetch=0), plc invoked
>> 16:18:10.359 strm00405D94 Start talksprut..
>> 16:18:10.907 sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:10.907 pjsua_core.c .RX 1097 bytes Response msg 183/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 183 Session Progress
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Require: 100rel
>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>> Contact: <sip:lucentNGFS-007410 at pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFFR0VFNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>> Content-Type: application/sdp
>> RSeq: 1
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 247
>>
>> v=0
>> o=LucentPCSF 600759623 600759623 IN IP4 imsgroup0-000.xxx.xxx.org
>> s=-
>> c=IN IP4 X.X.X.X
>> t=0 0
>> m=audio 37794 RTP/AVP 8 101
>> a=rtpmap:101 telephone-event/8000
>> a=sendrecv
>> a=ptime:20
>> a=maxptime:30
>> a=silenceSupp:off - - - -
>>
>> --end msg--
>> 16:18:10.907 tsx003FB084 .Incoming Response msg 183/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:10.907 tsx003FB084 ..State changed from Proceeding to Proceeding, event=RX_MSG
>> 16:18:10.907 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:10.907 dlg003F40FC ...Received Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:10.907 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:10.907 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>> 16:18:10.907 inv003F40FC ....SDP negotiation done, message body is ignored
>> 16:18:10.978 strm00405D94 VAD re-enabled
>> 16:18:10.978 strm00405D94 Starting silence
>> 16:18:11.085 strm00405D94 RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
>> 16:18:11.098 strm00405D94 Jitter buffer starts returning normal frames (after 37 empty/lost)
>> 16:18:11.875 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 2 to OUTBOUNDPROXY_IP:5060
>> 16:18:11.875 tdta00409890 Destroying txdata raw
>> 16:18:11.875 sip_endpoint.c pjsip_endpt_schedule_timer(entry=013DA2B4, delay=15.0)
>> 16:18:12.007 sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:12.007 pjsua_core.c .RX 1097 bytes Response msg 183/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 183 Session Progress
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Require: 100rel
>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>> Contact: <sip:lucentNGFS-007410 at pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFFR0VFNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>> Content-Type: application/sdp
>> RSeq: 1
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 247
>>
>> v=0
>> o=LucentPCSF 600759623 600759623 IN IP4 imsgroup0-000.xxx.xxx.org
>> s=-
>> c=IN IP4 X.X.X.X
>> t=0 0
>> m=audio 37794 RTP/AVP 8 101
>> a=rtpmap:101 telephone-event/8000
>> a=sendrecv
>> a=ptime:20
>> a=maxptime:30
>> a=silenceSupp:off - - - -
>>
>> --end msg--
>> 16:18:12.007 tsx003FB084 .Incoming Response msg 183/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:12.007 tsx003FB084 ..State changed from Proceeding to Proceeding, event=RX_MSG
>> 16:18:12.007 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:12.007 dlg003F40FC ...Received Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:12.007 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:12.007 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>> 16:18:12.007 inv003F40FC ....SDP negotiation done, message body is ignored
>> 16:18:12.418 strm00405D94 Start talksprut..
>> 16:18:12.438 strm00405D94 Starting silence
>> 16:18:14.106 sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:14.106 pjsua_core.c .RX 1097 bytes Response msg 183/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 183 Session Progress
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Require: 100rel
>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>> Contact: <sip:lucentNGFS-007410 at pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFFR0VFNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>> Content-Type: application/sdp
>> RSeq: 1
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 247
>>
>> v=0
>> o=LucentPCSF 600759623 600759623 IN IP4 imsgroup0-000.xxx.xxx.org
>> s=-
>> c=IN IP4 X.X.X.X
>> t=0 0
>> m=audio 37794 RTP/AVP 8 101
>> a=rtpmap:101 telephone-event/8000
>> a=sendrecv
>> a=ptime:20
>> a=maxptime:30
>> a=silenceSupp:off - - - -
>>
>> --end msg--
>> 16:18:14.106 tsx003FB084 .Incoming Response msg 183/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:14.106 tsx003FB084 ..State changed from Proceeding to Proceeding, event=RX_MSG
>> 16:18:14.106 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:14.106 dlg003F40FC ...Received Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:14.107 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:14.107 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>> 16:18:14.107 inv003F40FC ....SDP negotiation done, message body is ignored
>> 16:18:14.958 silencedet.c Re-adjust threshold (in silence)to 0
>> 16:18:17.419 strm00405D94 Start talksprut..
>> 16:18:17.439 strm00405D94 Starting silence
>> 16:18:18.208 sip_endpoint.c Processing incoming message: Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:18.208 pjsua_core.c .RX 1097 bytes Response msg 183/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 183 Session Progress
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Require: 100rel
>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>> Contact: <sip:lucentNGFS-007410 at pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFFR0VFNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>> Content-Type: application/sdp
>> RSeq: 1
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 247
>>
>> v=0
>> o=LucentPCSF 600759623 600759623 IN IP4 imsgroup0-000.xxx.xxx.org
>> s=-
>> c=IN IP4 X.X.X.X
>> t=0 0
>> m=audio 37794 RTP/AVP 8 101
>> a=rtpmap:101 telephone-event/8000
>> a=sendrecv
>> a=ptime:20
>> a=maxptime:30
>> a=silenceSupp:off - - - -
>>
>> --end msg--
>> 16:18:18.208 tsx003FB084 .Incoming Response msg 183/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:18.208 tsx003FB084 ..State changed from Proceeding to Proceeding, event=RX_MSG
>> 16:18:18.208 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:18.208 dlg003F40FC ...Received Response msg 183/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:18.208 dlg003F40FC ...Transaction tsx003FB084 state changed to Proceeding
>> 16:18:18.208 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>> 16:18:18.208 inv003F40FC ....SDP negotiation done, message body is ignored
>> 16:18:18.969 silencedet.c Re-adjust threshold (in silence)to 0
>> 16:18:22.428 strm00405D94 Start talksprut..
>> 16:18:22.448 strm00405D94 Starting silence
>> 16:18:22.968 silencedet.c Re-adjust threshold (in silence)to 0
>> 16:18:24.646 pjsua_call.c !Call 0 hanging up: code=0..
>> 16:18:24.647 endpoint ..Request msg CANCEL/cseq=27952 (tdta00409890) created.
>> 16:18:24.647 inv003F40FC ..Sending Request msg CANCEL/cseq=27952 (tdta00409890)
>> 16:18:24.647 dlg003F40FC ...Sending Request msg CANCEL/cseq=27952 (tdta00409890)
>> 16:18:24.647 tsx0040A8FC ...tsx_key=c$CANCEL$z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36
>> 16:18:24.647 tsx0040A8FC ....Transaction created for Request msg CANCEL/cseq=27952 (tdta00409890)
>> 16:18:24.647 tsx0040A8FC ...Sending Request msg CANCEL/cseq=27952 (tdta00409890) in state Null
>> 16:18:24.647 endpoint ....Request msg CANCEL/cseq=27952 (tdta00409890): skipping target resolution because address is already set
>> 16:18:24.647 pjsua_core.c ....TX 500 bytes Request msg CANCEL/cseq=27952 (tdta00409890) to UDP OUTBOUNDPROXY_IP:5060:
>> CANCEL sip:01xxxxxxxx at DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36
>> Max-Forwards: 70
>> From: sip:USERID@DOMAIN;tag=1162169bb9034eac9d245678948fabfc
>> To: sip:01xxxxxxxx at DOMAIN
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> CSeq: 27952 CANCEL
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:24.647 tsx0040A8FC ....State changed from Null to Calling, event=TX_MSG
>> 16:18:24.647 dlg003F40FC .....Transaction tsx0040A8FC state changed to Calling
>> 16:18:24.692 sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=27952 (rdata003A6214)
>> 16:18:24.692 pjsua_core.c .RX 493 bytes Response msg 200/CANCEL/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 200 OK
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: sip:01xxxxxxxx at DOMAIN;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: sip:USERID@DOMAIN;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 CANCEL
>> Date: Thu, 26 Feb 2015 15:16:37 GMT
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:24.692 tsx0040A8FC .Incoming Response msg 200/CANCEL/cseq=27952 (rdata003A6214) in state Calling
>> 16:18:24.692 tsx0040A8FC ..State changed from Calling to Completed, event=RX_MSG
>> 16:18:24.692 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:24.692 dlg003F40FC ...Received Response msg 200/CANCEL/cseq=27952 (rdata003A6214)
>> 16:18:24.692 dlg003F40FC ...Transaction tsx0040A8FC state changed to Completed
>> 16:18:24.692 sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:24.692 pjsua_core.c .RX 535 bytes Response msg 487/INVITE/cseq=27952 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 487 Request Terminated
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36;rport=5060
>> To: <sip:01xxxxxxxx at DOMAIN;user=phone>;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> From: <sip:USERID@DOMAIN;user=phone>;tag=1162169bb9034eac9d245678948fabfc
>> CSeq: 27952 INVITE
>> Date: Thu, 26 Feb 2015 15:16:37 GMT
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:24.692 tsx003FB084 .Incoming Response msg 487/INVITE/cseq=27952 (rdata003A6214) in state Proceeding
>> 16:18:24.692 endpoint ..Request msg ACK/cseq=27952 (tdta0040E5C8) created.
>> 16:18:24.693 pjsua_core.c ..TX 499 bytes Request msg ACK/cseq=27952 (tdta0040E5C8) to UDP OUTBOUNDPROXY_IP:5060:
>> ACK sip:01xxxxxxxx at DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPj4cff374a64f44dd59ed8163da9fcbd36
>> Max-Forwards: 70
>> From: sip:USERID@DOMAIN;tag=1162169bb9034eac9d245678948fabfc
>> To: sip:01xxxxxxxx at DOMAIN;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> Call-ID: b072b55fa1f14d3bb25591d61f3c73bc
>> CSeq: 27952 ACK
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:24.693 tsx003FB084 ..State changed from Proceeding to Completed, event=RX_MSG
>> 16:18:24.693 dlg003F40FC ...UA layer acquiring dialog lock for response
>> 16:18:24.693 dlg003F40FC ...Received Response msg 487/INVITE/cseq=27952 (rdata003A6214)
>> 16:18:24.693 dlg003F40FC ...Transaction tsx003FB084 state changed to Completed
>> 16:18:24.693 pjsua_app.c .....Call 0 is DISCONNECTED [reason=487 (Request Terminated)]
>> 16:18:24.693 pjsua_app.c .....Call 0 disconnected, dumping media stats..
>> 16:18:24.693 pjsua_app_comm .....
>> [DISCONNCTD] To: sip:01xxxxxxxx at DOMAIN;tag=54596251-54ef38c32e9e55a9-gm-po-lucentPCSF-035501
>> Call time: 00h:00m:00s, 1st res in 2949 ms, conn in 0ms
>> #0 audio PCMA @8kHz, sendrecv, peer=X.X.X.X:37794
>> SRTP status: Not active Crypto-suite:
>> RX pt=8, last update:00h:00m:04.245s ago
>> total 682pkt 108.8KB (136.1KB +IP hdr) @avg=60.6Kbps/75.8Kbps
>> pkt loss=0 (0.0%), discrd=0 (0.0%), dup=0 (0.0%), reord=0 (0.0%)
>> (msec) min avg max last dev
>> loss period: 0.000 0.000 0.000 0.000 0.000
>> jitter : 0.000 0.224 1.250 0.250 0.133
>> TX pt=8, ptime=20, last update:00h:00m:04.428s ago
>> total 34pkt 5.4KB (6.8KB +IP hdr) @avg=3.0Kbps/3.7Kbps
>> pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
>> (msec) min avg max last dev
>> loss period: 0.000 0.000 0.000 0.000 0.000
>> jitter : 107.250 260.125 413.000 413.000 56.755
>> RTT msec : 168.000 177.000 186.000 186.000 9.000
>> 16:18:24.693 pjsua_media.c .....Call 0: deinitializing media..
>> 16:18:24.693 sip_endpoint.c .......pjsip_endpt_schedule_timer(entry=014237B0, delay=1.0)
>> 16:18:24.694 mtx004067B4 .......Mutex destroyed
>> 16:18:24.694 strm00405D94 .......JB summary:
>> size=1/eff=1 prefetch=0 level=2
>> delay (min/max/avg/dev)=20/40/29/6 ms
>> burst (min/max/avg/dev)=1/4/2/0 frames
>> lost=0 discard=0 empty=37
>> 16:18:24.694 pjsua_media.c .......Media stream call00:0 is destroyed
>> 16:18:24.694 srtp003F70A8 ......Mutex destroyed
>> 16:18:24.694 dlg003F40FC .....Session count dec to 1 by mod-invite
>> 16:18:24.694 tdta003F9070 ..Destroying txdata Request msg INVITE/cseq=27952 (tdta003F9070)
>> 16:18:25.694 pjsua_aud.c Closing sound device after idle for 1 second(s)
>> 16:18:25.694 pjsua_app.c .Turning sound device OFF
>> 16:18:25.694 pjsua_aud.c .Closing Wave mapper sound playback device and Wave mapper sound capture device
>> 16:18:25.696 wmme_dev.c .Stopped WMME playback stream
>> 16:18:25.697 wmme_dev.c .Stopped WMME capture stream
>> 16:18:25.697 wmme_dev.c .Stopped WMME playback stream
>> 16:18:25.697 wmme_dev.c .Stopped WMME capture stream
>> 16:18:25.697 pjsua .Joining thread wmme
>> 16:18:25.697 wmme_dev.c !WMME: thread stopping..
>> 16:18:25.697 wmme Thread quitting
>> 16:18:25.697 wmme Thread stack max usage=4837 by ..\src\pj\string.c:226
>> 16:18:26.876 pjsua_acc.c Sending 2 bytes keep-alive packet for acc 2 to OUTBOUNDPROXY_IP:5060
>> 16:18:26.876 tdta003AE538 Destroying txdata raw
>> 16:18:26.876 sip_endpoint.c pjsip_endpt_schedule_timer(entry=013DA2B4, delay=15.0)
>> 16:18:29.692 tsx0040A8FC Timeout timer event
>> 16:18:29.692 tsx0040A8FC .State changed from Completed to Terminated, event=TIMER
>> 16:18:29.692 dlg003F40FC ..Transaction tsx0040A8FC state changed to Terminated
>> 16:18:29.692 tsx0040A8FC Timeout timer event
>> 16:18:29.692 tsx0040A8FC .State changed from Terminated to Destroyed, event=TIMER
>> 16:18:29.692 tdta00409890 ..Destroying txdata Request msg CANCEL/cseq=27952 (tdta00409890)
>> 16:18:29.692 tsx0040A8FC Transaction destroyed!
>> 16:18:31.257 pjsua_core.c Shutting down, flags=0...
>> 16:18:31.257 pjsua_core.c PJSUA state changed: RUNNING --> CLOSING
>> 16:18:31.257 thr00002704 Joining thread pjsua
>> 16:18:31.262 pjsua !Thread quitting
>> 16:18:31.262 pjsua Thread stack max usage=8473 by ..\src\pj\string.c:226
>> 16:18:31.262 pjsua_call.c !.Hangup all calls..
>> 16:18:31.262 pjsua_media.c .Call 0: deinitializing media..
>> 16:18:31.262 pjsua_media.c .Call 1: deinitializing media..
>> 16:18:31.262 pjsua_media.c .Call 2: deinitializing media..
>> 16:18:31.262 pjsua_media.c .Call 3: deinitializing media..
>> 16:18:31.262 pjsua_pres.c .Shutting down presence..
>> 16:18:31.262 sip_endpoint.c ..pjsip_endpt_cancel_timer(entry=01423638)
>> 16:18:31.262 pjsua_acc.c .Acc 2: setting unregistration..
>> 16:18:31.262 sip_endpoint.c ..pjsip_endpt_cancel_timer(entry=003AC76C)
>> 16:18:31.262 endpoint ..Request msg REGISTER/cseq=28618 (tdta003AE538) created.
>> 16:18:31.262 tsx0037CF24 ..tsx_key=c$REGISTER$z9hG4bKPjc97ba121b18c4073b6de2550e6d4d33d
>> 16:18:31.262 tsx0037CF24 ...Transaction created for Request msg REGISTER/cseq=28619 (tdta003AE538)
>> 16:18:31.262 tsx0037CF24 ..Sending Request msg REGISTER/cseq=28619 (tdta003AE538) in state Null
>> 16:18:31.262 sip_resolve.c ...DNS resolver not available, target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified will be resolved with getaddrinfo()
>> 16:18:31.263 sip_resolve.c ...Target 'OUTBOUNDPROXY_NAME:5060' type=Unspecified resolved to 'OUTBOUNDPROXY_IP:5060' type=UDP (UDP transport)
>> 16:18:31.263 pjsua_core.c ...TX 561 bytes Request msg REGISTER/cseq=28619 (tdta003AE538) to UDP OUTBOUNDPROXY_IP:5060:
>> REGISTER sip:DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPjc97ba121b18c4073b6de2550e6d4d33d
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Max-Forwards: 70
>> From: <sip:USERID@DOMAIN>;tag=e259de5bf7f2420f820f1213d293856b
>> To: <sip:USERID at DOMAIN>
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> CSeq: 28619 REGISTER
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Contact: <sip:USERID at 192.168.1.25:5060;ob>
>> Expires: 0
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:31.263 tsx0037CF24 ...State changed from Null to Calling, event=TX_MSG
>> 16:18:31.263 pjsua_acc.c ..Acc 2: Unregistration sent
>> 16:18:31.372 sip_endpoint.c .Processing incoming message: Response msg 401/REGISTER/cseq=28619 (rdata003A6214)
>> 16:18:31.372 pjsua_core.c ..RX 716 bytes Response msg 401/REGISTER/cseq=28619 (rdata003A6214) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 401 Unauthorized
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPjc97ba121b18c4073b6de2550e6d4d33d;rport=5060
>> To: <sip:USERID at DOMAIN>;tag=54596245-54ef38db29f74c9b
>> From: <sip:USERID@DOMAIN>;tag=e259de5bf7f2420f820f1213d293856b
>> CSeq: 28619 REGISTER
>> Date: Thu, 26 Feb 2015 15:16:43 GMT
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> WWW-Authenticate: Digest realm="REALM",
>> nonce="xxx",
>> opaque="ALU:xxx",
>> algorithm=MD5,
>> qop="auth"
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:31.372 tsx0037CF24 ..Incoming Response msg 401/REGISTER/cseq=28619 (rdata003A6214) in state Calling
>> 16:18:31.372 tsx0037CF24 ...State changed from Calling to Completed, event=RX_MSG
>> 16:18:31.372 glck003A9FD8 ....Mutex created
>> 16:18:31.372 tsx0041157C ....Mutex created
>> 16:18:31.372 tsx0041157C ....tsx_key=c$REGISTER$z9hG4bKPj529256ca5b38499d8ab92a12f22e9d83
>> 16:18:31.372 tsx0041157C .....Transaction created for Request msg REGISTER/cseq=28620 (tdta003AE538)
>> 16:18:31.372 tsx0041157C ....Sending Request msg REGISTER/cseq=28620 (tdta003AE538) in state Null
>> 16:18:31.372 endpoint .....Request msg REGISTER/cseq=28620 (tdta003AE538): skipping target resolution because address is already set
>> 16:18:31.372 pjsua_core.c .....TX 956 bytes Request msg REGISTER/cseq=28620 (tdta003AE538) to UDP OUTBOUNDPROXY_IP:5060:
>> REGISTER sip:DOMAIN SIP/2.0
>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPj529256ca5b38499d8ab92a12f22e9d83
>> Route: <sip:OUTBOUNDPROXY_NAME:5060;lr>
>> Max-Forwards: 70
>> From: <sip:USERID@DOMAIN>;tag=e259de5bf7f2420f820f1213d293856b
>> To: <sip:USERID at DOMAIN>
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> CSeq: 28620 REGISTER
>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>> Contact: <sip:USERID at 192.168.1.25:5060;ob>
>> Expires: 0
>> Authorization: Digest username="AUTHNAME", realm="REALM", nonce="xxx", uri="sip:DOMAIN", response="xxx", algorithm=MD5, cnonce="xxx", opaque="ALU:xxx", qop=auth, nc=00000001
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:31.373 tsx0041157C .....State changed from Null to Calling, event=TX_MSG
>> 16:18:31.447 sip_endpoint.c .Processing incoming message: Response msg 200/REGISTER/cseq=28620 (rdata003F9084)
>> 16:18:31.447 pjsua_core.c ..RX 772 bytes Response msg 200/REGISTER/cseq=28620 (rdata003F9084) from UDP OUTBOUNDPROXY_IP:5060:
>> SIP/2.0 200 OK
>> Call-ID: 9a4de08282c5425f87ad8241a66aad68
>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPj529256ca5b38499d8ab92a12f22e9d83;rport=5060
>> To: <sip:USERID at DOMAIN>;tag=54596245-54ef38db2e66fecc
>> From: <sip:USERID@DOMAIN>;tag=e259de5bf7f2420f820f1213d293856b
>> CSeq: 28620 REGISTER
>> Contact: <sip:USERID at 192.168.1.25:5060;ob;transport=udp>;expires=0
>> Date: Thu, 26 Feb 2015 15:16:43 GMT
>> Path: <sip:pcgw-0005.imsgroup0-000.xxx.xxx.org:5060;lr;ottag=ue_term;bidx=6201093;access-type=ADSL>
>> P-Associated-URI: <sip:USERID at DOMAIN>
>> P-Associated-URI: <tel:USERID>
>> Server: Alcatel-Lucent-HPSS/3.0.3
>> Content-Length: 0
>>
>>
>> --end msg--
>> 16:18:31.447 tsx0041157C ..Incoming Response msg 200/REGISTER/cseq=28620 (rdata003F9084) in state Calling
>> 16:18:31.448 tsx0041157C ...State changed from Calling to Completed, event=RX_MSG
>> 16:18:31.448 sip_endpoint.c .....pjsip_endpt_cancel_timer(entry=013DA2B4)
>> 16:18:31.448 pjsua_acc.c .....sip:USERID at DOMAIN: unregistration success
>> 16:18:31.448 regc003AC548 ....Mutex destroyed
>> 16:18:32.298 pjsua_core.c .Destroying...
>> 16:18:32.298 pjsua_media.c .Shutting down media..
>> 16:18:32.298 thr00002704 ..Joining thread media
>> 16:18:32.694 media !Thread quitting
>> 16:18:32.694 media Thread stack max usage=6153 by ..\src\pj\string.c:226
>> 16:18:32.695 sip_endpoint.c .Destroying endpoing instance..
>> 16:18:32.695 sip_transactio .Stopping transaction layer module
>> 16:18:32.695 tsx003FB084 .Request to terminate transaction
>> 16:18:32.695 tsx003FB084 ..State changed from Completed to Terminated, event=USER
>> 16:18:32.695 dlg003F40FC ...Transaction tsx003FB084 state changed to Terminated
>> 16:18:32.695 dlg003F40FC ....Dialog destroyed
>> 16:18:32.695 dlg003F40FC ....Mutex destroyed
>> 16:18:32.695 tdta0040E5C8 .Destroying txdata Request msg ACK/cseq=27952 (tdta0040E5C8)
>> 16:18:32.695 tsx003FB084 .Transaction destroyed!
>> 16:18:32.695 tsx0037CF24 .Request to terminate transaction
>> 16:18:32.695 tsx0037CF24 ..State changed from Completed to Terminated, event=USER
>> 16:18:32.695 tsx0037CF24 .Transaction destroyed!
>> 16:18:32.695 tsx0041157C .Request to terminate transaction
>> 16:18:32.695 tsx0041157C ..State changed from Completed to Terminated, event=USER
>> 16:18:32.696 tdta003AE538 .Destroying txdata Request msg REGISTER/cseq=28620 (tdta003AE538)
>> 16:18:32.696 tsx0041157C .Transaction destroyed!
>> 16:18:32.696 sip_transactio .Stopped transaction layer module
>> 16:18:32.696 sip_endpoint.c .Module "mod-default-handler" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-unsolicited-mwi" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-pjsua-options" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-pjsua-im" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-pjsua-pres" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-pjsua" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-stateful-util" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-refer" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-mwi" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-presence" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-evsub" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-invite" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-100rel" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-ua" unregistered
>> 16:18:32.696 sip_transactio .Transaction layer module destroyed
>> 16:18:32.696 sip_endpoint.c .Module "mod-tsx-layer" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-msg-print" unregistered
>> 16:18:32.696 sip_endpoint.c .Module "mod-pjsua-log" unregistered
>> 16:18:32.696 sip_transport. .Destroying transport manager
>> 16:18:32.697 tcplis:5060 .SIP TCP listener destroyed
>> 16:18:32.697 sip_endpoint.c .Endpoint 0036F554 destroyed
>> 16:18:32.698 pjsua_core.c .PJSUA state changed: CLOSING --> NULL
>> 16:18:32.698 pjsua_core.c .PJSUA destroyed...
>>
>>
>> Thanks !
>>
>>
>> Mathieu
>>
>>
>>
>>
>>
>>
>> Sent: Thursday, February 26, 2015 at 4:45 PM
>> From: "Bill Gardner" <billg@xxxxxxxxxxxx>
>> To: pjsip at lists.pjsip.org
>> Subject: Re: Strange behavior when making a call (format fix)
>> Hi Mathieu,
>>
>> I'm really not a SIP expert, but my reading of this is that the bad
>> contact address causes the PRACK to not be sent and the other endpoint
>> keeps sending the 183 and finally gives up and sends a BYE. But the
>> contact address looks OK. Can you do an nslookup of
>> pcgw-0005.xxx.wiz.net and see if that works on your machine?
>>
>> Regards,
>>
>> Bill
>>
>> On 2/26/2015 9:59 AM, Mathieu Trinc wrote:
>>> Hi Bill,
>>>
>>> The error occurs when PJSIP tries to resolve a hostname present in the Contact field of the first '183 Statut progress' message received:
>>>
>>> Contact: <sip:lucentNGFS-000116 at pcgw-0005.xxx.wiz.net:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFCQkVDNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>>>
>>> Could this error explain why I keep receiving these messages?
>>>
>>> I set the log verbosity level to 6 but there is not much information (Is there a way to get more detailed information?):
>>>
>>> 09:46:21.703 pjsua_core.c !.pjsua version 2.3 for win32-6.1/i386/msvc-18.0 initialized
>>> 09:46:21.711 main.c Ready: Success
>>> 09:46:22.002 pjsua_acc.c !....sip:from at foo.org: registration success, status=200 (OK), will re-register in 300 seconds
>>> 09:46:40.171 pjsua_app.c !..Turning sound device ON
>>> 09:46:40.222 pjsua_app.c .......Call 0 state changed to CALLING
>>> 09:46:42.919 pjsua_app.c !.....Call 0 state changed to EARLY (183 Session Progress)
>>> 09:46:42.976 tsx005CBDEC ......Failed to send Request msg PRACK/cseq=18743 (tdta005CAD80)! err=70018 (gethostbyname() has returned error (PJ_ERESOLVE))
>>> 09:46:43.494 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>> 09:46:44.593 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>> 09:46:46.694 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>> 09:46:50.795 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>> 09:46:53.696 pjsua_app.c .....Call 0 is DISCONNECTED [reason=487 (Request Terminated)]
>>> 09:46:53.696 pjsua_app_comm .....
>>> [DISCONNCTD] To: sip:to at foo.org;tag=54596251-54ef31642d05c34a-gm-po-lucentPCSF-152762
>>> Call time: 00h:00m:00s, 1st res in 2701 ms, conn in 0ms
>>> #0 audio PCMA @8kHz, sendrecv, peer=85.31.200.0:48546
>>> SRTP status: Not active Crypto-suite:
>>> RX pt=8, last update:00h:00m:00.684s ago
>>> total 508pkt 80.0KB (100.4KB +IP hdr) @avg=59.4Kbps/74.5Kbps
>>> pkt loss=1 (0.2%), discrd=0 (0.0%), dup=0 (0.0%), reord=0 (0.0%)
>>> (msec) min avg max last dev
>>> loss period: 20.000 20.000 20.000 20.000 0.000
>>> jitter : 0.000 0.291 1.500 0.125 0.210
>>> TX pt=8, ptime=20, last update:00h:00m:00.818s ago
>>> total 33pkt 5.2KB (6.6KB +IP hdr) @avg=3.9Kbps/4.8Kbps
>>> pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
>>> (msec) min avg max last dev
>>> loss period: 0.000 0.000 0.000 0.000 0.000
>>> jitter : 123.500 275.938 428.375 428.375 56.755
>>> RTT msec : 154.000 165.500 177.000 177.000 11.500
>>> 09:46:54.696 pjsua_app.c .Turning sound device OFF
>>> 09:46:57.188 pjsua_acc.c !.....sip:from at foo.org: unregistration success
>>>
>>>
>>> Thanks !
>>>
>>>
>>> Mathieu
>>>
>>>
>>>
>>> Sent: Thursday, February 26, 2015 at 2:45 PM
>>> From: "Bill Gardner" <billg@xxxxxxxxxxxx>
>>> To: pjsip at lists.pjsip.org
>>> Subject: Re: Strange behavior when making a call (format fix)
>>> Hi Mathieu,
>>>
>>> I think you should track down the source of the PJ_ERESOLVE error. Can
>>> you send a complete log?
>>>
>>> Regards,
>>>
>>> Bill
>>>
>>> On 2/26/2015 6:29 AM, Mathieu Trinc wrote:
>>>> (Sorry for the previous email which was in HTML format)
>>>>
>>>> Hello everyone,
>>>>
>>>> I'm trying to use pjsua to make a call. The registration process works fine but when I make a call I notice a strange behavior: the INVITE message is sent, I receive a "Status: 100 Trying" message
>>>> and then I keep receiving "Status: 183 Session Progress" messages until the recipient answers. The communication is then established but I think some SIP messages are missing (for instance there is no 200 OK message)
>>>> and this leads to an incorrect state (I do not know when the call is established, how long it lasts, etc.).
>>>>
>>>> (I tried to make the same call with a different softphone (XLite) and I get a different behavior:
>>>> INVITE - 100 Trying - 183 Session Progress - 180 Ringing. And when the recipient answers I get 200 OK)
>>>>
>>>> Any help to understand what is going on and how to get the standard behavior would be greatly appreciated.
>>>>
>>>> Here is the log displayed in pjsua and the details of some SIP messages (slightly modified for privacy concerns):
>>>>
>>>> 02:31:35.649 pjsua_app.c !..Turning sound device ON
>>>> 02:31:35.699 pjsua_app.c .......Call 0 state changed to CALLING
>>>> 02:31:39.446 pjsua_app.c !.....Call 0 state changed to EARLY (183 Session Progress)
>>>> 02:31:39.448 tsx0060CD0C ......Failed to send Request msg PRACK/cseq=17029 (tdta0060BCA0)! err=70018 (gethostbyname() has returned error (PJ_ERESOLVE))
>>>> 02:31:39.981 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>>> 02:31:41.081 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>>> 02:31:43.181 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>>> 02:31:47.280 pjsua_app.c .....Call 0 state changed to EARLY (183 Session Progress)
>>>>
>>>> // The recipient answers and we can communicate
>>>>
>>>> // I decide to hang up (if it is the recipient that hangs up I get this after a few seconds: Call 0 is DISCONNECTED [reason=500 (Server Inernal Error)])
>>>> h
>>>>
>>>> 02:31:54.231 pjsua_app.c .....Call 0 is DISCONNECTED [reason=487 (Request Terminated)]
>>>> 02:31:54.232 pjsua_app_comm .....
>>>> [DISCONNCTD] To: sip:to at foo.org;tag=54596251
>>>> -54ee770c1f6962c8-gm-po-lucentPCSF-055498
>>>> Call time: 00h:00m:00s, 1st res in 3750 ms, conn in 0ms
>>>> #0 audio PCMA @8kHz, sendrecv, peer=85.31.200.0:47386
>>>> SRTP status: Not active Crypto-suite:
>>>> RX pt=8, last update:00h:00m:04.702s ago
>>>> total 706pkt 112.6KB (140.8KB +IP hdr) @avg=60.9Kbps/76.2Kbps
>>>> pkt loss=0 (0.0%), discrd=0 (0.0%), dup=0 (0.0%), reord=0 (0.0%)
>>>> (msec) min avg max last dev
>>>> loss period: 0.000 0.000 0.000 0.000 0.000
>>>> jitter : 0.000 0.206 1.250 0.250 0.137
>>>> TX pt=8, ptime=20, last update:00h:00m:04.838s ago
>>>> total 34pkt 5.4KB (6.8KB +IP hdr) @avg=2.9Kbps/3.6Kbps
>>>> pkt loss=0 (0.0%), dup=0 (0.0%), reorder=0 (0.0%)
>>>> (msec) min avg max last dev
>>>> loss period: 0.000 0.000 0.000 0.000 0.000
>>>> jitter : 82.000 225.063 368.125 368.125 56.755
>>>> RTT msec : 175.000 233.500 292.000 175.000 56.755
>>>> 02:31:55.237 pjsua_app.c .Turning sound device OFF
>>>>
>>>> INVITE sip:to at foo.org SIP/2.0
>>>> Via: SIP/2.0/UDP 192.168.1.25:5060;rport;branch=z9hG4bKPja40ebf7032174a939b836f6a4030dfd9
>>>> Max-Forwards: 70
>>>> From: sip:from@xxxxxxx;tag=bc2c850cf705496cabe58b4a071794fb
>>>> To: sip:to at foo.org
>>>> Contact: <sip:from at 192.168.1.25:5060;ob>
>>>> Call-ID: 635050fa9ef7442990b7809c34a2328b
>>>> CSeq: 17028 INVITE
>>>> Route: <sip:p-cscf.wiz.net:5060;lr>
>>>> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
>>>> Supported: replaces, 100rel, timer, norefersub
>>>> Session-Expires: 1800
>>>> Min-SE: 90
>>>> User-Agent: PJSUA v2.3 win32-6.1/i386/msvc-18.0
>>>> Content-Type: application/sdp
>>>> Content-Length: 473
>>>> v=0
>>>> o=- 3633906695 3633906695 IN IP4 192.168.1.25
>>>> s=pjmedia
>>>> b=AS:84
>>>> t=0 0
>>>> a=X-nat:0
>>>> m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96
>>>> c=IN IP4 192.168.1.25
>>>> b=TIAS:64000
>>>> a=rtcp:4001 IN IP4 192.168.1.25
>>>> a=sendrecv
>>>> a=rtpmap:98 speex/16000
>>>> a=rtpmap:97 speex/8000
>>>> a=rtpmap:99 speex/32000
>>>> a=rtpmap:104 iLBC/8000
>>>> a=fmtp:104 mode=30
>>>> a=rtpmap:3 GSM/8000
>>>> a=rtpmap:0 PCMU/8000
>>>> a=rtpmap:8 PCMA/8000
>>>> a=rtpmap:9 G722/8000
>>>> a=rtpmap:96 telephone-event/8000
>>>> a=fmtp:96 0-16
>>>>
>>>> SIP/2.0 100 Trying
>>>> Call-ID: 635050fa9ef7442990b7809c34a2328b
>>>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPja40ebf7032174a939b836f6a4030dfd9;rport=5060
>>>> To: <sip:to at foo.org;user=phone>
>>>> From: <sip:from@xxxxxxx;user=phone>;tag=bc2c850cf705496cabe58b4a071794fb
>>>> CSeq: 17028 INVITE
>>>> Date: Thu, 26 Feb 2015 01:29:48 GMT
>>>> Server: Alcatel-Lucent-HPSS/3.0.3
>>>> Content-Length: 0
>>>>
>>>> SIP/2.0 183 Session Progress
>>>> Call-ID: 635050fa9ef7442990b7809c34a2328b
>>>> Via: SIP/2.0/UDP 192.168.1.25:5060;received=192.168.1.25;branch=z9hG4bKPja40ebf7032174a939b836f6a4030dfd9;rport=5060
>>>> To: <sip:to at foo.org;user=phone>;tag=54596251-54ee770c1f6962c8-gm-po-lucentPCSF-055498
>>>> From: <sip:from@xxxxxxx;user=phone>;tag=bc2c850cf705496cabe58b4a071794fb
>>>> CSeq: 17028 INVITE
>>>> Require: 100rel
>>>> Allow: INVITE,BYE,REGISTER,ACK,OPTIONS,CANCEL,SUBSCRIBE,NOTIFY,PRACK,INFO,REFER,UPDATE
>>>> Contact: <sip:lucentNGFS-000116 at pcgw-0005.xxx.wiz.net:5060;encoded-parm=QbkRBthOEgsTXgkTBA0HHiUrKz1CQEFCQkVDNgQMGAlsMTcgK2ghOyAnOCs.ITogYX9jZmR4NjsxblJGQAQEGF5VSh5dSBNMDQERXFJYX1o_>
>>>> Content-Type: application/sdp
>>>> RSeq: 1
>>>> Server: Alcatel-Lucent-HPSS/3.0.3
>>>> Content-Length: 220
>>>> v=0
>>>> o=LucentPCSF 113972553 113972553 IN IP4 .wiz.net
>>>> s=-
>>>> c=IN IP4 85.31.200.0
>>>> t=0 0
>>>> m=audio 47386 RTP/AVP 8 101
>>>> a=rtpmap:101 telephone-event/8000
>>>> a=sendrecv
>>>> a=ptime:20
>>>> a=maxptime:30
>>>>
>>>> Thank you !
>>>>
>>>> Mathieu
>>>>
>>>> _______________________________________________
>>>> Visit our blog: http://blog.pjsip.org
>>>>
>>>> pjsip mailing list
>>>> pjsip at lists.pjsip.org
>>>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]]]
>>> _______________________________________________
>>> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]][http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]][http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]][http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]]]
>>>
>>> pjsip mailing list
>>> pjsip at lists.pjsip.org
>>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]]]
>>>
>>> _______________________________________________
>>> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]][http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]]
>>>
>>> pjsip mailing list
>>> pjsip at lists.pjsip.org
>>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]]
>> _______________________________________________
>> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]][http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]]
>>
>> pjsip mailing list
>> pjsip at lists.pjsip.org
>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]]
>>
>> _______________________________________________
>> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]
>>
>> pjsip mailing list
>> pjsip at lists.pjsip.org
>> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]
>
> _______________________________________________
> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org][http://blog.pjsip.org[http://blog.pjsip.org]]
>
> pjsip mailing list
> pjsip at lists.pjsip.org
> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org][http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]]
>
> _______________________________________________
> Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org]
>
> pjsip mailing list
> pjsip at lists.pjsip.org
> http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]


_______________________________________________
Visit our blog: http://blog.pjsip.org[http://blog.pjsip.org]

pjsip mailing list
pjsip at lists.pjsip.org
http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org[http://lists.pjsip.org/mailman/listinfo/pjsip_lists.pjsip.org]



[Index of Archives]     [Asterisk Users]     [Asterisk App Development]     [Linux ARM Kernel]     [Linux ARM]     [Linux Omap]     [Fedora ARM]     [IETF Annouce]     [Security]     [Bugtraq]     [Linux]     [Linux OMAP]     [Linux MIPS]     [Linux API]
  Powered by Linux