Learn how easy it is to sync an existing GitHub or Google Code repo to a SourceForge project! See Demo

Close

#477 Wrong password column used for authentication

trunk
closed-fixed
core (110)
3
2014-08-13
2012-02-22
saghul
No

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@sip2sip.info from sip:85.17.186.7:5060 <sip:kptrquxh@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@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

Discussion

  • saghul
    saghul
    2012-02-27

    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,

     
  • 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

     
    • assigned_to: nobody --> vladut-paiu
     
  • saghul
    saghul
    2012-03-02

    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,

     
    • priority: 5 --> 3
     
  • Hi Saul,

    Any updates on this ?

    Regards,
    Vlad

     
  • saghul
    saghul
    2012-03-16

    Hi Vlad,

    Unfortunately I haven't been able to setup a test, it's still on my TODO list though :-S

    Regards,

     
    • assigned_to: Vladut-Stefan Paiu --> Bogdan-Andrei Iancu
     
    • status: open --> closed-fixed
     
  • saghul
    saghul
    2013-06-17

    Sweet! I'll test it on the next build we make. Thanks for the heads up!