Description

some unexpected error in kamailio.log when KSR.xhttp.xhttp_reply(404...)

Troubleshooting

Reproduction

cat /etc/kamailio/kamailio.cfg

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"

cat /etc/kamailio/kamailio.lua

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

curl http://127.0.0.1:5060 -v

Debugging Data

(paste your debugging data here)

Log Messages

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)

SIP Traffic

(paste your sip traffic here)

Possible Solutions

Additional Information

Kamailio5.6.1
Debian11


Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.Message ID: <kamailio/kamailio/issues/3204@github.com>