[kamailio/kamailio] tm: TMCB_REQUEST_FWDED callbacks are always executed as ROUTE_REQUEST (#2141)
### Description
<Sipwise Hat on> We have a module that has tm callbacks of type TMCB_REQUEST_FWDED and it calls uac.replace_from API. I noticed that this call was failing in a forking scenario:
First branch: ``` Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f89149cf660, callback type 16, id 0 entered Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} pv_headers [pv_headers.c:413]: pv_apply_headers(): xavp->name:headers.0 br_xname:headers.0 keys_count: 21 Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} pv_headers [pv_headers.c:445]: pv_apply_headers(): replace_from[From]: sip:4311002@spce.test Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} uac [uac.c:489]: replace_from_api(): dsp=(nil) (len=0) , uri=0x7ffde172f250 (len=21) Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} uac [replace.c:361]: replace_uri(): uri to replace [sip:testuser1002@spce.test] Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} uac [replace.c:362]: replace_uri(): replacement uri is [sip:4311002@spce.test] Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} uac [replace.c:506]: replace_uri(): encode is=<aVBYbwMxODMSLiN6KQM7LQplW2h4fiwKMBM-> len=36 Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[0]} pv_headers [pv_headers.c:464]: pv_apply_headers(): skip unchanged To header ``` Second branch: ``` Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f89149cf660, callback type 16, id 0 entered Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} pv_headers [pv_headers.c:413]: pv_apply_headers(): xavp->name:headers.1 br_xname:headers.1 keys_count: 21 Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} pv_headers [pv_headers.c:445]: pv_apply_headers(): replace_from[From]: sip:4311002@spce.test Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} uac [uac.c:489]: replace_from_api(): dsp=(nil) (len=0) , uri=0x7ffde172f250 (len=21) Nov 20 16:24:59 spce proxy[28430]: ERROR: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} uac [replace.c:267]: replace_uri(): called uac_replace_from() multiple times on the message Nov 20 16:24:59 spce proxy[28430]: DEBUG: {1 NGCP%invite_q_forking%///1-28692@127.126.0.1[1]} pv_headers [pv_headers.c:464]: pv_apply_headers(): skip unchanged To header ```
### Possible solution allow TMCB_REQUEST_FWDED cb to be executed as BRANCH_ROUTE
After applying tm patch, no error in second call to uac.replace_from:
First branch: ``` Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} tm [t_fwd.c:379]: prepare_new_uac(): ++++++ calling cb TMCB_REQUEST_FWDED in BRANCH_ROUTE +++++ Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f5c4d1a82b0, callback type 16, id 0 entered Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} pv_headers [pv_headers.c:413]: pv_apply_headers(): xavp->name:headers.0 br_xname:headers.0 keys_count: 21 Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} pv_headers [pv_headers.c:445]: pv_apply_headers(): replace_from[From]: sip:4311002@spce.test Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} uac [uac.c:489]: replace_from_api(): dsp=(nil) (len=0) , uri=0x7ffd6238a180 (len=21) Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} uac [replace.c:361]: replace_uri(): uri to replace [sip:testuser1002@spce.test] Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} uac [replace.c:362]: replace_uri(): replacement uri is [sip:4311002@spce.test] Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[0]} uac [replace.c:506]: replace_uri(): encode is=<aVBYbwMxODMSLiN6KQM7LQplW2h4fiwKMBM-> len=36 ``` Second branch: ``` Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} tm [t_fwd.c:379]: prepare_new_uac(): ++++++ calling cb TMCB_REQUEST_FWDED in BRANCH_ROUTE +++++ Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} tm [t_hooks.c:258]: run_trans_callbacks_internal(): DBG: trans=0x7f5c4d1a82b0, callback type 16, id 0 entered Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} pv_headers [pv_headers.c:413]: pv_apply_headers(): xavp->name:headers.1 br_xname:headers.1 keys_count: 21 Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} pv_headers [pv_headers.c:445]: pv_apply_headers(): replace_from[From]: sip:4311002@spce.test Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} uac [uac.c:489]: replace_from_api(): dsp=(nil) (len=0) , uri=0x7ffd6238a180 (len=21) Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} uac [replace.c:361]: replace_uri(): uri to replace [sip:testuser1002@spce.test] Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} uac [replace.c:362]: replace_uri(): replacement uri is [sip:4311002@spce.test] Nov 21 07:52:42 spce proxy[3502]: DEBUG: {1 NGCP%invite_q_forking%///1-3785@127.126.0.1[1]} uac [replace.c:506]: replace_uri(): encode is=<aVBYbwMxODMSLiN6KQM7LQplW2h4fiwKMBM-> len=36 ```
@miconda Is there any drawbacks with that fix approach?
I think it is ok, the TMCB_REQUEST_FWDED callback seems to be used only by dialog module for dmq replication.
Thanks!
Closed #2141.
-
Daniel-Constantin Mierla -
Victor Seva