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
Description: GNU Zip compressed data
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/
