### Description
I have a following problem with TOPOS module. I am trying to achieve a scenario where TOPOS will be activated in all other target peers but one and I managed to do this with event_route as described in TOPOS documentation: ``` event_route[topos:msg-outgoing] { if($sndto(ip)=="10.20.234.47") { drop; } } ``` This seems to work fine and when a call is coming from this peer, since 10.20.234.47 is not a target peer, TOPOS will be activated.
However when call is terminated from the receiving end and BYE message is destined to peer 10.20.234.47, kamailio at 10.30.160.60 answers '404 Not Here message'. I believe this has something to do with event_route below since this problem does not occur when I am not using event_route.
### Troubleshooting
I have debug logs from two examples, one with event_route enabled and another without event_route. For some reason when event_route is activated, topos will not populate BYE request with correct record routes but tries to find a branch from topos, which does not exist.
#### Reproduction
This issue can be reproduced with clean install of latest Kamailio dev from github.
#### Debugging Data
With event_route enabled ``` Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (112/100/501) [[BYE sip:btpsh-5b29f766-6a9d-1@10.30.160.60 SIP/2.0 0D 0A Max-Forwards: 68 0D 0A Via: SIP/2.0/UDP 10.20.234.25]] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <BYE> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: sip:btpsh-5b29f766-6a9d-1@10.30.160.60 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1ddd.efe198483f089826149438b9f015168d.0>; state=16 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKiwfg921gzhgpevsckfsgwvhgs>; state=16 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=4 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:505]: parse_headers(): this is the second via Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=as0af8e4f1 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [69]; uri=[sip:+358900000002@pbx.example.com] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Joonas Keskitalo" sip:+358900000002@pbx.example.com] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <BYE> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=h7g4Esbg_12001692187037 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_msg.c:742]: tps_request_received(): handling incoming request Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 10.20.234.25;branch=z9hG4bK1ddd.efe198483f089826149438b9f015168d.0](78) - x_via2: [SIP/2.0/UDP 212.146.3.173:5060;branch=z9hG4bKiwfg921gzhgpevsckfsgwvhgs](70) - x_vbranch1: [z9hG4bK1ddd.efe198483f089826149438b9f015168d.0](46) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [](0) - s_rr: [](0) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_storage.c:124]: tps_storage_lock_get(): tps lock get: 410 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:301]: redisc_get_server(): Hash 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:305]: redisc_get_server(): Entry 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:962]: tps_redis_load_dialog(): loading dialog record for [d:z:atpsh-5b29f766-6a9d-1] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:943]: redisc_exec_argv(): rsrv->ctxRedis = 0x5621e54bde90 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[1]: s[sip:btpsh-5b29f766-6a9d-1@10.30.160.60] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[3]: s[sip:+358900000002@10.20.234.47:5060;transport=TCP] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[5]: s[INVITE] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[7]: s[btpsh-5b29f766-6a9d-1] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[9]: s[as0af8e4f1] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[11]: s[102] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[13]: s[atpsh-5b29f766-6a9d-1] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[15]: s[sip:212.146.3.173;transport=udp;lr,sip:10.20.234.25;lr;pm] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[17]: s[sip:atpsh-5b29f766-6a9d-1@10.30.160.60;transport=tcp] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[19]: s[sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[21]: s[h7g4Esbg_12001692187037] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[23]: s[1529476980] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[25]: s[2] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[27]: s[02fc9c2217271d3b1195aa686164b509@pbx.example.com] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:301]: redisc_get_server(): Hash 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:305]: redisc_get_server(): Entry 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:301]: redisc_get_server(): Hash 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:305]: redisc_get_server(): Entry 2100282977 (srv8) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:610]: tps_redis_load_invite_branch(): loading branch record for [b:x:INVITE:02fc9c2217271d3b1195aa686164b509@pbx.example.com:as0af8e4f1] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:943]: redisc_exec_argv(): rsrv->ctxRedis = 0x5621e54bde90 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:628]: tps_redis_load_invite_branch(): hmap with key [b:x:INVITE:02fc9c2217271d3b1195aa686164b509@pbx.example.com:as0af8e4f1] not found Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:759]: tps_redis_load_branch(): loading branch record for [b:x:] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: ndb_redis [redis_client.c:943]: redisc_exec_argv(): rsrv->ctxRedis = 0x5621e54bde90 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos_redis [topos_redis_storage.c:777]: tps_redis_load_branch(): hmap with key [b:x:] not found Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: topos [tps_storage.c:136]: tps_storage_lock_release(): tps lock release: 410 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <BYE> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: sip:btpsh-5b29f766-6a9d-1@10.30.160.60 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1ddd.efe198483f089826149438b9f015168d.0>; state=16 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKiwfg921gzhgpevsckfsgwvhgs>; state=16 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=78 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:505]: parse_headers(): this is the second via Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=as0af8e4f1 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [69]; uri=[sip:+358900000002@pbx.example.com] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Joonas Keskitalo" sip:+358900000002@pbx.example.com] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <BYE> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/receive.c:200]: receive_msg(): --- received sip message - request - call-id: [02fc9c2217271d3b1195aa686164b509@pbx.example.com] - cseq: [1 BYE] Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/receive.c:248]: receive_msg(): preparing to run routing scripts... Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: pv [pv_core.c:966]: pv_get_useragent(): no User-Agent header Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 68 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=h7g4Esbg_12001692187037 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: sanity [sanity_mod.c:256]: w_sanity_check(): sanity checks result: 1 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} INFO: <script>: Received BYE from 10.20.234.25 to local IP 10.30.160.60, will do the needful. Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: tm [t_lookup.c:1018]: t_check_msg(): msg (0x7f3ab052c930) id=1 global id=0 T start=0xffffffffffffffff Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: tm [t_lookup.c:476]: t_lookup_request(): start searching: hash=56785, isACK=0 Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: tm [t_lookup.c:435]: matching_3261(): RFC3261 transaction matching failed Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: tm [t_lookup.c:659]: t_lookup_request(): no transaction found Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: tm [t_lookup.c:1087]: t_check_msg(): msg (0x7f3ab052c930) id=1 global id=1 T end=(nil) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: siputils [checks.c:123]: has_totag(): totag found Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: rr [loose.c:113]: find_first_route(): No Route headers found Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: rr [loose.c:960]: loose_route(): There is no Route HF Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/msg_translator.c:159]: check_via_address(): (10.20.234.25, 10.20.234.25, 0) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: topos [topos_mod.c:460]: tps_execute_event_route(): executing event_route[topos:...] (1) Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <404> Jun 20 09:43:11 edge3 /usr/local/sbin/kamailio[26884]: {1 1 BYE 02fc9c2217271d3b1195aa686164b509@pbx.example.com} DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Not here> ```
Without event_route ``` Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/udp_server.c:491]: udp_rcv_loop(): received on udp socket: (112/100/501) [[BYE sip:btpsh-5b29f51c-68b4-1@10.30.160.60 SIP/2.0 0D 0A Max-Forwards: 68 0D 0A Via: SIP/2.0/UDP 10.20.234.25]] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <BYE> Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: sip:btpsh-5b29f51c-68b4-1@10.30.160.60 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKc0da.006a721652ca40dc9f2f4d5d8eb387c0.0>; state=16 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKmozhccfz7thfkrmo7uikimq16>; state=16 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=4 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:505]: parse_headers(): this is the second via Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=as1e60e740 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [69]; uri=[sip:+35890000002@pbx.example.com] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body ["Joonas Keskitalo" sip:+35890000002@pbx.example.com] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <BYE> Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=h7g4Esbg_14000437127532 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:742]: tps_request_received(): handling incoming request Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 10.20.234.25;branch=z9hG4bKc0da.006a721652ca40dc9f2f4d5d8eb387c0.0](78) - x_via2: [SIP/2.0/UDP 212.146.3.165:5060;branch=z9hG4bKmozhccfz7thfkrmo7uikimq16](70) - x_vbranch1: [z9hG4bKc0da.006a721652ca40dc9f2f4d5d8eb387c0.0](46) Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [](0) - s_rr: [](0) Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0) Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_storage.c:124]: tps_storage_lock_get(): tps lock get: 213 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: ndb_redis [redis_client.c:301]: redisc_get_server(): Hash 2100282977 (srv8) Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: ndb_redis [redis_client.c:305]: redisc_get_server(): Entry 2100282977 (srv8) Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:962]: tps_redis_load_dialog(): loading dialog record for [d:z:atpsh-5b29f51c-68b4-1] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: ndb_redis [redis_client.c:943]: redisc_exec_argv(): rsrv->ctxRedis = 0x561a7d6dbe90 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[1]: s[sip:sgc_c@212.146.3.165;transport=udp] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[3]: s[sip:btpsh-5b29f51c-68b4-1@10.30.160.60] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[5]: s[sip:+35890000002@10.20.234.47:5060;transport=TCP] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[7]: s[INVITE] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[9]: s[btpsh-5b29f51c-68b4-1] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[11]: s[as1e60e740] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[13]: s[102] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[15]: s[atpsh-5b29f51c-68b4-1] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[17]: s[sip:212.146.3.165;transport=udp;lr,sip:10.20.234.25;lr;pm] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[19]: s[sip:atpsh-5b29f51c-68b4-1@10.30.160.60;transport=tcp] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[21]: s[sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[23]: s[h7g4Esbg_14000437127532] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[25]: s[1529476419] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[27]: s[0] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos_redis [topos_redis_storage.c:1008]: tps_redis_load_dialog(): r[29]: s[415ec07600838eb414117d5c66d67717@pbx.example.com] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_storage.c:136]: tps_storage_lock_release(): tps lock release: 213 Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:816]: tps_request_received(): r-uri updated to: [sip:+35890000002@10.20.234.47:5060;transport=TCP] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Route: sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr#015#012] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [P-SR-XUID: atpsh-5b29f51c-68b4-1#015#012] Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:604]: parse_msg(): SIP Request: Jun 20 09:33:57 edge3 /usr/local/sbin/kamailio[26395]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <BYE> ... <After this normal message parsing happens and BYE is routed to 10.20.234.47> ```
#### Log Messages
There is nothing related to this issue on normal logging.
#### SIP Traffic
Only event_route case is available, but basically it is the same case. ``` T 2018/06/20 06:42:59.980340 10.20.234.47:35408 -> 10.30.160.60:5060 [AP] INVITE sip:+358000000001@10.30.160.60 SIP/2.0. Via: SIP/2.0/TCP 10.20.234.47:5060;branch=z9hG4bK2ef81edd. Max-Forwards: 70. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60. Contact: sip:+358900000002@10.20.234.47:5060;transport=TCP. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. User-Agent: nmc. Date: Wed, 20 Jun 2018 06:42:59 GMT. Session-Expires: 1800. Min-SE: 90. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH. Supported: replaces, timer. P-Asserted-Identity: "Joonas Keskitalo" sip:+358900000002@pbx.example.com. Content-Type: application/sdp. Content-Length: 266. . v=0. o=noc 1822366190 1822366190 IN IP4 10.20.234.47. s=nmc. c=IN IP4 10.20.234.47. t=0 0. m=audio 18644 RTP/AVP 8 9 0 101. a=rtpmap:8 PCMA/8000. a=rtpmap:9 G722/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=ptime:20. a=sendrecv.
T 2018/06/20 06:43:00.005934 10.30.160.60:5060 -> 10.20.234.47:35408 [AP] SIP/2.0 100 trying -- your call is important to us. Via: SIP/2.0/TCP 10.20.234.47:5060;branch=z9hG4bK2ef81edd;rport=35408. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Server: kamailio (5.2.0-dev4 (x86_64/linux)). Content-Length: 0. .
U 2018/06/20 06:43:00.008814 10.30.160.60:5060 -> 10.20.234.25:5060 INVITE sip:+358000000001@10.20.234.25 SIP/2.0. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0;i=1. Max-Forwards: 69. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. User-Agent: nmc. Date: Wed, 20 Jun 2018 06:42:59 GMT. Session-Expires: 1800. Min-SE: 90. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH. Supported: replaces, timer. P-Asserted-Identity: "Joonas Keskitalo" sip:+358900000002@pbx.example.com. Content-Type: application/sdp. Content-Length: 266. P-hint: outbound. Contact: sip:btpsh-5b29f766-6a9d-1@10.30.160.60. . v=0. o=noc 1822366190 1822366190 IN IP4 10.20.234.47. s=nmc. c=IN IP4 10.20.234.47. t=0 0. m=audio 18644 RTP/AVP 8 9 0 101. a=rtpmap:8 PCMA/8000. a=rtpmap:9 G722/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=ptime:20. a=sendrecv.
U 2018/06/20 06:43:00.010152 10.20.234.25:5060 -> 10.30.160.60:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0;i=1. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Content-Length: 0. .
U 2018/06/20 06:43:03.101376 10.20.234.25:5060 -> 10.30.160.60:5060 SIP/2.0 183 Session Progress. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0;i=1. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Type: application/sdp. Content-Length: 251. Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,PRACK,UPDATE. . v=0. o=- 2372765 2372765 IN IP4 212.146.3.173. s=-. c=IN IP4 10.20.232.34. t=0 0. a=sendrecv. m=audio 10810 RTP/AVP 8 101. c=IN IP4 10.20.232.34. b=RR:0. b=RS:0. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=maxptime:40.
T 2018/06/20 06:43:03.105310 10.30.160.60:5060 -> 10.20.234.47:35408 [AP] SIP/2.0 183 Session Progress. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Type: application/sdp. Content-Length: 251. Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,PRACK,UPDATE. Via: SIP/2.0/TCP 10.20.234.47:5060;rport=35408;branch=z9hG4bK2ef81edd. Record-Route: sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr. P-SR-XBranch: z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0. . v=0. o=- 2372765 2372765 IN IP4 212.146.3.173. s=-. c=IN IP4 10.20.232.34. t=0 0. a=sendrecv. m=audio 10810 RTP/AVP 8 101. c=IN IP4 10.20.232.34. b=RR:0. b=RS:0. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=maxptime:40.
U 2018/06/20 06:43:04.030579 10.20.234.25:5060 -> 10.30.160.60:5060 SIP/2.0 180 Ringing. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0;i=1. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Length: 0. .
T 2018/06/20 06:43:04.034058 10.30.160.60:5060 -> 10.20.234.47:35408 [AP] SIP/2.0 180 Ringing. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Length: 0. Via: SIP/2.0/TCP 10.20.234.47:5060;rport=35408;branch=z9hG4bK2ef81edd. Record-Route: sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr. P-SR-XBranch: z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0. .
U 2018/06/20 06:43:07.037526 10.20.234.25:5060 -> 10.30.160.60:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0;i=1. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@212.146.3.173;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Type: application/sdp. Content-Length: 251. Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,PRACK,UPDATE. Accept: application/sdp. . v=0. o=- 2372765 2372765 IN IP4 212.146.3.173. s=-. c=IN IP4 10.20.232.34. t=0 0. a=sendrecv. m=audio 10810 RTP/AVP 8 101. c=IN IP4 10.20.232.34. b=RR:0. b=RS:0. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=maxptime:40.
T 2018/06/20 06:43:07.041369 10.30.160.60:5060 -> 10.20.234.47:35408 [AP] SIP/2.0 200 OK. To: sip:+358000000001@mrandom.example.com;user=phone;tag=h7g4Esbg_12001692187037. From: "Joonas Keskitalo" sip:+358900000002@212.146.3.173;tag=as0af8e4f1. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 INVITE. Contact: sip:sgc_c@212.146.3.173;transport=udp. Record-Route: sip:212.146.3.173;transport=udp;lr. Record-Route: sip:10.20.234.25;lr;pm. Content-Type: application/sdp. Content-Length: 251. Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,PRACK,UPDATE. Accept: application/sdp. Via: SIP/2.0/TCP 10.20.234.47:5060;rport=35408;branch=z9hG4bK2ef81edd. Record-Route: sip:10.30.160.60;r2=on;lr,sip:10.30.160.60;transport=tcp;r2=on;lr. P-SR-XBranch: z9hG4bK96cf.e1a6c393f0e655e25dec09a13d5463ab.0. . v=0. o=- 2372765 2372765 IN IP4 212.146.3.173. s=-. c=IN IP4 10.20.232.34. t=0 0. a=sendrecv. m=audio 10810 RTP/AVP 8 101. c=IN IP4 10.20.232.34. b=RR:0. b=RS:0. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=maxptime:40.
T 2018/06/20 06:43:07.042687 10.20.234.47:35408 -> 10.30.160.60:5060 [AP] ACK sip:sgc_c@212.146.3.173;transport=udp SIP/2.0. Via: SIP/2.0/TCP 10.20.234.47:5060;branch=z9hG4bK76432850. Route: sip:10.30.160.60;transport=tcp;r2=on;lr,sip:10.30.160.60;r2=on;lr,sip:10.20.234.25;lr;pm,sip:212.146.3.173;transport=udp;lr. Max-Forwards: 70. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60;tag=h7g4Esbg_12001692187037. Contact: sip:+358900000002@10.20.234.47:5060;transport=TCP. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 ACK. User-Agent: nmc. Content-Length: 0. .
U 2018/06/20 06:43:07.140001 10.30.160.60:5060 -> 10.20.234.25:5060 ACK sip:sgc_c@212.146.3.173;transport=udp SIP/2.0. Via: SIP/2.0/UDP 10.30.160.60;branch=z9hG4bK96cf.d1c298d0a34b6f6327f0e0c15abced89.0;i=1. Via: SIP/2.0/TCP 10.20.234.47:5060;rport=35408;branch=z9hG4bK76432850. Route: sip:10.20.234.25;lr;pm,sip:212.146.3.173;transport=udp;lr. Max-Forwards: 69. From: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. To: sip:+358000000001@10.30.160.60;tag=h7g4Esbg_12001692187037. Contact: sip:+358900000002@10.20.234.47:5060;transport=TCP. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 102 ACK. User-Agent: nmc. Content-Length: 0. .
U 2018/06/20 06:43:11.802426 10.20.234.25:5060 -> 10.30.160.60:5060 BYE sip:btpsh-5b29f766-6a9d-1@10.30.160.60 SIP/2.0. Max-Forwards: 68. Via: SIP/2.0/UDP 10.20.234.25;branch=z9hG4bK1ddd.efe198483f089826149438b9f015168d.0. Via: SIP/2.0/UDP 212.146.3.173:5060;branch=z9hG4bKiwfg921gzhgpevsckfsgwvhgs. To: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. From: sip:+358000000001@212.146.3.173;user=phone;tag=h7g4Esbg_12001692187037. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 1 BYE. Reason: Q.850;cause=16. Content-Length: 0. .
U 2018/06/20 06:43:11.806533 10.30.160.60:5060 -> 10.20.234.25:5060 SIP/2.0 404 Not here. Via: SIP/2.0/UDP 10.20.234.25;branch=z9hG4bK1ddd.efe198483f089826149438b9f015168d.0;rport=5060. Via: SIP/2.0/UDP 212.146.3.173:5060;branch=z9hG4bKiwfg921gzhgpevsckfsgwvhgs. To: "Joonas Keskitalo" sip:+358900000002@pbx.example.com;tag=as0af8e4f1. From: sip:+358000000001@212.146.3.173;user=phone;tag=h7g4Esbg_12001692187037. Call-ID: 02fc9c2217271d3b1195aa686164b509@pbx.example.com. CSeq: 1 BYE. Server: kamailio (5.2.0-dev4 (x86_64/linux)). Content-Length: 0. ```
### Possible Solutions
No idea
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.2.0-dev4 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 14:01:18 Mar 9 2018 with gcc 6.3.0 ```
* **Operating System**:
``` Linux edge3 4.9.0-6-amd64 #1 SMP Debian 4.9.82-1+deb9u3 (2018-03-02) x86_64 GNU/Linux ```
I tried the same with stable Kamailio version ``` # kamailio -v version: kamailio 5.1.4 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 08:12:48 Jun 20 2018 with gcc 6.3.0 ```
And noticed a small difference. Kamailio is trying to find `[b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:as34fa3a8d]` but when using kamailio 5.1.4 there is only `b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:h7g4Esbg_07000304592032`.
The difference between 5.2 and 5.1 is that in 5.2 there is nothing even close to that on redis and in 5.1 the tags seems to be switched.
On 183 Session progress and 180 Ringing: ``` Jun 20 13:09:53 edge3 /usr/local/sbin/kamailio[3686]: DEBUG: topos_redis [topos_redis_storage.c:363]: tps_redis_insert_invite_branch(): inserting branch record for [b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:h7g4Esbg_07000304592032] with argc 6 ``` On BYE: ``` Jun 20 13:10:11 edge3 /usr/local/sbin/kamailio[3689]: DEBUG: topos_redis [topos_redis_storage.c:610]: tps_redis_load_invite_branch(): loading branch record for [b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:as34fa3a8d] Jun 20 13:10:11 edge3 /usr/local/sbin/kamailio[3689]: DEBUG: ndb_redis [redis_client.c:878]: redisc_exec_argv(): rsrv->ctxRedis = 0x564c726d7e90 Jun 20 13:10:11 edge3 /usr/local/sbin/kamailio[3689]: DEBUG: topos_redis [topos_redis_storage.c:628]: tps_redis_load_invite_branch(): hmap with key [b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.comas34fa3a8d] not found ```
On SIP messages tags are as follows: Initial INVITE: ``` From: "UserName" sip:sip:user@domain.tld;tag=as34fa3a8d. To: sip:user@domain.tld. ``` 183 Session Progess: ``` From: "UserName" sip:sip:user@domain.tld;tag=as34fa3a8d. To: sip:user@domain.tld;tag=h7g4Esbg_07000304592032. ``` BYE message from receiving end: ``` From: sip:user@domain.tld;tag=h7g4Esbg_07000304592032. To: "UserName" sip:sip:user@domain.tld;tag=as34fa3a8d. ```
For speed reasons, the event_route was designed to allow testing only destination address and decide to do topos or not, meaning that all traffic with an ip is either with topos processing or without.
In your case I understand that you want calls initiated by Asterisk to be with topos, but not the calls towards Asterisk. This would require testing at a later point in topos processing, so this can be another event_route to get access to the SIP message and other related attributes, so this would be a feature request. It was somehow discussed when added the current event route, but the needs at that time were for address checking and the speed was considered relevant, otherwise is not something that complex to add.
If you want it, then open a new issue as a feature request.
Now here, I want to clarify your second comment, where I got it like you report a different behaviour between master and 5.1 branches, am I right? Is it a bug that you discovered? Not sure if the record was not found by topos_redis because you dropped topos for INVITE or there was some different scenario that you tried.
I think master and 5.1 branches should be the same from perspective of topos/topos_redis modules.
Thank you for your fast and clarifying response.
The problem here is that I simply can't use event_route to disable topos on calls destined to Asterisk since it will break every call made to another direction. That means that current event_route feature allows topos to be disabled but only if the SIP peers are for one-way traffic?
About my second comment on differences between branches, I noticed that for some reason when I tested with 5.2 I had different kind of keys on redis than on my tests on 5.1. The call scenario was exactly the same on both cases. I managed to reproduce this and I can't find the following log row on 5.2.0-dev4 kamailio at all: ``` Jun 20 13:09:53 edge3 /usr/local/sbin/kamailio[3686]: DEBUG: topos_redis [topos_redis_storage.c:363]: tps_redis_insert_invite_branch(): inserting branch record for [b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:h7g4Esbg_07000304592032] with argc 6 ``` which happens at kamailio 5.1.4.
Also only the following keys are present in redis when using 5.2.0-dev4: ``` 1) "d:z:atpsh-5b2a4f80-218-1" 2) "b:x:z9hG4bKb1d4.26a1938596920d3714191be44ad2684a.0" ```
When 5.1.4 had also `b:x:INVITE:1e004b4343c496750f1de6f156c779e8@pbx.example.com:h7g4Esbg_07000304592032`
Call case is the same, configuration is the same and all of the participants are the same. I only rebuilt kamailio and retried.
The request at that time was to disable traffic to a peer, you can search on the closed issues or pull requests here, the discussion was a while ago and the needs were limited to ip destination matching, with concerns to keep the speed of processing as fast as possible.
Is it 5.1.4 from tarball/packages or the git branch 5.1 that you are using? I will try to compare and see what is different between the two.
Ok, I will place a feature request on another event_route that can be called with full SIP headers so this problem can be then resolved via that.
I used the git branch 5.1 and master to rebuild between 5.1.4 and 5.2.0-dev4.
I looked at the code and the only significant difference between 5.1 and master branches for topos module is related to matching KDMQ method, so the behaviour should be the same.
I am closing this one, you said you are going to open another issue as feature request for a new event route.
Closed #1569.
-
Daniel-Constantin Mierla -
Joonas Keskitalo