Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

kamailio inserts buggy sip header #1257

Closed
defeden opened this Issue Sep 29, 2017 · 10 comments

Comments

Projects
None yet
2 participants
@defeden
Copy link

commented Sep 29, 2017

when kamailio try to dispatch the requests to Asterisk, it inserts a sip header without newline, so the sip header will be concatenated with the next header

herein an example:

sip:edi-2001@218.108.243.20:12983;transport=TCP;obContact: <sip:edi-2001@10.42.0.11:5060;transport=UDP>
@defeden

This comment has been minimized.

Copy link
Author

commented Sep 29, 2017

herein an other example:

sip:edi-1@218.108.243.20:30439;transport=tcpAuthorization:  Digest realm="dom.com", nonce="1506695211/99387b507b283bd808b5607a89e84418", algorithm=md5, opaque="364e55517313f549", username="edi-1",  uri="sip:edi-2001@dom.com", response="9a54d94abd75b08666666661ac2413", cnonce="5bizSdv1oIFfV782", nc=00000001, qop=auth
@miconda

This comment has been minimized.

Copy link
Member

commented Sep 29, 2017

You have to provide full sip message, so we can see what headers are mangled. It looks like a config issue, but to give the right points, we need full sip message.

@defeden

This comment has been minimized.

Copy link
Author

commented Oct 2, 2017

Hi;
herein a SIP message:

INVITE sip:edi-2001@mydomain.com SIP/2.0
Record-Route: sip:10.42.0.11;transport=tcp;lr=on;ftag=CXdThPs~D;nat=yes
Via: SIP/2.0/TCP 195.206.195.60:5062;branch=z9hG4bK75e7.c59c73a3d2c11ea11f537dd564b8f456.0;i=1
Via: SIP/2.0/TCP 192.168.0.162:33857;received=218.118.243.25;branch=z9hG4bK.7ow6fmWFa;rport=35428
From: sip:edi-1@mydomain.com;tag=CXdThPs~D
To: sip:edi-2001@mydomain.com
CSeq: 21 INVITE
Call-ID: OCj09Rh8FG
Contact: sip:edi-2001@10.42.0.11:5060;transport=TCP
Max-Forwards: 69
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 279
sip:edi-1@218.118.243.25:35428;transport=tcpUser-Agent: LinphoneAndroid/3.2.7 (belle-sip/1.6.1)
Authorization: Digest realm="mydomain.com", nonce="1506953052/0607f6c787e1c3a4d93b6914b15e5c8a", algorithm=md5, opaque="0c4d6f016c1af8a7", username="edi-1", uri="sip:edi-2001@mydomain.com", response="5a4ed7ff3a0c8d81fcd5e809ae55adba", cnonce="IlTh9WQHguYFL2aM", nc=00000001, qop=auth
Path: sip:195.206.195.60:5062;transport=tcp;lr;received=sip:218.118.243.25:35428%3Btransport%3Dtcp

v=0
o=edi-1 2638 2521 IN IP4 195.206.195.60
s=Talk
c=IN IP4 195.206.195.60
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 11204 RTP/AVP 0 8 3 101
a=rtpmap:101 telephone-event/8000
a=rtcp-fb:* ccm tmmbr
a=nortpproxy:yes

@miconda

This comment has been minimized.

Copy link
Member

commented Oct 2, 2017

That looks like a wrong operation done inside kamailio.cfg. There is no core component or module that would do that by default. To debug this, load the debugger module and enable cfgtrace feature, then you can paste here the output of cfg execution trace to see what actions are executed inside the cfg for the invite request.

@defeden

This comment has been minimized.

Copy link
Author

commented Oct 2, 2017

herein the debug trace:

17(3643) INFO: <script>: New message:
INVITE sip:edi-2001@mydomain.com SIP/2.0
Via: SIP/2.0/TCP 192.168.0.162:34348;branch=z9hG4bK.Mm9c9oajI;rport
From: sip:edi-1@mydomain.com;tag=J8Qbs6r5C
To: sip:edi-2001@mydomain.com
CSeq: 20 INVITE
Call-ID: JRsgN1qwek
Max-Forwards: 70
Route: sip:195.206.195.66:5062;transport=tcp;lr
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 258
Contact: sip:edi-1@218.118.243.20:52470;transport=tcp;+sip.instance="urn:uuid:dc62b3bd-0e31-41c1-a688-3f9b3cbbd170"
User-Agent: LinphoneAndroid/3.2.7 (belle-sip/1.6.1)

