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

Sat May 29 14:04:37 CEST 2021

### 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:  <GET>
12(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.1>
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/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:  <GET>
12(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.1>
12(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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20210529/5d5a40fb/attachment.htm>