[sr-dev] [kamailio/kamailio] msg_parser.c:747: cannot parse "503 Service Unavailable" (#2751)

### Description I sending an error "503 Service Unavailable" message for HTTP requests using `xhttp` module. Also, I use `siptrace` module to send packets to Homer. Looks as in this use case `msg_parser` not able to parse HTTP error message. ### Troubleshooting #### Reproduction Need to start Kamailio with config below and execute command `curl -v http://127.0.0.1:5060` Kamailio config ``` listen=udp:127.0.0.1:5060 listen=tcp:127.0.0.1:5060 loadmodule "tm.so" loadmodule "sl.so" loadmodule "pv.so" loadmodule "xlog.so" loadmodule "xhttp.so" loadmodule "siptrace.so" modparam("siptrace", "duplicate_uri", "sip:127.0.0.1:9060") modparam("siptrace", "hep_mode_on", 1) modparam("siptrace", "hep_version", 3) modparam("siptrace", "hep_capture_id", 1) modparam("siptrace", "trace_to_database", 0) modparam("siptrace", "trace_on", 1) modparam("siptrace", "trace_mode", 1) modparam("siptrace", "trace_init_mode", 1) # allow HTTP request tcp_accept_no_cl=yes request_route { drop; } event_route[siptrace:msg] { #xlog("L_ERROR", "trace|sip trace for method $mb\n"); drop(); } event_route[xhttp:request] { $var(status_code) = 503; $var(reason_phrase) = "Service Unavailable"; $var(response) = "{}"; xhttp_reply("$var(status_code)", "$var(reason_phrase)", "application/json", "$var(response)"); } ``` #### Log Messages Kamailio log messages for GET requests ``` 20(408) DEBUG: <core> [core/ip_addr.c:571]: print_ip(): tcpconn_new: new tcp connection: 127.0.0.1 20(408) DEBUG: <core> [core/tcp_main.c:1175]: tcpconn_new(): on port 55462, type 2, socket 35 20(408) DEBUG: <core> [core/tcp_main.c:1494]: tcpconn_add(): hashes: 2537:2327:2804, 1 20(408) DEBUG: <core> [core/io_wait.h:374]: io_watch_add(): DBG: io_watch_add(0x91b580, 35, 2, 0x7f8ec4bff0e0), fd_no=28 20(408) DEBUG: <core> [core/io_wait.h:599]: io_watch_del(): DBG: io_watch_del (0x91b580, 35, -1, 0x0) fd_no=29 called 20(408) DEBUG: <core> [core/tcp_main.c:4457]: handle_tcpconn_ev(): sending to child, events 1 20(408) DEBUG: <core> [core/tcp_main.c:4127]: send2child(): selected tcp worker idx:0 proc:12 pid:400 for activity on [tcp:127.0.0.1:5060], 0x7f8ec4bff0e0 12(400) DEBUG: <core> [core/tcp_read.c:1737]: handle_io(): received n=8 con=0x7f8ec4bff0e0, fd=7 12(400) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2 12(400) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2 12(400) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request: 12(400) DEBUG: <core> [core/parser/msg_parser.c:678]: parse_msg(): method: <GET12(400) DEBUG: <core> [core/parser/msg_parser.c:680]: parse_msg(): uri: </12(400) DEBUG: <core> [core/parser/msg_parser.c:682]: parse_msg(): version: <HTTP/1.112(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Host] type 0 12(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [User-Agent] type 28 12(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Accept] type 23 12(400) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header 12(400) DEBUG: <core> [core/receive.c:387]: receive_msg(): --- received sip message - request - call-id: [] - cseq: [] 12(400) DEBUG: <core> [core/receive.c:259]: ksr_evrt_pre_routing(): event route core:pre-routing not defined 12(400) DEBUG: xhttp [xhttp_mod.c:365]: xhttp_handler(): new fake msg created (112 bytes): <GET / HTTP/1.1 Via: SIP/2.0/TCP 127.0.0.1:55462 Host: 127.0.0.1:5060 User-Agent: curl/7.71.1 Accept: */* 12(400) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2 12(400) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request: 12(400) DEBUG: <core> [core/parser/msg_parser.c:678]: parse_msg(): method: <GET12(400) DEBUG: <core> [core/parser/msg_parser.c:680]: parse_msg(): uri: </12(400) DEBUG: <core> [core/parser/msg_parser.c:682]: parse_msg(): version: <HTTP/1.112(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Via] type 1 12(400) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 12(400) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2 12(400) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via 12(400) DEBUG: xhttp [xhttp_mod.c:410]: xhttp_send_reply(): response with content-type: application/json 12(400) DEBUG: xhttp [xhttp_mod.c:418]: xhttp_send_reply(): response with body: {} 12(400) DEBUG: xhttp [xhttp_mod.c:420]: xhttp_send_reply(): sending out response: 503 Service Unavailable 12(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Host] type 0 12(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [User-Agent] type 28 12(400) DEBUG: <core> [core/parser/parse_hname2.c:293]: parse_sip_header_name(): parsed header name [Accept] type 23 12(400) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header 12(400) DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 12(400) DEBUG: <core> [core/tcp_main.c:1590]: _tcpconn_find(): found connection by id: 1 12(400) DEBUG: <core> [core/tcp_main.c:2471]: tcpconn_send_put(): send from reader (400 (12)), reusing fd 12(400) DEBUG: <core> [core/tcp_main.c:2706]: tcpconn_do_send(): sending... 12(400) DEBUG: <core> [core/tcp_main.c:2739]: tcpconn_do_send(): after real write: c= 0x7f8ec4bff0e0 n=169 fd=7 12(400) DEBUG: <core> [core/tcp_main.c:2740]: tcpconn_do_send(): buf= HTTP/1.1 503 Service Unavailable Sia: SIP/2.0/TCP 127.0.0.1:55462 Content-Type: application/json Server: kamailio (5.6.0-dev0 (x86_64/linux)) Content-Length: 2 {} 12(400) DEBUG: <core> [core/parser/parse_fline.c:255]: parse_first_line(): bad request first line 12(400) DEBUG: <core> [core/parser/parse_fline.c:258]: parse_first_line(): at line 0 char 20: 12(400) DEBUG: <core> [core/parser/parse_fline.c:264]: parse_first_line(): parsed so far: HTTP/1.1 503 Service 12(400) ERROR: <core> [core/parser/parse_fline.c:271]: parse_first_line(): parse_first_line: bad message (offset: 20) 12(400) DEBUG: <core> [core/parser/msg_parser.c:673]: parse_msg(): invalid message 12(400) ERROR: <core> [core/parser/msg_parser.c:747]: parse_msg(): ERROR: parse_msg: message=<HTTP/1.1 503 Service Unavailable Sia: SIP/2.0/TCP 127.0.0.1:55462 Content-Type: application/json Server: kamailio (5.6.0-dev0 (x86_64/linux)) Content-Length: 2 {}12(400) DEBUG: siptrace [siptrace.c:2063]: siptrace_exec_evcb_msg(): parse_msg failed 12(400) DEBUG: siptrace [siptrace.c:2279]: siptrace_net_data_sent(): processing message mode 1 12(400) DEBUG: siptrace [siptrace_hep.c:496]: pipport2su(): the port string is 5060 12(400) DEBUG: siptrace [siptrace_hep.c:496]: pipport2su(): the port string is 55462 12(400) DEBUG: <core> [core/proxy.c:264]: mk_proxy(): doing DNS lookup... 12(400) DEBUG: siptrace [siptrace_hep.c:184]: trace_send_hep3_duplicate(): setting up the socket_info 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) 12(400) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) 12(400) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) 12(400) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) 12(400) DEBUG: <core> [core/receive.c:606]: receive_msg(): cleaning up 12(400) DEBUG: <core> [core/io_wait.h:374]: io_watch_add(): DBG: io_watch_add(0x95f820, 7, 2, 0x7f8ec4bff0e0), fd_no=1 12(400) DEBUG: <core> [core/tcp_read.c:300]: tcp_read_data(): EOF on connection 0x7f8ec4bff0e0 (state: 0, flags: 4018) - FD 7, bytes 0, rd-flags 10000 ([127.0.0.1]:55462 -> [127.0.0.1]:5060)12(400) DEBUG: <core> [core/tcp_read.c:184]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0) 12(400) DEBUG: <core> [core/tcp_read.c:192]: tcp_emit_closed_event(): no callback registering for handling TCP closed event 12(400) DEBUG: <core> [core/tcp_read.c:1503]: tcp_read_req(): EOF 12(400) DEBUG: <core> [core/io_wait.h:599]: io_watch_del(): DBG: io_watch_del (0x95f820, 7, -1, 0x10) fd_no=2 called 12(400) DEBUG: <core> [core/tcp_read.c:1872]: handle_io(): removing from list 0x7f8ec4bff0e0 id 1 fd 7, state 2, flags 4018, main fd 35, refcnt 2 ([127.0.0.1]:55462 -> [127.0.0.1]:5060) 12(400) DEBUG: <core> [core/tcp_read.c:1656]: release_tcpconn(): releasing con 0x7f8ec4bff0e0, state -1, fd=7, id=1 ([127.0.0.1]:55462 -> [127.0.0.1]:5060) 12(400) DEBUG: <core> [core/tcp_read.c:1660]: release_tcpconn(): extra_data (nil) 20(408) DEBUG: <core> [core/tcp_main.c:3559]: handle_tcp_child(): reader response= 7f8ec4bff0e0, -1 from 0 ``` ### Additional Information Tested master branch, commit 79fbb7c6df5d4c742b1283b752c2df0f51e77f09 -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/2751