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
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
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:
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@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
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
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:
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
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
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:
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
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
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
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@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
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
-
Daniel-Constantin Mierla -
Juha Heinanen