<p></p>
<h3>Description</h3>
<p>I sending an error "503 Service Unavailable" message for HTTP requests using <code>xhttp</code> module.<br>
Also, I use <code>siptrace</code> module to send packets to Homer.<br>
Looks as in this use case <code>msg_parser</code> not able to parse HTTP error message.</p>
<h3>Troubleshooting</h3>
<h4>Reproduction</h4>
<p>Need to start Kamailio with config below and execute command <code>curl -v http://127.0.0.1:5060</code></p>
<p>Kamailio config</p>
<pre><code>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)");
}
</code></pre>
<h4>Log Messages</h4>
<p>Kamailio log messages for GET requests</p>
<pre><code>
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 
</code></pre>
<h3>Additional Information</h3>
<p>Tested master branch, commit <a class="commit-link" data-hovercard-type="commit" data-hovercard-url="https://github.com/kamailio/kamailio/commit/79fbb7c6df5d4c742b1283b752c2df0f51e77f09/hovercard" href="https://github.com/kamailio/kamailio/commit/79fbb7c6df5d4c742b1283b752c2df0f51e77f09"><tt>79fbb7c</tt></a></p>

<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/2751">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/ABO7UZOK3DXB5AXTDJ75RC3TQDJ5LANCNFSM45YHPQ5A">unsubscribe</a>.<img src="https://github.com/notifications/beacon/ABO7UZNNT5G3JDJQ6CMFT5TTQDJ5LA5CNFSM45YHPQ5KYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4NQHNHYA.gif" height="1" width="1" alt="" /></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/2751",
"url": "https://github.com/kamailio/kamailio/issues/2751",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>