I read up a bit on 'Contact' in the SIP RFC and stared at the merged log and
pcap trace watching the ATA. The contact field is being supplied by the 3102
and passed around, but it is missing in the response to the INVITE message sent
from the proxy to the freeswitch process.
I'm happy to dig deeper if someone could give me a pointer where to start
poking around to save a bit of time (is this stuff handled down in the
sipXtackLib or somewhere in the proxy code?).
-Eric
Session Initiation Protocol
Request-Line: INVITE sip:[email protected] SIP/2.0
Method: INVITE
Request-URI: sip:[email protected]
Request-URI User Part: 0
Request-URI Host Part: d3.foo21.com
[Resent Packet: False]
Message Header
Via: SIP/2.0/UDP 192.172.252.21:5061;branch=z9hG4bK-5c3fd3ea
Transport: UDP
Sent-by Address: 192.172.252.21
Sent-by port: 5061
Branch: z9hG4bK-5c3fd3ea
From: SMITH,A <sip:[email protected]>;tag=6e8b9fe8ed9f4d3ao1
SIP Display info: SMITH,A
SIP from address: sip:[email protected]
SIP from address User Part: 17635191497
SIP from address Host Part: d3.foo21.com
SIP tag: 6e8b9fe8ed9f4d3ao1
To: <sip:[email protected]>
SIP to address: sip:[email protected]
SIP to address Host Part: d3.foo21.com
Remote-Party-ID: SMITH,A
<sip:[email protected]>;screen=yes;party=calling
[Expert Info (Note/Undecoded): Unrecognised SIP header
(Remote-Party-ID)]
[Message: Unrecognised SIP header (Remote-Party-ID)]
[Severity level: Note]
[Group: Undecoded]
Call-ID: [email protected]
CSeq: 101 INVITE
Sequence Number: 101
Method: INVITE
Max-Forwards: 70
Contact: "PSTN FXO1" <sip:[email protected]:5061>
Contact Binding: "PSTN FXO1" <sip:[email protected]:5061>
URI: "PSTN FXO1" <sip:[email protected]:5061>
SIP Display info: "PSTN FXO1"
SIP contact address: sip:[email protected]:5061
Expires: 240
User-Agent: Linksys/SPA3102-5.1.10(GW)
Content-Length: 452
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura, replaces
Content-Type: application/sdp
-Eric
On Jan 3, 2010, at 1:00 PM, Eric Varsanyi wrote:
> OK, finally had a chance to look into this a bit further. Freeswitch is
> SEGVing after I initially transfer from the AA to extension 200. If I wait
> long enough for freeswitch to restart I can hit reject and it ends up in
> voicemail as expected.
>
> It appears from a little gdbing around that freeswitch is failing because a
> 'ringing...' message from sipxproxy is resulting in the 'contact' field not
> getting set. I don't know the protocols well enough to say what 'contact'
> really means, but the parsed 'sip' structure in freeswitch has a 'from' and
> 'to' field (and some others) set. I'll look at freeswitch a bit more to see
> what sets the 'contact' field.
>
> I did build a newer RPM of freeswitch as of jan 1, 2010 (their svn 16111) and
> got the same behavior (the gdb traces below are from that more recent
> version, but there were no changes from the earlier version in the file that
> segfaulted so the line #'s are the same afaict).
>
> Here's some gdb spelunking from the SEGV'ing thread:
>
> #0 0x00007ff7e26fcf38 in sofia_handle_sip_i_notify (session=0x18d0228,
> status=<value optimized out>, phrase=<value optimized out>, nua=0x182a7a0,
> profile=0x7ff7dc02d370, nh=0x7ff7dc03cb40, sofia_private=0x1860180,
> sip=0x7ff7d402d8c8, tags=0x7ff7d407d8a0) at sofia.c:147
> 147 switch_event_add_header(s_event, SWITCH_STACK_BOTTOM,
> "contact", "%...@%s",
> Missing separate debuginfos, use: debuginfo-install
> sipx-freeswitch-1.0.5-16111.x86_64
> (gdb) bt
> #0 0x00007ff7e26fcf38 in sofia_handle_sip_i_notify (session=0x18d0228,
> status=<value optimized out>, phrase=<value optimized out>, nua=0x182a7a0,
> profile=0x7ff7dc02d370, nh=0x7ff7dc03cb40, sofia_private=0x1860180,
> sip=0x7ff7d402d8c8, tags=0x7ff7d407d8a0) at sofia.c:147
> #1 0x00007ff7e2700976 in sofia_event_callback (event=<value optimized out>,
> status=200, phrase=0x7ff7d407d91e "OK", nua=0x182a7a0,
> profile=0x7ff7dc02d370, nh=0x7ff7dc03cb40, sofia_private=0x1860180,
> sip=0x7ff7d402d8c8, tags=0x7ff7d407d8a0) at sofia.c:662
> #2 0x00007ff7e276c98f in nua_application_event (dummy=<value optimized out>,
> sumsg=<value optimized out>, ee=0x7ff7d407d878) at nua_stack.c:393
> #3 0x00007ff7e27bc098 in su_base_port_execute_msgs (queue=0x0) at
> su_base_port.c:280
> #4 0x00007ff7e27bc5c0 in su_base_port_step (self=0x1827f20, tout=0) at
> su_base_port.c:473
> #5 0x00007ff7e26fb25a in sofia_profile_thread_run (thread=<value optimized
> out>, obj=<value optimized out>) at sofia.c:1235
> #6 0x00000030152073da in start_thread () from /lib64/libpthread.so.0
> #7 0x0000003014ae62bd in clone () from /lib64/libc.so.6
> (gdb) list
> 142 /* add common headers for the NOTIFY to the switch_event and
> fire if it exists */
> 143 if (s_event != NULL) {
> 144 switch_event_add_header_string(s_event,
> SWITCH_STACK_BOTTOM, "event-package", sip->sip_event->o_type);
> 145 switch_event_add_header_string(s_event,
> SWITCH_STACK_BOTTOM, "event-id", sip->sip_event->o_id);
> 146
> 147 switch_event_add_header(s_event, SWITCH_STACK_BOTTOM,
> "contact", "%...@%s",
> 148
> sip->sip_contact->m_url->url_user, sip->sip_contact->m_url->url_host);
> 149 switch_event_add_header(s_event, SWITCH_STACK_BOTTOM,
> "from", "%...@%s",
> 150
> sip->sip_from->a_url->url_user, sip->sip_from->a_url->url_host);
> 151 switch_event_add_header_string(s_event,
> SWITCH_STACK_BOTTOM, "from-tag", sip->sip_from->a_tag);
> (gdb) p sip->sip_contact
> $1 = (sip_contact_t *) 0x0
> (gdb) p *sip
> $2 = {sip_common = {{h_succ = 0x0, h_prev = 0x0, h_class = 0x7ff7dc02c7f0,
> h_data = 0x0, h_len = 0}}, sip_next = 0x0, sip_user = 0x0, sip_size = 688,
> sip_flags = 18022402, sip_error = 0x0, sip_request = 0x7ff7d40530d0,
> sip_status = 0x0, sip_via = 0x7ff7d402e010, sip_route = 0x0, sip_record_route
> = 0x0,
> sip_max_forwards = 0x7ff7d402e470, sip_proxy_require = 0x0, sip_from =
> 0x7ff7d402e1d0, sip_to = 0x7ff7d402e2d0, sip_call_id = 0x7ff7d402e3d0,
> sip_cseq = 0x7ff7d402e420, sip_contact = 0x0, sip_rseq = 0x0, sip_rack = 0x0,
> sip_request_disposition = 0x0, sip_accept_contact = 0x0, sip_reject_contact =
> 0x0,
> sip_expires = 0x0, sip_date = 0x7ff7d402e620, sip_retry_after = 0x0,
> sip_timestamp = 0x0, sip_min_expires = 0x0, sip_subject = 0x0, sip_priority =
> 0x0, sip_call_info = 0x0, sip_organization = 0x0, sip_server = 0x0,
> sip_user_agent = 0x7ff7d402e500, sip_in_reply_to = 0x0, sip_accept = 0x0,
> sip_accept_encoding = 0x0, sip_accept_language = 0x0, sip_allow = 0x0,
> sip_require = 0x0, sip_supported = 0x0, sip_unsupported = 0x0, sip_event =
> 0x7ff7d402e4b0, sip_allow_events = 0x0, sip_subscription_state = 0x0,
> sip_proxy_authenticate = 0x0, sip_proxy_authentication_info = 0x0,
> sip_proxy_authorization = 0x0, sip_authorization = 0x0, sip_www_authenticate
> = 0x0, sip_authentication_info = 0x0, sip_error_info = 0x0, sip_warning =
> 0x0, sip_refer_to = 0x0, sip_referred_by = 0x0, sip_replaces = 0x0,
> sip_session_expires = 0x0, sip_min_se = 0x0, sip_path = 0x0,
> sip_service_route = 0x0,
> sip_reason = 0x0, sip_security_client = 0x0, sip_security_server = 0x0,
> sip_security_verify = 0x0, sip_privacy = 0x0, sip_etag = 0x0, sip_if_match =
> 0x0, sip_mime_version = 0x0, sip_content_type = 0x7ff7d402e580,
> sip_content_encoding = 0x0, sip_content_language = 0x0,
> sip_content_disposition = 0x0,
> sip_content_length = 0x7ff7d402e540, sip_unknown = 0x0, sip_separator =
> 0x7ff7d402e660, sip_payload = 0x7ff7d402e6a0, sip_multipart = 0x0}
> (gdb) p *sip->sip_request
> $3 = {rq_common = {{h_succ = 0x7ff7d402e010, h_prev = 0x7ff7d402d810, h_class
> = 0x7ff7e2a46860, h_data = 0x0, h_len = 0}}, rq_next = 0x0, rq_method =
> sip_method_notify, rq_method_name = 0x7ff7e2817e10 "NOTIFY", rq_url =
> {{url_pad = "\000\000\000\000\000", url_type = 1 '\001', url_root = 0 '\0',
> url_scheme = 0x7ff7d402ddc7 "sip", url_user = 0x7ff7d402ddcb "0",
> url_password = 0x0, url_host = 0x7ff7d402ddcd "192.172.252.163", url_port =
> 0x7ff7d402dddd "15060", url_path = 0x0, url_params = 0x7ff7d402dde3
> "transport=udp", url_headers = 0x0, url_fragment = 0x0}}, rq_version =
> 0x7ff7e2817dbd "SIP/2.0"}
>
> (gdb) p *sip->sip_via
> $2 = {v_common = {{h_succ = 0x7ff7d402e0f0, h_prev = 0x7ff7d40530d0, h_class
> = 0x7ff7e2a46d20, h_data = 0x0, h_len = 0}}, v_next = 0x7ff7d402e0f0,
> v_protocol = 0x7ff7e2817e25 "SIP/2.0/UDP", v_host = 0x7ff7d402de0b
> "192.172.252.163", v_port = 0x0, v_params = 0x7ff7d402e0a0, v_comment = 0x0,
> v_ttl = 0x0,
> v_maddr = 0x0, v_received = 0x0, v_branch = 0x7ff7d402de22
> "z9hG4bK-XX-00c37Rg`GG3bP5P2gMUD4x0oXA", v_rport = 0x0, v_comp = 0x0}
> (gdb) p *sip->sip_via->v_next
> $3 = {v_common = {{h_succ = 0x7ff7d402e1d0, h_prev = 0x7ff7d402e010, h_class
> = 0x7ff7e2a46d20, h_data = 0x0, h_len = 0}}, v_next = 0x0, v_protocol =
> 0x7ff7e2817e25 "SIP/2.0/UDP", v_host = 0x7ff7d402de5a "192.172.252.21",
> v_port = 0x7ff7d402de69 "5061", v_params = 0x7ff7d402e180, v_comment = 0x0,
> v_ttl = 0x0,
> v_maddr = 0x0, v_received = 0x0, v_branch = 0x7ff7d402de75
> "z9hG4bK-d93e133e", v_rport = 0x0, v_comp = 0x0}
>
> (gdb) p *sip->sip_from
> $5 = {a_common = {{h_succ = 0x7ff7d402e2d0, h_prev = 0x7ff7d402e0f0, h_class
> = 0x7ff7e2a46b60, h_data = 0x0, h_len = 0}}, a_next = 0x0, a_display =
> 0x7ff7d402de8d "\"SMITH,A\"", a_url = {{url_pad = "\000\000\000\000\000",
> url_type = 1 '\001', url_root = 0 '\0', url_scheme = 0x7ff7d402de98 "sip",
> url_user = 0x7ff7d402de9c "17635191497", url_password = 0x0, url_host =
> 0x7ff7d402dea8 "d3.foo21.com", url_port = 0x0, url_path = 0x0, url_params =
> 0x0, url_headers = 0x0, url_fragment = 0x0}}, a_params = 0x7ff7d402e280,
> a_comment = 0x0, a_tag = 0x7ff7d402deba "9d05312f1f1ac1d5o1"}
> (gdb) p *sip->sip_to
> $6 = {a_common = {{h_succ = 0x7ff7d402e3d0, h_prev = 0x7ff7d402e1d0, h_class
> = 0x7ff7e2a46ce0, h_data = 0x0, h_len = 0}}, a_next = 0x0, a_display =
> 0x7ff7e280adb3 "", a_url = {{url_pad = "\000\000\000\000\000", url_type = 1
> '\001', url_root = 0 '\0', url_scheme = 0x7ff7d402ded3 "sip",
> url_user = 0x7ff7d402ded7 "0", url_password = 0x0, url_host =
> 0x7ff7d402ded9 "d3.foo21.com", url_port = 0x0, url_path = 0x0, url_params =
> 0x0, url_headers = 0x0, url_fragment = 0x0}}, a_params = 0x7ff7d402e380,
> a_comment = 0x0, a_tag = 0x7ff7d402deeb "c08cmN7U3pQDN"}
> (gdb) p *sip->sip_event
> $7 = {o_common = {{h_succ = 0x7ff7d402e500, h_prev = 0x7ff7d402e470, h_class
> = 0x7ff7e2a46da0, h_data = 0x0, h_len = 0}}, o_next = 0x0, o_type =
> 0x7ff7d402df50 "refer", o_params = 0x0, o_id = 0x0}
> (gdb) p *sip_payload
> No symbol "sip_payload" in current context.
> (gdb) p *sip->sip_payload
> $8 = {pl_common = {{h_succ = 0x0, h_prev = 0x7ff7d402e660, h_class =
> 0x7ff7e2a468e0, h_data = 0x7ff7d402dfe5, h_len = 21}}, pl_next = 0x0, pl_data
> = 0x7ff7d402dfe5 "SIP/2.0 180 Ringing\r\n", pl_len = 21}
>
> Based on the 'via' tags from the core file and the source/dest, I think this
> is the message (from merged.xml) that caused the crash:
>
> </message>
> </branchNode>
> <branchNode>
> <branchIdSet>
>
> <branchId>z9hG4bK-XX-00c37Rg`GG3bP5P2gMUD4x0oXA</branchId>
> <branchId>z9hG4bK-d93e133e</branchId>
> </branchIdSet>
> <time>2010-01-03T18:27:46.386759Z</time>
> <source>d3.foo21.com-SipXProxy</source>
> <destination>192.172.252.163:15060</destination>
> <sourceAddress>d3.foo21.com-SipXProxy</sourceAddress>
> <destinationAddress>192.172.252.163:15060</destinationAddress>
>
> <transactionId>102,[email protected],9d05312f1f1ac1d5o1,c08cmN7U3pQDN</transactionId>
> <method>NOTIFY</method>
> <frameId>36 sipXproxy.xml:5099</frameId>
> <message><![CDATA[NOTIFY
> sip:[email protected]:15060;transport=udp SIP/2.0^M
> Via: SIP/2.0/UDP
> 192.172.252.163;branch=z9hG4bK-XX-00c37Rg`GG3bP5P2gMUD4x0oXA^M
> Via: SIP/2.0/UDP 192.172.252.21:5061;branch=z9hG4bK-d93e133e^M
> From: "SMITH,A" <sip:[email protected]>;tag=9d05312f1f1ac1d5o1^M
> To: <sip:[email protected]>;tag=c08cmN7U3pQDN^M
> Call-Id: [email protected]^m
> Cseq: 102 NOTIFY^M
> Max-Forwards: 20^M
> Event: refer^M
> User-Agent: Linksys/SPA3102-5.1.10(GW)^M
> Content-Length: 21^M
> Content-Type: message/sipfrag;version=2.0^M
> Date: Sun, 03 Jan 2010 18:27:46 GMT^M
> ^M
> SIP/2.0 180 Ringing^M
> ]]></message>
>
> -Eric
>
> <merged.xml.gz>
>
> On Dec 24, 2009, at 2:54 PM, Dale Worley wrote:
>
>> On Mon, 2009-12-21 at 17:10 -0500, Eric Varsanyi wrote:
>>> Definitely something going on with the sipxchange user on this box (as
>>> mentioned below), but I had no problem running other development
>>> builds (for my companies product) after I noticed the issue with
>>> sipxchange (the inability to fork).
>>>
>>> One concrete question: what can cause a "503 Maximum Calls In
>>> Progress" on a test system with no user traffic and 6 Polycom phones?
>>> None of the sip logs were growing when this was happening, there
>>> wasn't a lot of processes running (parented by the manager or
>>> otherwise). Maybe there's an fd leak?
>>
>> Specifically, when the call went to the IVR system (based on Freeswitch)
>> to be recorded as voicemail, the IVR system responded with 503. I don't
>> know why it would do that, but we need to look at Freeswitch's log
>> (/var/log/sipxpbx/freeswitch.log) to see what is going wrong.
>>
>> Dale
>>
>>
>
> _______________________________________________
> sipx-dev mailing list [email protected]
> List Archive: http://list.sipfoundry.org/archive/sipx-dev
> Unsubscribe: http://list.sipfoundry.org/mailman/listinfo/sipx-dev
> sipXecs IP PBX -- http://www.sipfoundry.org/
_______________________________________________
sipx-dev mailing list [email protected]
List Archive: http://list.sipfoundry.org/archive/sipx-dev
Unsubscribe: http://list.sipfoundry.org/mailman/listinfo/sipx-dev
sipXecs IP PBX -- http://www.sipfoundry.org/
