Bugs item #3490945, was opened at 2012-02-22 04:43 Message generated for change (Tracker Item Submitted) made by saghul You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3490945&group_id=232389
Please note that this message will contain a full copy of the comment thread, including the initial issue submission, for this request, not just the latest update. Category: core Group: trunk Status: Open Resolution: None Priority: 5 Private: No Submitted By: saghul (saghul) Assigned to: Nobody/Anonymous (nobody) Summary: Wrong password column used for authentication Initial Comment: Hi, I'm experiencing the following problem which happens consistently yet I can't find a way to reproduce it at my will: When www_authorize is called for a REGISTER request which does contain credentials and a domain-less username in the Authorization header, -2 (wrong password) is returned, even if the password was correct. By looking at the debug logs (level 4) I see that when this happens the ha1b field is used to build our (OpenSIPS) digest response and compare it with what was received from the remote endpoint, instead of ha1. In this case ha1 should be used, because the username in the Authorization header doesn't contain a domain. I've observed this behavior happen consistently several times a day, so sometimes the ha1b field will be used and most of the times ha1 (the correct one) will be used, even if packets are exactly the same. Here is the debug (level4) output for the failure case: Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: REGISTER sip:[email protected] from sip:85.17.186.7:5060 <sip:[email protected]:58353> Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_to_param: tag=k5Mi2wzv5.7uHiRzEEuS8aPyMNDMisfe Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_to: end of header reached, state=29 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_to: display={"saghul"}, ruri={sip:[email protected]} Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: This is the home proxy Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:avpops:ops_dbquery_avps: query [SELECT id FROM subscriber WHERE username='saghul' AND domain='sip2sip.info'] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x9306928 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x92e3018 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x92e301c)[0]=[id] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_allocate_rows: allocate 28 bytes for result rows and values at 0x92fd888 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting INT [5049] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:avpops:db_query_avp: rows [1] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:avpops:db_query_avp: row [0] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:avpops:db_close_query: close avp query Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_columns: freeing result columns at 0x92e3018 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_rows: freeing 1 rows Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_row: freeing row values at 0x92fd890 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_rows: freeing rows at 0x92fd888 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_result: freeing result set at 0x9306928 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:permissions:check_addr_6: Looking for : <5149, 62.131.6.55, any, 65462, (null)> Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:permissions:hash_match: specified group 5149 does not exist in hash table Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:permissions:match_subnet_table: subnet table is empty Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: Request came from Thor node 85.17.186.7:5060 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:escape_param: escaped string is <sip:62.131.6.55:65462> Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:comp_scriptvar: str 29 : Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:auth:check_nonce: comparing [4f44cdaf51a5c1b40f0866ebbf0203d574f56e38] and [4f44cdaf51a5c1b40f0866ebbf0203d574f56e38] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:has_stmt_ctx: ctx found for subscriber Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x92e2508 (tail=153993112) MC=0x92dbfc0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=12; type=254; is_null=0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 7 columns in result Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x92e3018 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: 7 columns returned from the query Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_allocate_columns: allocate 112 bytes for result columns at 0x9316048 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x9316064)[0]=[ha1b] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x931606c)[1]=[call_limit] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x9316074)[2]=[prepaid] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x931607c)[3]=[region] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x9316084)[4]=[rpid] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x931608c)[5]=[last_name] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x9316094)[6]=[first_name] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_allocate_rows: allocate 148 bytes for result rows and values at 0x93160c0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting STRING [586d941b3962895ee8a355de4ed4208b] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting INT [3] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting INT [1] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting STRING [] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting STRING [] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting STRING [Ibarra Corretge] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:db_mysql:db_mysql_str2val: converting STRING [Saul] Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:auth:check_response: our result = '55569377d229d4576ba641c8cb4b15ed' Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:auth:check_response: authorization failed Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_columns: freeing result columns at 0x9316048 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_rows: freeing 1 rows Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_row: freeing row values at 0x93160c8 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_rows: freeing rows at 0x93160c0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:db_free_result: freeing result set at 0x92e3018 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:comp_scriptvar: int 26 : -2 / 0 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: Asking credentials...(error code: -2) Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:auth:build_auth_hf: 'WWW-Authenticate: Digest realm="sip2sip.info", nonce="4f44cdaf51a5c1b40f0866ebbf0203d574f56e38"#015#012' Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:parse_headers: flags=ffffffffffffffff Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:check_ip_address: params 85.17.186.7, 85.17.186.7, 1 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:sl:run_sl_callbacks: callback id 2 entered Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:sl:run_sl_callbacks: callback id 0 entered Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:siptrace:trace_sl_onreply_out: trace slonreply out Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:siptrace:trace_sl_onreply_out: nothing to trace... Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:destroy_avp_list: destroying list 0xaf8328f8 Feb 22 12:12:17 node11 /usr/sbin/opensips[17758]: DBG:core:receive_msg: cleaning up ---------------------------------------------------------------------- You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3490945&group_id=232389 _______________________________________________ Devel mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
