17 Sep
2018
17 Sep
'18
2:59 p.m.
In order to be able to fail2ban an attacker that sends tons of SIP
requests with malformed request lines, it would need to be possible to
generate an appropriate syslog message from config file.
I didn't find any sanity module param value that would turn on checking
of request line syntax. Any other ideas?
As an example, below is what comes to syslog when I send a request that
has syntax error on request line.
-- Juha
Sep 17 14:46:39 char /usr/bin/sip-proxy[9458]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 14:46:39 char /usr/bin/sip-proxy[9458]: WARNING: <core> [core/receive.c:230]:
receive_msg(): parsing relevant headers failed
Sep 17 14:46:43 char /usr/bin/sip-proxy[9458]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 14:46:43 char /usr/bin/sip-proxy[9458]: WARNING: <core> [core/receive.c:230]:
receive_msg(): parsing relevant headers failed
17 Sep
17 Sep
3:24 p.m.
Juha Heinanen writes:
I didn't find any sanity module param value that
would turn on checking
of request line syntax. Any other ideas?
I added log message at the beginning of main route block:
route { # main route block (initial tasks)
xinfo("Here\n");
It was not printed when malformed request came in, which means that the
main route block was not executed at all.
Kamailio cannot be wide open to DoS attacks. What is it that I'm
missing.
-- Juha
4:24 p.m.
Hello,
try with event_route[core:receive-parse-error] { ... }
The variables related to sip message content (headers, body, ...) likely
not working there (should return null), but source IP/port should be good.
Cheers,
Daniel
On 17.09.18 14:24, Juha Heinanen wrote:
Juha Heinanen writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference -- www.kamailioworld.com
Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
I didn't find any sanity module param value
that would turn on checking
of request line syntax. Any other ideas?
I added log message at the beginning of
main route block:
route { # main route block (initial tasks)
xinfo("Here\n");
It was not printed when malformed request came in, which means that the
main route block was not executed at all.
Kamailio cannot be wide open to DoS attacks. What is it that I'm
missing.
-- Juha
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
4:42 p.m.
Daniel-Constantin Mierla writes:
try with event_route[core:receive-parse-error] { ...
}
The variables related to sip message content (headers, body, ...) likely
not working there (should return null), but source IP/port should be good.
Thanks for the pointer. I defined:
event_route[core:receive-parse-error] { # Catch message parse errors
xnotice("Request from <$var(src_ip)> has invalid syntax\n");
}
but didn't get the notice to syslog. Only these:
Sep 17 16:37:52 char /usr/bin/sip-proxy[23020]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:37:52 char /usr/bin/sip-proxy[23020]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
-- Juha
4:50 p.m.
Can you send all log messages with debug=3?
Btw, the source ip variable is $si.
Cheers,
Daniel
On 17.09.18 15:42, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference -- www.kamailioworld.com
Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
try with event_route[core:receive-parse-error] {
... }
The variables related to sip message content (headers, body, ...) likely
not working there (should return null), but source IP/port should be good.
Thanks
for the pointer. I defined:
event_route[core:receive-parse-error] { # Catch message parse errors
xnotice("Request from <$var(src_ip)> has invalid syntax\n");
}
but didn't get the notice to syslog. Only these:
Sep 17 16:37:52 char /usr/bin/sip-proxy[23020]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:37:52 char /usr/bin/sip-proxy[23020]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
-- Juha
4:59 p.m.
Daniel-Constantin Mierla writes:
Can you send all log messages with debug=3?
Below.
Btw, the source ip variable is $si.
Oh yes, I had just copied the statement from other part of config,
where $si has been assigned to $var(src_ip).
-- Juha
Sep 17 16:56:07 char /usr/bin/sip-proxy[24183]: INFO: <core>
[core/cfg/cfg_ctx.c:595]: cfg_set_now(): core.debug has been changed to 3
sip-proxy_ctl> Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 192.168.43.107
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/tcp_main.c:999]:
tcpconn_new(): on port 48636, type 2
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:1305]: tcpconn_add(): hashes: 1768:3207:3940, 1
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa16da0, 67, 2, 0x7fb01cc67930), fd_no=55
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:602]:
io_watch_del(): DBG: io_watch_del (0x55839aa16da0, 67, -1, 0x0) fd_no=56 called
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3847]: send2child(): checking per-socket generic workers
(24205/27..24230/34) [tcp:192.168.43.107:5060]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3875]: send2child(): selected tcp worker 0 27(24205) for activity on
[tcp:192.168.43.107:5060], 0x7fb01cc67930
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1759]: handle_io(): received n=8 con=0x7fb01cc67930, fd=12
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1560]: tcp_read_req(): content-length=0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:606]: parse_msg(): invalid message
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): ERROR: parse_msg:
message=<REGISTERsip:test.tutpro.com SIP/2.0#015#012Via: SIP/2.0/TCP
192.168.43.107:40797;branch=z9hG4bK7a6e707b367651ed;rport#015#012Contact:
<sip:test-0x560c9b9d4790@192.168.43.107:40797;transport=tcp>;expires=600;+sip.instance="<urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>";q=0.5;reg-id=1#015#012Max-Forwards:
70#015#012Route: <sip:192.168.43.107:5060;transport=tcp;lr>#015#012To:
<sip:test@test.tutpro.com>#015#012From:
<sip:test@test.tutpro.com>;tag=ab41d0eaaf619e81#015#012Call-ID:
08f94737eec75885#015#012CSeq: 26277 REGISTER#015#012User-Agent: baresip v0.5.11
(x86_64/linux)#015#012Supported: gruu, outbound, path#015#012Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE#015#012Content-Length:
0#015#012#015#012>
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:83]: get_hdr_field(): null buffer pointer
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:279]: get_hdr_field(): error exit
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:232]:
receive_msg(): --- received sip message - reply - call-id: [] - cseq: []
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/xavp.c:495]:
xavp_destroy_list(): destroying xavp list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:449]:
receive_msg(): cleaning up
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1560]: tcp_read_req(): content-length=0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:606]: parse_msg(): invalid message
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): ERROR: parse_msg:
message=<REGISTERsip:test.tutpro.com SIP/2.0#015#012Via: SIP/2.0/TCP
192.168.43.107:40797;branch=z9hG4bKf685c1d98f625150;rport#015#012Contact:
<sip:foo-0x560c9b9d88d0@192.168.43.107:40797;transport=tcp>;expires=600;+sip.instance="<urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>";q=0.5;reg-id=1#015#012Max-Forwards:
70#015#012Route: <sip:192.168.43.107:5060;transport=tcp;lr>#015#012To:
<sip:foo@test.tutpro.com>#015#012From:
<sip:foo@test.tutpro.com>;tag=4728ad9cfe4fd2bd#015#012Call-ID:
abee5e4caabe3878#015#012CSeq: 17544 REGISTER#015#012User-Agent: baresip v0.5.11
(x86_64/linux)#015#012Supported: gruu, outbound, path#015#012Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,REFER#015#012Content-Length:
0#015#012#015#012>
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:83]: get_hdr_field(): null buffer pointer
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:279]: get_hdr_field(): error exit
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:232]:
receive_msg(): --- received sip message - reply - call-id: [] - cseq: []
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/xavp.c:495]:
xavp_destroy_list(): destroying xavp list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:449]:
receive_msg(): cleaning up
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa5ff40, 12, 2, 0x7fb01cc67930), fd_no=1
sip-proxy_ctl> cfg.set core debug Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]:
DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del
(0x55839aa5ff40, 12, -1, 0x10) fd_no=2 called
Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1680]: release_tcpconn(): releasing con 0x7fb01cc67930, state 1, fd=12,
id=1 ([192.168.43.107]:48636 -> [192.168.43.107]:5060)
Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1684]: release_tcpconn(): extra_data (nil)
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3307]: handle_tcp_child(): reader response= 7fb01cc67930, 1 from 0
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa16da0, 67, 2, 0x7fb01cc67930), fd_no=55
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3434]: handle_tcp_child(): CONN_RELEASE 0x7fb01cc67930 refcnt= 1
1
5:20 p.m.
I guess you have some modules that registered to process non-sip
traffic, such as xhttp, xmlrpc, ... the parse_msg() throws error and in
such case the processing is delegated to non-sip message handling, if
all skipped, then ended up on trying going further as sip ...
I just pushed a patch to deal with it properly. Can you test? if all ok,
feel free to backport.
Cheers,
Daniel
On 17.09.18 15:59, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference -- www.kamailioworld.com
Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
Can you send all log messages with debug=3?
Below.
Btw, the source ip variable is $si.
Oh
yes, I had just copied the statement from other part of config,
where $si has been assigned to $var(src_ip).
-- Juha
Sep 17 16:56:07 char /usr/bin/sip-proxy[24183]: INFO: <core>
[core/cfg/cfg_ctx.c:595]: cfg_set_now(): core.debug has been changed to 3
sip-proxy_ctl> Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 192.168.43.107
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:999]: tcpconn_new(): on port 48636, type 2
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:1305]: tcpconn_add(): hashes: 1768:3207:3940, 1
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa16da0, 67, 2, 0x7fb01cc67930), fd_no=55
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:602]:
io_watch_del(): DBG: io_watch_del (0x55839aa16da0, 67, -1, 0x0) fd_no=56 called
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3847]: send2child(): checking per-socket generic workers
(24205/27..24230/34) [tcp:192.168.43.107:5060]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3875]: send2child(): selected tcp worker 0 27(24205) for activity on
[tcp:192.168.43.107:5060], 0x7fb01cc67930
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1759]: handle_io(): received n=8 con=0x7fb01cc67930, fd=12
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1560]: tcp_read_req(): content-length=0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:606]: parse_msg(): invalid message
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): ERROR: parse_msg:
message=<REGISTERsip:test.tutpro.com SIP/2.0#015#012Via: SIP/2.0/TCP
192.168.43.107:40797;branch=z9hG4bK7a6e707b367651ed;rport#015#012Contact:
<sip:test-0x560c9b9d4790@192.168.43.107:40797;transport=tcp>;expires=600;+sip.instance="<urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>";q=0.5;reg-id=1#015#012Max-Forwards:
70#015#012Route: <sip:192.168.43.107:5060;transport=tcp;lr>#015#012To:
<sip:test@test.tutpro.com>#015#012From:
<sip:test@test.tutpro.com>;tag=ab41d0eaaf619e81#015#012Call-ID:
08f94737eec75885#015#012CSeq: 26277 REGISTER#015#012User-Agent: baresip v0.5.11
(x86_64/linux)#015#012Supported: gruu, outbound, path#015#012Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE#015#012Content-Length:
0#015#012#015#012>
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:83]: get_hdr_field(): null buffer pointer
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:279]: get_hdr_field(): error exit
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:232]:
receive_msg(): --- received sip message - reply - call-id: [] - cseq: []
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/xavp.c:495]:
xavp_destroy_list(): destroying xavp list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:449]:
receive_msg(): cleaning up
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1560]: tcp_read_req(): content-length=0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:249]: parse_first_line(): parse_first_line: bad request first
line
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:251]: parse_first_line(): at line 0 char 35:
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:257]: parse_first_line(): parsed so far:
REGISTERsip:test.tutpro.com SIP/2.0
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/parse_fline.c:262]: parse_first_line(): parse_first_line: bad message
(offset: 35)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:606]: parse_msg(): invalid message
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:681]: parse_msg(): ERROR: parse_msg:
message=<REGISTERsip:test.tutpro.com SIP/2.0#015#012Via: SIP/2.0/TCP
192.168.43.107:40797;branch=z9hG4bKf685c1d98f625150;rport#015#012Contact:
<sip:foo-0x560c9b9d88d0@192.168.43.107:40797;transport=tcp>;expires=600;+sip.instance="<urn:uuid:9b21c1a8-dc58-a3d6-83d5-7be67cbe70ce>";q=0.5;reg-id=1#015#012Max-Forwards:
70#015#012Route: <sip:192.168.43.107:5060;transport=tcp;lr>#015#012To:
<sip:foo@test.tutpro.com>#015#012From:
<sip:foo@test.tutpro.com>;tag=4728ad9cfe4fd2bd#015#012Call-ID:
abee5e4caabe3878#015#012CSeq: 17544 REGISTER#015#012User-Agent: baresip v0.5.11
(x86_64/linux)#015#012Supported: gruu, outbound, path#015#012Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,NOTIFY,SUBSCRIBE,INFO,MESSAGE,REFER#015#012Content-Length:
0#015#012#015#012>
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:83]: get_hdr_field(): null buffer pointer
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/parser/msg_parser.c:279]: get_hdr_field(): error exit
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: ERROR: <core>
[core/parser/msg_parser.c:337]: parse_headers(): bad header field [(null)]
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: WARNING: <core>
[core/receive.c:230]: receive_msg(): parsing relevant headers failed
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:232]:
receive_msg(): --- received sip message - reply - call-id: [] - cseq: []
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/usr_avp.c:636]:
destroy_avp_list(): destroying list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/xavp.c:495]:
xavp_destroy_list(): destroying xavp list (nil)
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/receive.c:449]:
receive_msg(): cleaning up
Sep 17 16:56:16 char /usr/bin/sip-proxy[24205]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa5ff40, 12, 2, 0x7fb01cc67930), fd_no=1
sip-proxy_ctl> cfg.set core debug Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]:
DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del
(0x55839aa5ff40, 12, -1, 0x10) fd_no=2 called
Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1680]: release_tcpconn(): releasing con 0x7fb01cc67930, state 1, fd=12,
id=1 ([192.168.43.107]:48636 -> [192.168.43.107]:5060)
Sep 17 16:56:22 char /usr/bin/sip-proxy[24205]: DEBUG: <core>
[core/tcp_read.c:1684]: release_tcpconn(): extra_data (nil)
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3307]: handle_tcp_child(): reader response= 7fb01cc67930, 1 from 0
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core> [core/io_wait.h:380]:
io_watch_add(): DBG: io_watch_add(0x55839aa16da0, 67, 2, 0x7fb01cc67930), fd_no=55
Sep 17 16:56:22 char /usr/bin/sip-proxy[24255]: DEBUG: <core>
[core/tcp_main.c:3434]: handle_tcp_child(): CONN_RELEASE 0x7fb01cc67930 refcnt= 1
1
5:56 p.m.
Daniel-Constantin Mierla writes:
I guess you have some modules that registered to
process non-sip
traffic, such as xhttp, xmlrpc, ... the parse_msg() throws error and in
such case the processing is delegated to non-sip message handling, if
all skipped, then ended up on trying going further as sip ...
Yes, there is event_route [xhttp:request].
I just pushed a patch to deal with it properly. Can you test? if all ok,
feel free to backport.
Now the event_route[core:receive-parse-error] was executed:
Sep 17 17:52:14 char /usr/bin/sip-proxy[18269]: NOTICE: Request from
<192.168.43.107> has invalid syntax
and there was no ERROR/WARNING messages.
I'll backport to 5.1.
-- Juha
6:05 p.m.
Juha Heinanen writes:
I'll backport to 5.1.
cherry-pick didn't work:
$ git cherry-pick -x f088d2afe4153b9e440a4293211c78f5a25af691
error: could not apply f088d2afe... core: if nosip msg hooks skip handling the packet,
stop sip routing processing
hint: after resolving the conflicts, mark the corrected paths
hint: with 'git add <paths>' or 'git rm <paths>'
hint: and commit the result with 'git commit'
I'm not sure if I dare to do manual edit.
-- Juha
6:11 p.m.
I will check the cherry pick conflict and do the backport manually if
needed once. Going to be a bit later today.
Cheers,
Daniel
On Mon, 17 Sep 2018, 17:05 Juha Heinanen, <jh(a)tutpro.com> wrote:
Juha Heinanen writes:
I'll backport to 5.1.
cherry-pick didn't work:
$ git cherry-pick -x f088d2afe4153b9e440a4293211c78f5a25af691
error: could not apply f088d2afe... core: if nosip msg hooks skip handling
the packet, stop sip routing processing
hint: after resolving the conflicts, mark the corrected paths
hint: with 'git add <paths>' or 'git rm <paths>'
hint: and commit the result with 'git commit'
I'm not sure if I dare to do manual edit.
-- Juha
5:03 p.m.
Daniel-Constantin Mierla writes:
Can you send all log messages with debug=3?
I also started k with debug=3 to check that the event route is ok:
Sep 17 17:00:40 char sip-proxy: DEBUG: <core> [core/events.c:53]:
sr_core_ert_init(): event_route[core:receive-parse-error] is defined
-- Juha
2261
days inactive
2261
days old
11 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Juha Heinanen