### Description Sometimes "registered" function return different result for different SIP worker process. It seems reproduced for a some time after restart. I have locate it on 4.4.6version and reproduce for master branch too. I tried Register/Unregister sip account while testing (via SIP)
### Troubleshooting
#### Reproduction ``` children=8
# registrar params modparam("registrar", "append_branches", 0) modparam("registrar", "use_path", 1) modparam("registrar", "path_mode", 0) modparam("registrar", "max_expires", 1800) modparam("registrar", "min_expires", 60)
# usrloc params modparam("usrloc", "db_mode", 2) modparam("usrloc", "timer_interval", 20) #default 60 modparam("usrloc", "db_check_update", 1) modparam("usrloc", "use_domain", 1) modparam("usrloc", "nat_bflag", FLB_NATB) modparam("usrloc", "db_ops_ruid", 1)
request_route{ route(REG); route(TESTREG); exit; }
route[SEND_TESTREG] { $uac_req(method)="PUBLISH"; $uac_req(ruri) = $tu; $uac_req(furi) = $tu; $uac_req(turi) = $tu; $uac_req(callid) = $ci; $uac_req(ouri) = "MYADDRPORT"; uac_req_send(); }
route[PRINT_REGISTERED] { if (registered("location", "$tu")){ xlog("L_INFO", "$rm $ci registered"); } else{ xlog("L_INFO", "$rm $ci NOT registered"); } }
route[REG] { if (!is_method("REGISTER")) return; xlog("L_INFO", "-------------------------------------"); route(PRINT_REGISTERED); if ( !save("location") ) { sl_reply_error(); exit; } route(PRINT_REGISTERED); # children=8 route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); route(SEND_TESTREG); exit; }
route[TESTREG]{ if (!is_method("PUBLISH")) return; usleep("500"); route(PRINT_REGISTERED); sl_send_reply("200", "OK"); exit; } ```
#### Log Messages Oct 9 20:13:38 kamailio[19514] INFO: <script>: REGISTER vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg registered Oct 9 20:13:38 kamailio[19514] INFO: <script>: REGISTER vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg NOT registered Oct 9 20:13:38 kamailio[19525] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg NOT registered Oct 9 20:13:38 kamailio[19519] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg registered Oct 9 20:13:38 kamailio[19521] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg NOT registered Oct 9 20:13:38 kamailio[19516] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg NOT registered Oct 9 20:13:38 kamailio[19513] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg registered Oct 9 20:13:38 kamailio[19514] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg NOT registered Oct 9 20:13:38 kamailio[19523] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg registered Oct 9 20:13:38 kamailio[19527] INFO: <script>: PUBLISH vHUuAy7p-IzjmDD5jblwCsER9SPXm9Kg registered
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.1.0-dev7 (x86_64/linux) ```
Does this happen only during the start up interval (and shortly after)? If yes, this could be because the location records are loaded by the first worker process in order to have a fast (re)start, at the expense that the saved records are not available immediately.
It seems not startup issue. I add [usrloc:contact-expired] hook 11:58:31 kamailio started, then i register/unregister my endpoint and check it status for all workers. After one of unregister integrity was missed and continued up to [usrloc:contact-expired] fire ("usrloc", "timer_interval") ``` Oct 13 12:31:24 kamailio[32018] registered Oct 13 12:31:24 kamailio[32016] registered Oct 13 12:31:24 kamailio[32022] NOT registered Oct 13 12:31:24 kamailio[32025] NOT registered Oct 13 12:31:26 kamailio[32023] registered Oct 13 12:31:26 kamailio[32022] NOT registered Oct 13 12:31:26 kamailio[32016] registered Oct 13 12:31:26 kamailio[32020] NOT registered Oct 13 12:31:26 kamailio[32015] registered Oct 13 12:31:26 kamailio[32025] NOT registered Oct 13 12:31:26 kamailio[32018] registered Oct 13 12:31:26 kamailio[32028] registered Oct 13 12:31:28 kamailio[32015] registered Oct 13 12:31:28 kamailio[32018] registered Oct 13 12:31:28 kamailio[32022] NOT registered Oct 13 12:31:28 kamailio[32028] registered Oct 13 12:31:28 kamailio[32025] NOT registered Oct 13 12:31:28 kamailio[32020] NOT registered Oct 13 12:31:28 kamailio[32023] registered Oct 13 12:31:28 kamailio[32016] registered Oct 13 12:31:30 kamailio[32023] registered Oct 13 12:31:30 kamailio[32025] NOT registered Oct 13 12:31:30 kamailio[32018] registered Oct 13 12:31:30 kamailio[32015] registered Oct 13 12:31:30 kamailio[32020] NOT registered Oct 13 12:31:30 kamailio[32022] NOT registered Oct 13 12:31:30 kamailio[32028] registered Oct 13 12:31:30 kamailio[32016] registered Oct 13 12:31:32 kamailio[32022] NOT registered Oct 13 12:31:32 kamailio[32020] NOT registered Oct 13 12:31:32 kamailio[32016] registered Oct 13 12:31:32 kamailio[32025] NOT registered Oct 13 12:31:32 kamailio[32018] registered Oct 13 12:31:32 kamailio[32015] registered Oct 13 12:31:32 kamailio[32028] registered Oct 13 12:31:32 kamailio[32023] registered Oct 13 12:31:33 kamailio[32030] INFO: <script>: 123 [usrloc:contact-expired] expired contact for sip:000*090@siptest.ringme.ru; count: 1; callid: X9ZGbOyc58D6o4vRl806FZq7KEYqVDgI Oct 13 12:31:34 kamailio[32018] NOT registered Oct 13 12:31:34 kamailio[32028] NOT registered Oct 13 12:31:34 kamailio[32025] NOT registered Oct 13 12:31:34 kamailio[32016] NOT registered Oct 13 12:31:34 kamailio[32023] NOT registered Oct 13 12:31:34 kamailio[32020] NOT registered Oct 13 12:31:34 kamailio[32015] NOT registered Oct 13 12:31:34 kamailio[32022] NOT registered Oct 13 12:31:36 kamailio[32016] NOT registered Oct 13 12:31:36 kamailio[32020] NOT registered Oct 13 12:31:36 kamailio[32015] NOT registered Oct 13 12:31:36 kamailio[32022] NOT registered Oct 13 12:31:36 kamailio[32025] NOT registered Oct 13 12:31:36 kamailio[32018] NOT registered Oct 13 12:31:36 kamailio[32023] NOT registered Oct 13 12:31:36 kamailio[32028] NOT registered ```
I couldn't spot anything in the code and not able to reproduce. Can you print $tu in the log messages, like:
``` if (registered("location", "$tu")){ xlog("L_INFO", "$rm $ci - [$tu] registered"); } else{ xlog("L_INFO", "$rm $ci - [$tu] NOT registered"); } ```
Add also:
``` log_prefix="{$mt $hdr(CSeq) $ci} " ```
and set debug=3 in order to get all debug messages. Reproduce the case and attach the all debug message for analyzis.
with this path it seems ok ``` diff --git a/src/modules/registrar/lookup.c b/src/modules/registrar/lookup.c index b18fe99..84c0f40 100644 --- a/src/modules/registrar/lookup.c +++ b/src/modules/registrar/lookup.c @@ -759,6 +759,7 @@ int registered4(struct sip_msg* _m, udomain_t* _d, str* _uri, int match_flag, } }
+ get_act_time(); for (ptr = r->contacts; ptr; ptr = ptr->next) { if(!VALID_CONTACT(ptr, act_time)) continue; if (match_callid.s && /* optionally enforce tighter matching w/ Call-ID */ ```
Thanks! Pushed the change to master and it will be backported.
Closed #1267.