6 Aug
2016
6 Aug
'16
3:24 a.m.
Hello,
I've got an odd issue where:
1. TCP client makes call out through Kamailio.
2. Call is answered, TCP client sends e2e ACK.
3. Parser chokes on ACK, closes TCP connection (SYN+FIN).
4. Subsequent messages from the client, immediately following the ACK
(about 240 ms later), come through because the client is halfway around
the world - about 250 ms away - and is not yet aware the connection has
been closed. Otherwise, it would presumably try to re-establish the
connection before sending anything.
Anyway, messages from the parser concerning the ACK are:
---
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
INFO: <core> [parser/parse_fline.c:144]: parse_first_line():
ERROR:parse_first_line: method not followed by SP
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/parse_fline.c:257]: parse_first_line():
parse_first_line: bad message (offset: 0)
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/msg_parser.c:690]: parse_msg(): ERROR: parse_msg:
message=<0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via: SIP/2.0/TCP
1.1.1.1:61979;branch=z9hG4bKPjc15bf9fdded940cab7f859634b9f036e;alias#015#012Max-Forwards:
70#015#012From:
sip:4b57be8d-267d-48c4-aa82-0f3a269d74cb@sip.evaristesys.com;tag=dd1d7fd0344d47b7b22c4017091df17a#015#012To:
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@sip.evaristesys.com;tag=2rZDKcBFmU65S#015#012Call-ID:
5ba5a84451074159aaaa931eb1f98fe5#015#012CSeq: 3071 ACK#015#012Route:
<sip:2.2.2.2;transport=tcp;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Route:
<sip:10.0.2.119;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Content-Length:
0#015#012#015#012>
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [receive.c:173]: receive_msg(): core parsing of SIP
message failed (1.1.1.1:61979/2)
---
That doesn't look like a clean message buffer to me. The message should
start here:
ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via: SIP/2.0/TCP ...
But instead it's got these SDP attributes prepended:
0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012
These SDP attribute appear to have fallen off the back of the SDP offer
in the initial INVITE:
v=0
o=- 3679365582 3679365582 IN IP4 10.0.0.200
s=pjmedia
t=0 0
m=audio 4006 RTP/AVP 0 8 96
c=IN IP4 1.1.1.1
The relationship between the 4006 RTP port and the 4007 RTCP port
suggests that these two things belong together.
This is on kamailio 4.4.0 (x86_64/linux) d4f23c. Any help would be
greatly appreciated! The issue is consistently reproducible and this
happens every time.
Cheers,
-- Alex
--
Alex Balashov | Principal | Evariste Systems LLC
1447 Peachtree Street NE, Suite 700
Atlanta, GA 30309
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
6 Aug
6 Aug
3:27 a.m.
I've also got a binary capture and would be happy to provide privately.
On 08/05/2016 06:24 PM, Alex Balashov wrote:
Hello,
I've got an odd issue where:
1. TCP client makes call out through Kamailio.
2. Call is answered, TCP client sends e2e ACK.
3. Parser chokes on ACK, closes TCP connection (SYN+FIN).
4. Subsequent messages from the client, immediately following the ACK
(about 240 ms later), come through because the client is halfway around
the world - about 250 ms away - and is not yet aware the connection has
been closed. Otherwise, it would presumably try to re-establish the
connection before sending anything.
Anyway, messages from the parser concerning the ACK are:
---
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
INFO: <core> [parser/parse_fline.c:144]: parse_first_line():
ERROR:parse_first_line: method not followed by SP
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/parse_fline.c:257]: parse_first_line():
parse_first_line: bad message (offset: 0)
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/msg_parser.c:690]: parse_msg(): ERROR: parse_msg:
message=<0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP
1.1.1.1:61979;branch=z9hG4bKPjc15bf9fdded940cab7f859634b9f036e;alias#015#012Max-Forwards:
70#015#012From:
sip:4b57be8d-267d-48c4-aa82-0f3a269d74cb@sip.evaristesys.com;tag=dd1d7fd0344d47b7b22c4017091df17a#015#012To:
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@sip.evaristesys.com;tag=2rZDKcBFmU65S#015#012Call-ID:
5ba5a84451074159aaaa931eb1f98fe5#015#012CSeq: 3071 ACK#015#012Route:
<sip:2.2.2.2;transport=tcp;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Route:
<sip:10.0.2.119;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Content-Length:
0#015#012#015#012>
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [receive.c:173]: receive_msg(): core parsing of SIP
message failed (1.1.1.1:61979/2)
---
That doesn't look like a clean message buffer to me. The message should
start here:
ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP ...
But instead it's got these SDP attributes prepended:
0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012
These SDP attribute appear to have fallen off the back of the SDP offer
in the initial INVITE:
v=0
o=- 3679365582 3679365582 IN IP4 10.0.0.200
s=pjmedia
t=0 0
m=audio 4006 RTP/AVP 0 8 96
c=IN IP4 1.1.1.1
The relationship between the 4006 RTP port and the 4007 RTCP port
suggests that these two things belong together.
This is on kamailio 4.4.0 (x86_64/linux) d4f23c. Any help would be
greatly appreciated! The issue is consistently reproducible and this
happens every time.
Cheers,
-- Alex
--
Alex Balashov | Principal | Evariste Systems LLC
1447 Peachtree Street NE, Suite 700
Atlanta, GA 30309
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
3:39 a.m.
I'll also add: the initial INVITE is split. Wireshark shows its >= Layer
3 payload size to be 1497. There is a "Continuation" message displayed
which contains the trailing SDP.
So, it sounds like the problem is that the trailing segment is getting
packed into the message buffer for the ACK.
-- Alex
On 08/05/2016 06:24 PM, Alex Balashov wrote:
Hello,
I've got an odd issue where:
1. TCP client makes call out through Kamailio.
2. Call is answered, TCP client sends e2e ACK.
3. Parser chokes on ACK, closes TCP connection (SYN+FIN).
4. Subsequent messages from the client, immediately following the ACK
(about 240 ms later), come through because the client is halfway around
the world - about 250 ms away - and is not yet aware the connection has
been closed. Otherwise, it would presumably try to re-establish the
connection before sending anything.
Anyway, messages from the parser concerning the ACK are:
---
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
INFO: <core> [parser/parse_fline.c:144]: parse_first_line():
ERROR:parse_first_line: method not followed by SP
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/parse_fline.c:257]: parse_first_line():
parse_first_line: bad message (offset: 0)
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/msg_parser.c:690]: parse_msg(): ERROR: parse_msg:
message=<0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP
1.1.1.1:61979;branch=z9hG4bKPjc15bf9fdded940cab7f859634b9f036e;alias#015#012Max-Forwards:
70#015#012From:
sip:4b57be8d-267d-48c4-aa82-0f3a269d74cb@sip.evaristesys.com;tag=dd1d7fd0344d47b7b22c4017091df17a#015#012To:
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@sip.evaristesys.com;tag=2rZDKcBFmU65S#015#012Call-ID:
5ba5a84451074159aaaa931eb1f98fe5#015#012CSeq: 3071 ACK#015#012Route:
<sip:2.2.2.2;transport=tcp;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Route:
<sip:10.0.2.119;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Content-Length:
0#015#012#015#012>
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [receive.c:173]: receive_msg(): core parsing of SIP
message failed (1.1.1.1:61979/2)
---
That doesn't look like a clean message buffer to me. The message should
start here:
ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP ...
But instead it's got these SDP attributes prepended:
0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012
These SDP attribute appear to have fallen off the back of the SDP offer
in the initial INVITE:
v=0
o=- 3679365582 3679365582 IN IP4 10.0.0.200
s=pjmedia
t=0 0
m=audio 4006 RTP/AVP 0 8 96
c=IN IP4 1.1.1.1
The relationship between the 4006 RTP port and the 4007 RTCP port
suggests that these two things belong together.
This is on kamailio 4.4.0 (x86_64/linux) d4f23c. Any help would be
greatly appreciated! The issue is consistently reproducible and this
happens every time.
Cheers,
-- Alex
--
Alex Balashov | Principal | Evariste Systems LLC
1447 Peachtree Street NE, Suite 700
Atlanta, GA 30309
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
7 Aug
7 Aug
10:50 a.m.
Hello,
tcp being a stream protocol, kamailio is reading the body of sip
messages based on content-lenght header -- can you check and see if the
values for content length are accurate?
Do you have the parameter tcp_accept_no_cl set?
Cheers,
Daniel
On 06/08/16 00:39, Alex Balashov wrote:
I'll also add: the initial INVITE is split.
Wireshark shows its >=
Layer 3 payload size to be 1497. There is a "Continuation" message
displayed which contains the trailing SDP.
So, it sounds like the problem is that the trailing segment is getting
packed into the message buffer for the ACK.
-- Alex
On 08/05/2016 06:24 PM, Alex Balashov wrote:
--
Daniel-Constantin Mierla
http://www.asipto.com - http://www.kamailio.org
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Hello,
I've got an odd issue where:
1. TCP client makes call out through Kamailio.
2. Call is answered, TCP client sends e2e ACK.
3. Parser chokes on ACK, closes TCP connection (SYN+FIN).
4. Subsequent messages from the client, immediately following the ACK
(about 240 ms later), come through because the client is halfway around
the world - about 250 ms away - and is not yet aware the connection has
been closed. Otherwise, it would presumably try to re-establish the
connection before sending anything.
Anyway, messages from the parser concerning the ACK are:
---
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
INFO: <core> [parser/parse_fline.c:144]: parse_first_line():
ERROR:parse_first_line: method not followed by SP
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/parse_fline.c:257]: parse_first_line():
parse_first_line: bad message (offset: 0)
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [parser/msg_parser.c:690]: parse_msg(): ERROR: parse_msg:
message=<0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP
1.1.1.1:61979;branch=z9hG4bKPjc15bf9fdded940cab7f859634b9f036e;alias#015#012Max-Forwards:
70#015#012From:
sip:4b57be8d-267d-48c4-aa82-0f3a269d74cb@sip.evaristesys.com;tag=dd1d7fd0344d47b7b22c4017091df17a#015#012To:
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@sip.evaristesys.com;tag=2rZDKcBFmU65S#015#012Call-ID:
5ba5a84451074159aaaa931eb1f98fe5#015#012CSeq: 3071 ACK#015#012Route:
<sip:2.2.2.2;transport=tcp;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Route:
<sip:10.0.2.119;lr;r2=on;ftag=dd1d7fd0344d47b7b22c4017091df17a;rtp_set_id=1>#015#012Content-Length:
0#015#012#015#012>
Aug 4 21:55:57 sip-proxy /usr/local/kamailio/sbin/kamailio[14680]:
ERROR: <core> [receive.c:173]: receive_msg(): core parsing of SIP
message failed (1.1.1.1:61979/2)
---
That doesn't look like a clean message buffer to me. The message should
start here:
ACK
sip:*98*0b3ff883-a89d-4317-b758-8979682f5357@10.0.2.53:5060;transport=udp
SIP/2.0#015#012Via:
SIP/2.0/TCP ...
But instead it's got these SDP attributes prepended:
0#015#012a=rtcp:4007 IN IP4
1.1.1.1:1071#015#012a=sendrecv#015#012a=rtpmap:0
PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96 0-16#015#012
These SDP attribute appear to have fallen off the back of the SDP offer
in the initial INVITE:
v=0
o=- 3679365582 3679365582 IN IP4 10.0.0.200
s=pjmedia
t=0 0
m=audio 4006 RTP/AVP 0 8 96
c=IN IP4 1.1.1.1
The relationship between the 4006 RTP port and the 4007 RTCP port
suggests that these two things belong together.
This is on kamailio 4.4.0 (x86_64/linux) d4f23c. Any help would be
greatly appreciated! The issue is consistently reproducible and this
happens every time.
Cheers,
-- Alex
10:57 a.m.
On 08/07/2016 01:50 AM, Daniel-Constantin Mierla wrote:
tcp being a stream protocol, kamailio is reading the
body of sip
messages based on content-lenght header -- can you check and see if the
values for content length are accurate?
The initial INVITE has a Content-Length value of 122, but 116 is the
length of the incomplete SDP body in that packet:
v=0
o=- 3679365582 3679365582 IN IP4 10.0.0.200
s=pjmedia
t=0 0
m=audio 4006 RTP/AVP 0 8 96
c=IN IP4 1.1.1.1
The remainder, sent in the continuation/trailer, has 149 bytes.
So, I'm guessing the answer to your question is no: the Content-Length
is not accurate, and doesn't reflect the full payload from the combined
length of the SDP stanzas (122 + 149 = 271).
Do you have the parameter tcp_accept_no_cl set?
I do not.
--
Alex Balashov | Principal | Evariste Systems LLC
1447 Peachtree Street NE, Suite 700
Atlanta, GA 30309
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
10:59 a.m.
On 08/07/2016 01:57 AM, Alex Balashov wrote:
So, I'm guessing the answer to your question is
no: the Content-Length
is not accurate, and doesn't reflect the full payload from the combined
length of the SDP stanzas (122 + 149 = 271).
I guess it should be 265, not 271.
--
Alex Balashov | Principal | Evariste Systems LLC
1447 Peachtree Street NE, Suite 700
Atlanta, GA 30309
United States
Tel: +1-800-250-5920 (toll-free) / +1-678-954-0671 (direct)
Web: http://www.evaristesys.com/, http://www.csrpswitch.com/
8 Aug
8 Aug
1:46 p.m.
Is the messages sent by the end UA directly, or via some proxy?
Cheers,
Daniel
On 07/08/16 07:59, Alex Balashov wrote:
On 08/07/2016 01:57 AM, Alex Balashov wrote:
--
Daniel-Constantin Mierla
http://www.asipto.com - http://www.kamailio.org
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
So, I'm guessing the answer to your question
is no: the Content-Length
is not accurate, and doesn't reflect the full payload from the combined
length of the SDP stanzas (122 + 149 = 271).
I guess it should be 265, not 271.
2821
days inactive
2824
days old
6 comments
2 participants
participants (2)
-
Alex Balashov -
Daniel-Constantin Mierla