[SR-Users] UAC module fails to refresh registrations

Isaac McDonald imcdona at suscall.com
Fri Jul 26 10:30:20 CEST 2013


Thanks for your help with this Daniel. I've attached a SIP trace along 
with debugging information from Kamailio.

On 7/25/2013 1:47 AM, Daniel-Constantin Mierla wrote:
> Hello,
>
> the log message shows that authentication failed. Use debug=3 for more
> details. Also, grab the sip traffic with ngrep.
>
> Cheers,
> Daniel
>
> On 7/25/13 9:50 AM, Isaac McDonald wrote:
>> Hello Daniel,
>>
>> Thanks for your help on this. I set the registration to expire after
>> 10 seconds and restarted Kamailio with debug level 1. Here's the output:
>>
>> Jul 25 02:43:41 Kamailio-DEV /usr/sbin/kamailio[30148]: ERROR: uac
>> [uac_reg.c:537]: uac_reg_tm_callback(): authentication failed for
>> <2500-xxx.xxx.xxxx.com>
>>
>> Thanks!
>>
>> On 7/22/2013 1:57 AM, Daniel-Constantin Mierla wrote:
>>> Hello,
>>>
>>> can you send the log messages with debug=1 when the re-registration 401
>>> is processed?
>>>
>>> Cheers,
>>> Daniel
>>>
>>> On 7/21/13 1:35 AM, Isaac McDonald wrote:
>>>> Hello,
>>>>
>>>> I'm using the UAC module to register to remote sip proxies. When
>>>> starting Kamailio, the UAC module successfully registers with the
>>>> remote
>>>> sip proxies as expected. Upon expiration of the registration (refresh
>>>> interval) the UAC module fails to re-register.
>>>>
>>>> I've done some sip traces and found the following:
>>>>
>>>> During Kamailio startup the registration process is typical of what
>>>> you'd expect:
>>>>
>>>> 1. UAC module sends registration request without authentication
>>>> information to remote registrar
>>>>
>>>> 2. Remote sip proxy sends a 401 back to Kamailio saying unauthorized
>>>>
>>>> 3. UAC module sends another registration request with credentials and
>>>> registration is complete.
>>>>
>>>> After the refresh interval expires, the UAC module performs step 1
>>>> from above, and the remote sip proxy sends back a 401 (step 2). At
>>>> this point, the UAC module doesn't resend the registration request
>>>> with credentials thus failing to register.
>>>>
>>>> I've got the following modparam's set on the UAC module.
>>>>
>>>> modparam("uac", "reg_contact_addr", "10.0.0.31:5060")
>>>> modparam("uac", "reg_timer_interval", 60)
>>>> modparam("uac", "reg_retry_interval", 300)
>>>>
>>>>
>>>> Anyone have any idea's as to why registrations are failing after the
>>>> refresh interval?
>>>>
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>>>> sr-users at lists.sip-router.org
>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>>
>>> --
>>> Daniel-Constantin Mierla -http://www.asipto.com
>>> http://twitter.com/#!/miconda -http://www.linkedin.com/in/miconda
>>>
>>>
>>>
>>> _______________________________________________
>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>>> sr-users at lists.sip-router.org
>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>>
>
-------------- next part --------------
kamailio[3396]: DEBUG: db_mysql [km_dbase.c:358]: db_mysql_fetch_result(): converting row 0 of 1 count 1
kamailio[3396]: DEBUG: <core> [db_row.c:119]: db_allocate_row(): allocate 320 bytes for row values at 0x7fe87e48c0a0
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [2500-cti.sip.example.com]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [2500]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [cti.sip.example.com]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [2500]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [10.140.1.11]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [asterisk]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [2500]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [Qa31mwWv3MBdFYuVKY]
kamailio[3396]: DEBUG: <core> [db_val.c:117]: db_str2val(): converting STRING [sip:10.140.1.11]
kamailio[3396]: DEBUG: <core> [db_val.c:73]: db_str2val(): converting INT [10]
kamailio[3400]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (5): sqlops
kamailio[3398]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-1): sqlops
kamailio[3404]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [ulcx-51f2284e-d4c-] (0 / 18)
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): registrar
kamailio[3404]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [uloc-51f2284e-d4c-] (0 / 18)
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): ctl
kamailio[3398]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3398]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3398]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49eff0 found in pool
kamailio[3398]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-1): dispatcher
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): mi_rpc
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): acc
kamailio[3400]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3400]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3400]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49eef0 found in pool
kamailio[3400]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (5): dispatcher
kamailio[3404]: DEBUG: <core> [db_id.c:292]: cmp_db_id(): identical DB URLs, but different DB connection pid [3404/3369]
kamailio[3404]: DEBUG: <core> [db.c:318]: db_do_init2(): connection 0x7fe87e437d20 not found in pool
kamailio[3404]: DEBUG: db_mysql [km_my_con.c:94]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/kamailio
kamailio[3396]: DEBUG: <core> [db_res.c:54]: db_free_rows(): freeing 1 rows
kamailio[3396]: DEBUG: <core> [db_row.c:97]: db_free_row(): freeing row values at 0x7fe87e48c0a0
kamailio[3396]: DEBUG: <core> [db_res.c:62]: db_free_rows(): freeing rows at 0x7fe87e48c070
kamailio[3396]: DEBUG: <core> [db_res.c:81]: db_free_columns(): freeing 10 columns
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[0] at 0x7fe87e48be90
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[1] at 0x7fe87e48bec0
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[2] at 0x7fe87e48bef0
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[3] at 0x7fe87e48bf20
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[4] at 0x7fe87e48bf50
kamailio[3400]: DEBUG: <core> [local_timer.c:74]: init_local_timer(): init_local_timer: timer_list between 0x894708 and 0x8d8708
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[5] at 0x7fe87e48bf80
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[6] at 0x7fe87e48bfb0
kamailio[3400]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x894540, 27, 1, (nil)), fd_no=0
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[7] at 0x7fe87e48bfe0
kamailio[3377]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (1): sqlops
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[8] at 0x7fe87e48c010
kamailio[3396]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[9] at 0x7fe87e48c040
kamailio[3396]: DEBUG: <core> [db_res.c:94]: db_free_columns(): freeing result names at 0x7fe87e48bdd0
kamailio[3396]: DEBUG: <core> [db_res.c:99]: db_free_columns(): freeing result types at 0x7fe87e48be40
kamailio[3396]: DEBUG: <core> [db_res.c:136]: db_free_result(): freeing result set at 0x7fe87e49f2e0
kamailio[3396]: DEBUG: tm [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:10.140.1.11>
kamailio[3396]: DEBUG: tm [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 33416
kamailio[3377]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3377]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3377]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49fc20 found in pool
kamailio[3377]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (1): dispatcher
kamailio[3404]: DEBUG: db_mysql [km_my_con.c:121]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP
kamailio[3404]: DEBUG: db_mysql [km_my_con.c:122]: db_mysql_new_connection(): protocol version is 10
kamailio[3404]: DEBUG: db_mysql [km_my_con.c:123]: db_mysql_new_connection(): server version is 5.1.67
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply  (status):
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg():  version: <SIP/2.0>
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg():  status:  <401>
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg():  reason:  <Unauthorized>
kamailio[3379]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK8828.d5a9fe43.0>; state=6
kamailio[3379]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <10.140.1.31>; state=16
kamailio[3379]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
kamailio[3379]: DEBUG: <core> [receive.c:149]: receive_msg(): After parse_msg...
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): mi_fifo
kamailio[3379]: DEBUG: tm [t_lookup.c:1095]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff
kamailio[3379]: DEBUG: <core> [parser/parse_to.c:176]: parse_to_param(): DEBUG: add_param: tag=as2ec7b125
kamailio[3379]: DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached, state=29
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [37]; uri=[sip:2500 at 10.140.1.11]
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [sip:2500 at 10.140.1.11]
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <10> <REGISTER>
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
kamailio[3379]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
kamailio[3379]: DEBUG: tm [t_lookup.c:972]: t_reply_matching(): DEBUG: t_reply_matching: hash 33416 label 888117853 branch 0
kamailio[3379]: DEBUG: tm [t_lookup.c:1032]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7fe875ae8820)!
kamailio[3379]: DEBUG: tm [t_lookup.c:1164]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7fe875ae8820
kamailio[3379]: DEBUG: tm [t_reply.c:2085]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
kamailio[3379]: DEBUG: tm [t_reply.c:1207]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=401
kamailio[3379]: DEBUG: tm [t_reply.c:1965]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
kamailio[3379]: DEBUG: tm [t_reply.c:2002]: local_reply(): DEBUG: local transaction completed
kamailio[3379]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fe875ae8820, callback type 1024, id 0 entered
kamailio[3379]: DEBUG: uac [uac_reg.c:465]: uac_reg_tm_callback(): completed with status 401 [uuid: 2500-cti.sip.example.com]
kamailio[3379]: DEBUG: uac [auth.c:225]: get_autenticate_hdr(): looking for header "WWW-Authenticate"
kamailio[3379]: DEBUG: uac [uac_reg.c:548]: uac_reg_tm_callback(): auth header body [Digest algorithm=MD5, realm="asterisk", nonce="6a2fb9b1"]
kamailio[3379]: DEBUG: uac [auth_hdr.c:210]: parse_authenticate_body(): <algorithm>="MD5" state=7
kamailio[3379]: DEBUG: uac [auth_hdr.c:210]: parse_authenticate_body(): <realm>="asterisk" state=2
kamailio[3379]: DEBUG: uac [auth_hdr.c:210]: parse_authenticate_body(): <nonce>="6a2fb9b1" state=3
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): kex
kamailio[3379]: DEBUG: uac [auth_hdr.c:409]: build_authorization_hdr(): hdr is <Authorization: Digest username="2500", realm="asterisk", nonce="6a2fb9b1", uri="sip:10.140.1.11", response="299f8b5fd0dec1df93cdf796fdbb6280", algorithm=MD5#015#012>
kamailio[3379]: DEBUG: <core> [parser/parse_to.c:176]: parse_to_param(): DEBUG: add_param: tag=51b6a5d1a9ebf21332da43af5e84fad4-d180
kamailio[3379]: DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached, state=29
kamailio[3379]: DEBUG: tm [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:10.140.1.11>
kamailio[3406]: DEBUG: kex [kex_mod.c:156]: child_init(): rank is (7)
kamailio[3406]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [srid-51f2284e-d4e-] (0 / 18)
kamailio[3379]: DEBUG: tm [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 33417
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): tm
kamailio[3379]: DEBUG: tm [t_reply.c:1547]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3379]: DEBUG: <core> [xavp.c:447]: xavp_destroy_list(): destroying xavp list (nil)
kamailio[3379]: DEBUG: <core> [receive.c:293]: receive_msg(): receive_msg: cleaning up
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): auth_db
kamailio[3404]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e4981b0 found in pool
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): permissions
kamailio[3406]: DEBUG: tm [callid.c:137]: child_init_callid(): DEBUG: callid: '496dc8f41bad3cd2-3406 at 10.140.1.31'
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): domain
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply  (status):
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg():  version: <SIP/2.0>
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg():  status:  <200>
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg():  reason:  <OK>
kamailio[3378]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK9828.307c3916.0>; state=6
kamailio[3378]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <10.140.1.31>; state=16
kamailio[3378]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
kamailio[3378]: DEBUG: <core> [receive.c:149]: receive_msg(): After parse_msg...
kamailio[3378]: DEBUG: tm [t_lookup.c:1095]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff
kamailio[3378]: DEBUG: <core> [parser/parse_to.c:176]: parse_to_param(): DEBUG: add_param: tag=as2ec7b125
kamailio[3378]: DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached, state=29
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [37]; uri=[sip:2500 at 10.140.1.11]
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [sip:2500 at 10.140.1.11]
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): sl
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <11> <REGISTER>
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): usrloc
kamailio[3378]: DEBUG: tm [t_lookup.c:972]: t_reply_matching(): DEBUG: t_reply_matching: hash 33417 label 1637074691 branch 0
kamailio[3378]: DEBUG: tm [t_lookup.c:1032]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7fe875ae9d60)!
kamailio[3378]: DEBUG: tm [t_lookup.c:1164]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7fe875ae9d60
kamailio[3378]: DEBUG: tm [t_reply.c:2085]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
kamailio[3378]: DEBUG: tm [t_reply.c:1207]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200
kamailio[3378]: DEBUG: tm [t_reply.c:1965]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
kamailio[3378]: DEBUG: tm [t_reply.c:2002]: local_reply(): DEBUG: local transaction completed
kamailio[3378]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fe875ae9d60, callback type 1024, id 0 entered
kamailio[3406]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [ulcx-51f2284e-d4e-] (0 / 18)
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): registrar
kamailio[3378]: DEBUG: uac [uac_reg.c:465]: uac_reg_tm_callback(): completed with status 200 [uuid: 2500-cti.sip.example.com]
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
kamailio[3378]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
kamailio[3406]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [uloc-51f2284e-d4e-] (0 / 18)
kamailio[3378]: DEBUG: tm [t_reply.c:1547]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3378]: DEBUG: <core> [xavp.c:447]: xavp_destroy_list(): destroying xavp list (nil)
kamailio[3378]: DEBUG: <core> [receive.c:293]: receive_msg(): receive_msg: cleaning up
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): ctl
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): mi_rpc
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): acc
kamailio[3406]: DEBUG: <core> [db_id.c:292]: cmp_db_id(): identical DB URLs, but different DB connection pid [3406/3369]
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): presence
kamailio[3404]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e498350 found in pool
kamailio[3404]: DEBUG: presence [presence.c:474]: child_init(): child 6: Database connection opened successfully
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): presence_xml
kamailio[3404]: DEBUG: presence_xml [presence_xml.c:316]: child_init(): [6]  pid [3404]
kamailio[3404]: DEBUG: presence_xml [presence_xml.c:341]: child_init(): child 6: Database connection opened successfully
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): nathelper
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): rtpproxy
kamailio[3406]: DEBUG: <core> [db.c:318]: db_do_init2(): connection 0x7fe87e437d20 not found in pool
kamailio[3406]: DEBUG: db_mysql [km_my_con.c:94]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/kamailio
kamailio[3404]: INFO: rtpproxy [rtpproxy.c:1559]: rtpp_test(): rtp proxy <udp:127.0.0.1:7722> found, support for it enabled
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): mi_fifo
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): debugger
kamailio[3404]: DEBUG: debugger [debugger_mod.c:124]: child_init(): rank is (6)
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): uac
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): siptrace
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): kex
kamailio[3407]: DEBUG: kex [kex_mod.c:156]: child_init(): rank is (8)
kamailio[3407]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [srid-51f2284e-d4f-] (0 / 18)
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): tm
kamailio[3407]: DEBUG: tm [callid.c:137]: child_init_callid(): DEBUG: callid: '496dc8f41bad3cd2-3407 at 10.140.1.31'
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): sl
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): usrloc
kamailio[3407]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [ulcx-51f2284e-d4f-] (0 / 18)
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): registrar
kamailio[3407]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [uloc-51f2284e-d4f-] (0 / 18)
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): ctl
kamailio[3404]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49ed30 found in pool
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): mi_datagram
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): rtimer
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): mi_rpc
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): acc
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): sqlops
kamailio[3407]: DEBUG: <core> [db_id.c:292]: cmp_db_id(): identical DB URLs, but different DB connection pid [3407/3369]
kamailio[3407]: DEBUG: <core> [db.c:318]: db_do_init2(): connection 0x7fe87e437d20 not found in pool
kamailio[3406]: DEBUG: db_mysql [km_my_con.c:121]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP
kamailio[3406]: DEBUG: db_mysql [km_my_con.c:122]: db_mysql_new_connection(): protocol version is 10
kamailio[3406]: DEBUG: db_mysql [km_my_con.c:123]: db_mysql_new_connection(): server version is 5.1.67
kamailio[3404]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3404]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3404]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49eef0 found in pool
kamailio[3404]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (6): dispatcher
kamailio[3404]: DEBUG: <core> [local_timer.c:74]: init_local_timer(): init_local_timer: timer_list between 0x894708 and 0x8d8708
kamailio[3404]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x894540, 29, 1, (nil)), fd_no=0
kamailio[3407]: DEBUG: db_mysql [km_my_con.c:94]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/kamailio
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): auth_db
kamailio[3406]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e4981b0 found in pool
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): permissions
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): domain
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): presence
kamailio[3406]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e498350 found in pool
kamailio[3406]: DEBUG: presence [presence.c:474]: child_init(): child 7: Database connection opened successfully
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): presence_xml
kamailio[3406]: DEBUG: presence_xml [presence_xml.c:316]: child_init(): [7]  pid [3406]
kamailio[3406]: DEBUG: presence_xml [presence_xml.c:341]: child_init(): child 7: Database connection opened successfully
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): nathelper
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): rtpproxy
kamailio[3406]: INFO: rtpproxy [rtpproxy.c:1559]: rtpp_test(): rtp proxy <udp:127.0.0.1:7722> found, support for it enabled
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): mi_fifo
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): kex
kamailio[3407]: DEBUG: db_mysql [km_my_con.c:121]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP
kamailio[3407]: DEBUG: db_mysql [km_my_con.c:122]: db_mysql_new_connection(): protocol version is 10
kamailio[3407]: DEBUG: db_mysql [km_my_con.c:123]: db_mysql_new_connection(): server version is 5.1.67
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): auth_db
kamailio[3407]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e4981b0 found in pool
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): permissions
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): domain
kamailio[3409]: DEBUG: kex [kex_mod.c:156]: child_init(): rank is (-4)
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): presence
kamailio[3407]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e498350 found in pool
kamailio[3407]: DEBUG: presence [presence.c:474]: child_init(): child 8: Database connection opened successfully
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): presence_xml
kamailio[3407]: DEBUG: presence_xml [presence_xml.c:316]: child_init(): [8]  pid [3407]
kamailio[3407]: DEBUG: presence_xml [presence_xml.c:341]: child_init(): child 8: Database connection opened successfully
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): nathelper
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): rtpproxy
kamailio[3409]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [srid-51f2284e-d51-] (0 / 18)
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): tm
kamailio[3409]: DEBUG: tm [callid.c:137]: child_init_callid(): DEBUG: callid: '496dc8f41bad3cd2-3409 at 10.140.1.31'
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): sl
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): usrloc
kamailio[3409]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [ulcx-51f2284e-d51-] (0 / 18)
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): registrar
kamailio[3409]: DEBUG: <core> [sruid.c:100]: sruid_init(): root for sruid is [uloc-51f2284e-d51-] (0 / 18)
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): ctl
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): mi_rpc
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): acc
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): auth_db
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): permissions
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): domain
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): presence
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): presence_xml
kamailio[3409]: DEBUG: presence_xml [presence_xml.c:316]: child_init(): [-4]  pid [3409]
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): nathelper
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): rtpproxy
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): debugger
kamailio[3406]: DEBUG: debugger [debugger_mod.c:124]: child_init(): rank is (7)
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): uac
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): siptrace
kamailio[3406]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49ed30 found in pool
kamailio[3407]: INFO: rtpproxy [rtpproxy.c:1559]: rtpp_test(): rtp proxy <udp:127.0.0.1:7722> found, support for it enabled
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): mi_datagram
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): rtimer
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): sqlops
kamailio[3409]: INFO: rtpproxy [rtpproxy.c:1559]: rtpp_test(): rtp proxy <udp:127.0.0.1:7722> found, support for it enabled
kamailio[3406]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3406]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3406]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49eef0 found in pool
kamailio[3406]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (7): dispatcher
kamailio[3406]: DEBUG: <core> [local_timer.c:74]: init_local_timer(): init_local_timer: timer_list between 0x894708 and 0x8d8708
kamailio[3406]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x894540, 31, 1, (nil)), fd_no=0
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): debugger
kamailio[3407]: DEBUG: debugger [debugger_mod.c:124]: child_init(): rank is (8)
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): uac
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): siptrace
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): debugger
kamailio[3409]: DEBUG: debugger [debugger_mod.c:124]: child_init(): rank is (-4)
kamailio[3407]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49ed30 found in pool
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): uac
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): mi_datagram
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): siptrace
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): mi_datagram
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): rtimer
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): sqlops
kamailio[3407]: DEBUG: <core> [sr_module.c:674]: find_mod_export_record(): find_export_record: found <db_bind_api> in module db_mysql [/usr/lib64/kamailio/modules/db_mysql.so]
kamailio[3407]: DEBUG: <core> [db.c:213]: db_bind_mod(): using db bind api for db_mysql
kamailio[3407]: DEBUG: <core> [db.c:327]: db_do_init2(): connection 0x7fe87e49eef0 found in pool
kamailio[3407]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (8): dispatcher
kamailio[3407]: DEBUG: <core> [local_timer.c:74]: init_local_timer(): init_local_timer: timer_list between 0x894708 and 0x8d8708
kamailio[3407]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x894540, 33, 1, (nil)), fd_no=0
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): rtimer
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): sqlops
kamailio[3409]: DEBUG: <core> [sr_module.c:892]: init_mod_child(): DEBUG: init_mod_child (-4): dispatcher
kamailio[3409]: DEBUG: <core> [local_timer.c:74]: init_local_timer(): init_local_timer: timer_list between 0x8504a8 and 0x8944a8
kamailio[3396]: DEBUG: tm [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<sip:10.140.1.11>
kamailio[3396]: DEBUG: tm [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 33413
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply  (status):
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg():  version: <SIP/2.0>
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg():  status:  <401>
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg():  reason:  <Unauthorized>
kamailio[3381]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK5828.83893957.0>; state=6
kamailio[3381]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <10.140.1.31>; state=16
kamailio[3381]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
kamailio[3381]: DEBUG: <core> [receive.c:149]: receive_msg(): After parse_msg...
kamailio[3381]: DEBUG: tm [t_lookup.c:1095]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff
kamailio[3381]: DEBUG: <core> [parser/parse_to.c:176]: parse_to_param(): DEBUG: add_param: tag=as28816372
kamailio[3381]: DEBUG: <core> [parser/parse_to.c:799]: parse_to(): end of header reached, state=29
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [37]; uri=[sip:2500 at 10.140.1.11]
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [sip:2500 at 10.140.1.11]
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <10> <REGISTER>
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
kamailio[3381]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
kamailio[3381]: DEBUG: tm [t_lookup.c:972]: t_reply_matching(): DEBUG: t_reply_matching: hash 33413 label 1972607032 branch 0
kamailio[3381]: DEBUG: tm [t_lookup.c:1032]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7fe875ae9d60)!
kamailio[3381]: DEBUG: tm [t_lookup.c:1164]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7fe875ae9d60
kamailio[3381]: DEBUG: tm [t_reply.c:2085]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
kamailio[3381]: DEBUG: tm [t_reply.c:1207]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=401
kamailio[3381]: DEBUG: tm [t_reply.c:1965]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0
kamailio[3381]: DEBUG: tm [t_reply.c:2002]: local_reply(): DEBUG: local transaction completed
kamailio[3381]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fe875ae9d60, callback type 1024, id 0 entered
kamailio[3381]: DEBUG: uac [uac_reg.c:465]: uac_reg_tm_callback(): completed with status 401 [uuid: 2500-cti.sip.example.com]
kamailio[3381]: ERROR: uac [uac_reg.c:537]: uac_reg_tm_callback(): authentication failed for <2500-cti.sip.example.com>
kamailio[3381]: DEBUG: tm [t_reply.c:1547]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
kamailio[3381]: DEBUG: <core> [xavp.c:447]: xavp_destroy_list(): destroying xavp list (nil)
kamailio[3381]: DEBUG: <core> [receive.c:293]: receive_msg(): receive_msg: cleaning up

-------------- next part --------------
IP 10.140.1.31.sip > 10.140.1.11.sip: UDP, length 413
REGISTER sip:10.140.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK8828.d5a9fe43.0
To: sip:2500 at 10.140.1.11
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-d180
CSeq: 10 REGISTER
Call-ID: 496dc8f41bad3cd3-3396 at 10.140.1.31
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (4.0.2 (x86_64/linux))
Contact: <sip:2500-cti.sip.example.com at 10.140.1.31:5060>
Expires: 10


IP 10.140.1.11.sip > 10.140.1.31.sip: UDP, length 519
.........$FSIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK8828.d5a9fe43.0;received=10.140.1.31
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-d180
To: sip:2500 at 10.140.1.11;tag=as2ec7b125
Call-ID: 496dc8f41bad3cd3-3396 at 10.140.1.31
CSeq: 10 REGISTER
Server: FPBX-2.10.0(1.8.8.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6a2fb9b1"
Content-Length: 0


IP 10.140.1.31.sip > 10.140.1.11.sip: UDP, length 571

........C..REGISTER sip:10.140.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK9828.307c3916.0
To: sip:2500 at 10.140.1.11
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-d180
CSeq: 11 REGISTER
Call-ID: 496dc8f41bad3cd3-3396 at 10.140.1.31
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (4.0.2 (x86_64/linux))
Contact: <sip:2500-cti.sip.example.com at 10.140.1.31:5060>
Expires: 10
Authorization: Digest username="2500", realm="asterisk", nonce="6a2fb9b1", uri="sip:10.140.1.11", response="299f8b5fd0dec1df93cdf796fdbb6280", algorithm=MD5

IP 10.140.1.11.sip > 10.140.1.31.sip: UDP, length 557
........5;.SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK9828.307c3916.0;received=10.140.1.31
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-d180
To: sip:2500 at 10.140.1.11;tag=as2ec7b125
Call-ID: 496dc8f41bad3cd3-3396 at 10.140.1.31
CSeq: 11 REGISTER
Server: FPBX-2.10.0(1.8.8.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 60
Contact: <sip:2500-cti.sip.example.com at 10.140.1.31:5060>;expires=60
Date: Fri, 26 Jul 2013 07:42:06 GMT
Content-Length: 0

IP 10.140.1.31.sip > 10.140.1.11.sip: UDP, length 413
...........REGISTER sip:10.140.1.11 SIP/2.0
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK5828.83893957.0
To: sip:2500 at 10.140.1.11
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-a82f
CSeq: 10 REGISTER
Call-ID: 496dc8f41bad3cd4-3396 at 10.140.1.31
Max-Forwards: 70
Content-Length: 0
User-Agent: kamailio (4.0.2 (x86_64/linux))
Contact: <sip:2500-cti.sip.example.com at 10.140.1.31:5060>
Expires: 10

IP 10.140.1.11.sip > 10.140.1.31.sip: UDP, length 519

SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.140.1.31;branch=z9hG4bK5828.83893957.0;received=10.140.1.31
From: sip:2500 at 10.140.1.11;tag=51b6a5d1a9ebf21332da43af5e84fad4-a82f
To: sip:2500 at 10.140.1.11;tag=as28816372
Call-ID: 496dc8f41bad3cd4-3396 at 10.140.1.31
CSeq: 10 REGISTER
Server: FPBX-2.10.0(1.8.8.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="69eb786a"
Content-Length: 0
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 3748 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20130726/14576cbb/attachment-0001.bin>


More information about the sr-users mailing list