Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

msg_parser.c:747: cannot parse "503 Service Unavailable" #2751

Closed
sergey-safarov opened this issue May 29, 2021 · 1 comment
Closed

msg_parser.c:747: cannot parse "503 Service Unavailable" #2751

sergey-safarov opened this issue May 29, 2021 · 1 comment

Comments

@sergey-safarov
Copy link
Member

sergey-safarov commented May 29, 2021 •
edited

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.

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

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 79fbb7c
@miconda
Copy link
Member

miconda commented May 31, 2021

Does not seem set in your sample config -- see:

@miconda miconda closed this as completed May 31, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@miconda @sergey-safarov