v=0
o=edi-1 1263 2377 IN IP4 192.168.0.162
s=Talk
c=IN IP4 192.168.0.162
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/AVP 0 8 3 101
a=rtpmap:101 telephone-event/8000
a=rtcp-fb:* ccm tmmbr
17(3643) DEBUG: [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=9
17(3643) DEBUG: [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: [32]; uri=[sip:edi-2001@mydomain.com]
17(3643) DEBUG: [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [sip:edi-2001@mydomain.com
]
17(3643) DEBUG: [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq : <20>
17(3643) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70
17(3643) DEBUG: [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=258
17(3643) DEBUG: [parser/msg_parser.c:106]: get_hdr_field(): found end of header
17(3643) DEBUG: [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=J8Qbs6r5C
17(3643) DEBUG: [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
17(3643) DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
17(3643) DEBUG: siputils [checks.c:103]: has_totag(): no totag
17(3643) DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff
17(3643) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=63038, isACK=0
17(3643) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
17(3643) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
17(3643) DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=(nil)
17(3643) DEBUG: outbound [ob_mod.c:496]: use_outbound(): Analysing INVITE for outbound markers
17(3643) DEBUG: [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 14==9 && [195.206.195.66] == [127.0.0.1]
17(3643) DEBUG: [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5062
17(3643) DEBUG: [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 14==10 && [195.206.195.66] == [10.42.0.11]
17(3643) DEBUG: [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5062
17(3643) DEBUG: [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 14==9 && [195.206.195.66] == [127.0.0.1]
17(3643) DEBUG: [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5062
17(3643) DEBUG: [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 14==10 && [195.206.195.66] == [10.42.0.11]
17(3643) DEBUG: [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5062
17(3643) DEBUG: [forward.c:448]: check_self(): check_self: host != me
17(3643) DEBUG: outbound [ob_mod.c:378]: use_outbound_non_reg(): top Route-URI is not me - outbound not used
17(3643) ERROR: <script>: 3. =============================================>
17(3643) DEBUG: [select.c:429]: run_select(): Calling SELECT 0x7f8fedeae7b8
17(3643) INFO: <script>: if 218.118.243.20 == 10.42.0.70?
17(3643) DEBUG: [select.c:429]: run_select(): Calling SELECT 0x7f8fedeae7b8
17(3643) INFO: <script>: Method (INVITE) ==> from Peer
17(3643) INFO: <script>: Route from peer
17(3643) DEBUG: dispatcher [dispatch.c:1664]: ds_select_dst_limit(): set [1]
17(3643) DEBUG: dispatcher [dispatch.c:1772]: ds_select_dst_limit(): alg hash [2334507456]
17(3643) DEBUG: dispatcher [dispatch.c:1815]: ds_select_dst_limit(): selected [0-1/0] sip:10.42.0.70:5060;transport=TCP
17(3643) INFO: <script>: Relay message to sip:edi-2001@mydomain.com via sip:10.42.0.70:5060;transport=TCP
17(3643) DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=1 , global msg id=1 , T on entrance=(nil)
17(3643) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=63038, isACK=0
17(3643) DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
17(3643) DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
17(3643) DEBUG: tm [t_hooks.c:380]: run_reqin_callbacks_internal(): DBG: trans=0x7f8fe11b1a80, callback type 1, id 0 entered
17(3643) DEBUG: [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: 435a550d1fcde96f6297d49dd19084f2
17(3643) DEBUG: tm [t_funcs.c:347]: t_relay_to(): SER: new INVITE
17(3643) DEBUG: [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called
17(3643) DEBUG: [tcp_main.c:2281]: tcpconn_send_put(): tcp_send: send from reader (3643 (17)), reusing fd
17(3643) DEBUG: [tcp_main.c:2516]: tcpconn_do_send(): tcp_send: sending...
17(3643) DEBUG: [tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c= 0x7f8fe119b3e8 n=535 fd=12
17(3643) DEBUG: [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/TCP 192.168.0.162:34348;branch=z9hG4bK.Mm9c9oajI;rport=52470;received=218.118.243.20
From: sip:edi-1@mydomain.com;tag=J8Qbs6r5C
To: sip:edi-2001@mydomain.com
CSeq: 20 INVITE
Call-ID: JRsgN1qwek
Server: kamailio (4.2.3 (x86_64/linux))
Content-Length: 0
Warning: 392 10.42.0.11:5060 "Noisy feedback tells: pid=3643 req_src_ip=218.118.243.20 req_src_port=52470 in_uri=sip:edi-2001@mydomain.com out_uri=sip:edi-2001@mydomain.com via_cnt==1"

17(3643) DEBUG: tm [t_reply.c:728]: _reply_light(): DEBUG: reply sent out. buf=0x7f8fede9a1d8: SIP/2.0 100 trying -..., shmem=0x7f8fe11b1190: SIP/2.0 100 trying -
17(3643) DEBUG: tm [t_reply.c:738]: _reply_light(): DEBUG: _reply_light: finished
17(3643) INFO: <script>: FIRST LEG======>>>>>>>new branch [0] to sip:edi-2001@mydomain.com
17(3643) DEBUG: siputils [checks.c:103]: has_totag(): no totag
17(3643) DEBUG: [select.c:429]: run_select(): Calling SELECT 0x7f8fedeae7b8
17(3643) INFO: <script>: if 218.118.243.20 == 10.42.0.70?
17(3643) DEBUG: [select.c:429]: run_select(): Calling SELECT 0x7f8fedeae7b8
17(3643) INFO: <script>: Method (INVITE) ==> from Peer
17(3643) DEBUG: [parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [192.168.0.162] in o=' field 17(3643) DEBUG: <core> [parser/sdp/sdp_helpr_funcs.c:504]: extract_mediaip(): located IP address [192.168.0.162] in c=' field
17(3643) DEBUG: [parser/sdp/sdp.c:574]: parse_sdp_session(): ignoring unknown type in a= line: `a=rtcp-fb:* ccm tmmbr
'
17(3643) DEBUG: rtpproxy [rtpproxy_funcs.c:148]: check_content_type(): type <application/sdp> found valid
17(3643) DEBUG: rtpproxy [rtpproxy.c:2704]: force_rtp_proxy(): proxy reply: 10862 195.206.195.66

17(3643) DEBUG: siputils [checks.c:103]: has_totag(): no totag
17(3643) DEBUG: [msg_translator.c:470]: clen_builder(): clen_builder: content-length: 279 (279)
17(3643) DEBUG: [msg_translator.c:2893]: create_via_hf(): create_via_hf: id added: <;i=1>, rcv proto=2
17(3643) DEBUG: [tcp_main.c:2297]: tcpconn_send_put(): tcp_send: tcp connection found (0x7f8fe11a2938), acquiring fd
17(3643) DEBUG: [tcp_main.c:2307]: tcpconn_send_put(): tcp_send, c= 0x7f8fe11a2938, n=16
18(3644) DEBUG: [tcp_main.c:3565]: handle_ser_child(): handle_ser_child: read response= 7f8fe11a2938, 2, fd -1 from 17 (3643)
17(3643) DEBUG: [tcp_main.c:2337]: tcpconn_send_put(): tcp_send: after receive_fd: c= 0x7f8fe11a2938 n=8 fd=13
17(3643) DEBUG: [tcp_main.c:2516]: tcpconn_do_send(): tcp_send: sending...
17(3643) DEBUG: [tcp_main.c:2550]: tcpconn_do_send(): tcp_send: after real write: c= 0x7f8fe11a2938 n=1169 fd=13
17(3643) DEBUG: [tcp_main.c:2551]: tcpconn_do_send(): tcp_send: buf=
INVITE sip:edi-2001@mydomain.com SIP/2.0
Record-Route: sip:10.42.0.11;transport=tcp;lr=on;ftag=J8Qbs6r5C;nat=yes
Via: SIP/2.0/TCP 195.206.195.66:5062;branch=z9hG4bKe36f.435a550d1fcde96f6297d49dd19084f2.0;i=1
Via: SIP/2.0/TCP 192.168.0.162:34348;received=218.118.243.20;branch=z9hG4bK.Mm9c9oajI;rport=52470
From: sip:edi-1@mydomain.com;tag=J8Qbs6r5C
To: sip:edi-2001@mydomain.com
CSeq: 20 INVITE
Call-ID: JRsgN1qwek
Contact: sip:edi-2001@10.42.0.11:5060;transport=TCP
Max-Forwards: 69
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 279
sip:edi-1@218.118.243.20:52470;transport=tcpUser-Agent: LinphoneAndroid/3.2.7 (belle-sip/1.6.1)
Path: sip:195.206.195.66:5062;transport=tcp;lr;received=sip:218.118.243.20:52470%3Btransport%3Dtcp

v=0
o=edi-1 1263 2377 IN IP4 195.206.195.66
s=Talk
c=IN IP4 195.206.195.66
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 10862 RTP/AVP 0 8 3 101
a=rtpmap:101 telephone-event/8000
a=rtcp-fb:* ccm tmmbr
a=nortpproxy:yes

@miconda

This comment has been minimized.

Copy link
Member

commented Oct 2, 2017

@defeden

This comment has been minimized.

Copy link
Author

commented Oct 4, 2017

hi;

i have done this:

loadmodule debugger.so
modparam("debugger", "cfgtrace", 1)
modparam("debugger", "log_level", 3)
modparam("debugger", "log_level_name", "tracer")

but, i cannot see debug messages. i don't know if it is the way to activate them or not

@miconda

This comment has been minimized.

Copy link
Member

commented Oct 4, 2017

Set log_level parameter to a lower value (at least the same as debug global parameter).

@defeden

This comment has been minimized.

Copy link
Author

commented Oct 4, 2017

I think i have found the source of the problem; my request come from the caller is as follow:

Via: SIP/2.0/TCP 192.168.0.179:33857;branch=z9hG4bK.KpHCWZWuW;rport
From: sip:edi-1@mydomain.com;tag=jS9zm-Q~G
To: sip:edi-2001@mydomain.com
CSeq: 20 INVITE
Call-ID: TAggUqcveg
Max-Forwards: 70
Route: sip:195.206.195.78:5062;transport=tcp;lr
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 258
Contact: sip:edi-1@218.118.243.20:54126;transport=tcp;+sip.instance="urn:uuid:dc62b3bd-0e31-41c1-a688-3f9b3cbbd170"
User-Agent: LinphoneAndroid/3.2.7 (belle-sip/1.6.1)

in my script; i make a call to:

fix_nated_contact();

after that in other section i call

if (remove_hf("Contact")) {
append_hf("Contact: sip:$tU@10.42.0.11:5060;transport=TCP\r\n", "Call-ID");
}

so, this will create a bad header

Record-Route: sip:10.42.0.11;transport=tcp;lr=on;ftag=jS9zm-Q~G;nat=yes
Via: SIP/2.0/TCP 195.206.195.78:5062;branch=z9hG4bK1d4.1ff4886829747640d9da5b5cc1ea0713.0;i=3
Via: SIP/2.0/TCP 192.168.0.179:33857;received=218.118.243.20;branch=z9hG4bK.KpHCWZWuW;rport=54126
From: sip:edi-1@mydomain.com;tag=jS9zm-Q~G
To: sip:edi-2001@mydomain.com
CSeq: 20 INVITE
Call-ID: TAggUqcveg
Contact: sip:edi-2001@10.42.0.11:5060;transport=TCP
Max-Forwards: 69
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 334
sip:edi-1@218.118.243.20:54126;transport=tcpUser-Agent: LinphoneAndroid/3.2.7 (belle-sip/1.6.1)
Path: sip:195.206.195.78:5062;transport=tcp;lr;received=sip:218.118.243.20:54126%3Btransport%3Dtcp

can you advice Please?

@miconda

This comment has been minimized.

Copy link
Member

commented Oct 5, 2017

You have to use only one of them or do msg_apply_changes() in between. See FAQ on wiki for more details on how header operations are done. If you still do not get it working, email to sr-users mailing lists, this is not a bug in the code, the issue tracker is used for code related things.

@miconda miconda closed this Oct 5, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.