Bugs item #3490945, was opened at 2012-02-22 04:43 Message generated for change (Settings changed) made by vladut-paiu 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: 3 Private: No Submitted By: saghul (saghul) Assigned to: Vladut-Stefan Paiu (vladut-paiu) 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 ---------------------------------------------------------------------- Comment By: saghul (saghul) Date: 2012-03-02 04:02 Message: Hi Vlad, Yes, it is very weird :-S I'll enable query debug and see if I can find the appropriate parts of the log, since I have to do this in a server with quite some traffic. Regards, ---------------------------------------------------------------------- Comment By: Vladut-Stefan Paiu (vladut-paiu) Date: 2012-03-02 03:53 Message: Hi, Can you please enable MySQL query logging on the MySQL server side and see exactly which prep. statements are prepared & then executed ? The behavior you are describing sounds very weird... Regards, Vlad ---------------------------------------------------------------------- Comment By: saghul (saghul) Date: 2012-02-27 00:45 Message: Hi, After more debugging I have some more information on this. By adding some debug statements to the code I verified that the right column was being selected for the query. However, when the query was actually executed I got the wrong column back :-O Of course, I only see this happening in an environment where endpoints require the use of ha1 and ha1b. If I test it in an environment where only ha1 should be used (only username is sent in the authorization digest) the problem doesn't show up. Given this facts I suspect there is a race of some sort when building and sending the prepared statement (I only tested MySQL db backend). In order to verify this I modified the code to remove prepared statements support and the problem ceased. Any hints on how to further debug this? Regards, ---------------------------------------------------------------------- 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
