Kamailio version: 5.1.6 (x86_64/linux)
cfgtrace reports strange call route flow going back and forward from the parent route. For example, if the cfg file looks like the following:
############################################### loadmodule "cfgt.so" modparam("cfgt", "mask", 30) modparam("cfgt", "basedir", "/tmp/cfgtest/") loadmodule "debugger.so" modparam("debugger", "cfgtrace", 1) modparam("debugger", "mod_level_mode", 1) modparam("debugger", "mod_hash_size", 4) modparam("debugger", "mod_level", "core=3") modparam("debugger", "cfgtest", 1)
request_route { route(ENTRY); route(TEST_1); } route[ENTRY] { xlog("L_NOTICE", "New request\n"); } route[TEST_2] { xlog("L_NOTICE", "End\n"); } route[TEST_1] { xlog("L_NOTICE", "I'm here\n"); if(is_method("BYE")) { xlog("L_NOTICE", "I'm here, again\n"); route(TEST_2); } xlog("L_NOTICE", "I'm still here\n"); return; } ###############################################
If I send an INVITE message, I get the following cfgtrace:
DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/proxy/kamailio.cfg] l=472 a=5 n=route ERROR: *** cfgtrace:request_route=[ENTRY] c=[/etc/kamailio/proxy/kamailio.cfg] l=479 a=26 n=xlog NOTICE: <script>: New request ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/proxy/kamailio.cfg] l=474 a=5 n=route ERROR: *** cfgtrace:request_route=[TEST_1] c=[/etc/kamailio/proxy/kamailio.cfg] l=489 a=26 n=xlog NOTICE: <script>: I'm here ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/proxy/kamailio.cfg] l=497 a=16 n=if ERROR: *** cfgtrace:request_route=[TEST_1] c=[/etc/kamailio/proxy/kamailio.cfg] l=491 a=25 n=is_method ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/proxy/kamailio.cfg] l=497 a=26 n=xlog NOTICE: <script>: I'm still here ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/etc/kamailio/proxy/kamailio.cfg] l=499 a=2 n=return DEBUG: <core> [core/receive.c:298]: receive_msg(): request-route executed in: 395 usec
As you see some actions are assigned to route "DEFAULT_ROUTE" even if they are in TEST_1.
The issue completely disappear if I remove "route(TEST_2);" line inside the IF.
maybe related to #1536 fix 92f8fdabcffd84e315d749bae8ded3490f8de014
@marcocapetta can you, please, confirm that it works with the fix?
``` #!KAMAILIO
log_stderror=yes mpath="modules/"
loadmodule "xlog.so" loadmodule "textops.so" loadmodule "debugger.so" modparam("debugger", "cfgtrace", 1) modparam("debugger", "mod_level_mode", 1) modparam("debugger", "mod_hash_size", 4) modparam("debugger", "mod_level", "core=3")
request_route { route(ENTRY); route(TEST_1); }
route[ENTRY] { xlog("L_NOTICE", "New request\n"); if (is_method("BYE")) xinfo('BYE'); } route[TEST_2] { xlog("L_NOTICE", "End\n"); if (is_method("BYE")) xinfo('BYE'); } route[TEST_1] { xlog("L_NOTICE", "I'm here\n"); if (is_method("BYE")) { xlog("L_NOTICE", "I'm here, again\n"); route(TEST_2); } xlog("L_NOTICE", "I'm still here\n"); return; } ``` without the patch ``` 9(3432) DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (109/100/509) [[INVITE sip:service@127.0.1.1:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP 127.0.1.1:5061;branch=z9hG4bK-32445-1-0 0D ]] 9(3432) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 9(3432) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): method: <INVITE> 9(3432) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): uri: sip:service@127.0.1.1:5060 9(3432) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> 9(3432) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-32445-1-0>; state=16 9(3432) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 9(3432) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 9(3432) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 9(3432) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 9(3432) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [38]; uri=[sip:service@127.0.1.1:5060] 9(3432) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [service sip:service@127.0.1.1:5060 ], to tag [] 9(3432) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE> 9(3432) DEBUG: <core> [core/receive.c:240]: receive_msg(): --- received sip message - request - call-id: [1-32445@127.0.1.1] - cseq: [1 INVITE] 9(3432) DEBUG: <core> [core/receive.c:295]: receive_msg(): preparing to run routing scripts... 9(3432) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=16 a=5 n=route 9(3432) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=22 a=26 n=xlog 9(3432) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=24 a=16 n=if 9(3432) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=23 a=25 n=is_method 9(3432) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=17 a=5 n=route 9(3432) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=32 a=26 n=xlog 9(3432) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=38 a=16 n=if 9(3432) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=33 a=25 n=is_method 9(3432) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=38 a=26 n=xlog 9(3432) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=39 a=2 n=return 9(3432) DEBUG: <core> [core/receive.c:353]: receive_msg(): request-route executed in: 156 usec ``` with the patch: ``` 11(3592) DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (112/100/503) [[INVITE sip:service@127.0.1.1:5060 SIP/2.0 0D 0A Via: SIP/2.0/UDP 127.0.1.1:5061;branch=z9hG4bK-572-1-0 0D 0A F]] 11(3592) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 11(3592) DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): method: <INVITE> 11(3592) DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): uri: sip:service@127.0.1.1:5060 11(3592) DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> 11(3592) DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-572-1-0>; state=16 11(3592) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 11(3592) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 11(3592) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 11(3592) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 11(3592) DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [38]; uri=[sip:service@127.0.1.1:5060] 11(3592) DEBUG: <core> [core/parser/msg_parser.c:174]: get_hdr_field(): to body [service sip:service@127.0.1.1:5060 ], to tag [] 11(3592) DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE> 11(3592) DEBUG: <core> [core/receive.c:240]: receive_msg(): --- received sip message - request - call-id: [1-572@127.0.1.1] - cseq: [1 INVITE] 11(3592) DEBUG: <core> [core/receive.c:295]: receive_msg(): preparing to run routing scripts... 11(3592) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=16 a=5 n=route 11(3592) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=22 a=26 n=xlog 11(3592) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=24 a=16 n=if 11(3592) ERROR: *** cfgtrace:request_route=[ENTRY] c=[/code/src/../etc/test.cfg] l=23 a=25 n=is_method 11(3592) ERROR: *** cfgtrace:request_route=[DEFAULT_ROUTE] c=[/code/src/../etc/test.cfg] l=17 a=5 n=route 11(3592) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=32 a=26 n=xlog 11(3592) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=38 a=16 n=if 11(3592) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=33 a=25 n=is_method 11(3592) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=38 a=26 n=xlog 11(3592) ERROR: *** cfgtrace:request_route=[TEST_1] c=[/code/src/../etc/test.cfg] l=39 a=2 n=return 11(3592) DEBUG: <core> [core/receive.c:353]: receive_msg(): request-route executed in: 422 usec ```
Applying manually the patch on my system solved the issue.
Thanks a lot!
Closed #1668 via 6d1bf58d468e8ee62da2b1a2e50a57feb7c576c6.
-
Marco Capetta -
Victor Seva