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:[email protected]: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:[email protected]>#015#012From: > <sip:[email protected]>;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:[email protected]: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:[email protected]>#015#012From: > <sip:[email protected]>;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 -- 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 _______________________________________________ Kamailio (SER) - Users Mailing List [email protected] https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
