[sr-dev] [kamailio/kamailio] unexpected error log when KSR.xhttp.xhttp_reply(404...) (Issue #3204)
hance2010
notifications at github.com
Mon Aug 1 05:15:25 CEST 2022
<!--
Kamailio Project uses GitHub Issues only for bugs in the code or feature requests. Please use this template only for bug reports.
If you have questions about using Kamailio or related to its configuration file, ask on sr-users mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
If you have questions about developing extensions to Kamailio or its existing C code, ask on sr-dev mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
Please try to fill this template as much as possible for any issue. It helps the developers to troubleshoot the issue.
If there is no content to be filled in a section, the entire section can be removed.
You can delete the comments from the template sections when filling.
You can delete next line and everything above before submitting (it is a comment).
-->
### Description
<!--
Explain what you did, what you expected to happen, and what actually happened.
-->
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
<!--
If the issue can be reproduced, describe how it can be done.
-->
#### Debugging Data
<!--
If you got a core dump, use gdb to extract troubleshooting data - full backtrace,
local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile
bt full
info locals
list
If you are familiar with gdb, feel free to attach more of what you consider to
be relevant.
-->
```
(paste your debugging data here)
```
#### Log Messages
<!--
Check the syslog file and if there are relevant log messages printed by Kamailio, add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site).
-->
```
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
<!--
If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site).
-->
```
(paste your sip traffic here)
```
### Possible Solutions
<!--
If you found a solution or workaround for the issue, describe it. Ideally, provide a pull request with a fix.
-->
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
```
Kamailio5.6.1
```
* **Operating System**:
<!--
Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...;
Kernel details (output of `lsb_release -a` and `uname -a`)
-->
```
Debian11
```
--
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/3204
You are receiving this because you are subscribed to this thread.
Message ID: <kamailio/kamailio/issues/3204 at github.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20220731/d941b6d1/attachment-0001.htm>
More information about the sr-dev
mailing list