#343 CRITICAL:siptrace:ip_addr2a: unknown address family 0

1.6.x
closed-fixed
modules (454)
7
2011-02-18
2011-01-24
Anonymous
No

I added
local_route {
xlog("================LOCAL_ROUTE============\n");
setflag(22);
sip_trace();
if (is_method("BYE") ) {
xlog("================BYE============\n");
}
}

to the routing script in order to get BYE messages written into sip_trace when CallControl interrupts a session. When the sip_trace function is called for the BYE message that was sent to the caller, OpenSIPS crashes:

Jan 24 14:36:31 P4237 cdrtool[8306]: DebitBalance Duration=12 CallId=216034819 From=sip:1000@localhost Gateway=127.0.0.1 To=sip:01234@localhost
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: found newline before attr_separator--we have just the attribute's value
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: empty name, attr not quoted value <2246> found
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: 1 data->len is 17
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: 2 data->len is 12
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_tree: adding node <> ; val <2246>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_tree: the remaining datagram has 12 bytes
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: the remaining datagram to be parsed is 1988155359 and 12 in length
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: the string is not just a quoted string
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: found newline before attr_separator--we have just the attribute's value
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: empty name, attr not quoted value <1988155359> found
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: 1 data->len is 12
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: 2 data->len is 1
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_tree: adding node <> ; val <1988155359>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_tree: the remaining datagram has 1 bytes
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_parse_node: the remaining datagram to be parsed is and 1 in length
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:mi_datagram:mi_datagram_server: done parsing the mi tree
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:dialog:mi_terminate_dlg: h_entry 2246 h_id 1988155359
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:dialog:lookup_dlg: ref dlg 0xb5c2157c with 1 -> 3
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:dialog:lookup_dlg: dialog id=1988155359 found on entry 2246
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:dialog:send_leg_bye: sending BYE to caller (0)
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:dialog:ref_dlg: ref dlg 0xb5c2157c with 1 -> 4
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:tm:t_uac: next_hop=<sip:1000@127.0.0.1:5061>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: parsed uri: type=1 user=<1000>(4) passwd=<>(0) host=<127.0.0.1>(9) port=<5061>(4): 5061 params=<>(0) headers=<>(0)
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: uri params: transport=<>, val=<>, proto=0
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: user-param=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: method=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: ttl=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: maddr=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: lr=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_uri: r2=<>, val=<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:mk_proxy: doing DNS lookup...
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:tm:dlg2hash: 36165
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:tm:print_request_uri: sip:1000@127.0.0.1:5061
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:tm:t_uac: building sip_msg from buffer
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: SIP Request:
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: method: <BYE>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: uri: <sip:1000@127.0.0.1:5061>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: version: <SIP/2.0>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: flags=2
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK54d8.7214f724.0>; state=16
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_via: end of header reached, state=5
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: via found, flags=2
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: this is the first via
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: header field type 1, name=<Via>, body=<SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK54d8.7214f724.0>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: first via: <SIP/2.0/UDP> <127.0.0.1:(0)>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: ;<>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg:
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_msg: exiting
Jan 24 14:36:31 P4237 cdrtool[8306]: ConnectFee=0.0000 CallId=216034819 Span=1 Duration=12 DestId=31 default Profile=grn_premium Period=weekday Rate=grn_premium Interval=0-24 Cost=0.1000/6 Price=0.2000 PriceIn=0.0000
Jan 24 14:36:31 P4237 ./opensips[8254]: INFO:core:buf_init: initializing...
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:pv_printf: final buffer length 40
Jan 24 14:36:31 P4237 ./opensips[8254]: ================LOCAL_ROUTE============
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: flags=10
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to_param: tag=1058707960
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to: end of header reached, state=29
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to: display={}, ruri={sip:1000@localhost}
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:get_hdr_field: <To> [37]; uri=[sip:1000@localhost]
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:get_hdr_field: to body [<sip:1000@localhost>]
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: header field type 3, name=<To>, body=<<sip:1000@localhost>;tag=1058707960>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: header field type 4, name=<From>, body=<<sip:01234@localhost>;tag=994088071>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to_param: tag=994088071
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to: end of header reached, state=29
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_to: display={}, ruri={sip:01234@localhost}
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: flags=40
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:get_hdr_field: cseq <CSeq>: <21> <BYE>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: header field type 5, name=<CSeq>, body=<21 BYE>
Jan 24 14:36:31 P4237 ./opensips[8254]: DBG:core:parse_headers: header field type 6, name=<Call-ID>, body=<216034819>
Jan 24 14:36:31 P4237 ./opensips[8254]: CRITICAL:siptrace:ip_addr2a: unknown address family 0
Jan 24 14:36:31 P4237 kernel: [18005.607196] opensips[8254]: segfault at 0 ip b7f11bb9 sp bfe8fbf8 error 4 in libc-2.11.2.so[b7e9f000+140000]
Jan 24 14:36:31 P4237 cdrtool[8306]: Price=0.2000 Duration=12 CallId=216034819 BillingParty=1000@localhost DestId=31 MaxSessionTime=0
Jan 24 14:36:31 P4237 call-control[3909]: Call id 216034819 of 1000@localhost to sip:01234@localhost disconnected by call control after 12 seconds, call price is 0.2000
Jan 24 14:36:31 P4237 ./opensips[8286]: CRITICAL:core:receive_fd: EOF on 11
Jan 24 14:36:31 P4237 ./opensips[8286]: DBG:core:handle_ser_child: dead child 1, pid 8254 (shutting down?)
Jan 24 14:36:31 P4237 ./opensips[8286]: DBG:core:io_watch_del: io_watch_del (0x8167a60, 11, -1, 0x0) fd_no=22 called
Jan 24 14:36:31 P4237 ./opensips[8252]: INFO:core:handle_sigs: child process 8254 exited by a signal 11
Jan 24 14:36:31 P4237 ./opensips[8252]: INFO:core:handle_sigs: core was generated
Jan 24 14:36:31 P4237 ./opensips[8252]: INFO:core:handle_sigs: terminating due to SIGCHLD
Jan 24 14:36:31 P4237 ./opensips[8255]: INFO:core:sig_usr: signal 15 received
Jan 24 14:36:31 P4237 media-dispatcher[3885]: debug: Connection to OpenSIPS lost: Connection was closed cleanly

Discussion

    • priority: 5 --> 7
    • assigned_to: nobody --> bogdan_iancu
    • status: open --> open-accepted
     
    • status: open-accepted --> closed-fixed
     
  • Hi,

    The fix is available on SVN (trunk and stable) - please update .

    Regards,
    Bogdan