[OpenSIPS-Devel] [ opensips-Bugs-3490945 ] Wrong password column used for authentication

SourceForge.net noreply at sourceforge.net
Fri Mar 16 11:46:58 CET 2012


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:saghul at sip2sip.info from sip:85.17.186.7:5060 <sip:kptrquxh at 192.168.99.53: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:saghul at sip2sip.info}
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



More information about the Devel mailing list