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(): DEBUGt_uac: next_hop=sip:callcentric.com
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: [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: [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: [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: [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status):
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:618]: parse_msg(): version:
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:620]: parse_msg(): status: <407>
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:622]: parse_msg(): reason:
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, = ; state=16
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [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: [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
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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(): DEBUGt_uac: next_hop=sip:callcentric.com
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [receive.c:278]: receive_msg(): cleaning up
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status):
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:618]: parse_msg(): version:
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:620]: parse_msg(): status: <200>
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:622]: parse_msg(): reason:
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, = ; state=16
Sat Jul 18 23:03:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [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: [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: [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: [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: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:03:41 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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(): DEBUGt_uac: next_hop=sip:callcentric.com
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25189]: DEBUG: [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: [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: [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: [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status):
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:618]: parse_msg(): version:
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:620]: parse_msg(): status: <407>
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:622]: parse_msg(): reason:
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, = ; state=16
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [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: [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(): ="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(): ="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
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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(): DEBUGt_uac: next_hop=sip:callcentric.com
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [receive.c:278]: receive_msg(): cleaning up
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:616]: parse_msg(): SIP Reply (status):
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:618]: parse_msg(): version:
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:620]: parse_msg(): status: <200>
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/msg_parser.c:622]: parse_msg(): reason:
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, = ; state=16
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [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: [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: [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: [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: [parser/msg_parser.c:173]: get_hdr_field(): DEBUG: get_hdr_field: [35]; uri=[sip:removed@callcentric.com]
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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: [parser/msg_parser.c:153]: get_hdr_field(): get_hdr_field: cseq : <11>
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: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
Sat Jul 18 23:18:40 2015 local0.debug /usr/sbin/kamailio[25184]: DEBUG: [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.