git:master:d6b1c20d: tm: restore X/AVP values from initial transaction in DNS failover processing
9 Aug
2022
9 Aug
'22
10:16 a.m.
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL: https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover processing
- restore X/AVP values from initial transaction in DNS failover processing
- the X/AVP context gets lost, so we need to re-create it from the transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c
index fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
11 Aug
11 Aug
4:46 a.m.
Hello,
I haven't looked in the code to try to figure out the execution paths to
this function and where ends up afterwards, so more for safety: have you
checked that there are no other X/AVPs set at that moment, or if they
are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in
order to be sure it does not end up in memory leaks (or the old ones
have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover processing
- restore X/AVP values from initial transaction in DNS failover processing
- the X/AVP context gets lost, so we need to re-create it from the transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67b7fc0…
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c
index fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List
sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
9:30 a.m.
Hi Daniel,
Thanks for the feedback. I have done a lot of tests on my setup, but of course it’s a
complicated module.
The relevant function part is called when the DNS failover is executed, to my
understanding like this:
1. INVITE is sent to proxy (auth challenge etc..)
2. proxy is sending to DNS domain
3. DNS domain is resolved to two A records, first IP is chosen
4. proxy sends INVITE to first IP
5. IP does not reply, tm timeout is triggered
6. X/AVP context gets lost, probably due to cleanup from core (this will cleanup internal
X/AVP list)
7. add_uac_dns_fallback function is executed, restore X/AVP list from transaction
8. INVITE is sent to second IP
9. Call is established
10. Cleanup is done again to delete internal X/AVP list
See below for an example call log with added local debugging before the fix. TM timeout is
5s.
First INVITE:
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e9570, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: set XAVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2 from
customer group 0 (116.203.XX.XX)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2 from customer
group 0 (116.203.XX.XX)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]: xavu_reset_list():
resetting list
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:244]: t_relay_to(): 1
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [h_table.c:373]: build_cell(): setting list in
new context
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:344]:
run_reqin_callbacks_internal(): backup AVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:360]:
run_reqin_callbacks_internal(): restore backup AVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:289]: t_relay_to(): 2: T
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:342]: t_relay_to(): 3: T
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1642]: t_forward_nonack(): 1, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1690]: t_forward_nonack(): 2, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1776]: t_forward_nonack(): 3, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name a_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]:
xavu_reset_list(): resetting list
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]: receive_msg():
cleaning up
DNS failover:
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO: <core>
[core/xavp.c:1222]: xavu_reset_list(): resetting list
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO: <core>
[core/receive.c:628]: receive_msg(): cleaning up
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[h_table.c:132]: free_cell_helper(): freeing transaction 0x7fc9a041b288 from timer.c:650
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:247]: run_trans_callbacks_internal(): backup AVPs
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a041b4c0
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:269]: run_trans_callbacks_internal(): restore backup AVPs
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x561157559088
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm
[t_fwd.c:1012]: add_uac_dns_fallback(): 1: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm
[t_fwd.c:1047]: add_uac_dns_fallback(): 2: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0
(Print the transaction X/AVP list below)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a041ebb0
(0x7fc9a0421c68) (level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) XAVU name:
_tps_
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 1420310448
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 6
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:717]: xavx_print_list_content(): XAVU value:
<xavp:0x7fc9a0421428>
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a0421428
(0x7fc9a041ebd0) (level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) XAVU name:
b_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3522184920
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_b
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) XAVU name:
a_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3511692759
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_a
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a0421428
(level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a041ebb0
(level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1559]: xavu_get_child(): ravp (nil), xavu current list 0x561157559088
(Topos does not find any AVPs)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:331]: tps_storage_fill_contact(): could not evaluate a_contact xavu
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:615]: tps_storage_record(): failed to store
For completeness here a successful call after the fix, here the trace shows that the
cleanup is called after every INVITE (only added one log to the cleanup):
First INVITE:
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]: INFO: {2 14468
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 407 - Proxy
Authentication Required in reply_route
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]: ERROR: {2 14468
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: ERROR: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
DNS Failover:
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 - trying --
your call is important to us in reply_route
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: routing out
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed INVITE to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with udp:116.203.YY.YY:5060
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30657]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 - Trying in
reply_route
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30657]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30658]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 - Decline in
reply_route
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30658]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed ACK to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with udp:116.203.YY.YY:5060
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30641]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 - Decline in
reply_route
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30641]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 10:47 AM
To: Kamailio (SER) - Development Mailing List <sr-dev(a)lists.kamailio.org>rg>; Henning
Westerholt <hw(a)gilawa.com>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hello,
I haven't looked in the code to try to figure out the execution paths to this function
and where ends up afterwards, so more for safety: have you checked that there are no other
X/AVPs set at that moment, or if they are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in order to be sure it
does not end up in memory leaks (or the old ones have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover
processing
- restore X/AVP values from initial transaction in DNS failover
processing
- the X/AVP context gets lost, so we need to re-create it from the
transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding
will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.diff
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.patch
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c index
fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
9:33 a.m.
The line-breaks got mangled from the copy and paste, sorry for that. Let me know if you
like to get the files as attachment.
Cheers,
Henning
-----Original Message-----
From: Henning Westerholt
Sent: Thursday, August 11, 2022 3:31 PM
To: miconda(a)gmail.com; Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>
Subject: RE: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hi Daniel,
Thanks for the feedback. I have done a lot of tests on my setup, but of course it’s a
complicated module.
The relevant function part is called when the DNS failover is executed, to my
understanding like this:
1. INVITE is sent to proxy (auth challenge etc..) 2. proxy is sending to DNS domain 3. DNS
domain is resolved to two A records, first IP is chosen 4. proxy sends INVITE to first IP
5. IP does not reply, tm timeout is triggered 6. X/AVP context gets lost, probably due to
cleanup from core (this will cleanup internal X/AVP list) 7. add_uac_dns_fallback function
is executed, restore X/AVP list from transaction 8. INVITE is sent to second IP 9. Call is
established 10. Cleanup is done again to delete internal X/AVP list
See below for an example call log with added local debugging before the fix. TM timeout is
5s.
[...]
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/ Kamailio services – https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 10:47 AM
To: Kamailio (SER) - Development Mailing List <sr-dev(a)lists.kamailio.org>rg>; Henning
Westerholt <hw(a)gilawa.com>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hello,
I haven't looked in the code to try to figure out the execution paths to this function
and where ends up afterwards, so more for safety: have you checked that there are no other
X/AVPs set at that moment, or if they are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in order to be sure it
does not end up in memory leaks (or the old ones have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover
processing
- restore X/AVP values from initial transaction in DNS failover
processing
- the X/AVP context gets lost, so we need to re-create it from the
transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding
will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.diff
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.patch
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c index
fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
1:39 p.m.
Hello,
my concert was related to what happens between 5/6 and 7. If it is a udp
retransmission timeout, then 7 is done in (another) timer process. If it
is tcp/tls connect timeout, it can be another worker (?!?) process. Then
I am not sure if any branch failure route could get executed (I think
there is something on tracker about it or on list discussions) before
add_uac_dns_fallback() where one can add x/avps.
What I wanted to cover is that when the tm x/avps are set back, in the
eventuality that there were other x/avps set in the global core lists,
they are not lost, either by freeing them or restore them after the does
the work related to next address in the DNS-based re-routing.
Usually, doing a x/avps swap should be followed by a swap back to
initial lists. However, in this case could be the case that the core
lists are null always, but I wanted to check if you analysed that and it
is so. Otherwise, maybe just calling ksr_msg_env_reset() before the swap
would make it sure there is no leak and the future will tell if
something else got side effects by losing eventual existing x/avps.
Cheers,
Daniel
On 11.08.22 15:30, Henning Westerholt wrote:
Hi Daniel,
Thanks for the feedback. I have done a lot of tests on my setup, but of course it’s a
complicated module.
The relevant function part is called when the DNS failover is executed, to my
understanding like this:
1. INVITE is sent to proxy (auth challenge etc..)
2. proxy is sending to DNS domain
3. DNS domain is resolved to two A records, first IP is chosen
4. proxy sends INVITE to first IP
5. IP does not reply, tm timeout is triggered
6. X/AVP context gets lost, probably due to cleanup from core (this will cleanup internal
X/AVP list)
7. add_uac_dns_fallback function is executed, restore X/AVP list from transaction
8. INVITE is sent to second IP
9. Call is established
10. Cleanup is done again to delete internal X/AVP list
See below for an example call log with added local debugging before the fix. TM timeout
is 5s.
First INVITE:
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e9570, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: set XAVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2 from
customer group 0 (116.203.XX.XX)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2 from customer
group 0 (116.203.XX.XX)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]: xavu_reset_list():
resetting list
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:244]: t_relay_to(): 1
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [h_table.c:373]: build_cell(): setting list in
new context
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:344]:
run_reqin_callbacks_internal(): backup AVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:360]:
run_reqin_callbacks_internal(): restore backup AVPs
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]: xavu_set_list():
setting list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:289]: t_relay_to(): 2: T
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:342]: t_relay_to(): 3: T
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1642]: t_forward_nonack(): 1, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1690]: t_forward_nonack(): 2, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1776]: t_forward_nonack(): 3, T:
0x7fc9a0421a30, XAVU 0x7fc9a041ebb0
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name a_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list 0x7fc9a0421c68
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]:
xavu_reset_list(): resetting list
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]: receive_msg():
cleaning up
DNS failover:
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO: <core>
[core/xavp.c:1222]: xavu_reset_list(): resetting list
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO: <core>
[core/receive.c:628]: receive_msg(): cleaning up
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[h_table.c:132]: free_cell_helper(): freeing transaction 0x7fc9a041b288 from timer.c:650
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:247]: run_trans_callbacks_internal(): backup AVPs
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a041b4c0
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:269]: run_trans_callbacks_internal(): restore backup AVPs
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x561157559088
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm
[t_fwd.c:1012]: add_uac_dns_fallback(): 1: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm
[t_fwd.c:1047]: add_uac_dns_fallback(): 2: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0
(Print the transaction X/AVP list below)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a041ebb0
(0x7fc9a0421c68) (level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) XAVU name:
_tps_
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 1420310448
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 6
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:717]: xavx_print_list_content(): XAVU value:
<xavp:0x7fc9a0421428>
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a0421428
(0x7fc9a041ebd0) (level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) XAVU name:
b_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3522184920
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_b
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) XAVU name:
a_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3511692759
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_a
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a0421428
(level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a041ebb0
(level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv (nil)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1559]: xavu_get_child(): ravp (nil), xavu current list 0x561157559088
(Topos does not find any AVPs)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:331]: tps_storage_fill_contact(): could not evaluate a_contact xavu
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:615]: tps_storage_record(): failed to store
For completeness here a successful call after the fix, here the trace shows that the
cleanup is called after every INVITE (only added one log to the cleanup):
First INVITE:
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]: INFO: {2 14468
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 407 - Proxy
Authentication Required in reply_route
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]: ERROR: {2 14468
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: ERROR: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
DNS Failover:
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 - trying --
your call is important to us in reply_route
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: routing out
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed INVITE to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with udp:116.203.YY.YY:5060
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30657]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 - Trying in
reply_route
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30657]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30658]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 - Decline in
reply_route
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30658]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed ACK to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with udp:116.203.YY.YY:5060
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30641]: INFO: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 - Decline in
reply_route
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30641]: ERROR: {2 14469
INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]: receive_msg():
cleaning up
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 10:47 AM
To: Kamailio (SER) - Development Mailing List <sr-dev(a)lists.kamailio.org>rg>; Henning
Westerholt <hw(a)gilawa.com>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hello,
I haven't looked in the code to try to figure out the execution paths to this
function and where ends up afterwards, so more for safety: have you checked that there are
no other X/AVPs set at that moment, or if they are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in order to be sure
it does not end up in memory leaks (or the old ones have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover
processing
- restore X/AVP values from initial transaction in DNS failover
processing
- the X/AVP context gets lost, so we need to re-create it from the
transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding
will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.diff
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e67
b7fc0d32b18d3b.patch
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c index
fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
14 Aug
14 Aug
5:22 a.m.
Hi Daniel,
I will have another look/test run in the next days. So far its only in git master.
In my tests I saw that the XAVP lists are always null, but this was of course on a test
system.
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 7:39 PM
To: Henning Westerholt <hw(a)gilawa.com>om>; Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hello,
my concert was related to what happens between 5/6 and 7. If it is a udp retransmission
timeout, then 7 is done in (another) timer process. If it is tcp/tls connect timeout, it
can be another worker (?!?) process. Then I am not sure if any branch failure route could
get executed (I think there is something on tracker about it or on list discussions)
before
add_uac_dns_fallback() where one can add x/avps.
What I wanted to cover is that when the tm x/avps are set back, in the eventuality that
there were other x/avps set in the global core lists, they are not lost, either by freeing
them or restore them after the does the work related to next address in the DNS-based
re-routing.
Usually, doing a x/avps swap should be followed by a swap back to initial lists. However,
in this case could be the case that the core lists are null always, but I wanted to check
if you analysed that and it is so. Otherwise, maybe just calling ksr_msg_env_reset()
before the swap would make it sure there is no leak and the future will tell if something
else got side effects by losing eventual existing x/avps.
Cheers,
Daniel
On 11.08.22 15:30, Henning Westerholt wrote:
Hi Daniel,
Thanks for the feedback. I have done a lot of tests on my setup, but of course it’s a
complicated module.
The relevant function part is called when the DNS failover is executed, to my
understanding like this:
1. INVITE is sent to proxy (auth challenge etc..) 2. proxy is sending
to DNS domain 3. DNS domain is resolved to two A records, first IP is
chosen 4. proxy sends INVITE to first IP 5. IP does not reply, tm
timeout is triggered 6. X/AVP context gets lost, probably due to
cleanup from core (this will cleanup internal X/AVP list) 7.
add_uac_dns_fallback function is executed, restore X/AVP list from
transaction 8. INVITE is sent to second IP 9. Call is established 10.
Cleanup is done again to delete internal X/AVP list
See below for an example call log with added local debugging before the fix. TM timeout
is 5s.
First INVITE:
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: got
request INVITE to sip:customer-2@sip01.tst.nbg.domain.net from
116.203.XX.XX:5095 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil) Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil) Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e9570, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: set
XAVPs Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2
from customer group 0 (116.203.XX.XX) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2
from customer group 0 (116.203.XX.XX) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]:
xavu_reset_list(): resetting list Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:244]: t_relay_to(): 1
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm
[h_table.c:373]: build_cell(): setting list in new context Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a0421c68 Aug
9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:344]:
run_reqin_callbacks_internal(): backup AVPs Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:360]:
run_reqin_callbacks_internal(): restore backup AVPs Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:289]: t_relay_to(): 2:
T 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:342]: t_relay_to(): 3:
T 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1642]:
t_forward_nonack(): 1, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1690]:
t_forward_nonack(): 2, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1776]:
t_forward_nonack(): 3, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name a_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1222]: xavu_reset_list(): resetting list Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]:
receive_msg(): cleaning up
DNS failover:
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]:
INFO: <core> [core/xavp.c:1222]: xavu_reset_list(): resetting list Aug
9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO:
<core> [core/receive.c:628]: receive_msg(): cleaning up Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO:
tm [h_table.c:132]: free_cell_helper(): freeing transaction
0x7fc9a041b288 from timer.c:650 Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:247]: run_trans_callbacks_internal(): backup AVPs Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO:
<core> [core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a041b4c0 Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm [t_hooks.c:269]:
run_trans_callbacks_internal(): restore backup AVPs Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x561157559088 Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm [t_fwd.c:1012]:
add_uac_dns_fallback(): 1: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0 Aug 9 09:56:14
kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm [t_fwd.c:1047]:
add_uac_dns_fallback(): 2: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0 (Print the
transaction X/AVP list below) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core> [core/xavp.c:689]:
xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a041ebb0 (0x7fc9a0421c68)
(level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) XAVU name:
_tps_
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 1420310448
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 6
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:717]: xavx_print_list_content(): XAVU value:
<xavp:0x7fc9a0421428>
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a0421428
(0x7fc9a041ebd0) (level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) XAVU name:
b_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3522184920
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_b
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) XAVU name:
a_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3511692759
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_a
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a0421428
(level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]:
INFO: <core> [core/xavp.c:733]: xavx_print_list_content(): ----- end
XAVU list: 0x7fc9a041ebb0 (level=0) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1559]: xavu_get_child(): ravp (nil), xavu current list
0x561157559088 (Topos does not find any AVPs) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:331]: tps_storage_fill_contact(): could not evaluate
a_contact xavu Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:615]: tps_storage_record(): failed to store
For completeness here a successful call after the fix, here the trace shows that the
cleanup is called after every INVITE (only added one log to the cleanup):
First INVITE:
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]:
INFO: {2 14468 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
incoming reply 407 - Proxy Authentication Required in reply_route Aug
11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]:
ERROR: {2 14468 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up Aug 11 13:05:00 kam01
/usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO:
{1 14468 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]:
ERROR: {1 14468 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up Aug 11 13:05:00 kam01
/usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO:
{1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]:
ERROR: {1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up
DNS Failover:
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]:
INFO: {2 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
incoming reply 100 - trying -- your call is important to us in
reply_route Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30643]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060 Aug 11
13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO:
{1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]:
ERROR: {1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
routing out Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed INVITE to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with
udp:116.203.YY.YY:5060 Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30657]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 -
Trying in reply_route Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30657]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30658]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 -
Decline in reply_route Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30658]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060 Aug 11
13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO:
{1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]:
INFO: {1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed
ACK to sip:customer-2@116.203.XX.XX:5066;ob over <null> with
udp:116.203.YY.YY:5060 Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30640]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30641]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 -
Decline in reply_route Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30641]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO:
{1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]:
ERROR: {1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/ Kamailio services –
https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 10:47 AM
To: Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>rg>; Henning Westerholt <hw(a)gilawa.com>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values
from initial transaction in DNS failover processing
Hello,
I haven't looked in the code to try to figure out the execution paths to this
function and where ends up afterwards, so more for safety: have you checked that there are
no other X/AVPs set at that moment, or if they are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in order to be sure
it does not end up in memory leaks (or the old ones have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover
processing
- restore X/AVP values from initial transaction in DNS failover
processing
- the X/AVP context gets lost, so we need to re-create it from the
transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding
will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b.diff
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b.patch
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c index
fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
19 Aug
19 Aug
9:36 a.m.
Hi Daniel,
I have added a backup/restore approach to the tm for this particular problem.
Please refer to commit 399b34c6bd4e5cbf.
I have moved the logic to the timer function for this particular case, where the impact
should be also smaller as the previous location.
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: sr-dev <sr-dev-bounces(a)lists.kamailio.org> On Behalf Of Henning Westerholt
Sent: Sunday, August 14, 2022 11:23 AM
To: miconda(a)gmail.com; Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hi Daniel,
I will have another look/test run in the next days. So far its only in git master.
In my tests I saw that the XAVP lists are always null, but this was of course on a test
system.
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/ Kamailio services – https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 7:39 PM
To: Henning Westerholt <hw(a)gilawa.com>om>; Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values from initial
transaction in DNS failover processing
Hello,
my concert was related to what happens between 5/6 and 7. If it is a udp retransmission
timeout, then 7 is done in (another) timer process. If it is tcp/tls connect timeout, it
can be another worker (?!?) process. Then I am not sure if any branch failure route could
get executed (I think there is something on tracker about it or on list discussions)
before
add_uac_dns_fallback() where one can add x/avps.
What I wanted to cover is that when the tm x/avps are set back, in the eventuality that
there were other x/avps set in the global core lists, they are not lost, either by freeing
them or restore them after the does the work related to next address in the DNS-based
re-routing.
Usually, doing a x/avps swap should be followed by a swap back to initial lists. However,
in this case could be the case that the core lists are null always, but I wanted to check
if you analysed that and it is so. Otherwise, maybe just calling ksr_msg_env_reset()
before the swap would make it sure there is no leak and the future will tell if something
else got side effects by losing eventual existing x/avps.
Cheers,
Daniel
On 11.08.22 15:30, Henning Westerholt wrote:
Hi Daniel,
Thanks for the feedback. I have done a lot of tests on my setup, but of course it’s a
complicated module.
The relevant function part is called when the DNS failover is executed, to my
understanding like this:
1. INVITE is sent to proxy (auth challenge etc..) 2. proxy is sending
to DNS domain 3. DNS domain is resolved to two A records, first IP is
chosen 4. proxy sends INVITE to first IP 5. IP does not reply, tm
timeout is triggered 6. X/AVP context gets lost, probably due to
cleanup from core (this will cleanup internal X/AVP list) 7.
add_uac_dns_fallback function is executed, restore X/AVP list from
transaction 8. INVITE is sent to second IP 9. Call is established 10.
Cleanup is done again to delete internal X/AVP list
See below for an example call log with added local debugging before the fix. TM timeout
is 5s.
First INVITE:
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: got
request INVITE to sip:customer-2@sip01.tst.nbg.domain.net from
116.203.XX.XX:5095 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil) Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name _tps_, list (nil), prv (nil) Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e9570, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: set
XAVPs Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2
from customer group 0 (116.203.XX.XX) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <script>: received call customer-2
from customer group 0 (116.203.XX.XX) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1222]:
xavu_reset_list(): resetting list Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24655]: INFO: {1 14601 ACK
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:244]: t_relay_to(): 1
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm
[h_table.c:373]: build_cell(): setting list in new context Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a0421c68 Aug
9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:344]:
run_reqin_callbacks_internal(): backup AVPs Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_hooks.c:360]:
run_reqin_callbacks_internal(): restore backup AVPs Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:289]: t_relay_to(): 2:
T 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_funcs.c:342]: t_relay_to(): 3:
T 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1642]:
t_forward_nonack(): 1, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1690]:
t_forward_nonack(): 2, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} tm [t_fwd.c:1776]:
t_forward_nonack(): 3, T: 0x7fc9a0421a30, XAVU 0x7fc9a041ebb0 Aug 9
09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO:
{1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name a_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name b_contact, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1559]:
xavu_get_child(): ravp 0x7fc9a041ebb0, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1562]:
xavu_get_child(): ravp 0x7fc9a041ebb0, type 6, xavu current list
0x7fc9a0421c68 Aug 9 09:56:09 kam01
/usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602 INVITE
Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/xavp.c:1258]:
xavu_get_internal(): name contact_host, list 0x7ffd5e5e11f0, prv (nil)
Aug 9 09:56:09 kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]:
INFO: {1 14602 INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core>
[core/xavp.c:1222]: xavu_reset_list(): resetting list Aug 9 09:56:09
kam01 /usr/local/kamailio-devel/sbin/kamailio[24652]: INFO: {1 14602
INVITE Kt5POLYd9pvtxqx1idXSgNqZ4OFkSxOS} <core> [core/receive.c:628]:
receive_msg(): cleaning up
DNS failover:
Aug 9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]:
INFO: <core> [core/xavp.c:1222]: xavu_reset_list(): resetting list Aug
9 09:56:11 kam01 /usr/local/kamailio-devel/sbin/kamailio[24672]: INFO:
<core> [core/receive.c:628]: receive_msg(): cleaning up Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO:
tm [h_table.c:132]: free_cell_helper(): freeing transaction
0x7fc9a041b288 from timer.c:650 Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm
[t_hooks.c:247]: run_trans_callbacks_internal(): backup AVPs Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO:
<core> [core/xavp.c:1236]: xavu_set_list(): setting list 0x7fc9a041b4c0 Aug 9
09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: tm [t_hooks.c:269]:
run_trans_callbacks_internal(): restore backup AVPs Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24665]: INFO: <core> [core/xavp.c:1236]:
xavu_set_list(): setting list 0x561157559088 Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm [t_fwd.c:1012]:
add_uac_dns_fallback(): 1: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0 Aug 9 09:56:14
kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: tm [t_fwd.c:1047]:
add_uac_dns_fallback(): 2: T 0x7fc9a0421a30, XAVU list 0x7fc9a041ebb0 (Print the
transaction X/AVP list below) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core> [core/xavp.c:689]:
xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a041ebb0 (0x7fc9a0421c68)
(level=0)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) XAVU name:
_tps_
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 1420310448
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 6
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:717]: xavx_print_list_content(): XAVU value:
<xavp:0x7fc9a0421428>
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:689]: xavx_print_list_content(): +++++ start XAVU list: 0x7fc9a0421428
(0x7fc9a041ebd0) (level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) XAVU name:
b_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3522184920
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_b
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a0421428) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:693]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) XAVU name:
a_contact
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:694]: xavx_print_list_content(): XAVU id: 3511692759
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:695]: xavx_print_list_content(): XAVU value type: 2
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:704]: xavx_print_list_content(): XAVU value (str): sbc_a
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:1 - 0x7fc9a041eb00) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:733]: xavx_print_list_content(): ----- end XAVU list: 0x7fc9a0421428
(level=1)
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:730]: xavx_print_list_content(): *** (l:0 - 0x7fc9a041ebb0) end
Aug 9 09:56:14 kam01 /usr/local/kamailio-devel/sbin/kamailio[24664]:
INFO: <core> [core/xavp.c:733]: xavx_print_list_content(): ----- end
XAVU list: 0x7fc9a041ebb0 (level=0) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1258]: xavu_get_internal(): name _tps_, list (nil), prv
(nil) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: INFO: <core>
[core/xavp.c:1559]: xavu_get_child(): ravp (nil), xavu current list
0x561157559088 (Topos does not find any AVPs) Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:331]: tps_storage_fill_contact(): could not evaluate
a_contact xavu Aug 9 09:56:14 kam01
/usr/local/kamailio-devel/sbin/kamailio[24664]: ERROR: topos
[tps_storage.c:615]: tps_storage_record(): failed to store
For completeness here a successful call after the fix, here the trace shows that the
cleanup is called after every INVITE (only added one log to the cleanup):
First INVITE:
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]:
INFO: {2 14468 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
incoming reply 407 - Proxy Authentication Required in reply_route Aug
11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30646]:
ERROR: {2 14468 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up Aug 11 13:05:00 kam01
/usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14468 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO:
{1 14468 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]:
ERROR: {1 14468 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up Aug 11 13:05:00 kam01
/usr/local/kamailio-devel/sbin/kamailio[30661]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]: INFO:
{1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:00 kam01 /usr/local/kamailio-devel/sbin/kamailio[30661]:
ERROR: {1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up
DNS Failover:
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30643]:
INFO: {2 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
incoming reply 100 - trying -- your call is important to us in
reply_route Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30643]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request INVITE to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060 Aug 11
13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]: INFO:
{1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs
Aug 11 13:05:05 kam01 /usr/local/kamailio-devel/sbin/kamailio[30642]:
ERROR: {1 14469 INVITE Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>:
routing out Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: INFO: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed INVITE to
sip:customer-2@116.203.XX.XX:5066;ob over <null> with
udp:116.203.YY.YY:5060 Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30642]: ERROR: {1 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30657]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 100 -
Trying in reply_route Aug 11 13:05:05 kam01
/usr/local/kamailio-devel/sbin/kamailio[30657]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30658]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 -
Decline in reply_route Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30658]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30640]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@116.203.XX.XX:5066;ob from 116.203.YY.YY:5060 Aug 11
13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]: INFO:
{1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30640]:
INFO: {1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: relayed
ACK to sip:customer-2@116.203.XX.XX:5066;ob over <null> with
udp:116.203.YY.YY:5060 Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30640]: ERROR: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30641]: INFO: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: incoming reply 603 -
Decline in reply_route Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30641]: ERROR: {2 14469 INVITE
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core> [core/receive.c:628]:
receive_msg(): cleaning up Aug 11 13:05:07 kam01
/usr/local/kamailio-devel/sbin/kamailio[30659]: INFO: {1 14469 ACK
Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: got request ACK to
sip:customer-2@sip01.tst.nbg.domain.net from 116.203.XX.XX:5095 Aug 11
13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]: INFO:
{1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <script>: set XAVPs Aug
11 13:05:07 kam01 /usr/local/kamailio-devel/sbin/kamailio[30659]:
ERROR: {1 14469 ACK Y0VBO45pTjq3fmfpSLGngyq2F6UMaR5f} <core>
[core/receive.c:628]: receive_msg(): cleaning up
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/ Kamailio services –
https://gilawa.com
-----Original Message-----
From: Daniel-Constantin Mierla <miconda(a)gmail.com>
Sent: Thursday, August 11, 2022 10:47 AM
To: Kamailio (SER) - Development Mailing List
<sr-dev(a)lists.kamailio.org>rg>; Henning Westerholt <hw(a)gilawa.com>
Subject: Re: [sr-dev] git:master:d6b1c20d: tm: restore X/AVP values
from initial transaction in DNS failover processing
Hello,
I haven't looked in the code to try to figure out the execution paths to this
function and where ends up afterwards, so more for safety: have you checked that there are
no other X/AVPs set at that moment, or if they are they are restored later?
Usually when setting x/avps lists, the old ones have to be restored in order to be sure
it does not end up in memory leaks (or the old ones have to be cleaned up).
Cheers,
Daniel
On 09.08.22 16:16, Henning Westerholt wrote:
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
Module: kamailio
Branch: master
Commit: d6b1c20d3ad94d9136cf247e67b7fc0d32b18d3b
URL:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b
Author: Henning Westerholt <hw(a)gilawa.com>
Committer: Henning Westerholt <hw(a)gilawa.com>
Date: 2022-08-09T14:11:59Z
tm: restore X/AVP values from initial transaction in DNS failover
processing
- restore X/AVP values from initial transaction in DNS failover
processing
- the X/AVP context gets lost, so we need to re-create it from the
transaction
- otherwise modules that depends on the X/AVPs, e.g. topology hiding
will not work
- tested with one load-balancer and two proxy servers
---
Modified: src/modules/tm/t_fwd.c
---
Diff:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b.diff
Patch:
https://github.com/kamailio/kamailio/commit/d6b1c20d3ad94d9136cf247e6
7
b7fc0d32b18d3b.patch
---
diff --git a/src/modules/tm/t_fwd.c b/src/modules/tm/t_fwd.c index
fbcf1b3e02..6b26f28f6a 100644
--- a/src/modules/tm/t_fwd.c
+++ b/src/modules/tm/t_fwd.c
@@ -1042,6 +1042,8 @@ int add_uac_dns_fallback(struct cell *t, struct sip_msg* msg,
t->uac[t->nr_of_outgoings].on_branch_failure = old_uac->on_branch_failure;
/* copy branch flags */
t->uac[t->nr_of_outgoings].branch_flags = old_uac->branch_flags;
+ /* restore X/AVP values from initial transaction */
+ tm_xdata_swap(t, 0, 0);
if (cfg_get(tm, tm_cfg, reparse_on_dns_failover)){
/* Reuse the old buffer and only replace the via header.
_______________________________________________
Kamailio (SER) - Development Mailing List sr-dev(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda
863
days inactive
873
days old
6 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Henning Westerholt