[SR-Users] Auth problem with Jitsi on current kamailio stable

flow27 at meta-matrix.de flow27 at meta-matrix.de
Fri Oct 17 14:57:27 CEST 2014 

Hi,

I have installed kamailio stable on Debian Wheezy from the repository, 
followed the main tutorial and pretty much everything looked like it was 
working at first. I can connect to my sip server but when I try to log 
in I keep getting a failed login.

In the mysql database I have the correct username and domain in the 
subscriber table. No typos there so then I enabled logging with debug=3 
to check the logs but I am not sure how to interprete what I see.

It seems like there 2 two login procedures. The first one seems to 
fail, the second one seems to work since I see a "check_response: 
Authorization is OK" in there but still on Jitsi I keep getting told my 
password is incorrect. Here is the log dump of both login procedures 
from the same login attempt (I only tried to login once and as you see 
on the timestamp it all happens within the same second)



This is the first attempt where the realm is not found even though it 
is exactly the domain I have in the subscriber mysql table:


Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: auth_db 
[authorize.c:486]: auth_check(): realm [video.mydomain.de] table 
[subscriber] flags [1]
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: auth [api.c:86]: 
pre_auth(): auth:pre_auth: Credentials with realm 'video.mydomain.de' 
not found
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: auth_db 
[authorize.c:252]: digest_authenticate_hdr(): no credentials
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: auth 
[challenge.c:127]: get_challenge_hf(): build_challenge_hf: 
realm='video.mydomain.de'
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: auth 
[challenge.c:269]: get_challenge_hf(): auth: 'WWW-Authenticate: Digest 
realm="video.mydomain.de", 
nonce="VEEK6VRBCb32GLPSTiKlfAo4loEn7BTY"#015#012'
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: sl [sl.c:288]: 
send_reply(): reply in stateless mode (sl)
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: <core> 
[msg_translator.c:204]: check_via_address(): 
check_via_address(79.212.239.151, 192.168.2.32, 0)
Oct 17 08:21:17 video /usr/sbin/kamailio[5170]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list 0x7f2f830daa10


Then a second login attempt takes place where it looks different:

Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:623]: parse_msg(): SIP Request:
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:625]: parse_msg():  method:  <REGISTER>
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:627]: parse_msg():  uri:     
<sip:video.mydomain.de:5188>
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:629]: parse_msg():  version: <SIP/2.0>
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: 
<2> <REGISTER>
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header 
reached, state=10
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> 
[46]; uri=[sip:oliver2 at video.mydomain.de]
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body ["oliver2" 
<sip:oliver2 at video.mydomain.de>#015#012]
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/parse_via.c:1284]: parse_via_param(): Found param type 232, 
<branch> = <z9hG4bK-383534-d21acd094f094ec7f76ca01734bb9c80>; state=16
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, 
flags=2
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the 
first via
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[receive.c:152]: receive_msg(): After parse_msg...
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[receive.c:193]: receive_msg(): preparing to run routing scripts...
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: maxfwd 
[mf_funcs.c:85]: is_maxfwd_present(): value = 70
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : 
content_length=0
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/msg_parser.c:106]: get_hdr_field(): found end of header
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: 
tag=f59174d
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header 
reached, state=29
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: sanity 
[mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: siputils 
[checks.c:103]: has_totag(): no totag
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: tm 
[t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global 
id=1 T start=(nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: tm 
[t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: 
hash=60350, isACK=0
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: tm 
[t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching 
failed
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: tm 
[t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no 
transaction found
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: tm 
[t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global 
id=2 T end=(nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth_db 
[authorize.c:486]: auth_check(): realm [video.mydomain.de] table 
[subscriber] flags [1]
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth [api.c:96]: 
pre_auth(): auth: digest-algo:  parsed value: 0
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:118]: db_new_result(): allocate 56 bytes for result set at 
0x7f2f8d09c040
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: db_mysql 
[km_res.c:68]: db_mysql_get_columns(): 1 columns returned from the query
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:155]: db_allocate_columns(): allocate 8 bytes for result names 
at 0x7f2f8d09c148
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:165]: db_allocate_columns(): allocate 4 bytes for result types 
at 0x7f2f8d09c0d8
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: db_mysql 
[km_res.c:86]: db_mysql_get_columns(): allocate 16 bytes for 
RES_NAMES[0] at 0x7f2f8d0aa448
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: db_mysql 
[km_res.c:93]: db_mysql_get_columns(): 
RES_NAMES(0x7f2f8d0aa448)[0]=[password]
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: db_mysql 
[km_res.c:137]: db_mysql_get_columns(): use DB1_STRING result type
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:184]: db_allocate_rows(): allocate 16 bytes for rows at 
0x7f2f8d09c288
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_row.c:119]: db_allocate_row(): allocate 32 bytes for row values at 
0x7f2f8d09e480
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_val.c:117]: db_str2val(): converting STRING [xxxxxxx]
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth_db 
[authorize.c:196]: get_ha1(): HA1 string calculated: 
a4fe9f8e75b2cb7b19da2cbc37b33bcc
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth 
[api.c:211]: auth_check_response(): check_response: Our result = 
'1aab3cbf895ec5c2491135a0a6869f4e'
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth 
[api.c:218]: auth_check_response(): check_response: Authorization is OK
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:81]: db_free_columns(): freeing 1 columns
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:85]: db_free_columns(): freeing RES_NAMES[0] at 0x7f2f8d0aa448
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:94]: db_free_columns(): freeing result names at 0x7f2f8d09c148
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:99]: db_free_columns(): freeing result types at 0x7f2f8d09c0d8
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:54]: db_free_rows(): freeing 1 rows
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_row.c:97]: db_free_row(): freeing row values at 0x7f2f8d09e480
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:62]: db_free_rows(): freeing rows at 0x7f2f8d09c288
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[db_res.c:136]: db_free_result(): freeing result set at 0x7f2f8d09c040
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth 
[challenge.c:127]: get_challenge_hf(): build_challenge_hf: 
realm='video.mydomain.de'
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: auth 
[challenge.c:269]: get_challenge_hf(): auth: 'WWW-Authenticate: Digest 
realm="video.mydomain.de", 
nonce="VEEK6VRBCb32GLPSTiKlfAo4loEn7BTY"#015#012'
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: sl [sl.c:288]: 
send_reply(): reply in stateless mode (sl)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[msg_translator.c:204]: check_via_address(): 
check_via_address(79.212.239.151, 192.168.2.32, 0)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list 0x7f2f830daa10
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying 
list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)
Oct 17 08:21:17 video /usr/sbin/kamailio[5172]: DEBUG: <core> 
[receive.c:296]: receive_msg(): receive_msg: cleaning up


Any help on what I did wrong is appreciated...
Best regards
Oliver

More information about the sr-users mailing list