I was finally able to catch an occurrence of the issue where a registration was getting stuck in the ONGOING state and not being retried. This is with 4.3.0. Here's an example of a successful registration from the logs:
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha19.callcentric.com(23), 1), h=201 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x7751b8e4 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 42513 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <407> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Proxy Authentication Required> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK116a.65ec1863000000000000000000000000.0>; state=16 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=16741 global id=16740 T start=0xffffffff Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: uac [auth_hdr.c:402]: build_authorization_hdr(): hdr is <Proxy-Authorization: Digest username="removed", realm="callcentric.com", nonce="75a3bdc28a8d7f8bd7531ec41ac9ea25", uri="sip:callcentric.com", response="f8dc5c3d85280da5972c1a7ef0b53f08", algorithm=MD5 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:172]: parse_to_param(): DEBUG: add_param: tag=2afe4db221460197112d59bc9a08ee82-bb3d Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=29 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha19.callcentric.com(23), 1), h=201 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x7751b8e4 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 42514 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <200> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Ok> Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK216a.928c6026000000000000000000000000.0>; state=16 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=16742 global id=16741 T start=0xffffffff Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:2053]: local_reply(): DEBUG: local transaction completed Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x76abc580, callback type 1024, id 0 entered Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: uac [uac_reg.c:723]: uac_reg_tm_callback(): completed with status 200 [uuid: removed+uac] Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0 Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end of header Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Here's where the registration got stuck (I added the "ONGOING flag still set" message myself to help capture when this occurred). I see the 200 Ok response to the REGISTER with the Proxy-Authorization header, but don't see uac_reg_tm_callback being invoked.
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha17.callcentric.com(23), 1), h=135 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x7751b8e4 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 42871 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <407> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Proxy Authentication Required> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK777a.be9fe760000000000000000000000000.0>; state=16 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=16764 global id=16763 T start=0xffffffff Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <stale>="TRUE" state=4 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <algorithm>="MD5" state=7 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: uac [auth_hdr.c:402]: build_authorization_hdr(): hdr is <Proxy-Authorization: Digest username="removed", realm="callcentric.com", nonce="b281825597a5ca2370701bd5a71d0f7b", uri="sip:callcentric.com", response="eae092a16bc01ac1333d922d088293a5", algorithm=MD5 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:172]: parse_to_param(): DEBUG: add_param: tag=2afe4db221460197112d59bc9a08ee82-5239 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=29 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha17.callcentric.com(23), 1), h=135 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x7751b8e4 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 42872 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <200> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Ok> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK877a.1f487c81000000000000000000000000.0>; state=16 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=16765 global id=16764 T start=0xffffffff Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG: get_hdr_field: <t> [35]; uri=[sip:removed@callcentric.com] Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [sip:removed@callcentric.com Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <11> <REGISTER> Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:888]: t_reply_matching(): DEBUG: t_reply_matching: hash 42872 label 0 branch 0 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x76abc580)! Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=16765 global id=16765 T end=0x76abc580 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:2136]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:1230]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:2016]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0 Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:2053]: local_reply(): DEBUG: local transaction completed Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up Sat Jul 18 23:24:40 2015 local0.err /usr/sbin/kamailio[25189]: ERROR: uac [uac_reg.c:935]: uac_reg_update(): ONGOING flag still set
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255
Paste here also the patch (git diff or diff -u ...) to the code to see where you added new stuff in order to match properly the lines of debug messages.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-122814640
The only other thing going on at the time (before 23:18:40 and between 23:18:40 and 23:24:40) was some registrations (I have kamailio set up as a registrar), so I eliminated the log messages associated with those for brevity. The local patch that I've applied to log the message and keep things going is:
--- a/modules/uac/uac_reg.c 2015-07-13 10:55:13.596283423 -0400 +++ b/modules/uac/uac_reg.c 2015-07-13 10:57:09.301555783 -0400 @@ -929,7 +929,10 @@ if(reg->expires==0) return 1; if(reg->flags&UAC_REG_ONGOING) - return 2; + if (reg->timer_expires > tn - reg_retry_interval) + return 2; + else + LM_ERR("ONGOING flag still set"); if(reg->flags&UAC_REG_DISABLED) return 4; if(reg->timer_expires > tn + reg_timer_interval + 3) @@ -942,7 +945,7 @@ } reg->timer_expires = tn; reg->flags |= UAC_REG_ONGOING; - reg->flags &= ~UAC_REG_ONLINE; + reg->flags &= ~(UAC_REG_ONLINE|UAC_REG_AUTHSENT); counter_add(regactive, -1); /* Take it out of the active pool while re-registering */ memcpy(uuid, reg->l_uuid.s, reg->l_uuid.len); uuid[reg->l_uuid.len] = '\0';
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-122951498
Some comments about generating the credentials after receiving 401 are missing for the case with issues, that made me think are not complete logs. As you selected them, maybe some other relevant were skipped, specially from core or tm module.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-123193482
I've re-pasted the logs with better formatting, but for the bad case, that's all the messages there are for that time period (23:18:40). The previous message was as 23:18:12 at the end of processing of a REGISTER: ``` Sat Jul 18 23:18:12 2015 local0.debug /usr/sbin/kamailio[25183]: DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request: Sat Jul 18 23:18:12 2015 local0.debug /usr/sbin/kamailio[25183]: DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method: <REGISTER> ... Sat Jul 18 23:18:12 2015 local0.debug /usr/sbin/kamailio[25183]: DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up ``` and the next messages are the start of another incoming REGISTER:
``` Sat Jul 18 23:18:42 2015 local0.debug /usr/sbin/kamailio[25183]: DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request: Sat Jul 18 23:18:42 2015 local0.debug /usr/sbin/kamailio[25183]: DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method: <REGISTER> ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-123516134
I think my log buffer may not be set large enough, resulting in log messages being dropped. I've reconfigured kamailio to log to stderr, with stderr redirected to a file. It appears that I'm now seeing all the messages. Once again, I'll keep an eye on the log and post back here when the condition occurs again.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-123875703
Here's another occurence of the issue. It looks like all the messages were captured this time. It appears that the callback is not being called after the second 200 OK.
``` 7(14177) DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com 7(14177) DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 7(14177) DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha13.callcentric.com(23), 1), h=8 7(14177) DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x771578e4 7(14177) DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 23186 2(14172) DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): 2(14172) DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> 2(14172) DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <407> 2(14172) DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Proxy Authentication Required> 2(14172) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK29a5.d1684c32000000000000000000000000.0>; state=16 2(14172) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2(14172) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 2(14172) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via 2(14172) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... 2(14172) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=3497 global id=3496 T start=0xffffffff 2(14172) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 2(14172) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG: get_hdr_field: <t> [35]; uri=[sip:removedXXXX@callcentric.com] 2(14172) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [sip:removedXXXX@callcentric.com ] 2(14172) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <10> <REGISTER> 2(14172) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0 2(14172) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end of header 2(14172) DEBUG: tm [t_lookup.c:888]: t_reply_matching(): DEBUG: t_reply_matching: hash 23186 label 0 branch 0 2(14172) DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x766f92f0)! 2(14172) DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=3497 global id=3497 T end=0x766f92f0 2(14172) DEBUG: tm [t_reply.c:2136]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0) 2(14172) DEBUG: tm [t_reply.c:1230]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=407 2(14172) DEBUG: tm [t_reply.c:2016]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0 2(14172) DEBUG: tm [t_reply.c:2053]: local_reply(): DEBUG: local transaction completed 2(14172) DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x766f92f0, callback type 1024, id 0 entered 2(14172) DEBUG: uac [uac_reg.c:723]: uac_reg_tm_callback(): completed with status 407 [uuid: removedXXXX+uac] 2(14172) DEBUG: uac [auth.c:218]: get_autenticate_hdr(): looking for header "Proxy-Authenticate" 2(14172) DEBUG: uac [uac_reg.c:806]: uac_reg_tm_callback(): auth header body [Digest realm="callcentric.com", domain="sip:callcentric.com", nonce="5e6f1a6152212007fcd6fbbd6616612c", opaque="", stale=TRUE, algorithm=MD5] 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <realm>="callcentric.com" state=2 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <domain>="sip:callcentric.com" state=0 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <nonce>="5e6f1a6152212007fcd6fbbd6616612c" state=3 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <opaque>="" state=6 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <stale>="TRUE" state=4 2(14172) DEBUG: uac [auth_hdr.c:203]: parse_authenticate_body(): <algorithm>="MD5" state=7 2(14172) DEBUG: uac [auth_hdr.c:402]: build_authorization_hdr(): hdr is <Proxy-Authorization: Digest username="removedXXXX", realm="callcentric.com", nonce="5e6f1a6152212007fcd6fbbd6616612c", uri="sip:callcentric.com", response="cd8a7b2cb2b24a12034a7ad70f8e8150", algorithm=MD5
2(14172) DEBUG: <core> [parser/parse_addr_spec.c:172]: parse_to_param(): DEBUG: add_param: tag=2afe4db221460197112d59bc9a08ee82-778a 2(14172) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=29 2(14172) DEBUG: tm [uac.c:249]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=sip:callcentric.com 2(14172) DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (_sip._udp.callcentric.com(25), 33), h=428 2(14172) DEBUG: <core> [dns_cache.c:537]: _dns_hash_find(): (alpha13.callcentric.com(23), 1), h=8 2(14172) DEBUG: <core> [forward.c:174]: get_out_socket(): socket determined: 0x771578e4 2(14172) DEBUG: tm [uac.c:150]: dlg2hash(): DEBUG: dlg2hash: 23187 2(14172) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2(14172) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up 2(14172) DEBUG: <core> [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status): 2(14172) DEBUG: <core> [parser/msg_parser.c:618]: parse_msg(): version: <SIP/2.0> 2(14172) DEBUG: <core> [parser/msg_parser.c:620]: parse_msg(): status: <200> 2(14172) DEBUG: <core> [parser/msg_parser.c:622]: parse_msg(): reason: <Ok> 2(14172) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK39a5.32682cb2000000000000000000000000.0>; state=16 2(14172) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2(14172) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers(): parse_headers: Via found, flags=2 2(14172) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers(): parse_headers: this is the first via 2(14172) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg... 2(14172) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=3498 global id=3497 T start=0xffffffff 2(14172) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=10 2(14172) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG: get_hdr_field: <t> [35]; uri=[sip:removedXXXX@callcentric.com] 2(14172) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [sip:removedXXXX@callcentric.com ] 2(14172) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <11> <REGISTER> 2(14172) DEBUG: tm [t_lookup.c:888]: t_reply_matching(): DEBUG: t_reply_matching: hash 23187 label 0 branch 0 2(14172) DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x766facc4)! 2(14172) DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=3498 global id=3498 T end=0x766facc4 2(14172) DEBUG: tm [t_reply.c:2136]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0) 2(14172) DEBUG: tm [t_reply.c:1230]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 2(14172) DEBUG: tm [t_reply.c:2016]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0 2(14172) DEBUG: tm [t_reply.c:2053]: local_reply(): DEBUG: local transaction completed 2(14172) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2(14172) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2(14172) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up ```
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-125188355
Indeed the logs don't show that the callback is executed. I checked quickly and the callback is set for execution.
For now I will push a patch based on your changes to reset the flags if the retry interval is reached.
In long term, I may add a second callback for the event when transaction is destroyed to catch the situation when transaction completed is skipped.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-125196266
I pushed a patch to uac along with another one for tm module, to have more verbose log message when transaction is completed.
Would be good to get same situation with that log printed in order to be able to troubleshoot more.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-125212508
I've applied the uac and tm changes, and will watch the logs for the "resetting" debug message.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-126816831
It's been almost 3 weeks since I updated to the latest 4.3.x, and I haven't seen the new "resetting" debug message yet. Perhaps another fix also fixed this issue.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-132583650
Closing this one, as it seems fixed. Re-open if the issue appears again.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#issuecomment-140041429
Closed #255.
--- Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/255#event-408542495
-
AndyJRobinson -
Daniel-Constantin Mierla