[Freeswitch-users] 200 OK not forwarded
David Villasmil
david.villasmil.work at gmail.com
Fri Mar 3 01:53:37 MSK 2017
Hello guys,
By the way, the subject reads "200 ok not forwarded", but it's actually the
BYE...
I'm hoping there's something obvious i'm not seeing.... but it's still
happening, BYE is not being forwarded and the other leg stays there until a
timeout where the a leg triggers a BYE to be sent to FS and FS responds
with 481...
The only thing I see is a "not found by name" but i'm not sure what that
means (I'd say fs can't find the other leg by name? Don't know why, the
call is up)
Help is very much appreciated.
Attaching fs log with sofia debug on...
David
ᐧ
Regards,
David Villasmil
email: david.villasmil.work at gmail.com
phone: +34669448337
On Thu, Mar 2, 2017 at 9:13 PM, David Villasmil <
david.villasmil.work at gmail.com> wrote:
> Michael,
>
> Installing FreeSWITCH (Version 1.6.15 -32-bec4538 64bit) seems to have
> solved the problem, keep you posted.
>
> Thanks for the suggestion.
>
> David
> ᐧ
>
> Regards,
>
> David Villasmil
> email: david.villasmil.work at gmail.com
> phone: +34669448337 <+34%20669%2044%2083%2037>
>
> On Thu, Mar 2, 2017 at 6:38 PM, David Villasmil <
> david.villasmil.work at gmail.com> wrote:
>
>> Will do, still will also do the debugging
>>
>> On Thu, Mar 2, 2017 at 6:24 PM Michael Jerris <mike at jerris.com> wrote:
>>
>>> I’d update to latest 1.6 release or latest master before you do anything
>>> else here.
>>>
>>> On Mar 2, 2017, at 10:04 AM, David Villasmil <
>>> david.villasmil.work at gmail.com> wrote:
>>>
>>> Hello Guys,
>>>
>>> I'm using FreeSWITCH (Version 1.9.0 git f3b7105 2016-11-15 01:50:51Z
>>> 64bit) is ready
>>>
>>> And i'm seeing the issue where the 200OK is not being forwarded from FS
>>> to the client.
>>>
>>> I'm attaching FS Log and sip trace.
>>>
>>> 1.1.1.1 = Client (Grandstream GXP1165)
>>> 9.9.9.9 = freeSWITCH
>>> 10.10.10.10 = Terminating GW (my_gateway)
>>>
>>> Been scratching my head for some time...
>>>
>>>
>>> Appreciate your help!
>>>
>>>
>>>
>>> Regards,
>>>
>>> David Villasmil
>>> email: david.villasmil.work at gmail.com
>>> phone: +34669448337 <+34%20669%2044%2083%2037>
>>> ᐧ
>>>
>>> <no_forward_200_ok.txt><no_forward_200ok_fs_log.txt>________
>>> _________________________________________________________________
>>>
>>>
>>> Professional FreeSWITCH Consulting Services:
>>> consulting at freeswitch.org
>>> http://www.freeswitchsolutions.com
>>>
>>> Official FreeSWITCH Sites
>>> http://www.freeswitch.org
>>> http://confluence.freeswitch.org
>>> http://www.cluecon.com
>>>
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>>
>>> ____________________________________________________________
>>> _____________
>>> Professional FreeSWITCH Consulting Services:
>>> consulting at freeswitch.org
>>> http://www.freeswitchsolutions.com
>>>
>>> Official FreeSWITCH Sites
>>> http://www.freeswitch.org
>>> http://confluence.freeswitch.org
>>> http://www.cluecon.com
>>>
>>> FreeSWITCH-users mailing list
>>> FreeSWITCH-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20170302/994b3eb5/attachment-0001.html
-------------- next part --------------
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940f9740 from (udp/9.9.9.9:5066) has 20 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): bad msg 0x7f78940f9740 (0 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103899443)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78baeedd40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f78940048f0): events IN
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940f6af0
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f6af0): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f6af0): Setting TCP_KEEPINTVL to 30
tport.c:2640 tport_accept() tport_accept(0x7f78940f6af0): new connection from tcp/1.1.1.1:33919/sip
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f6af0) msg 0x7f78940edcc0 from (tcp/1.1.1.1:33919) has 1223 bytes, veclen = 1
recv 1223 bytes from tcp/[1.1.1.1]:33919 at 17:23:59.741159:
------------------------------------------------------------------------
INVITE sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK1821569725;rport;alias
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1300 INVITE
Contact: "3059001003" <sip:3059001003 at 192.168.1.103:5066;transport=tcp;user=phone>
Max-Forwards: 70
User-Agent: Grandstream GXP1165 1.0.5.26
Privacy: none
P-Preferred-Identity: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>
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: 410
v=0
o=3059001003 8000 8000 IN IP4 192.168.1.103
s=SIP Call
c=IN IP4 192.168.1.103
t=0 0
m=audio 5004 RTP/AVP 18 0 8 97 9 4 2 101
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:40
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:9 G722/8000
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f78940f6af0): msg 0x7f78940edcc0 (1223 bytes) from tcp/1.1.1.1:33919/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0 (CSeq 1300)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3248 agent_aliases() nta: canonizing sip:0017864732820 at 9.9.9.9:5066 with contact
nta.c:3085 agent_recv_request() nta: INVITE (1300) going to a default leg
nta.c:1350 set_timeout() nta: timer set to 2000 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f78940f7560) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940e3e90, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f78940eb7d0)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f78940e3e90) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f78940e3e90, (nil), 0x7f78940f574d, 410) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f78940f7560): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 404 bytes of 404 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 404
send 404 bytes to tcp/[1.1.1.1]:33919 at 17:23:59.741508:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK1821569725;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1300 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Content-Length: 0
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1300)
nua_stack.c:271 nua_stack_event() nua(0x7f78940f7560): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f7560): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f78940e3e90, [0x7f78baeed8c8], [0x7f78baeed8d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x7f78940f7560): event i_state 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-03-02 17:23:59.732052 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/3059001003 at 9.9.9.9:5066 [bd617718-2614-4849-9976-af940afd2e17]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-03-02 17:23:59.732052 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_NEW (Cur 1 Tot 100)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.732052 [DEBUG] sofia.c:9819 sofia/internal/3059001003 at 9.9.9.9:5066 receiving invite from 1.1.1.1:33919 version: 1.6.15 -32-bec4538 64bit
2017-03-02 17:23:59.732052 [DEBUG] sofia.c:9990 IP 1.1.1.1 Rejected by acl "domain". Falling back to Digest auth.
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f78940f7560): recv signal r_respond 407 Proxy Authentication Required
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940e3e90, ...) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f78940e3e90) called
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 909 bytes of 909 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 909
send 909 bytes to tcp/[1.1.1.1]:33919 at 17:23:59.742806:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK1821569725;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=t33eyj4X6UaZe
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1300 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="9.9.9.9", nonce="0cb6e459-5f17-4ef2-94af-bcd5bac0eee4", algorithm=MD5, qop="auth"
Content-Length: 0
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 407 Proxy Authentication Required for INVITE (1300)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f78940f7560): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f7560): call state changed: received -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f78940f7560): event i_state 407 Proxy Authentication Required
nua_stack.c:271 nua_stack_event() nua(0x7f78940f7560): event i_terminated 407 Proxy Authentication Required
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940e3e90) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f78940eb7d0)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2017-03-02 17:23:59.732052 [DEBUG] sofia.c:2334 detaching session bd617718-2614-4849-9976-af940afd2e17
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f78940f7560): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f78940f7560): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0x7f78940f7560): sent signal r_respond
2017-03-02 17:23:59.732052 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [0017864732820 at 9.9.9.9] from ip 1.1.1.1
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2017-03-02 17:23:59.732052 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/3059001003 at 9.9.9.9:5066) State NEW
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f6af0) msg 0x7f78940efe40 from (tcp/1.1.1.1:33919) has 373 bytes, veclen = 1
recv 373 bytes from tcp/[1.1.1.1]:33919 at 17:23:59.839587:
------------------------------------------------------------------------
ACK sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK1821569725;rport;alias
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=t33eyj4X6UaZe
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1300 ACK
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f78940f6af0): msg 0x7f78940efe40 (373 bytes) from tcp/1.1.1.1:33919/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0 (CSeq 1300)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3019 agent_recv_request() nta: ACK (1300) is going to INVITE (1300)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f6af0) msg 0x7f78940e3e90 from (tcp/1.1.1.1:33919) has 1460 bytes, veclen = 1
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f6af0) msg 0x7f78940e3e90 from (tcp/1.1.1.1:33919) has 41 bytes, veclen = 1
recv 1501 bytes from tcp/[1.1.1.1]:33919 at 17:23:59.924649:
------------------------------------------------------------------------
INVITE sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK835826063;rport;alias
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 INVITE
Contact: "3059001003" <sip:3059001003 at 192.168.1.103:5066;transport=tcp;user=phone>
Proxy-Authorization: Digest username="3059001003", realm="9.9.9.9", nonce="0cb6e459-5f17-4ef2-94af-bcd5bac0eee4", uri="sip:0017864732820 at 9.9.9.9:5066;user=phone", response="6e45981809c2e90f457a31fe6f0a8ab6", algorithm=MD5, cnonce="07978621", qop=auth, nc=0000000d
Max-Forwards: 70
User-Agent: Grandstream GXP1165 1.0.5.26
Privacy: none
P-Preferred-Identity: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>
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: 410
v=0
o=3059001003 8000 8000 IN IP4 192.168.1.103
s=SIP Call
c=IN IP4 192.168.1.103
t=0 0
m=audio 5004 RTP/AVP 18 0 8 97 9 4 2 101
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:40
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:9 G722/8000
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f78940f6af0): msg 0x7f78940e3e90 (1501 bytes) from tcp/1.1.1.1:33919/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:0017864732820 at 9.9.9.9:5066;user=phone SIP/2.0 (CSeq 1301)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3248 agent_aliases() nta: canonizing sip:0017864732820 at 9.9.9.9:5066 with contact
nta.c:3085 agent_recv_request() nta: INVITE (1301) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:899 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f78940f0970) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940ea6c0, ...) called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f78940acc30)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f78940ea6c0) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f78940ea6c0, (nil), 0x7f78940f0283, 410) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f78940f0970): adding session usage
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 403 bytes of 403 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 403
send 403 bytes to tcp/[1.1.1.1]:33919 at 17:23:59.924992:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK835826063;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Content-Length: 0
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (1301)
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_invite 100 Trying
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f78940ea6c0, [0x7f78baeed8c8], [0x7f78baeed8d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:2442 Re-attaching to session bd617718-2614-4849-9976-af940afd2e17
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:9819 sofia/internal/3059001003 at 9.9.9.9:5066 receiving invite from 1.1.1.1:33919 version: 1.6.15 -32-bec4538 64bit
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:9990 IP 1.1.1.1 Rejected by acl "domain". Falling back to Digest auth.
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:11131 Setting NAT mode based on via received
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:7042 Channel sofia/internal/3059001003 at 9.9.9.9:5066 entering state [received][100]
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:7052 Remote SDP:
v=0
o=3059001003 8000 8000 IN IP4 192.168.1.103
s=SIP Call
c=IN IP4 192.168.1.103
t=0 0
m=audio 5004 RTP/AVP 18 0 8 97 9 4 2 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:9 G722/8000
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:40
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:7444 (sofia/internal/3059001003 at 9.9.9.9:5066) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_INIT (Cur 1 Tot 100)
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3059001003 at 9.9.9.9:5066) State INIT
2017-03-02 17:23:59.912035 [DEBUG] mod_sofia.c:90 sofia/internal/3059001003 at 9.9.9.9:5066 SOFIA INIT
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:40 sofia/internal/3059001003 at 9.9.9.9:5066 Standard INIT
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/3059001003 at 9.9.9.9:5066) State Change CS_INIT -> CS_ROUTING
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3059001003 at 9.9.9.9:5066) State INIT going to sleep
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_ROUTING (Cur 1 Tot 100)
2017-03-02 17:23:59.912035 [DEBUG] switch_channel.c:2249 (sofia/internal/3059001003 at 9.9.9.9:5066) Callstate Change DOWN -> RINGING
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3059001003 at 9.9.9.9:5066) State ROUTING
2017-03-02 17:23:59.912035 [DEBUG] mod_sofia.c:143 sofia/internal/3059001003 at 9.9.9.9:5066 SOFIA ROUTING
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3059001003 at 9.9.9.9:5066 Standard ROUTING
2017-03-02 17:23:59.912035 [INFO] mod_dialplan_xml.c:637 Processing 3059001003 <3059001003>->0017864732820 in context default
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 parsing [default->unloop] continue=false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 parsing [default->Add_Internal_UUID] continue=true
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (PASS) [Add_Internal_UUID] destination_number(0017864732820) =~ /^.*$/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action session_loglevel(debug)
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action log(ERR Call-ID: [${sip_call_id}])
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action set(sip_h_X-cid=${sip_call_id})
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 parsing [default->local.example.com] continue=false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (PASS) [local.example.com] ${toll_allow}(domestic,international,local) =~ /local/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (FAIL) [local.example.com] destination_number(0017864732820) =~ /^(305900100[0-9])$/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 parsing [default->david_test] continue=false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (FAIL) [david_test] destination_number(0017864732820) =~ /^(9999999)$/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 parsing [default->domestic] continue=false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Regex (PASS) [domestic] destination_number(0017864732820) =~ /^00(1[2-9][0-9]{2}[2-9][0-9]{6}$)/ break=on-false
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action ring_ready()
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action set(effective_caller_id_number=17863580970)
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action set(effective_caller_id_name=17863580970)
Dialplan: sofia/internal/3059001003 at 9.9.9.9:5066 Action bridge(sofia/gateway/creacomm/17864732820)
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3059001003 at 9.9.9.9:5066) State Change CS_ROUTING -> CS_EXECUTE
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3059001003 at 9.9.9.9:5066) State ROUTING going to sleep
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_EXECUTE (Cur 1 Tot 100)
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3059001003 at 9.9.9.9:5066) State EXECUTE
2017-03-02 17:23:59.912035 [DEBUG] mod_sofia.c:198 sofia/internal/3059001003 at 9.9.9.9:5066 SOFIA EXECUTE
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3059001003 at 9.9.9.9:5066 Standard EXECUTE
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 session_loglevel(debug)
2017-03-02 17:23:59.912035 [DEBUG] mod_dptools.c:4515 Setting log level "DEBUG" on session
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 log(ERR Call-ID: [661215423-5066-131 at BJC.BGI.B.BAD])
2017-03-02 17:23:59.912035 [ERR] mod_dptools.c:1721 Call-ID: [661215423-5066-131 at BJC.BGI.B.BAD]
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 set(sip_h_X-cid=661215423-5066-131 at BJC.BGI.B.BAD)
2017-03-02 17:23:59.912035 [DEBUG] mod_dptools.c:1527 SET sofia/internal/3059001003 at 9.9.9.9:5066 [sip_h_X-cid]=[661215423-5066-131 at BJC.BGI.B.BAD]
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 ring_ready()
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f78940f0970): recv signal r_respond 180 Ringing
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940ea6c0, ...) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 899 bytes of 899 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 899
send 899 bytes to tcp/[1.1.1.1]:33919 at 17:23:59.928622:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK835826063;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 INVITE
Contact: <sip:0017864732820 at 9.9.9.9:5066;transport=tcp>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
P-Asserted-Identity: "0017864732820" <sip:0017864732820 at 9.9.9.9>
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 180 Ringing for INVITE (1301)
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: received -> early
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 180 Ringing
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_respond
2017-03-02 17:23:59.912035 [NOTICE] mod_sofia.c:2263 Ring-Ready sofia/internal/3059001003 at 9.9.9.9:5066!
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.912035 [DEBUG] sofia.c:7042 Channel sofia/internal/3059001003 at 9.9.9.9:5066 entering state [early][180]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.912035 [NOTICE] mod_dptools.c:1025 Ring Ready sofia/internal/3059001003 at 9.9.9.9:5066!
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 set(effective_caller_id_number=17863580970)
2017-03-02 17:23:59.912035 [DEBUG] mod_dptools.c:1527 SET sofia/internal/3059001003 at 9.9.9.9:5066 [effective_caller_id_number]=[17863580970]
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 set(effective_caller_id_name=17863580970)
2017-03-02 17:23:59.912035 [DEBUG] mod_dptools.c:1527 SET sofia/internal/3059001003 at 9.9.9.9:5066 [effective_caller_id_name]=[17863580970]
EXECUTE sofia/internal/3059001003 at 9.9.9.9:5066 bridge(sofia/gateway/creacomm/17864732820)
2017-03-02 17:23:59.912035 [DEBUG] switch_ivr_originate.c:2138 Parsing global variables
2017-03-02 17:23:59.912035 [NOTICE] switch_channel.c:1104 New Channel sofia/external/17864732820 [4d2d5e62-710f-467d-9468-e584e335c141]
2017-03-02 17:23:59.912035 [DEBUG] mod_sofia.c:4809 (sofia/external/17864732820) State Change CS_NEW -> CS_INIT
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_INIT (Cur 2 Tot 101)
2017-03-02 17:23:59.912035 [DEBUG] switch_core_state_machine.c:627 (sofia/external/17864732820) State INIT
2017-03-02 17:23:59.912035 [DEBUG] mod_sofia.c:90 sofia/external/17864732820 SOFIA INIT
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2017-03-02 17:23:59.932020 [DEBUG] sofia_glue.c:1293 sofia/external/17864732820 sending invite version: 1.6.15 -32-bec4538 64bit
Local SDP:
v=0
o=FreeSWITCH 1488453939 1488453940 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21500 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv
nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f78a00047b0): recv signal r_invite
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f78a00047b0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78980122f0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78980122f0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f78980122f0, (nil), 0x7f78a0001916, -1) called
nua_stack.c:529 nua_signal() nua(0x7f78a00047b0): sent signal r_invite
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:40 sofia/external/17864732820 Standard INIT
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:48 (sofia/external/17864732820) State Change CS_INIT -> CS_ROUTING
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f78980122f0, (nil), 0x7f78a0001916, -1) called
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:627 (sofia/external/17864732820) State INIT going to sleep
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f78a00047b0): adding session usage
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f7898018b80)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f78980122f0) called
soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f78980122f0, 0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f78980122f0, soa_generate_offer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f78980122f0, soa_generate_offer): generating local description
soa_static.c:1217 offer_answer_step() soa_static(0x7f78980122f0, soa_generate_offer): upgrade with local description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f78bbffca70, (nil), ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f78980122f0, soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78980122f0, [(nil)], [0x7f78bbffebf8], [0x7f78bbffebf4]) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = */10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name */10.10.10.10:5060
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_ROUTING (Cur 2 Tot 101)
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:643 (sofia/external/17864732820) State ROUTING
2017-03-02 17:23:59.932020 [DEBUG] mod_sofia.c:143 sofia/external/17864732820 SOFIA ROUTING
2017-03-02 17:23:59.932020 [DEBUG] switch_ivr_originate.c:67 (sofia/external/17864732820) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:643 (sofia/external/17864732820) State ROUTING going to sleep
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 101)
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:662 (sofia/external/17864732820) State CONSUME_MEDIA
2017-03-02 17:23:59.932020 [DEBUG] switch_core_state_machine.c:662 (sofia/external/17864732820) State CONSUME_MEDIA going to sleep
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 1193 bytes of 1193 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 1193
send 1193 bytes to udp/[10.10.10.10]:5060 at 17:23:59.932287:
------------------------------------------------------------------------
INVITE sip:17864732820 at 10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bK9vmg8Uj7mcDZH
Max-Forwards: 69
From: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
To: <sip:17864732820 at 10.10.10.10:5060>
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103901655 INVITE
Contact: <sip:gw+creacomm at 9.9.9.9:5080;transport=udp;gw=creacomm>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 295
X-cid: 661215423-5066-131 at BJC.BGI.B.BAD
X-FS-Support: update_display,send_info
Remote-Party-ID: "17863580970" <sip:17863580970 at 9.9.9.9>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1488453939 1488453940 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21500 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent INVITE (103901655) to */10.10.10.10:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f78980217c0 for udp/9.9.9.9:5080 (already 0)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_session.c:4139 signal_call_state_change() nua(0x7f78a00047b0): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78980122f0, [0x7f78bbffebd8], [0x7f78bbffebe0], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x7f78a00047b0): event i_state INVITE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:23:59.932020 [DEBUG] sofia.c:7042 Channel sofia/external/17864732820 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f789803ed30 from (udp/9.9.9.9:5080) has 329 bytes, veclen = 1
recv 329 bytes from udp/[10.10.10.10]:5060 at 17:23:59.933826:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bK9vmg8Uj7mcDZH
From: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
To: <sip:17864732820 at 10.10.10.10:5060>
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103901655 INVITE
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f789803ed30 (329 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE (103901655)
nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 1.623 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f78980217c0 by 0x7f7898018340 with 0x7f789803ed30 (preliminary)
nta.c:1289 agent_timer() nta: timer not set
nta.c:5825 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f78baeedc60)
nta.c:7188 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 0/0 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 58187 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f78980480b0 from (udp/9.9.9.9:5080) has 783 bytes, veclen = 1
recv 783 bytes from udp/[10.10.10.10]:5060 at 17:24:03.779239:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bK9vmg8Uj7mcDZH
To: <sip:17864732820 at 10.10.10.10:5060>;tag=3697482296-311493
From: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103901655 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:17864732820 at 10.10.10.10:5060>
Call-Info: <sip:10.10.10.10>;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 155
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 18014 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f78980480b0 (783 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 183 Session Progress for INVITE (103901655)
nta.c:3366 agent_recv_response() nta: 183 Session Progress is going to a transaction
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f78980217c0 by 0x7f7898018340 with 0x7f78980480b0 (preliminary)
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f78980122f0, (nil), 0x7f7898046b04, 155) called
soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f78980122f0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f78980122f0, soa_process_answer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f7898023d80, 0x7f789803de20, ""): called
soa_static.c:1304 offer_answer_step() soa_static(0x7f78980122f0, soa_process_answer): upgrade codecs with remote description
soa.c:1730 soa_activate() soa_activate(static::0x7f78980122f0, (nil)) called
nua_session.c:988 nua_session_client_response() nua(0x7f78a00047b0): INVITE: processed SDP answer in 183 Session Progress
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event r_invite 183 Session Progress
nua_session.c:4139 signal_call_state_change() nua(0x7f78a00047b0): call state changed: calling -> proceeding, received answer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f78980122f0, [0x7f78bbffe5e8], [0x7f78bbffe5f0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f78980122f0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_state 183 Session Progress
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:03.772031 [DEBUG] sofia.c:7042 Channel sofia/external/17864732820 entering state [proceeding][183]
2017-03-02 17:24:03.772031 [DEBUG] sofia.c:7052 Remote SDP:
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 18014 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:40:8000:1]
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4455 Audio Codec Compare [G729:18:8000:40:8000:1] ++++ is saved as a match
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:40:64000:1]
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:40:64000:1]
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:3047 Set Codec sofia/external/17864732820 G729/8000 40 ms 320 samples 8000 bits 1 channels
2017-03-02 17:24:03.772031 [DEBUG] switch_core_codec.c:111 sofia/external/17864732820 Original read codec set to G729:18
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4689 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:4718 sofia/external/17864732820 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:6732 AUDIO RTP [sofia/external/17864732820] 9.9.9.9 port 21500 -> 173.230.226.241 port 18014 codec: 18 ms: 40
2017-03-02 17:24:03.772031 [DEBUG] switch_rtp.c:3878 Starting timer [soft] 320 bytes per 40ms
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:7038 sofia/external/17864732820 Set 2833 dtmf send payload to 101
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:7045 sofia/external/17864732820 Set 2833 dtmf receive payload to 101
2017-03-02 17:24:03.772031 [DEBUG] switch_core_media.c:7068 sofia/external/17864732820 Set rtp dtmf delay to 40
2017-03-02 17:24:03.772031 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/17864732820!
2017-03-02 17:24:03.772031 [DEBUG] switch_channel.c:3473 (sofia/external/17864732820) Callstate Change DOWN -> EARLY
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:03.792043 [INFO] switch_ivr_originate.c:3635 Sending early media
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:40:8000:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [G729:18:8000:20:8000:1] is saved as a near-match
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:40:8000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G729:18:8000:40:8000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a near-match
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4436 Audio Codec Compare [PCMA:8:8000:20:64000:1] is saved as a near-match
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [iLBC:97:8000:40:0:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [iLBC:97:8000:40:0:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [iLBC:97:8000:40:0:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G722:9:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G722:9:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G722:9:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G723:4:8000:40:6300:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G723:4:8000:40:6300:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G723:4:8000:40:6300:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G726-32:2:8000:40:0:1]/[G729:18:8000:20:8000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G726-32:2:8000:40:0:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4400 Audio Codec Compare [G726-32:2:8000:40:0:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4316 Set telephone-event payload to 101 at 8000
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4507 Substituting codec G729 at 40i@8000h at 1c
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:3047 Set Codec sofia/internal/3059001003 at 9.9.9.9:5066 G729/8000 40 ms 320 samples 8000 bits 1 channels
2017-03-02 17:24:03.792043 [DEBUG] switch_core_codec.c:111 sofia/internal/3059001003 at 9.9.9.9:5066 Original read codec set to G729:18
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4659 Set telephone-event payload to 101 at 8000
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:4718 sofia/internal/3059001003 at 9.9.9.9:5066 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:6732 AUDIO RTP [sofia/internal/3059001003 at 9.9.9.9:5066] 9.9.9.9 port 25936 -> 192.168.1.103 port 5004 codec: 18 ms: 40
2017-03-02 17:24:03.792043 [DEBUG] switch_rtp.c:3878 Starting timer [soft] 320 bytes per 40ms
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:7038 sofia/internal/3059001003 at 9.9.9.9:5066 Set 2833 dtmf send payload to 101
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:7045 sofia/internal/3059001003 at 9.9.9.9:5066 Set 2833 dtmf receive payload to 101
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:7068 sofia/internal/3059001003 at 9.9.9.9:5066 Set rtp dtmf delay to 40
2017-03-02 17:24:03.792043 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/3059001003 at 9.9.9.9:5066!
2017-03-02 17:24:03.792043 [DEBUG] switch_channel.c:3473 (sofia/internal/3059001003 at 9.9.9.9:5066) Callstate Change RINGING -> EARLY
2017-03-02 17:24:03.792043 [DEBUG] switch_core_media.c:6715 Audio params are unchanged for sofia/internal/3059001003 at 9.9.9.9:5066.
2017-03-02 17:24:03.792043 [DEBUG] mod_sofia.c:2354 Ring SDP:
v=0
o=FreeSWITCH 1488449507 1488449508 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 25936 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_respond
2017-03-02 17:24:03.792043 [DEBUG] switch_ivr_originate.c:3686 Originate Resulted in Success: [sofia/external/17864732820]
nua_stack.c:573 nua_stack_signal() nua(0x7f78940f0970): recv signal r_respond 183 Session Progress
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940ea6c0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f78940ea6c0, (nil), 0x7f789800fec3, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f78940ea6c0, (nil), 0x7f789800fec3, -1) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f78940ea6c0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f78940ea6c0, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f78940ea6c0, soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x7f78940ea6c0, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f78baeebab0, 0x7f78940fbbb0, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f78940ea6c0, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f78940ea6c0, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78940ea6c0, [(nil)], [0x7f78baeedc38], [0x7f78baeedc34]) called
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 1191 bytes of 1191 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 1191
send 1191 bytes to tcp/[1.1.1.1]:33919 at 17:24:03.797039:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK835826063;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 INVITE
Contact: <sip:0017864732820 at 9.9.9.9:5066;transport=tcp>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247
P-Asserted-Identity: "Outbound Call" <sip:17864732820 at 9.9.9.9>
v=0
o=FreeSWITCH 1488449507 1488449508 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 25936 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 183 Session Progress for INVITE (1301)
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: early -> early, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78940ea6c0, [0x7f78baeedce8], [0x7f78baeedcf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f78940ea6c0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 183 Session Progress
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:03.792043 [DEBUG] sofia.c:7042 Channel sofia/internal/3059001003 at 9.9.9.9:5066 entering state [early][183]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:03.792043 [DEBUG] switch_ivr_bridge.c:1566 (sofia/external/17864732820) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-03-02 17:24:03.792043 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 101)
2017-03-02 17:24:03.792043 [DEBUG] switch_core_state_machine.c:653 (sofia/external/17864732820) State EXCHANGE_MEDIA
2017-03-02 17:24:03.792043 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2017-03-02 17:24:03.892018 [DEBUG] switch_rtp.c:6994 Correct audio ip/port confirmed.
2017-03-02 17:24:04.172051 [WARNING] switch_core_media.c:2472 [CBR]: Asynchronous PTIME not supported, changing our end from 40 to 20
2017-03-02 17:24:04.212058 [DEBUG] switch_core_media.c:2945 Changing Codec from G729 at 40ms@8000hz to G729 at 20ms@8000hz
2017-03-02 17:24:04.292046 [DEBUG] switch_rtp.c:3756 RE-Starting timer [soft] 160 bytes per 20ms
2017-03-02 17:24:04.292046 [DEBUG] switch_core_media.c:3047 Set Codec sofia/external/17864732820 G729/8000 20 ms 160 samples 8000 bits 1 channels
2017-03-02 17:24:04.292046 [DEBUG] switch_core_codec.c:123 sofia/external/17864732820 Original read codec replaced with G729:18
2017-03-02 17:24:04.312033 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 320 bytes to accommodate 640->320
2017-03-02 17:24:04.332084 [DEBUG] switch_core_io.c:1448 Engaging Write Buffer at 640 bytes to accommodate 320->640
2017-03-02 17:24:04.472049 [INFO] switch_rtp.c:6954 Auto Changing audio port from 192.168.1.103:5004 to 1.1.1.1:5004
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_stack.c:529 nua_signal() nua(0x7f7888021bf0): sent signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898049e80, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898049e80, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/9.9.9.9:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 9.9.9.9:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/9.9.9.9:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 547 bytes of 547 to udp/9.9.9.9:5060
tport.c:3492 tport_send_msg() tport_vsend returned 547
send 547 bytes to udp/[9.9.9.9]:5060 at 17:24:04.589988:
------------------------------------------------------------------------
OPTIONS sip:9.9.9.9:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKa6D99p3ajN3HD
Max-Forwards: 70
From: <sip:9.9.9.9:5060>;tag=vXmUpQ4ryZ97j
To: <sip:9.9.9.9:5060>
Call-ID: e0309566-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900182 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900182) to udp/9.9.9.9:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f789804a0a0 for udp/9.9.9.9:5080 (already 1)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events ERR
tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
tport_type_udp.c:524 tport_udp_error() reported by [9.9.9.9]:0
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f789804a0a0 by 0x7f789804a450 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103900182): Connection refused (111) with udp/[9.9.9.9]:5060
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 503 Service Unavailable
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021bf0): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f7888021bf0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898048c70, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898048c70, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/10.10.10.10:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 550 bytes of 550 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 550
send 550 bytes to udp/[10.10.10.10]:5060 at 17:24:04.590338:
------------------------------------------------------------------------
OPTIONS sip:10.10.10.10:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKBF71BjmeFyS4r
Max-Forwards: 70
From: <sip:10.10.10.10:5060>;tag=yF7ctD6ZrHpDa
To: <sip:10.10.10.10:5060>
Call-ID: e030a4fc-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900183 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900183) to udp/10.10.10.10:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f7898002450 for udp/9.9.9.9:5080 (already 1)
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:04.572056 [WARNING] sofia.c:6092 Ping failed my_212 with code 503 - count 1/0/1, state DOWN
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898049e80) called
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f7898066e60 from (udp/9.9.9.9:5080) has 578 bytes, veclen = 1
recv 578 bytes from udp/[10.10.10.10]:5060 at 17:24:04.592046:
------------------------------------------------------------------------
SIP/2.0 200 OK
Session-Expires: 3600
Require: timer
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bKBF71BjmeFyS4r
To: <sip:10.10.10.10:5060>;tag=3697482297-124379
From: <sip:10.10.10.10:5060>;tag=yF7ctD6ZrHpDa
Call-ID: e030a4fc-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900183 OPTIONS
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:10.10.10.10:5060>
Allow-Events: talk
Allow-Events: hold
Allow-Events: conference
Allow-Events: refer
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f7898066e60 (578 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (103900183)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 1.84 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f7898002450 by 0x7f78980031f0 with 0x7f7898066e60
nua_stack.c:271 nua_stack_event() nua(0x7f7888021bf0): event r_options 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f7888021bf0): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021bf0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898048c70) called
nta.c:1296 agent_timer() nta: timer set next to 3999 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940fa6d0 from (udp/9.9.9.9:5066) has 20 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): bad msg 0x7f78940fa6d0 (0 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900182)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 2 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900183)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free
nta.c:1289 agent_timer() nta: timer not set
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898005890, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898005890, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/162.212.218.50:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 162.212.218.50:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/162.212.218.50:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 532 bytes of 532 to udp/162.212.218.50:5060
tport.c:3492 tport_send_msg() tport_vsend returned 532
send 532 bytes to udp/[162.212.218.50]:5060 at 17:24:09.597933:
------------------------------------------------------------------------
OPTIONS sip:162.212.218.50;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKcr0tDD5Hc7FQm
Max-Forwards: 70
From: <sip:162.212.218.50>;tag=Zr05U8p3Ntc0N
To: <sip:162.212.218.50>
Call-ID: e32cbc18-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900184 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900184) to udp/162.212.218.50:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f789803f420 for udp/9.9.9.9:5080 (already 1)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f789800eca0 from (udp/9.9.9.9:5080) has 351 bytes, veclen = 1
recv 351 bytes from udp/[162.212.218.50]:5060 at 17:24:09.644388:
------------------------------------------------------------------------
SIP/2.0 200 ok
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;branch=z9hG4bKcr0tDD5Hc7FQm;received=9.9.9.9
From: <sip:162.212.218.50>;tag=Zr05U8p3Ntc0N
To: <sip:162.212.218.50>;tag=900aae4af3fd28f18c13cc10467a9d91.bd75
Call-ID: e32cbc18-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900184 OPTIONS
Server: AlcazarProxy 1.25
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f789800eca0 (351 bytes) from udp/162.212.218.50:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 ok for OPTIONS (103900184)
nta.c:3366 agent_recv_response() nta: 200 ok is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 46.564 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f789803f420 by 0x7f7898047180 with 0x7f789800eca0
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 200 ok
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898005890) called
nta.c:1296 agent_timer() nta: timer set next to 4045 ms
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789801d560, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789801d560, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/162.212.218.52:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 162.212.218.52:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/162.212.218.52:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 532 bytes of 532 to udp/162.212.218.52:5060
tport.c:3492 tport_send_msg() tport_vsend returned 532
send 532 bytes to udp/[162.212.218.52]:5060 at 17:24:10.599485:
------------------------------------------------------------------------
OPTIONS sip:162.212.218.52;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKD1SKF8NN9F69F
Max-Forwards: 70
From: <sip:162.212.218.52>;tag=01SyX376j32jH
To: <sip:162.212.218.52>
Call-ID: e3c58ecf-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900185 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900185) to udp/162.212.218.52:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f789801b950 for udp/9.9.9.9:5080 (already 1)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f78980644f0 from (udp/9.9.9.9:5080) has 351 bytes, veclen = 1
recv 351 bytes from udp/[162.212.218.52]:5060 at 17:24:10.645802:
------------------------------------------------------------------------
SIP/2.0 200 ok
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;branch=z9hG4bKD1SKF8NN9F69F;received=9.9.9.9
From: <sip:162.212.218.52>;tag=01SyX376j32jH
To: <sip:162.212.218.52>;tag=ce5d5216cc02f22158052e1d29245ffc.cc4b
Call-ID: e3c58ecf-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900185 OPTIONS
Server: AlcazarProxy 1.25
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f78980644f0 (351 bytes) from udp/162.212.218.52:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 ok for OPTIONS (103900185)
nta.c:3366 agent_recv_response() nta: 200 ok is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 46.442 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f789801b950 by 0x7f789800fd00 with 0x7f78980644f0
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 200 ok
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f789801d560) called
nta.c:1296 agent_timer() nta: timer set next to 3044 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f7898049310 from (udp/9.9.9.9:5080) has 822 bytes, veclen = 1
recv 822 bytes from udp/[10.10.10.10]:5060 at 17:24:14.119045:
------------------------------------------------------------------------
SIP/2.0 200 OK
Session-Expires: 3600;refresher=uas
Require: timer
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bK9vmg8Uj7mcDZH
To: <sip:17864732820 at 10.10.10.10:5060>;tag=3697482296-311493
From: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103901655 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:17864732820 at 10.10.10.10:5060>
Call-Info: <sip:10.10.10.10>;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 155
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 18014 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f7898049310 (822 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (103901655)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f78980217c0 by 0x7f7898018340 with 0x7f7898049310
nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 1803 seconds (in [1795..1805])
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f78980122f0, (nil), 0x7f789804995b, 155) called
soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f78980122f0) called
nua_session.c:978 nua_session_client_response() nua(0x7f78a00047b0): INVITE: error processing SDP answer in 200 OK
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event r_invite 200 OK
nua_session.c:4139 signal_call_state_change() nua(0x7f78a00047b0): call state changed: proceeding -> completing, received answer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f78980122f0, [0x7f78bbffe778], [0x7f78bbffe780], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f78980122f0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.112049 [DEBUG] sofia.c:7042 Channel sofia/external/17864732820 entering state [completing][200]
2017-03-02 17:24:14.112049 [DEBUG] sofia.c:7049 Duplicate SDP
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 18014 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
nua.c:639 nua_ack() nua: nua_ack: entering
nua_stack.c:529 nua_signal() nua(0x7f78a00047b0): sent signal r_ack
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f78a00047b0): recv signal r_ack
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78980122f0, ...) called
soa.c:1730 soa_activate() soa_activate(static::0x7f78980122f0, (nil)) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = */10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name */10.10.10.10:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 441 bytes of 441 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 441
send 441 bytes to udp/[10.10.10.10]:5060 at 17:24:14.123575:
------------------------------------------------------------------------
ACK sip:17864732820 at 10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKeaKcH36r6rvvB
Max-Forwards: 70
From: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
To: <sip:17864732820 at 10.10.10.10:5060>;tag=3697482296-311493
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103901655 ACK
Contact: <sip:gw+creacomm at 9.9.9.9:5080;transport=udp;gw=creacomm>
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent ACK (103901655) to */10.10.10.10:5060
nua_session.c:4139 signal_call_state_change() nua(0x7f78a00047b0): call state changed: completing -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_state 200 ACK sent
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.132021 [DEBUG] sofia.c:7042 Channel sofia/external/17864732820 entering state [ready][200]
2017-03-02 17:24:14.132021 [NOTICE] sofia.c:8102 Channel [sofia/external/17864732820] has been answered
2017-03-02 17:24:14.132021 [DEBUG] switch_channel.c:3772 (sofia/external/17864732820) Callstate Change EARLY -> ACTIVE
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.152056 [DEBUG] switch_core_media.c:6715 Audio params are unchanged for sofia/internal/3059001003 at 9.9.9.9:5066.
2017-03-02 17:24:14.152056 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/3059001003 at 9.9.9.9:5066:
v=0
o=FreeSWITCH 1488449507 1488449509 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 25936 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f78940f0970): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940ea6c0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f78940ea6c0, (nil), 0x7f789804a284, -1) called
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_respond
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78940ea6c0, [(nil)], [0x7f78baeedc38], [0x7f78baeedc34]) called
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f6af0) tpn = TCP/1.1.1.1:33919
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f6af0): 1229 bytes of 1229 to tcp/1.1.1.1:33919
tport.c:3492 tport_send_msg() tport_vsend returned 1229
send 1229 bytes to tcp/[1.1.1.1]:33919 at 17:24:14.156005:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK835826063;rport=33919;alias;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 INVITE
Contact: <sip:0017864732820 at 9.9.9.9:5066;transport=tcp>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Require: timer
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Session-Expires: 120;refresher=uac
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 247
P-Asserted-Identity: "Outbound Call" <sip:17864732820 at 9.9.9.9>
v=0
o=FreeSWITCH 1488449507 1488449508 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 25936 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nta.c:6791 incoming_reply() nta: sent 200 OK for INVITE (1301)
nta.c:1348 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: early -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f78940ea6c0, [0x7f78baeedce8], [0x7f78baeedcf0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f78940ea6c0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 200 OK
2017-03-02 17:24:14.152056 [NOTICE] switch_ivr_bridge.c:590 Channel [sofia/internal/3059001003 at 9.9.9.9:5066] has been answered
2017-03-02 17:24:14.152056 [DEBUG] switch_channel.c:3772 (sofia/internal/3059001003 at 9.9.9.9:5066) Callstate Change EARLY -> ACTIVE
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.192033 [DEBUG] sofia.c:7042 Channel sofia/internal/3059001003 at 9.9.9.9:5066 entering state [completed][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.192033 [DEBUG] switch_rtp.c:6994 Correct audio ip/port confirmed.
2017-03-02 17:24:14.272025 [DEBUG] switch_rtp.c:6994 Correct audio ip/port confirmed.
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f6af0) msg 0x7f78940fa6d0 from (tcp/1.1.1.1:33919) has 905 bytes, veclen = 1
recv 905 bytes from tcp/[1.1.1.1]:33919 at 17:24:14.345236:
------------------------------------------------------------------------
ACK sip:0017864732820 at 9.9.9.9:5066;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK1995827622;rport
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1301 ACK
Contact: <sip:3059001003 at 192.168.1.103:5066;transport=tcp;user=phone>
Proxy-Authorization: Digest username="3059001003", realm="9.9.9.9", nonce="0cb6e459-5f17-4ef2-94af-bcd5bac0eee4", uri="sip:0017864732820 at 9.9.9.9:5066;user=phone", response="6e45981809c2e90f457a31fe6f0a8ab6", algorithm=MD5, cnonce="07978621", qop=auth, nc=0000000d
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream GXP1165 1.0.5.26
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f78940f6af0): msg 0x7f78940fa6d0 (905 bytes) from tcp/1.1.1.1:33919/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:0017864732820 at 9.9.9.9:5066;transport=tcp SIP/2.0 (CSeq 1301)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3019 agent_recv_request() nta: ACK (1301) is going to INVITE (1301)
nua_session.c:2569 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f78940ea6c0) called
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_ack 200 OK
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_active 200 Call active
nua_dialog.c:564 nua_dialog_usage_set_refresh_range() nua(): refresh session after 108 seconds (in [108..108])
nta.c:5744 incoming_free() nta: incoming_free(0x7f78940f30e0)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f78940f0970): recv signal r_respond 401 Unauthorized
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_error 500 Responding to a Non-Existing Request
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:14.352019 [DEBUG] sofia.c:7042 Channel sofia/internal/3059001003 at 9.9.9.9:5066 entering state [ready][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900184)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
nta.c:1296 agent_timer() nta: timer set next to 1002 ms
nta.c:1289 agent_timer() nta: timer not set
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport_type_tcp.c:302 tport_recv_stream() tport_recv_stream(0x7f78940f6af0): received keepalive (total 0)
tport_type_tcp.c:542 tport_tcp_pong() tport_tcp_pong(0x7f78940f6af0): sending PONG to tcp/1.1.1.1:33919/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f6af0): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f6af0)
tport.c:2157 tport_shutdown0() tport_shutdown0(0x7f78940f6af0, 2)
tport.c:2090 tport_close() tport_close(0x7f78940f6af0): tcp/1.1.1.1:33919/sip
tport.c:2263 tport_set_secondary_timer() tport(0x7f78940f6af0): set timer at 0 ms because zap
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900185)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 30473 ms
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788401d860): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f788401d860) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940cc2f0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940cc2f0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
nua_stack.c:529 nua_signal() nua(0x7f788401d860): sent signal r_options
tport.c:3257 tport_tsend() tport_tsend(0x7f78940048f0) tpn = tcp/1.1.1.1:57489
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:57489
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f78940048f0): not found by name tcp/1.1.1.1:57489
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940f6af0
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f6af0): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f6af0): Setting TCP_KEEPINTVL to 30
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
tport.c:1032 tport_base_connect() tport_base_connect(0x7f78940f6af0): connecting to tcp/1.1.1.1:57489/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:3782 tport_queue() tport_queue(0x7f78940f6af0): queueing 0x7f78940e3e90 for tcp/1.1.1.1:57489
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899445) to tcp/1.1.1.1:57489
tport.c:4160 tport_pend() tport_pend(0x7f78940f6af0): pending 0x7f78940e3e90 for tcp/1.1.1.1:57489 (already 0)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nua_stack.c:569 nua_stack_signal() nua(0x7f78840145d0): recv signal r_options
nua_stack.c:529 nua_signal() nua(0x7f78840145d0): sent signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f78840145d0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940df1d0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940df1d0, ...) called
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
nua_stack.c:529 nua_signal() nua(0x7f78840252d0): sent signal r_options
tport.c:3257 tport_tsend() tport_tsend(0x7f7894004440) tpn = */1.1.1.1:5066
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:5066
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7894004440): not found by name */1.1.1.1:5066
tport.c:3594 tport_vsend() tport_vsend(0x7f7894004440): 849 bytes of 849 to udp/1.1.1.1:5066
tport.c:3492 tport_send_msg() tport_vsend returned 849
send 849 bytes to udp/[1.1.1.1]:5066 at 17:24:23.920315:
------------------------------------------------------------------------
OPTIONS sip:3059001001 at 192.168.1.101:5066;user=phone SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5066;rport;branch=z9hG4bK7ZeN9Ucgtg9Hm
Route: <sip:3059001001 at 1.1.1.1:5066>;user=phone
Max-Forwards: 70
From: <sip:mod_sofia at 9.9.9.9:5066>;tag=XyFS33p8XpDQH
To: <sip:3059001001 at 9.9.9.9>
Call-ID: 6223e86f-90dd-4092-a3af-fe0617630210_383685583-5066-1 at BJC.BGI.B.BAB
CSeq: 103899446 OPTIONS
Contact: <sip:mod_sofia at 9.9.9.9:5066>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899446) to */1.1.1.1:5066
tport.c:4160 tport_pend() tport_pend(0x7f7894004440): pending 0x7f78940fc3d0 for udp/9.9.9.9:5066 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_stack.c:569 nua_stack_signal() nua(0x7f78840252d0): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f78840252d0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940934a0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940934a0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f78940048f0) tpn = tcp/1.1.1.1:59162
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:59162
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f78940048f0): not found by name tcp/1.1.1.1:59162
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940f0250
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f0250): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f0250): Setting TCP_KEEPINTVL to 30
tport.c:1032 tport_base_connect() tport_base_connect(0x7f78940f0250): connecting to tcp/1.1.1.1:59162/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f0250): reset timer
tport.c:3782 tport_queue() tport_queue(0x7f78940f0250): queueing 0x7f78940fe860 for tcp/1.1.1.1:59162
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899447) to tcp/1.1.1.1:59162
tport.c:4160 tport_pend() tport_pend(0x7f78940f0250): pending 0x7f78940fe860 for tcp/1.1.1.1:59162 (already 0)
tport.c:2689 tport_connected() tport_connected(0x7f78940f6af0): events CONNECTED ERR
tport.c:4222 tport_release() tport_release(0x7f78940f6af0): 0x7f78940e3e90 by 0x7f78940f43f0 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103899445): Connection refused (111) with tcp/[1.1.1.1]:57489
nua_stack.c:271 nua_stack_event() nua(0x7f788401d860): event r_options 503 Service Unavailable
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f78940f43f0)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f6af0): reset timer
tport.c:2090 tport_close() tport_close(0x7f78940f6af0): tcp/1.1.1.1:57489/sip
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2689 tport_connected() tport_connected(0x7f78940f0250): events CONNECTED ERR
tport.c:4222 tport_release() tport_release(0x7f78940f0250): 0x7f78940fe860 by 0x7f78940ed660 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103899447): Connection refused (111) with tcp/[1.1.1.1]:59162
nua_stack.c:271 nua_stack_event() nua(0x7f78840252d0): event r_options 503 Service Unavailable
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f78940ed660)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f0250): reset timer
tport.c:2090 tport_close() tport_close(0x7f78940f0250): tcp/1.1.1.1:59162/sip
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788401d860): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788401d860): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940cc2f0) called
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f78840252d0): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f78840252d0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940934a0) called
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940f88e0 from (udp/9.9.9.9:5066) has 496 bytes, veclen = 1
recv 496 bytes from udp/[1.1.1.1]:5066 at 17:24:23.994114:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 9.9.9.9:5066;rport=5066;branch=z9hG4bK7ZeN9Ucgtg9Hm
From: <sip:mod_sofia at 9.9.9.9:5066>;tag=XyFS33p8XpDQH
To: <sip:3059001001 at 9.9.9.9>;tag=481865407
Call-ID: 6223e86f-90dd-4092-a3af-fe0617630210_383685583-5066-1 at BJC.BGI.B.BAB
CSeq: 103899446 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP1165 1.0.5.23
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): msg 0x7f78940f88e0 (496 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (103899446)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 73.9 ms
tport.c:4222 tport_release() tport_release(0x7f7894004440): 0x7f78940fc3d0 by 0x7f78940fcd20 with 0x7f78940f88e0
nua_stack.c:271 nua_stack_event() nua(0x7f78840145d0): event r_options 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f78840145d0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940df1d0) called
nua_stack.c:529 nua_signal() nua(0x7f78840145d0): sent signal r_destroy
nta.c:1296 agent_timer() nta: timer set next to 4073 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940e3e90 from (udp/9.9.9.9:5066) has 20 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): bad msg 0x7f78940e3e90 (0 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103899446)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78baeedd40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua.c:657 nua_options() nua: nua_options: entering
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:529 nua_signal() nua(0x7f7888021cd0): sent signal r_options
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898046e40, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898046e40, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/9.9.9.9:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 9.9.9.9:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/9.9.9.9:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 547 bytes of 547 to udp/9.9.9.9:5060
tport.c:3492 tport_send_msg() tport_vsend returned 547
send 547 bytes to udp/[9.9.9.9]:5060 at 17:24:29.671792:
------------------------------------------------------------------------
OPTIONS sip:9.9.9.9:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKFKc5jyQv31jFQ
Max-Forwards: 70
From: <sip:9.9.9.9:5060>;tag=1aKQZyragcS5c
To: <sip:9.9.9.9:5060>
Call-ID: ef23c2b8-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900186 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900186) to udp/9.9.9.9:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f78980139c0 for udp/9.9.9.9:5080 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events ERR
tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
tport_type_udp.c:524 tport_udp_error() reported by [9.9.9.9]:0
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f78980139c0 by 0x7f789804a450 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103900186): Connection refused (111) with udp/[9.9.9.9]:5060
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 503 Service Unavailable
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021cd0): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f7888021cd0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/10.10.10.10:5060
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:29.672020 [WARNING] sofia.c:6092 Ping failed my_212 with code 503 - count 1/0/1, state DOWN
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 550 bytes of 550 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 550
send 550 bytes to udp/[10.10.10.10]:5060 at 17:24:29.672175:
------------------------------------------------------------------------
OPTIONS sip:10.10.10.10:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKgv5XmS8Z0a91j
Max-Forwards: 70
From: <sip:10.10.10.10:5060>;tag=3v582mtHay5am
To: <sip:10.10.10.10:5060>
Call-ID: ef23d3d2-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900187 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900187) to udp/10.10.10.10:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f7898003d60 for udp/9.9.9.9:5080 (already 0)
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898046e40) called
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f7898003690 from (udp/9.9.9.9:5080) has 578 bytes, veclen = 1
recv 578 bytes from udp/[10.10.10.10]:5060 at 17:24:29.673685:
------------------------------------------------------------------------
SIP/2.0 200 OK
Session-Expires: 3600
Require: timer
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bKgv5XmS8Z0a91j
To: <sip:10.10.10.10:5060>;tag=3697482322-206106
From: <sip:10.10.10.10:5060>;tag=3v582mtHay5am
Call-ID: ef23d3d2-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900187 OPTIONS
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:10.10.10.10:5060>
Allow-Events: talk
Allow-Events: hold
Allow-Events: conference
Allow-Events: refer
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f7898003690 (578 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (103900187)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 1.607 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f7898003d60 by 0x7f78980221a0 with 0x7f7898003690
nua_stack.c:271 nua_stack_event() nua(0x7f7888021cd0): event r_options 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f7888021cd0): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021cd0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f789800abe0) called
nta.c:1296 agent_timer() nta: timer set next to 4000 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900186)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
nta.c:1296 agent_timer() nta: timer set next to 1 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900187)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 11445 ms
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/162.212.218.50:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 162.212.218.50:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/162.212.218.50:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 532 bytes of 532 to udp/162.212.218.50:5060
tport.c:3492 tport_send_msg() tport_vsend returned 532
send 532 bytes to udp/[162.212.218.50]:5060 at 17:24:39.686170:
------------------------------------------------------------------------
OPTIONS sip:162.212.218.50;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKH5yppmS3XKZme
Max-Forwards: 70
From: <sip:162.212.218.50>;tag=45y14FBN76UXF
To: <sip:162.212.218.50>
Call-ID: f51bd57e-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900188 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900188) to udp/162.212.218.50:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f789801cfb0 for udp/9.9.9.9:5080 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f789800eca0 from (udp/9.9.9.9:5080) has 351 bytes, veclen = 1
recv 351 bytes from udp/[162.212.218.50]:5060 at 17:24:39.732641:
------------------------------------------------------------------------
SIP/2.0 200 ok
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;branch=z9hG4bKH5yppmS3XKZme;received=9.9.9.9
From: <sip:162.212.218.50>;tag=45y14FBN76UXF
To: <sip:162.212.218.50>;tag=900aae4af3fd28f18c13cc10467a9d91.9545
Call-ID: f51bd57e-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900188 OPTIONS
Server: AlcazarProxy 1.25
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f789800eca0 (351 bytes) from udp/162.212.218.50:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 ok for OPTIONS (103900188)
nta.c:3366 agent_recv_response() nta: 200 ok is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 46.594 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f789801cfb0 by 0x7f7898047180 with 0x7f789800eca0
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 200 ok
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f789800abe0) called
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f789800abe0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/162.212.218.52:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 162.212.218.52:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/162.212.218.52:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 532 bytes of 532 to udp/162.212.218.52:5060
tport.c:3492 tport_send_msg() tport_vsend returned 532
send 532 bytes to udp/[162.212.218.52]:5060 at 17:24:40.687634:
------------------------------------------------------------------------
OPTIONS sip:162.212.218.52;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKjerFrFa7tvN7S
Max-Forwards: 70
From: <sip:162.212.218.52>;tag=5ert6avr4FjgB
To: <sip:162.212.218.52>
Call-ID: f5b4a4b2-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900189 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900189) to udp/162.212.218.52:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f7898002450 for udp/9.9.9.9:5080 (already 0)
nta.c:1296 agent_timer() nta: timer set next to 1000 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f7898048e40 from (udp/9.9.9.9:5080) has 351 bytes, veclen = 1
recv 351 bytes from udp/[162.212.218.52]:5060 at 17:24:40.734001:
------------------------------------------------------------------------
SIP/2.0 200 ok
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;branch=z9hG4bKjerFrFa7tvN7S;received=9.9.9.9
From: <sip:162.212.218.52>;tag=5ert6avr4FjgB
To: <sip:162.212.218.52>;tag=ce5d5216cc02f22158052e1d29245ffc.61b4
Call-ID: f5b4a4b2-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900189 OPTIONS
Server: AlcazarProxy 1.25
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f7898048e40 (351 bytes) from udp/162.212.218.52:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 ok for OPTIONS (103900189)
nta.c:3366 agent_recv_response() nta: 200 ok is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 46.495 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f7898002450 by 0x7f7898048a40 with 0x7f7898048e40
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 200 ok
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f789800abe0) called
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nta.c:1296 agent_timer() nta: timer set next to 3045 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900188)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/3 term, 1/4 free
nta.c:1296 agent_timer() nta: timer set next to 1000 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900189)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 383 ms
nta.c:9101 outgoing_timer_dk() nta: timer D fired, terminate INVITE (103901655)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/1 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 5 ms
nta.c:8982 outgoing_timer_bf() nta: timer F fired, terminating ACK (103901655)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1 tout, 0/0 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940e3e90 from (udp/9.9.9.9:5066) has 20 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): bad msg 0x7f78940e3e90 (0 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f7888021cd0): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898012bb0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898012bb0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/9.9.9.9:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 9.9.9.9:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/9.9.9.9:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 547 bytes of 547 to udp/9.9.9.9:5060
tport.c:3492 tport_send_msg() tport_vsend returned 547
send 547 bytes to udp/[9.9.9.9]:5060 at 17:24:54.713377:
------------------------------------------------------------------------
OPTIONS sip:9.9.9.9:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKKQH8SaUar5BtN
Max-Forwards: 70
From: <sip:9.9.9.9:5060>;tag=6QHK85cv1r82p
To: <sip:9.9.9.9:5060>
Call-ID: fe10cc62-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900190 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900190) to udp/9.9.9.9:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f78980480b0 for udp/9.9.9.9:5080 (already 0)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021cd0): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f7888021cd0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898021e40, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898021e40, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/10.10.10.10:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 550 bytes of 550 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 550
send 550 bytes to udp/[10.10.10.10]:5060 at 17:24:54.715062:
------------------------------------------------------------------------
OPTIONS sip:10.10.10.10:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5080;rport;branch=z9hG4bKm0a1U5BeNe2cH
Max-Forwards: 70
From: <sip:10.10.10.10:5060>;tag=70aca1XZy1yNj
To: <sip:10.10.10.10:5060>
Call-ID: fe1110ab-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900191 OPTIONS
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103900191) to udp/10.10.10.10:5060
tport.c:4160 tport_pend() tport_pend(0x7f7898008a70): pending 0x7f7898047a00 for udp/9.9.9.9:5080 (already 1)
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events ERR
tport_type_udp.c:519 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
tport_type_udp.c:524 tport_udp_error() reported by [9.9.9.9]:0
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f78980480b0 by 0x7f7898047180 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103900190): Connection refused (111) with udp/[9.9.9.9]:5060
nua_stack.c:271 nua_stack_event() nua(0x7f788801a090): event r_options 503 Service Unavailable
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:24:54.712058 [WARNING] sofia.c:6092 Ping failed my_212 with code 503 - count 1/0/1, state DOWN
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898012bb0) called
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f7898010ad0 from (udp/9.9.9.9:5080) has 578 bytes, veclen = 1
recv 578 bytes from udp/[10.10.10.10]:5060 at 17:24:54.717078:
------------------------------------------------------------------------
SIP/2.0 200 OK
Session-Expires: 3600
Require: timer
Via: SIP/2.0/UDP 9.9.9.9:5080;rport=5080;received=9.9.9.9;branch=z9hG4bKm0a1U5BeNe2cH
To: <sip:10.10.10.10:5060>;tag=3697482347-248953
From: <sip:10.10.10.10:5060>;tag=70aca1XZy1yNj
Call-ID: fe1110ab-7a0f-1235-f1ac-be187db6d1b8
CSeq: 103900191 OPTIONS
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:10.10.10.10:5060>
Allow-Events: talk
Allow-Events: hold
Allow-Events: conference
Allow-Events: refer
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f7898010ad0 (578 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (103900191)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 2.289 ms
tport.c:4222 tport_release() tport_release(0x7f7898008a70): 0x7f7898047a00 by 0x7f789801d240 with 0x7f7898010ad0
nua_stack.c:271 nua_stack_event() nua(0x7f7888021cd0): event r_options 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f7888021cd0): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f7888021cd0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f7898021e40) called
nta.c:1296 agent_timer() nta: timer set next to 4000 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900190)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 1 ms
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103900191)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78bbffed40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f7884025d50): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f7884025d50): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f7884025d50) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940aabb0, ...) called
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940aabb0, ...) called
nua_stack.c:529 nua_signal() nua(0x7f788401d820): sent signal r_options
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f7884026790): sent signal r_options
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f78940048f0) tpn = tcp/1.1.1.1:57489
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:57489
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f78940048f0): not found by name tcp/1.1.1.1:57489
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940f5420
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f5420): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f5420): Setting TCP_KEEPINTVL to 30
tport.c:1032 tport_base_connect() tport_base_connect(0x7f78940f5420): connecting to tcp/1.1.1.1:57489/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f5420): reset timer
tport.c:3782 tport_queue() tport_queue(0x7f78940f5420): queueing 0x7f78940f88e0 for tcp/1.1.1.1:57489
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899448) to tcp/1.1.1.1:57489
tport.c:4160 tport_pend() tport_pend(0x7f78940f5420): pending 0x7f78940f88e0 for tcp/1.1.1.1:57489 (already 0)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nua_stack.c:569 nua_stack_signal() nua(0x7f788401d820): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f788401d820) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940cc2f0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940cc2f0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7894004440) tpn = */1.1.1.1:5066
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:5066
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7894004440): not found by name */1.1.1.1:5066
tport.c:3594 tport_vsend() tport_vsend(0x7f7894004440): 849 bytes of 849 to udp/1.1.1.1:5066
tport.c:3492 tport_send_msg() tport_vsend returned 849
send 849 bytes to udp/[1.1.1.1]:5066 at 17:25:00.021679:
------------------------------------------------------------------------
OPTIONS sip:3059001001 at 192.168.1.101:5066;user=phone SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9:5066;rport;branch=z9hG4bKaUtZeDZtHBcaQ
Route: <sip:3059001001 at 1.1.1.1:5066>;user=phone
Max-Forwards: 70
From: <sip:mod_sofia at 9.9.9.9:5066>;tag=2BeNcBBtF3vmB
To: <sip:3059001001 at 9.9.9.9>
Call-ID: 313b31d8-d3cd-40f5-b8cd-89ff32611ac8_383685583-5066-1 at BJC.BGI.B.BAB
CSeq: 103899449 OPTIONS
Contact: <sip:mod_sofia at 9.9.9.9:5066>
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
------------------------------------------------------------------------
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899449) to */1.1.1.1:5066
tport.c:4160 tport_pend() tport_pend(0x7f7894004440): pending 0x7f78940fc660 for udp/9.9.9.9:5066 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_stack.c:569 nua_stack_signal() nua(0x7f7884026790): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7894001930, 0x7f7894001130, 0x7f7884026790) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940934a0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940934a0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f78940048f0) tpn = tcp/1.1.1.1:59162
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:59162
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f78940048f0): not found by name tcp/1.1.1.1:59162
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940ff060
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940ff060): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940ff060): Setting TCP_KEEPINTVL to 30
tport.c:1032 tport_base_connect() tport_base_connect(0x7f78940ff060): connecting to tcp/1.1.1.1:59162/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940ff060): reset timer
tport.c:3782 tport_queue() tport_queue(0x7f78940ff060): queueing 0x7f78940fecb0 for tcp/1.1.1.1:59162
nta.c:8304 outgoing_send() nta: sent OPTIONS (103899450) to tcp/1.1.1.1:59162
tport.c:4160 tport_pend() tport_pend(0x7f78940ff060): pending 0x7f78940fecb0 for tcp/1.1.1.1:59162 (already 0)
tport.c:2689 tport_connected() tport_connected(0x7f78940ff060): events CONNECTED ERR
tport.c:4222 tport_release() tport_release(0x7f78940ff060): 0x7f78940fecb0 by 0x7f78940efa60 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103899450): Connection refused (111) with tcp/[1.1.1.1]:59162
nua_stack.c:271 nua_stack_event() nua(0x7f7884026790): event r_options 503 Service Unavailable
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f78940efa60)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940ff060): reset timer
tport.c:2090 tport_close() tport_close(0x7f78940ff060): tcp/1.1.1.1:59162/sip
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2689 tport_connected() tport_connected(0x7f78940f5420): events CONNECTED ERR
tport.c:4222 tport_release() tport_release(0x7f78940f5420): 0x7f78940f88e0 by 0x7f78940f43f0 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: OPTIONS (103899448): Connection refused (111) with tcp/[1.1.1.1]:57489
nua_stack.c:271 nua_stack_event() nua(0x7f7884025d50): event r_options 503 Service Unavailable
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f78940f43f0)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f5420): reset timer
tport.c:2090 tport_close() tport_close(0x7f78940f5420): tcp/1.1.1.1:57489/sip
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f7884026790): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f7884026790): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940934a0) called
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f7884025d50): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f7884025d50): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940aabb0) called
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940f88e0 from (udp/9.9.9.9:5066) has 496 bytes, veclen = 1
recv 496 bytes from udp/[1.1.1.1]:5066 at 17:25:00.098416:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 9.9.9.9:5066;rport=5066;branch=z9hG4bKaUtZeDZtHBcaQ
From: <sip:mod_sofia at 9.9.9.9:5066>;tag=2BeNcBBtF3vmB
To: <sip:3059001001 at 9.9.9.9>;tag=472551479
Call-ID: 313b31d8-d3cd-40f5-b8cd-89ff32611ac8_383685583-5066-1 at BJC.BGI.B.BAB
CSeq: 103899449 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP1165 1.0.5.23
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): msg 0x7f78940f88e0 (496 bytes) from udp/1.1.1.1:5066/sip next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for OPTIONS (103899449)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 76.879 ms
tport.c:4222 tport_release() tport_release(0x7f7894004440): 0x7f78940fc660 by 0x7f78940eb6f0 with 0x7f78940f88e0
nua_stack.c:271 nua_stack_event() nua(0x7f788401d820): event r_options 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f788401d820): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f788401d820): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940cc2f0) called
nta.c:1296 agent_timer() nta: timer set next to 4076 ms
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7898008a70): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7898008a70)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7898008a70) msg 0x7f78980480b0 from (udp/9.9.9.9:5080) has 532 bytes, veclen = 1
recv 532 bytes from udp/[10.10.10.10]:5060 at 17:25:02.944958:
------------------------------------------------------------------------
BYE sip:gw+creacomm at 9.9.9.9:5080;gw=creacomm SIP/2.0
Max-Forwards: 69
To: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
From: <sip:17864732820 at 10.10.10.10:5060>;tag=3697482296-311493
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 2 BYE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Via: SIP/2.0/UDP 10.10.10.10:5060;branch=z9hG4bK42e5da9c5b3106a6887a0af153a3e263
Contact: <sip:17864732820 at 10.10.10.10:5060>
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f7898008a70): msg 0x7f78980480b0 (532 bytes) from udp/10.10.10.10:5080/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received BYE sip:gw+creacomm at 9.9.9.9:5080;gw=creacomm SIP/2.0 (CSeq 2)
nta.c:3248 agent_aliases() nta: canonizing sip:gw+creacomm at 9.9.9.9:5080 with contact
nta.c:3060 agent_recv_request() nta: BYE (2) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_bye 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2017-03-02 17:25:02.952048 [NOTICE] sofia.c:1012 Hangup sofia/external/17864732820 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f78a00047b0): sent signal r_respond
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f78a00047b0): sent signal r_destroy
nua_stack.c:573 nua_stack_signal() nua(0x7f78a00047b0): recv signal r_respond 200 OK
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78980122f0, ...) called
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = UDP/10.10.10.10:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 10.10.10.10:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name UDP/10.10.10.10:5060
2017-03-02 17:25:02.952048 [DEBUG] switch_ivr_bridge.c:752 BRIDGE THREAD DONE [sofia/external/17864732820]
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:653 (sofia/external/17864732820) State EXCHANGE_MEDIA going to sleep
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_HANGUP (Cur 2 Tot 101)
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 503 bytes of 503 to udp/10.10.10.10:5060
tport.c:3492 tport_send_msg() tport_vsend returned 503
send 503 bytes to udp/[10.10.10.10]:5060 at 17:25:02.962671:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.10.10:5060;branch=z9hG4bK42e5da9c5b3106a6887a0af153a3e263
From: <sip:17864732820 at 10.10.10.10:5060>;tag=3697482296-311493
To: "17863580970" <sip:17863580970 at 9.9.9.9>;tag=UmU2mvKN1pKNQ
Call-ID: dd69de46-7a0f-1235-f1ac-be187db6d1b8
CSeq: 2 BYE
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0
------------------------------------------------------------------------
nta.c:6791 incoming_reply() nta: sent 200 OK for BYE (2)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f78a00047b0): removing session usage
nua_session.c:4139 signal_call_state_change() nua(0x7f78a00047b0): call state changed: ready -> terminated
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:850 (sofia/external/17864732820) Callstate Change ACTIVE -> HANGUP
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_state 200 Session Terminated
nua_stack.c:271 nua_stack_event() nua(0x7f78a00047b0): event i_terminated 200 Session Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f78980122f0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f7898018b80)
nua_stack.c:569 nua_stack_signal() nua(0x7f78a00047b0): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:852 (sofia/external/17864732820) State HANGUP
2017-03-02 17:25:02.952048 [DEBUG] mod_sofia.c:438 Channel sofia/external/17864732820 hanging up, cause: NORMAL_CLEARING
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:60 sofia/external/17864732820 Standard HANGUP, cause: NORMAL_CLEARING
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:852 (sofia/external/17864732820) State HANGUP going to sleep
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:619 (sofia/external/17864732820) State Change CS_HANGUP -> CS_REPORTING
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17864732820) Running State Change CS_REPORTING (Cur 2 Tot 101)
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:938 (sofia/external/17864732820) State REPORTING
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:174 sofia/external/17864732820 Standard REPORTING, cause: NORMAL_CLEARING
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:938 (sofia/external/17864732820) State REPORTING going to sleep
2017-03-02 17:25:02.952048 [DEBUG] switch_core_state_machine.c:610 (sofia/external/17864732820) State Change CS_REPORTING -> CS_DESTROY
2017-03-02 17:25:02.952048 [DEBUG] switch_core_session.c:1664 Session 101 (sofia/external/17864732820) Locked, Waiting on external entities
2017-03-02 17:25:02.992038 [DEBUG] switch_ivr_bridge.c:752 BRIDGE THREAD DONE [sofia/internal/3059001003 at 9.9.9.9:5066]
2017-03-02 17:25:02.992038 [NOTICE] switch_core_session.c:1682 Session 101 (sofia/external/17864732820) Ended
2017-03-02 17:25:02.992038 [NOTICE] switch_core_session.c:1686 Close Channel sofia/external/17864732820 [CS_DESTROY]
2017-03-02 17:25:02.992038 [NOTICE] switch_core_state_machine.c:385 sofia/internal/3059001003 at 9.9.9.9:5066 has executed the last dialplan instruction, hanging up.
2017-03-02 17:25:02.992038 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/3059001003 at 9.9.9.9:5066 [CS_EXECUTE] [NORMAL_CLEARING]
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:741 (sofia/external/17864732820) Running State Change CS_DESTROY (Cur 1 Tot 101)
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3059001003 at 9.9.9.9:5066) State EXECUTE going to sleep
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_HANGUP (Cur 1 Tot 101)
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:751 (sofia/external/17864732820) State DESTROY
2017-03-02 17:25:02.992038 [DEBUG] mod_sofia.c:343 sofia/external/17864732820 SOFIA DESTROY
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/3059001003 at 9.9.9.9:5066) Callstate Change ACTIVE -> HANGUP
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:181 sofia/external/17864732820 Standard DESTROY
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:751 (sofia/external/17864732820) State DESTROY going to sleep
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3059001003 at 9.9.9.9:5066) State HANGUP
2017-03-02 17:25:02.992038 [DEBUG] mod_sofia.c:432 sofia/internal/3059001003 at 9.9.9.9:5066 Overriding SIP cause 480 with 200 from the other leg
2017-03-02 17:25:02.992038 [DEBUG] mod_sofia.c:438 Channel sofia/internal/3059001003 at 9.9.9.9:5066 hanging up, cause: NORMAL_CLEARING
2017-03-02 17:25:02.992038 [DEBUG] mod_sofia.c:491 Sending BYE to sofia/internal/3059001003 at 9.9.9.9:5066
nua.c:645 nua_bye() nua: nua_bye: entering
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_bye
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:60 sofia/internal/3059001003 at 9.9.9.9:5066 Standard HANGUP, cause: NORMAL_CLEARING
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3059001003 at 9.9.9.9:5066) State HANGUP going to sleep
nua_stack.c:569 nua_stack_signal() nua(0x7f78940f0970): recv signal r_bye
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f78940ea6c0, ...) called
soa.c:1784 soa_terminate() soa_terminate(static::0x7f78940ea6c0) called
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/3059001003 at 9.9.9.9:5066) State Change CS_HANGUP -> CS_REPORTING
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f78940ea6c0) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f78940048f0) tpn = tcp/1.1.1.1:33919
tport.c:4046 tport_resolve() tport_resolve addrinfo = 1.1.1.1:33919
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f78940048f0): not found by name tcp/1.1.1.1:33919
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940e3e90
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940e3e90): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940e3e90): Setting TCP_KEEPINTVL to 30
tport.c:1032 tport_base_connect() tport_base_connect(0x7f78940e3e90): connecting to tcp/1.1.1.1:33919/sip
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940e3e90): reset timer
tport.c:3782 tport_queue() tport_queue(0x7f78940e3e90): queueing 0x7f78941006e0 for tcp/1.1.1.1:33919
nta.c:8304 outgoing_send() nta: sent BYE (103901687) to tcp/1.1.1.1:33919
tport.c:4160 tport_pend() tport_pend(0x7f78940e3e90): pending 0x7f78941006e0 for tcp/1.1.1.1:33919 (already 0)
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_REPORTING (Cur 1 Tot 101)
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3059001003 at 9.9.9.9:5066) State REPORTING
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:174 sofia/internal/3059001003 at 9.9.9.9:5066 Standard REPORTING, cause: NORMAL_CLEARING
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3059001003 at 9.9.9.9:5066) State REPORTING going to sleep
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/3059001003 at 9.9.9.9:5066) State Change CS_REPORTING -> CS_DESTROY
2017-03-02 17:25:02.992038 [DEBUG] switch_core_session.c:1664 Session 100 (sofia/internal/3059001003 at 9.9.9.9:5066) Locked, Waiting on external entities
2017-03-02 17:25:02.992038 [NOTICE] switch_core_session.c:1682 Session 100 (sofia/internal/3059001003 at 9.9.9.9:5066) Ended
2017-03-02 17:25:02.992038 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/3059001003 at 9.9.9.9:5066 [CS_DESTROY]
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/3059001003 at 9.9.9.9:5066) Running State Change CS_DESTROY (Cur 0 Tot 101)
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3059001003 at 9.9.9.9:5066) State DESTROY
2017-03-02 17:25:02.992038 [DEBUG] mod_sofia.c:343 sofia/internal/3059001003 at 9.9.9.9:5066 SOFIA DESTROY
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:181 sofia/internal/3059001003 at 9.9.9.9:5066 Standard DESTROY
2017-03-02 17:25:02.992038 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3059001003 at 9.9.9.9:5066) State DESTROY going to sleep
tport.c:2689 tport_connected() tport_connected(0x7f78940e3e90): events CONNECTED ERR
tport.c:4222 tport_release() tport_release(0x7f78940e3e90): 0x7f78941006e0 by 0x7f78940f43f0 with (nil)
nta.c:8496 outgoing_print_tport_error() nta: BYE (103901687): Connection refused (111) with tcp/[1.1.1.1]:33919
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event r_bye 503 Service Unavailable
nua_session.c:4139 signal_call_state_change() nua(0x7f78940f0970): call state changed: terminating -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_state 503 to BYE
nua_stack.c:271 nua_stack_event() nua(0x7f78940f0970): event i_terminated 503 to BYE
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f78940f0970): removing session usage
soa.c:356 soa_destroy() soa_destroy(static::0x7f78940ea6c0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f78940acc30)
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f78940f0970
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f78940f43f0)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940e3e90): reset timer
tport.c:2090 tport_close() tport_close(0x7f78940e3e90): tcp/1.1.1.1:33919/sip
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f78940f0970): recv signal r_destroy
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:529 nua_signal() nua(0x7f78940f0970): sent signal r_destroy
nta.c:9101 outgoing_timer_dk() nta: timer K fired, terminate OPTIONS (103899449)
nta.c:8799 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f78baeedd40)
nta.c:8929 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f7894004440): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f7894004440)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f7894004440) msg 0x7f78940f9740 from (udp/9.9.9.9:5066) has 20 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f7894004440): bad msg 0x7f78940f9740 (0 bytes) from udp/1.1.1.1:5066/sip next=(nil)
tport.c:2749 tport_wakeup_pri() tport_wakeup_pri(0x7f78940048f0): events IN
tport.c:862 tport_alloc_secondary() tport_alloc_secondary(0x7f78940048f0): new secondary tport 0x7f78940f0450
tport_type_tcp.c:203 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f0450): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary() tport_tcp_init_secondary(0x7f78940f0450): Setting TCP_KEEPINTVL to 30
tport.c:2640 tport_accept() tport_accept(0x7f78940f0450): new connection from tcp/1.1.1.1:33920/sip
tport.c:2773 tport_wakeup() tport_wakeup(0x7f78940f0450): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f78940f0450)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f78940f0450) msg 0x7f78940edcc0 from (tcp/1.1.1.1:33920) has 625 bytes, veclen = 1
recv 625 bytes from tcp/[1.1.1.1]:33920 at 17:25:08.872547:
------------------------------------------------------------------------
BYE sip:0017864732820 at 9.9.9.9:5066;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK646800288;rport
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1302 BYE
Contact: <sip:3059001003 at 192.168.1.103:5066;transport=tcp;user=phone>
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream GXP1165 1.0.5.26
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x7f78940f0450): msg 0x7f78940edcc0 (625 bytes) from tcp/1.1.1.1:33920/sip next=(nil)
nta.c:2880 agent_recv_request() nta: received BYE sip:0017864732820 at 9.9.9.9:5066;transport=tcp SIP/2.0 (CSeq 1302)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3248 agent_aliases() nta: canonizing sip:0017864732820 at 9.9.9.9:5066 with contact
nta.c:3085 agent_recv_request() nta: BYE (1302) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
tport.c:3257 tport_tsend() tport_tsend(0x7f78940f0450) tpn = TCP/1.1.1.1:33920
tport.c:3594 tport_vsend() tport_vsend(0x7f78940f0450): 569 bytes of 569 to tcp/1.1.1.1:33920
tport.c:3492 tport_send_msg() tport_vsend returned 569
send 569 bytes to tcp/[1.1.1.1]:33920 at 17:25:08.872729:
------------------------------------------------------------------------
SIP/2.0 481 Call Does Not Exist
Via: SIP/2.0/TCP 192.168.1.103:5066;branch=z9hG4bK646800288;rport=33920;received=1.1.1.1
From: "3059001003" <sip:3059001003 at 9.9.9.9:5066;user=phone>;tag=1168498006
To: <sip:0017864732820 at 9.9.9.9:5066;user=phone>;tag=UcX7ZDN1340Ha
Call-ID: 661215423-5066-131 at BJC.BGI.B.BAD
CSeq: 1302 BYE
User-Agent: FreeSWITCH-mod_sofia/1.6.15-32-bec4538~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0
------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f0450): reset timer
nta.c:6791 incoming_reply() nta: sent 481 Call Does Not Exist for BYE (1302)
nta.c:5744 incoming_free() nta: incoming_free(0x7f7894076990)
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f0450): reset timer
tport.c:2296 tport_set_secondary_timer() tport(0x7f78940f0450): reset timer
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:657 nua_options() nua: nua_options: entering
nua_stack.c:529 nua_signal() nua(0x7f788801a090): sent signal r_options
nua_stack.c:569 nua_stack_signal() nua(0x7f788801a090): recv signal r_options
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f7898001100, 0x7f78980078e0, 0x7f788801a090) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898049de0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f7898049de0, ...) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3257 tport_tsend() tport_tsend(0x7f7898008a70) tpn = udp/162.212.218.50:5060
tport.c:4046 tport_resolve() tport_resolve addrinfo = 162.212.218.50:5060
tport.c:4680 tport_by_addrinfo() tport_by_addrinfo(0x7f7898008a70): not found by name udp/162.212.218.50:5060
tport.c:3594 tport_vsend() tport_vsend(0x7f7898008a70): 532 bytes of 532 to udp/162.212.218.50:5060
tport.c:3492 tport_send_msg() tport_vsend returned 532
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list