<p></p>
<h3 dir="auto">Description</h3>
<p dir="auto">some unexpected error in kamailio.log when KSR.xhttp.xhttp_reply(404...)</p>
<h3 dir="auto">Troubleshooting</h3>
<h4 dir="auto">Reproduction</h4>
<p dir="auto">cat /etc/kamailio/kamailio.cfg</p>
<pre class="notranslate"><code class="notranslate">listen=tcp:127.0.0.1:5060
tcp_accept_no_cl=yes
debug=3
log_stderror=yes
loadmodule "jsonrpcs.so"
loadmodule "tm.so"
loadmodule "sl.so"
loadmodule "pv.so"
loadmodule "xlog.so"
loadmodule "ctl.so"
loadmodule "cfg_rpc.so"
loadmodule "xhttp.so"
loadmodule "app_lua.so"
modparam("xhttp", "event_callback", "ksr_xhttp_event")
modparam("app_lua", "load", "/etc/kamailio/kamailio.lua")
cfgengine "lua"
</code></pre>
<p dir="auto">cat /etc/kamailio/kamailio.lua</p>
<pre class="notranslate"><code class="notranslate">function ksr_request_route()
KSR.sl.send_reply(200, "OK")
KSR.x.exit()
end
function ksr_xhttp_event()
KSR.set_reply_no_connect()
KSR.set_reply_close()
KSR.xhttp.xhttp_reply(404, "Not Found", "", "")
KSR.x.exit()
end
</code></pre>
<p dir="auto">curl <a href="http://127.0.0.1:5060" rel="nofollow">http://127.0.0.1:5060</a> -v</p>
<h4 dir="auto">Debugging Data</h4>
<pre class="notranslate"><code class="notranslate">(paste your debugging data here)
</code></pre>
<h4 dir="auto">Log Messages</h4>
<pre class="notranslate"><code class="notranslate">15(5845) DEBUG: <core> [core/ip_addr.c:571]: print_ip(): tcpconn_new: new tcp connection: 127.0.0.1
15(5845) DEBUG: <core> [core/tcp_main.c:1216]: tcpconn_new(): on port 54884, type 2, socket 29
15(5845) DEBUG: <core> [core/tcp_main.c:1548]: tcpconn_add(): hashes: 1846:1992:1067, 1
15(5845) DEBUG: <core> [core/io_wait.h:374]: io_watch_add(): processing io_watch_add(0x563c94544c20, 29, 2, 0x7fb2e4691088) - fd_no=23
15(5845) DEBUG: <core> [core/io_wait.h:599]: io_watch_del(): DBG: io_watch_del (0x563c94544c20, 29, -1, 0x0) fd_no=24 called
15(5845) DEBUG: <core> [core/tcp_main.c:4545]: handle_tcpconn_ev(): sending to child, events 1
15(5845) DEBUG: <core> [core/tcp_main.c:4215]: send2child(): selected tcp worker idx:0 proc:7 pid:5837 for activity on [tcp:127.0.0.1:5060], 0x7fb2e4691088
7(5837) DEBUG: <core> [core/tcp_read.c:1735]: handle_io(): received n=8 con=0x7fb2e4691088, fd=6
7(5837) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2
7(5837) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2
7(5837) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
7(5837) DEBUG: <core> [core/parser/msg_parser.c:678]: parse_msg(): method: <GET>
7(5837) DEBUG: <core> [core/parser/msg_parser.c:680]: parse_msg(): uri: </>
7(5837) DEBUG: <core> [core/parser/msg_parser.c:682]: parse_msg(): version: <HTTP/1.1>
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Host] type 0
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [User-Agent] type 28
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Accept] type 23
7(5837) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
7(5837) DEBUG: <core> [core/receive.c:389]: receive_msg(): --- received sip message - request - call-id: [] - cseq: []
7(5837) DEBUG: <core> [core/receive.c:261]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
7(5837) DEBUG: <core> [core/receive.c:426]: receive_msg(): handling non-sip request message
7(5837) DEBUG: xhttp [xhttp_mod.c:371]: xhttp_handler(): new fake msg created (112 bytes):
<GET / HTTP/1.1
Via: SIP/2.0/TCP 127.0.0.1:54884
Host: 127.0.0.1:5060
User-Agent: curl/7.74.0
Accept: */*
>
7(5837) DEBUG: <core> [core/parser/parse_fline.c:249]: parse_first_line(): first line type 1 (request) flags 2
7(5837) DEBUG: <core> [core/parser/msg_parser.c:677]: parse_msg(): SIP Request:
7(5837) DEBUG: <core> [core/parser/msg_parser.c:678]: parse_msg(): method: <GET>
7(5837) DEBUG: <core> [core/parser/msg_parser.c:680]: parse_msg(): uri: </>
7(5837) DEBUG: <core> [core/parser/msg_parser.c:682]: parse_msg(): version: <HTTP/1.1>
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Via] type 1
7(5837) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5
7(5837) DEBUG: <core> [core/parser/msg_parser.c:555]: parse_headers(): Via found, flags=2
7(5837) DEBUG: <core> [core/parser/msg_parser.c:557]: parse_headers(): this is the first via
7(5837) DEBUG: app_lua [app_lua_api.c:549]: sr_lua_reload_script(): No need to reload [/etc/kamailio/kamailio.lua] is version 0
7(5837) DEBUG: app_lua [app_lua_api.c:733]: app_lua_run_ex(): executing Lua function: [[ksr_xhttp_event]]
7(5837) DEBUG: app_lua [app_lua_api.c:735]: app_lua_run_ex(): lua top index is: 11
7(5837) DEBUG: app_lua [app_lua_api.c:1067]: sr_kemi_lua_exec_func_ex(): param[0] for: xhttp_reply is int: 404
7(5837) DEBUG: app_lua [app_lua_api.c:1063]: sr_kemi_lua_exec_func_ex(): param[1] for: xhttp_reply is str: Not Found
7(5837) DEBUG: app_lua [app_lua_api.c:1063]: sr_kemi_lua_exec_func_ex(): param[2] for: xhttp_reply is str:
7(5837) DEBUG: app_lua [app_lua_api.c:1063]: sr_kemi_lua_exec_func_ex(): param[3] for: xhttp_reply is str:
7(5837) DEBUG: xhttp [xhttp_mod.c:426]: xhttp_send_reply(): sending out response: 404 Not Found
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Host] type 0
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [User-Agent] type 28
7(5837) DEBUG: <core> [core/parser/parse_hname2.c:301]: parse_sip_header_name(): parsed header name [Accept] type 23
7(5837) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
7(5837) DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (127.0.0.1, 127.0.0.1, 0)
7(5837) DEBUG: <core> [core/tcp_main.c:1644]: _tcpconn_find(): found connection by id: 1
7(5837) DEBUG: <core> [core/tcp_main.c:2526]: tcpconn_send_put(): send from reader (5837 (7)), reusing fd
7(5837) DEBUG: <core> [core/tcp_main.c:2761]: tcpconn_do_send(): sending...
7(5837) DEBUG: <core> [core/tcp_main.c:2794]: tcpconn_do_send(): after real write: c= 0x7fb2e4691088 n=120 fd=6
7(5837) DEBUG: <core> [core/tcp_main.c:2795]: tcpconn_do_send(): buf=
HTTP/1.1 404 Not Found
Sia: SIP/2.0/TCP 127.0.0.1:54884
Server: kamailio (5.6.1 (x86_64/linux))
Content-Length: 0
15(5845) DEBUG: <core> [core/tcp_main.c:3880]: handle_ser_child(): read response= 7fb2e4691088, -1, fd -1 from 7 (5837)
7(5837) DEBUG: <core> [core/parser/parse_fline.c:255]: parse_first_line(): bad request first line
7(5837) DEBUG: <core> [core/parser/parse_fline.c:258]: parse_first_line(): at line 0 char 16:
7(5837) DEBUG: <core> [core/parser/parse_fline.c:264]: parse_first_line(): parsed so far: HTTP/1.1 404 Not
7(5837) ERROR: <core> [core/parser/parse_fline.c:271]: parse_first_line(): parse_first_line: bad message (offset: 16)
7(5837) DEBUG: <core> [core/parser/msg_parser.c:673]: parse_msg(): invalid message
7(5837) ERROR: <core> [core/parser/msg_parser.c:747]: parse_msg(): ERROR: parse_msg: message=<HTTP/1.1 404 Not Found
Sia: SIP/2.0/TCP 127.0.0.1:54884
Server: kamailio (5.6.1 (x86_64/linux))
Content-Length: 0
>
7(5837) ERROR: <core> [core/msg_translator.c:3256]: build_sip_msg_from_buf(): parsing failed 7(5837) DEBUG: app_lua [app_lua_mod.c:164]: sr_kemi_config_engine_lua(): execution of route type 513 with name [ksr_xhttp_event] returned 1
7(5837) DEBUG: <core> [core/receive.c:432]: receive_msg(): finished handling non-sip request message
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil)
7(5837) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
7(5837) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
7(5837) DEBUG: <core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil)
7(5837) DEBUG: <core> [core/receive.c:628]: receive_msg(): cleaning up
7(5837) DEBUG: <core> [core/io_wait.h:374]: io_watch_add(): processing io_watch_add(0x563c94588ec0, 6, 2, 0x7fb2e4691088) - fd_no=1
7(5837) DEBUG: <core> [core/io_wait.h:599]: io_watch_del(): DBG: io_watch_del (0x563c94588ec0, 6, -1, 0x10) fd_no=2 called
7(5837) DEBUG: <core> [core/tcp_read.c:1870]: handle_io(): removing from list 0x7fb2e4691088 id 1 fd 6, state -1, flags 4028, main fd -1, refcnt 1 ([127.0.0.1]:54884 -> [127.0.0.1]:5060)
7(5837) DEBUG: <core> [core/tcp_read.c:1653]: release_tcpconn(): releasing con 0x7fb2e4691088, state -2, fd=6, id=1 ([127.0.0.1]:54884 -> [127.0.0.1]:5060)
7(5837) DEBUG: <core> [core/tcp_read.c:1657]: release_tcpconn(): extra_data (nil)
15(5845) DEBUG: <core> [core/tcp_main.c:3641]: handle_tcp_child(): reader response= 7fb2e4691088, -2 from 0
15(5845) DEBUG: <core> [core/tcp_main.c:3566]: tcp_emit_closed_event(): TCP closed event creation triggered (reason: 0)
15(5845) DEBUG: <core> [core/tcp_main.c:3574]: tcp_emit_closed_event(): no callback registering for handling TCP closed event
2(5832) DEBUG: <core> [core/timer.c:422]: adjust_ticks(): adjusting timer ticks (677813966) with 312 ms (5 ticks)
2(5832) DEBUG: <core> [core/timer.c:422]: adjust_ticks(): adjusting timer ticks (677815246) with 250 ms (4 ticks)
2(5832) DEBUG: <core> [core/timer.c:422]: adjust_ticks(): adjusting timer ticks (677816206) with 250 ms (4 ticks)
2(5832) DEBUG: <core> [core/timer.c:422]: adjust_ticks(): adjusting timer ticks (677817406) with 312 ms (5 ticks)
</code></pre>
<h4 dir="auto">SIP Traffic</h4>
<pre class="notranslate"><code class="notranslate">(paste your sip traffic here)
</code></pre>
<h3 dir="auto">Possible Solutions</h3>
<h3 dir="auto">Additional Information</h3>
<ul dir="auto">
<li><strong>Kamailio Version</strong> - output of <code class="notranslate">kamailio -v</code></li>
</ul>
<pre class="notranslate"><code class="notranslate">Kamailio5.6.1
</code></pre>
<ul dir="auto">
<li><strong>Operating System</strong>:</li>
</ul>
<pre class="notranslate"><code class="notranslate">Debian11
</code></pre>
<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/3204">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/ABO7UZOHVXBPW6SQIAQGQALVW46M3ANCNFSM55GAWOMA">unsubscribe</a>.<br />You are receiving this because you are subscribed to this thread.<img src="https://github.com/notifications/beacon/ABO7UZPARTNTEU7DWUORGI3VW46M3A5CNFSM55GAWOMKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4TXGX4DQ.gif" height="1" width="1" alt="" /><span style="color: transparent; font-size: 0; display: none; visibility: hidden; overflow: hidden; opacity: 0; width: 0; height: 0; max-width: 0; max-height: 0; mso-hide: all">Message ID: <span><kamailio/kamailio/issues/3204</span><span>@</span><span>github</span><span>.</span><span>com></span></span></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/3204",
"url": "https://github.com/kamailio/kamailio/issues/3204",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>