19 Jul
2015
19 Jul
'15
7:46 p.m.
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
20 Jul
20 Jul
10:45 a.m.
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
7 p.m.
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
21 Jul
21 Jul
9:05 a.m.
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
22 Jul
22 Jul
2:25 a.m.
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
11:44 p.m.
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
27 Jul
27 Jul
2:29 p.m.
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
2:55 p.m.
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
3:51 p.m.
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
31 Jul
31 Jul
11:33 p.m.
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
19 Aug
19 Aug
3:04 p.m.
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
14 Sep
14 Sep
1:10 p.m.
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
1:10 p.m.
Closed #255.
---
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/255#event-408542495
3155
days inactive
3212
days old
12 comments
2 participants
participants (2)
-
AndyJRobinson -
Daniel-Constantin Mierla