amnapa created an issue (kamailio/kamailio#4205)
### Description
Using sCSCF sample found [here](https://github.com/kamailio/kamailio/blob/master/misc/examples/ims/scscf/kam...), after calling ims_www_challenge in REGISTER route block and sending a Diameter MAR request, the control is never passed to REG_MAR_REPLY route block and debug messages within REG_MAR_REPLY are not logged. This is not the case with REG_SAR_REPLY and PRE_REG_SAR_REPLY, those blocks are executed as expected.
``` ###################################################################### # Route for handling Registrations: ###################################################################### route[REGISTER] { xlog("ALGORITHM IS [$aa] and User-Agent is [$ua]\n"); $var(alg) = $aa; if ($aa == $null) { $var(alg) = "MD5"; #force to MD5 for zoiper.... non-ims } #!ifdef WITH_AUTH if (!ims_www_authenticate("$td")) { #!else if (($var(alg) == "MD5") && (!ims_www_authenticate("$td"))) { #!endif if ($? == -2) { send_reply("403", "Authentication Failed"); exit; } else if ($? == -3) { send_reply("400", "Bad Request"); exit; } else if ($? == -9) { xlog("L_DBG", "Authentication re-sync requested\n"); ims_www_resync_auth("REG_RESYNC_REPLY", "$td"); exit; } else { #user has not been authenticated. Lets send a challenge via 401 Unauthorized xlog("L_DBG", "About to challenge! auth_ims\n"); ims_www_challenge("REG_MAR_REPLY", "$td", "$var(alg)"); exit; } } else { xlog("L_DBG", "Auth succeeded\n"); # We need to check if this user is registered or not if (!impu_registered("location")) { xlog("L_ERR", "Not REGISTERED\n"); save("PRE_REG_SAR_REPLY", "location"); exit; } else { isc_match_filter_reg("1", "location"); save("REG_SAR_REPLY", "location"); exit; } } }
route[REG_MAR_REPLY] { #this is async so to know status we have to check the reply avp xlog("L_DBG", "maa_return code is $avp(s:maa_return_code)\n");
switch ($avp(s:maa_return_code)){ case 1: #success xlog("L_DBG", "MAR success - 401/407 response sent from module\n"); break; case -1: #failure xlog("L_ERR", "MAR failure - error response sent from module\n"); break; case -2: #error xlog("L_ERR", "MAR error - sending error response now\n"); send_reply("500", "MAR failed"); break; default: xlog("L_ERR", "Unknown return code from MAR, value is [$avp(s:maa_return_code)]\n"); send_reply("500", "Unknown response code from MAR"); break; } exit; } ```
### Troubleshooting
#### Reproduction
<!-- If the issue can be reproduced, describe how it can be done. -->
#### Debugging Data
``` (paste your debugging data here) ```
#### Log Messages
``` ERROR: *** cfgtrace:request_route=[REGISTER] c=[/usr/local/etc/kamailio/kamailio.cfg] l=712 a=27 n=ims_www_challenge DEBUG: ims_auth [authorize.c:290]: challenge(): Looking for route block [REG_MAR_REPLY] INFO: ims_auth [cxdx_mar.c:76]: create_return_code(): created AVP successfully : [maa_return_code] - [-2] DEBUG: ims_auth [authorize.c:314]: challenge(): Need to challenge for realm [ims.mnc072.mcc432.3gppnetwork.org] DEBUG: ims_auth [authorize.c:321]: challenge(): Checking if REGISTER is authorized for realm [ims.mnc072.mcc432.3gppnetwork.org]... DEBUG: ims_auth [authorize.c:1446]: get_auth_userdata(): Searching auth_userdata for IMPU sip:bob@ims.mnc072.mcc432.3gppnetwork.org (Hash 295) DEBUG: ims_auth [authorize.c:1455]: get_auth_userdata(): Found auth_userdata DEBUG: ims_auth [authorize.c:1061]: get_auth_vector(): looping through AV status is 3 and were looking for 0 DEBUG: tm [t_lookup.c:1343]: t_newtran(): msg (0x7f8d3f410cb0) id=1/11 global id=1/11 T start=(nil) DEBUG: tm [t_lookup.c:498]: t_lookup_request(): start searching: hash=21555, isACK=0 DEBUG: tm [t_lookup.c:456]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK3345.d6f2aff0d9192c2647aca3baea62cf94.1] DEBUG: tm [t_lookup.c:681]: t_lookup_request(): no transaction found DEBUG: tm [t_hooks.c:337]: run_reqin_callbacks_internal(): trans=0x7f8d2bff4520, callback type 1, id 0 entered DEBUG: ims_auth [authorize.c:457]: challenge(): Suspending SIP TM transaction DEBUG: ims_auth [authorize.c:1526]: multimedia_auth_request(): Sending MAR DEBUG: ims_auth [cxdx_mar.c:572]: cxdx_send_mar(): Successfully sent async diameter DEBUG: tm [t_lookup.c:1628]: t_lookup_ident_filter(): transaction found INFO: ims_auth [cxdx_avp.c:134]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0) DEBUG: ims_auth [authorize.c:1557]: pack_challenge(): setting QOP str used is [, qop="auth"] DEBUG: ims_auth [authorize.c:1559]: pack_challenge(): QOP str used is [, qop="auth"] DEBUG: tm [t_reply.c:1660]: cleanup_uac_timers(): RETR/FR timers reset DEBUG: tm [t_reply.c:595]: _reply_light(): reply sent out. buf=0x7f8d3f4120b8: SIP/2.0 401 Unauthor..., shmem=0x7f8d2bff9288: SIP/2.0 401 Unauthor DEBUG: tm [t_reply.c:606]: _reply_light(): finished DEBUG: ims_auth [authorize.c:1446]: get_auth_userdata(): Searching auth_userdata for IMPU sip:bob@ims.mnc072.mcc432.3gppnetwork.org (Hash 295) DEBUG: ims_auth [authorize.c:1455]: get_auth_userdata(): Found auth_userdata DEBUG: ims_auth [authorize.c:1679]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:bob@ims.mnc072.mcc432.3gppnetwork.org / IMPI bob@ims.mnc072.mcc432.3gppnetwork.org (Hash 295) DEBUG: ims_auth [cxdx_mar.c:483]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction INFO: ims_auth [cxdx_mar.c:76]: create_return_code(): created AVP successfully : [maa_return_code] - [1] DEBUG: ims_auth [cxdx_mar.c:495]: async_cdp_callback(): Destroying current transaction prevented! DEBUG: tm [t_lookup.c:1620]: t_lookup_ident_filter(): transaction in terminated phase - skipping ERROR: tm [t_suspend.c:196]: t_continue_helper(): active transaction not found DEBUG: ims_auth [cxdx_mar.c:84]: free_saved_transaction_data(): Freeing saved transaction data: async
```
#### SIP Traffic
``` (paste your sip traffic here) ```
### Possible Solutions
The issue is related to ims_auth module, in [cxdx_mar.c ](https://github.com/kamailio/kamailio/blob/master/src/modules/ims_auth/cxdx_m...). within async_cdp_callback function, if I replace: ``` tmb.t_continue(data->tindex, data->tlabel, data->act); ```` with the following: ``` tmb.t_continue_skip_timer(data->tindex, data->tlabel, data->act); ``` the issue will be fixed and the control will be passed to REG_MAR_REPLY route block. In fact, in ims_registrar_scscf module, in [cxdx_sar.c ](https://github.com/kamailio/kamailio/blob/master/src/modules/ims_registrar_s...) file, the t_continue_skip_timer is called instead of t_continue, if I replace it with t_continue the same issue happens for SAR callbacks.
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 6.1.0-dev0 (x86_64/linux) c858ce-dirty flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, MEM_JOIN_FREE, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_SEND_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: c858ce -dirty compiled on 10:33:37 Apr 5 2025 with gcc 11.4.0 ```
* **Operating System**:
``` Distributor ID: Ubuntu Description: Ubuntu 22.04.5 LTS Release: 22.04 Codename: jammy
Linux kuber-worker 5.15.0-133-generic #144-Ubuntu SMP Fri Feb 7 20:47:38 UTC 2025 x86_64 x86_64 x86_64 GNU/Linux ```
Kidwithservers left a comment (kamailio/kamailio#4205)
Hi. I believe that I might be experiencing the same issue that you have been. I've built and applied your patch, but I am still experiencing issues. Some sip devices can successfully register with no issues, but many cannot. I've included the logs output below. Does this match what you've been seeing?
``` May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: ERROR: <script>: ALGORITHM IS [] and User-Agent is [Grandstream GXP2170 1.0.7.81] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:920]: ims_authenticate(): Running authenticate, is_proxy_auth=0 May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:931]: ims_authenticate(): Checking if REGISTER is authorized for realm [ims.owlink.net]... May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:175]: get_nonce_response(): Calling find_credentials with realm [ims.owlink.net] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:60]: ims_find_credentials(): Searching credentials in realm [ims.owlink.net] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:97]: ims_find_credentials(): *hook = 0x7fe02d23faf0 May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:108]: ims_find_credentials(): Credential parsed successfully May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:111]: ims_find_credentials(): Comparing realm <ims.owlink.net> and <ims.owlink.net> May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [utils.c:203]: get_nonce_response(): Found nonce response May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:972]: ims_authenticate(): Nonce or response missing: nonce len [0], response16 len[0] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:390]: ims_challenge(): Looking for route block [REG_MAR_REPLY] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: INFO: ims_auth [cxdx_mar.c:82]: create_return_code(): created AVP successfully : [maa_return_code] - [-2] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:406]: ims_challenge(): Need to challenge for realm [ims.owlink.net] May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:413]: ims_challenge(): Checking if REGISTER is authorized for realm [ims.owlink.net]... May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:1712]: get_auth_userdata(): Searching auth_userdata for IMPU sip:310999001000001@ims.owlink.net (Hash 292) May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:1725]: get_auth_userdata(): Found auth_userdata May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:1284]: get_auth_vector(): looping through AV status is 1 and were looking for 0 May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:554]: ims_challenge(): Suspending SIP TM transaction May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [authorize.c:1805]: multimedia_auth_request(): Sending MAR May 09 11:40:24 zirconium /usr/local/sbin/kamailio[93577]: DEBUG: ims_auth [cxdx_mar.c:588]: cxdx_send_mar(): Successfully sent async diameter May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_dialog [dlg_handlers.c:2060]: print_all_dlgs(): ******************** May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_dialog [dlg_handlers.c:2061]: print_all_dlgs(): printing 4096 dialogs May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_dialog [dlg_handlers.c:2071]: print_all_dlgs(): ******************** May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:283]: reg_await_timer(): Looking for expired/useless at 90890914 May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:288]: reg_await_timer(): Slot 292 310999001000001@ims.owlink.net May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:293]: reg_await_timer(): .. AV 0 - 1 Exp 90890961 0x7fe025ea62f0 May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:288]: reg_await_timer(): Slot 452 310999001000002@ims.owlink.net May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:293]: reg_await_timer(): .. AV 0 - 3 Exp 91490687 0x7fe025ea54d0 May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93579]: DEBUG: ims_auth [authorize.c:337]: reg_await_timer(): [DONE] Looking for expired/useless at 90890914 May 09 11:40:25 zirconium /usr/local/sbin/kamailio[93576]: NOTICE: <script>: SCSCF: REGISTER sip:ims.owlink.net (sip:310999001000001@ims.owlink.net (23.157.168.135:5060) to sip:310999001000001@ims.owlink.net, 837231497-5060-4@BJC.BGI.C.DC) May 09 11:40:26 zirconium /usr/local/sbin/kamailio[93575]: NOTICE: <script>: SCSCF: REGISTER sip:ims.owlink.net (sip:310999001000001@ims.owlink.net (23.157.168.135:5060) to sip:310999001000001@ims.owlink.net, 837231497-5060-4@BJC.BGI.C.DC) May 09 11:40:30 zirconium /usr/local/sbin/kamailio[93602]: ERROR: ims_auth [cxdx_mar.c:132]: async_cdp_callback(): Transaction timeout - did not get MAA May 09 11:40:30 zirconium /usr/local/sbin/kamailio[93602]: ERROR: <script>: MAR error - sending error response now May 09 11:40:30 zirconium /usr/local/sbin/kamailio[93602]: DEBUG: ims_auth [cxdx_mar.c:92]: free_saved_transaction_data(): Freeing saved transaction data: async ```
amnapa left a comment (kamailio/kamailio#4205)
@Kidwithservers My patch (which got approved and merged with master branch) fixed executing MAR callback function in configs, I didn't have any registration issue and I just wanted to count the number of successful/unsuccessful MAR request based on the receiving MAA.
Your logs (particularly the following line) shows that the diameter peer is not getting any response from HSS and that may be the reason you have trouble registration.
`May 09 11:40:30 zirconium /usr/local/sbin/kamailio[93602]: ERROR: ims_auth [cxdx_mar.c:132]: async_cdp_callback(): Transaction timeout - did not get MAA`
I suggest increasing log levels for cdp module and inspecting scscf logs.
Closed #4205 as completed.