[Freeswitch-dev] Registered two SIP sets, but can't make calls
Hi Experts, I am new to this mailing list. I am trying to port the Freeswitch-1.0.6 to an embedded system. The Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue? The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL. Best Regards, Guoren tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0 ------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release. Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result. What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above. Start by upgrading to 1.2 and then you'll get more assistance. On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0
------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/ 1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/ 1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :) ________________________________ From: Steven Ayre <steveayre@gmail.com> To: "freeswitch-dev@lists.freeswitch.org" <freeswitch-dev@lists.freeswitch.org> Sent: Sunday, September 1, 2013 10:17 PM Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release. Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result. What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above. Start by upgrading to 1.2 and then you'll get more assistance. On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote: Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The
Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID:
QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK
CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409:
SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0 ------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889:
ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
True. But 1) it's age makes it harder to support because of the number of changes made since then and 2) there are many known bugs which have been fixed since then. It's entirely possible that there have been changes since then that might affect embedded platforms which might not appear on desktop architectures. If he's working on packaging FreeSWITCH for an embedded system his time would be far better spent using the latest stable version rather than having to later repeat all his work when upgrading to that version. Ignoring version, his log still lacks any of the dialplan processing to see what's happening to the call. We're still waiting to know if that was the entire call log or just an excerpt. On 1 September 2013 22:25, Stanislav Sinyagin <ssinyagin@yahoo.com> wrote:
but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :)
------------------------------ *From:* Steven Ayre <steveayre@gmail.com> *To:* "freeswitch-dev@lists.freeswitch.org" < freeswitch-dev@lists.freeswitch.org> *Sent:* Sunday, September 1, 2013 10:17 PM *Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release.
Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result.
What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above.
Start by upgrading to 1.2 and then you'll get more assistance.
On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0
------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/ 1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/ 1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
Hi Steven and Stanislav, Thanks for your responses. The reason I have choosen 1.0.6 was because I could refer the DD-WRT embedded porting and it has fewer modules. I just want to prove it works on my target, then I can work on the newer FS releases. The log I posted is just sections from the call was made to the call hangup. What logs do you need to identify the issue? How do I check if the dialplan was executed or not? Or how do I check what events are send to dialplan. There's no ERR messages of the call failure. I build the same load on Ubuntu and it works fine. Is there a way to check if the database works okay? Best Regards, Guoren ________________________________ From: Steven Ayre <steveayre@gmail.com> To: "freeswitch-dev@lists.freeswitch.org" <freeswitch-dev@lists.freeswitch.org> Sent: Monday, September 2, 2013 10:43 AM Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls True. But 1) it's age makes it harder to support because of the number of changes made since then and 2) there are many known bugs which have been fixed since then. It's entirely possible that there have been changes since then that might affect embedded platforms which might not appear on desktop architectures. If he's working on packaging FreeSWITCH for an embedded system his time would be far better spent using the latest stable version rather than having to later repeat all his work when upgrading to that version. Ignoring version, his log still lacks any of the dialplan processing to see what's happening to the call. We're still waiting to know if that was the entire call log or just an excerpt. On 1 September 2013 22:25, Stanislav Sinyagin <ssinyagin@yahoo.com> wrote: but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :)
________________________________ From: Steven Ayre <steveayre@gmail.com> To: "freeswitch-dev@lists.freeswitch.org" <freeswitch-dev@lists.freeswitch.org> Sent: Sunday, September 1, 2013 10:17 PM Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release.
Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result.
What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above.
Start by upgrading to 1.2 and then you'll get more assistance.
On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The
Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID:
QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK
CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409:
SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0 ------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889:
ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
It looks like whatever changed the state from new to init was not triggered by the 2nd invite. You could try disabling auth-calls and turn off the acls. The area in question in the mod_sofia code has been completely redone since this version so there is no use in debugging it. There are more modern builds of FS for openwrt to play with. On Mon, Sep 2, 2013 at 7:44 PM, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Steven and Stanislav,
Thanks for your responses. The reason I have choosen 1.0.6 was because I could refer the DD-WRT embedded porting and it has fewer modules. I just want to prove it works on my target, then I can work on the newer FS releases.
The log I posted is just sections from the call was made to the call hangup. What logs do you need to identify the issue? How do I check if the dialplan was executed or not? Or how do I check what events are send to dialplan. There's no ERR messages of the call failure.
I build the same load on Ubuntu and it works fine. Is there a way to check if the database works okay?
Best Regards, Guoren
------------------------------ *From:* Steven Ayre <steveayre@gmail.com> *To:* "freeswitch-dev@lists.freeswitch.org" < freeswitch-dev@lists.freeswitch.org> *Sent:* Monday, September 2, 2013 10:43 AM
*Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
True.
But 1) it's age makes it harder to support because of the number of changes made since then and 2) there are many known bugs which have been fixed since then. It's entirely possible that there have been changes since then that might affect embedded platforms which might not appear on desktop architectures.
If he's working on packaging FreeSWITCH for an embedded system his time would be far better spent using the latest stable version rather than having to later repeat all his work when upgrading to that version.
Ignoring version, his log still lacks any of the dialplan processing to see what's happening to the call. We're still waiting to know if that was the entire call log or just an excerpt.
On 1 September 2013 22:25, Stanislav Sinyagin <ssinyagin@yahoo.com> wrote:
but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :)
------------------------------ *From:* Steven Ayre <steveayre@gmail.com> *To:* "freeswitch-dev@lists.freeswitch.org" < freeswitch-dev@lists.freeswitch.org> *Sent:* Sunday, September 1, 2013 10:17 PM *Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release.
Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result.
What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above.
Start by upgrading to 1.2 and then you'll get more assistance.
On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0
------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/ 1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/ 1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
Hi Anthony, Thanks for your response and your great work. I have tried to disable the authentication in the vars.xml (<X-PRE-PROCESS cmd="set" data="internal_auth_calls=false"/>), I also have tried to turn off the acls in acl.conf.xml (<list name="lan" default="allow">) But still no luck. I am interested in working on the latest fs for openwrt. Do you know the FS link for openwrt project? Best Regards, Guoren ________________________________ From: Anthony Minessale <anthony.minessale@gmail.com> To: freeswitch-dev@lists.freeswitch.org Sent: Tuesday, September 3, 2013 3:26 PM Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls It looks like whatever changed the state from new to init was not triggered by the 2nd invite. You could try disabling auth-calls and turn off the acls. The area in question in the mod_sofia code has been completely redone since this version so there is no use in debugging it. There are more modern builds of FS for openwrt to play with. On Mon, Sep 2, 2013 at 7:44 PM, Guoren Chen <guoren.chen@yahoo.com> wrote: Hi Steven and Stanislav,
Thanks for your responses. The reason I have choosen 1.0.6 was because I could refer the DD-WRT embedded porting and it has fewer modules. I just want to prove it works on my target, then I can work on the newer FS releases.
The log I posted is just sections from the call was made to the call hangup. What logs do you need to identify the issue? How do I check if the dialplan was executed or not? Or how do I check what events are send to dialplan. There's no ERR messages of the call failure.
I build the same load on Ubuntu and it works fine. Is there a way to check if the database works okay?
Best Regards, Guoren
________________________________ From: Steven Ayre <steveayre@gmail.com> To: "freeswitch-dev@lists.freeswitch.org" <freeswitch-dev@lists.freeswitch.org> Sent: Monday, September 2, 2013 10:43 AM
Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
True.
But 1) it's age makes it harder to support because of the number of changes made since then and 2) there are many known bugs which have been fixed since then. It's entirely possible that there have been changes since then that might affect embedded platforms which might not appear on desktop architectures.
If he's working on packaging FreeSWITCH for an embedded system his time would be far better spent using the latest stable version rather than having to later repeat all his work when upgrading to that version.
Ignoring version, his log still lacks any of the dialplan processing to see what's happening to the call. We're still waiting to know if that was the entire call log or just an excerpt.
On 1 September 2013 22:25, Stanislav Sinyagin <ssinyagin@yahoo.com> wrote:
but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :)
________________________________ From: Steven Ayre <steveayre@gmail.com> To: "freeswitch-dev@lists.freeswitch.org" <freeswitch-dev@lists.freeswitch.org> Sent: Sunday, September 1, 2013 10:17 PM Subject: Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release.
Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result.
What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above.
Start by upgrading to 1.2 and then you'll get more assistance.
On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The
Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID:
QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK
CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344 v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409:
SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0 ------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889:
ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900 _________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
There is some info at http://www.dslreports.com/forum/r26175270-PBX-Building-Freeswitch-under-open... On Tue, Sep 3, 2013 at 10:49 PM, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Anthony,
Thanks for your response and your great work.
I have tried to disable the authentication in the vars.xml (<X-PRE-PROCESS cmd="set" data="internal_auth_calls=false"/>), I also have tried to turn off the acls in acl.conf.xml (<list name="lan" default="allow">) But still no luck.
I am interested in working on the latest fs for openwrt. Do you know the FS link for openwrt project?
Best Regards, Guoren
------------------------------ *From:* Anthony Minessale <anthony.minessale@gmail.com> *To:* freeswitch-dev@lists.freeswitch.org *Sent:* Tuesday, September 3, 2013 3:26 PM
*Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
It looks like whatever changed the state from new to init was not triggered by the 2nd invite. You could try disabling auth-calls and turn off the acls.
The area in question in the mod_sofia code has been completely redone since this version so there is no use in debugging it. There are more modern builds of FS for openwrt to play with.
On Mon, Sep 2, 2013 at 7:44 PM, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Steven and Stanislav,
Thanks for your responses. The reason I have choosen 1.0.6 was because I could refer the DD-WRT embedded porting and it has fewer modules. I just want to prove it works on my target, then I can work on the newer FS releases.
The log I posted is just sections from the call was made to the call hangup. What logs do you need to identify the issue? How do I check if the dialplan was executed or not? Or how do I check what events are send to dialplan. There's no ERR messages of the call failure.
I build the same load on Ubuntu and it works fine. Is there a way to check if the database works okay?
Best Regards, Guoren
------------------------------ *From:* Steven Ayre <steveayre@gmail.com> *To:* "freeswitch-dev@lists.freeswitch.org" < freeswitch-dev@lists.freeswitch.org> *Sent:* Monday, September 2, 2013 10:43 AM
*Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
True.
But 1) it's age makes it harder to support because of the number of changes made since then and 2) there are many known bugs which have been fixed since then. It's entirely possible that there have been changes since then that might affect embedded platforms which might not appear on desktop architectures.
If he's working on packaging FreeSWITCH for an embedded system his time would be far better spent using the latest stable version rather than having to later repeat all his work when upgrading to that version.
Ignoring version, his log still lacks any of the dialplan processing to see what's happening to the call. We're still waiting to know if that was the entire call log or just an excerpt.
On 1 September 2013 22:25, Stanislav Sinyagin <ssinyagin@yahoo.com> wrote:
but honestly, 1.0.6 is a completely functional release, and a simple call like this should work the same :)
------------------------------ *From:* Steven Ayre <steveayre@gmail.com> *To:* "freeswitch-dev@lists.freeswitch.org" < freeswitch-dev@lists.freeswitch.org> *Sent:* Sunday, September 1, 2013 10:17 PM *Subject:* Re: [Freeswitch-dev] Registered two SIP sets, but can't make calls
First, 1.0.6 is an absolutely ancient release now. Use the latest 1.2.12 release.
Second, you are using the logging of the internal Sofia SIP stack. That's very rarely needed... while useful sometimes in this case it's probably making the log overly verbose and harder to read as a result.
What looks a little odd is once the call is authenticated it doesn't appear to do anything for 10s until the hangup. Is this the complete log, or a selected excerpt? Normally the call would log itself looking through the dialplan showing what dialplan extensions matched and what actions would be/are being executed. I don't see that in the above.
Start by upgrading to 1.2 and then you'll get more assistance.
On 1 September 2013 17:12, Guoren Chen <guoren.chen@yahoo.com> wrote:
Hi Experts,
I am new to this mailing list.
I am trying to port the Freeswitch-1.0.6 to an embedded system. The Freeswitch can run on the target and I can register two SIP sets on the target. However, I can't make calls between them. I am using the default configuration files copied from the Linux build. Here are the logs from the target. Could some one help me to find out the issue?
The call was made from 1002 calling 1001. Freeswitch does not send requests to 1001. Then, 1002 sends CANCEL.
Best Regards, Guoren
tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x670fd0c8 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 1023 bytes, veclen = 1 recv 1023 bytes from udp/[192.168.1.127]:53708 at 14:33:17.958167: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (1023 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23696) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67111080) called soa_set_params(static::0x6723ddf8, ...) called nta_leg_tcreate(0x67111160) soa_init_offer_answer(static::0x6723ddf8) called soa_set_remote_sdp(static::0x6723ddf8, 0x0, 0x67111d97, 344) called nua(0x67111080): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.976794: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23696) nua(0x67111080): event i_invite 100 Trying nua(0x67111080): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x6723ddf8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua: nua_application_event: entering nua(0x67111080): event i_state 100 Trying 2013-09-01 22:33:17.976039 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua: nua_respond: entering nua(0x67111080): sent signal r_respond nua: nua_handle_magic: entering nua: nua_handle_destroy: entering nua(0x67111080): sent signal r_destroy nua: nua_application_event: entering nua(0x67111080): event i_state dropped nua(0x67111080): recv signal r_respond 407 Proxy Authentication Required nua: nua_stack_set_params: entering soa_set_params(static::0x6723ddf8, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x6723ddf8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 833 bytes of 833 to udp/192.168.1.127:53708 tport_vsend returned 833 send 833 bytes to udp/[192.168.1.127]:53708 at 14:33:17.983158: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ nta: sent 407 Proxy Authentication Required for INVITE (23696) nua(0x67111080): removing session usage nua(0x67111080): call state changed: received -> terminated nua(0x67111080): event i_state 407 Proxy Authentication Required nua(0x67111080): event i_terminated 407 Proxy Authentication Required soa_destroy(static::0x6723ddf8) called nta_leg_destroy(0x67111160) nua(0x67111080): recv signal r_destroy nta_leg_destroy(0x0) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:17.990814: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjobYcaLv1k0J-Sc62VfANoNHr6WPEgFSH Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=9v5Hv8D1Z7emg Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23696 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23696) nta: ACK (23696) is going to INVITE (23696) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x67238bc8 from (udp/192.168.1.101:5060) has 1293 bytes, veclen = 1 recv 1293 bytes from udp/[192.168.1.127]:53708 at 14:33:17.992057: ------------------------------------------------------------------------ INVITE sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Contact: <sip:1002@192.168.1.127:53708;ob> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE Route: <sip:192.168.1.101;transport=udp;lr> Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 1800 Min-SE: 90 User-Agent: CSipSimple_thunderg-8/r2272 Proxy-Authorization: Digest username="1002", realm="192.168.1.101", nonce="7170d9ac-1313-11e3-b4ff-1f256118ae1c", uri="sip:1001@192.168.1.101", response="7030c512040326bd546d40934f2014c0", algorithm=MD5, cnonce="8FFIKkeUBmBir9b4TvXVFFJPNm6uOzWJ", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 344
v=0 o=- 3587034797 3587034797 IN IP4 192.168.1.127 s=pjmedia c=IN IP4 192.168.1.127 t=0 0 m=audio 4012 RTP/AVP 98 0 8 101 c=IN IP4 192.168.1.127 a=rtcp:4013 IN IP4 192.168.1.127 a=sendrecv a=rtpmap:98 SILK/16000 a=fmtp:98 useinbandfec=0 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 ------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x67238bc8 (1293 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received INVITE sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: canonizing sip:1001@192.168.1.101 with contact nta: INVITE (23697) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x66f02188, 0x66eaa058, 0x67129d70) called soa_set_params(static::0x671122d8, ...) called nta_leg_tcreate(0x670f2388) soa_init_offer_answer(static::0x671122d8) called soa_set_remote_sdp(static::0x671122d8, 0x0, 0x6723ddbd, 344) called nua(0x67129d70): adding session usage tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 351 bytes of 351 to udp/192.168.1.127:53708 tport_vsend returned 351 send 351 bytes to udp/[192.168.1.127]:53708 at 14:33:17.993409: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Content-Length: 0
------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (23697) nua(0x67129d70): event i_invite 100 Trying nua: nua_application_event: entering 2013-09-01 22:33:17.991895 [DEBUG] sofia.c:5856 IP 192.168.1.127 Rejected by acl "domains". Falling back to Digest auth. nua(0x67129d70): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x671122d8, [0x68d1a8ec], [0x68d1a8f0], [0x0]) called nua(0x67129d70): event i_state 100 Trying 2013-09-01 22:33:17.999970 [NOTICE] switch_channel.c:669 New Channel sofia/internal/1002@192.168.1.101 [71742bb6-1313-11e3-b500-1f256118ae1c] nua: nua_handle_bind: entering 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_NEW 2013-09-01 22:33:18.000945 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1002@192.168.1.101) State NEW nua: nua_handle_magic: entering nua: nua_application_event: entering nta: timer set next to 4833 ms nta: timer I fired, terminate 407 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/2 free nta: timer not set tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x670fd0c8 from (udp/192.168.1.101:5060) has 420 bytes, veclen = 1 recv 420 bytes from udp/[192.168.1.127]:53708 at 14:33:29.147169: ------------------------------------------------------------------------ CANCEL sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101> Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Route: <sip:192.168.1.101;transport=udp;lr> User-Agent: CSipSimple_thunderg-8/r2272 Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x670fd0c8 (420 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received CANCEL sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: CANCEL (23697) is going to INVITE (23697) tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 316 bytes of 316 to udp/192.168.1.127:53708 tport_vsend returned 316 send 316 bytes to udp/[192.168.1.127]:53708 at 14:33:29.149288: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 CANCEL Content-Length: 0
------------------------------------------------------------------------ nua: process_ack_or_cancel: entering nua(0x67129d70): event i_cancel 200 OK nua: nua_application_event: entering nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0x671122d8) called tport_tsend(0x66fafcc0) tpn = UDP/192.168.1.127:53708 tport_resolve addrinfo = 192.168.1.127:53708 tport_by_addrinfo(0x66fafcc0): not found by name UDP/192.168.1.127:53708 tport_vsend(0x66fafcc0): 699 bytes of 699 to udp/192.168.1.127:53708 tport_vsend returned 699 send 699 bytes to udp/[192.168.1.127]:53708 at 14:33:29.156960: ------------------------------------------------------------------------ SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport=53708;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 INVITE User-Agent: FreeSWITCH-mod_sofia/1.0.6-exported Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
------------------------------------------------------------------------ nta: sent 487 Request Terminated for INVITE (23697) nta: timer set to 500 ms nua(0x67129d70): removing session usage nua(0x67129d70): call state changed: received -> terminated nua(0x67129d70): event i_state 487 Request Terminated nua: nua_application_event: entering nua(0x67129d70): event i_terminated 487 Request Terminated nua: nua_application_event: entering soa_destroy(static::0x671122d8) called nta_leg_destroy(0x670f2388) tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x671275d0 from (udp/192.168.1.101:5060) has 391 bytes, veclen = 1 recv 391 bytes from udp/[192.168.1.127]:53708 at 14:33:29.172889: ------------------------------------------------------------------------ ACK sip:1001@192.168.1.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.127:53708 ;rport;branch=z9hG4bKPjaGeluUtZsgBXv.Qg12.KDnfSX20HvCLa Max-Forwards: 70 From: <sip:1002@192.168.1.101>;tag=kixbEsV8lfAeqJQCxjCz.pQROBdSABlx To: <sip:1001@192.168.1.101>;tag=a6yay3y4vg56B Call-ID: QMiyKhBszEBh1szWNPnrCKG1j5CJsXGK CSeq: 23697 ACK Route: <sip:192.168.1.101;transport=udp;lr> Content-Length: 0
------------------------------------------------------------------------ tport_deliver(0x66fafcc0): msg 0x671275d0 (391 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta: received ACK sip:1001@192.168.1.101 SIP/2.0 (CSeq 23697) nta: ACK (23697) is going to INVITE (23697) nta: timer set next to 4526 ms nta: timer I fired, terminate 487 response incoming_reclaim_all(0x0, 0x0, 0x68d1adc0) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set 2013-09-01 22:34:20.044273 [CRIT] switch_core_state_machine.c:382 71742bb6-1313-11e3-b500-1f256118ae1c Timeout waiting for next instruction in CS_NEW! 2013-09-01 22:34:20.044273 [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/1002@192.168.1.101 [CS_NEW] [INVALID_CALL_REFERENCE] 2013-09-01 22:34:20.044273 [DEBUG] switch_channel.c:2102 Send signal sofia/internal/1002@192.168.1.101 [KILL] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_HANGUP 2013-09-01 22:34:20.044273 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP 2013-09-01 22:34:20.044273 [DEBUG] mod_sofia.c:414 Channel sofia/internal/ 1002@192.168.1.101 hanging up, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.075383 [DEBUG] mod_sofia.c:476 Responding to INVITE with: 480 nua: nua_respond: entering nua(0x67129d70): recv signal r_respond 480 Temporarily Unavailable nua(0x67129d70): event i_error 500 Responding to a Non-Existing Request nua: nua_application_event: entering nua(0x67129d70): sent signal r_respond 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.1.101 Standard HANGUP, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.076358 [DEBUG] switch_core_state_machine.c:499 (sofia/internal/1002@192.168.1.101) State HANGUP going to sleep 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:333 (sofia/internal/1002@192.168.1.101) State Change CS_HANGUP -> CS_REPORTING 2013-09-01 22:34:20.078303 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.078303 [DEBUG] switch_core_state_machine.c:314 (sofia/internal/1002@192.168.1.101) Running State Change CS_REPORTING 2013-09-01 22:34:20.079283 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.1.101 Standard REPORTING, cause: INVALID_CALL_REFERENCE 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:590 (sofia/internal/1002@192.168.1.101) State REPORTING going to sleep 2013-09-01 22:34:20.081246 [DEBUG] switch_core_state_machine.c:327 (sofia/internal/1002@192.168.1.101) State Change CS_REPORTING -> CS_DESTROY 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1021 Send signal sofia/internal/1002@192.168.1.101 [BREAK] 2013-09-01 22:34:20.082232 [DEBUG] switch_core_session.c:1164 Session 1 (sofia/internal/1002@192.168.1.101) Locked, Waiting on external entities 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1182 Session 1 (sofia/internal/1002@192.168.1.101) Ended 2013-09-01 22:34:20.082232 [NOTICE] switch_core_session.c:1184 Close Channel sofia/internal/1002@192.168.1.101 [CS_DESTROY] 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:428 (sofia/internal/1002@192.168.1.101) Running State Change CS_DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY 2013-09-01 22:34:20.083207 [DEBUG] mod_sofia.c:341 sofia/internal/ 1002@192.168.1.101 SOFIA DESTROY 2013-09-01 22:34:20.083207 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.1.101 Standard DESTROY 2013-09-01 22:34:20.084324 [DEBUG] switch_core_state_machine.c:439 (sofia/internal/1002@192.168.1.101) State DESTROY going to sleep tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.127:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.121:5060/sip next=0x0 nta_agent: received garbage from udp/192.168.1.121:5060/sip tport_wakeup_pri(0x66fafcc0): events IN tport_recv_event(0x66fafcc0) tport_recv_iovec(0x66fafcc0) msg 0x6719d5e0 from (udp/192.168.1.101:5060) has 2 bytes, veclen = 1 tport_deliver(0x66fafcc0): bad msg 0x6719d5e0 (2 bytes) from udp/ 192.168.1.127:5060/sip next=0x0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
participants (4)
-
Anthony Minessale
-
Guoren Chen
-
Stanislav Sinyagin
-
Steven Ayre