[SR-Users] Unauthorized register with persistence PostgreSQL

[Gabrielle Eymard]

Hello,
First, thank you for your quick answer!

When you say it’s a password problem, do you talk about the password of the user that kamailio use to connect my database?
Because it doesn’t seem to be a connection problem between PostgreSQL and Kamailio. I think the connection is established between those two because I’m able to see the result of my “kamctl db show subscriber” command. Indeed, I saw what sip contacts are registered in the database. They are the ones I added with the kamctl add command. (By the way, if I finally make my configuration working, sip phones will be seeable in this command results?)

If you talk about sip phones password, I know that when I add manually a new sip contact with kamctl add (and it’s registered in the database), I have to set a password. But before I change the basic config of Kamailio, when sip-phones registered on it (and they’ve been in its cache), no password was needed (at least, this was what I thought).
Is it still wright with my new configuration? 

So, I follow your advice and set debug=3. In Kamailio log, I can see that the REGISTER is correctly received and parse. But I can see this line and I don’t really know what to think about it:

Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed

And this line inquires me too :

Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth_db [authorize.c:196]: get_ha1(): no result for user '1001@'
“1001” is the ID of one of my sip-phones. And I don’t understand why there is nothing after the @...

I did the same test with a jitsi client and I still have the sale “ID@” and nothing after.

Here is a more complete extract of the Kamailio log, if it helps:

Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26614]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26614]: DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP Request:
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:625]: parse_msg():  method:  <REGISTER>
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:627]: parse_msg():  uri:     <sip:sipr.domain>
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:629]: parse_msg():  version: <SIP/2.0>
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-8141f9e3>; state=16
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg...
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [receive.c:197]: receive_msg(): preparing to run routing scripts...
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=10
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [26]; uri=[sip:1001 at sipr.domain] 
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:1001 at sipr.domain>#015#012]
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <53896> <REGISTER>
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70 
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=f10d25c01b845303o0
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: sanity [mod_sanity.c:255]: w_sanity_check(): sanity checks result: 1
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: siputils [checks.c:103]: has_totag(): no totag
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=1 T start=(nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=51997, isACK=0
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=2 global id=2 T end=(nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [select.c:429]: run_select(): Calling SELECT 0x7fc256a21030 
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth_db [authorize.c:498]: auth_check(): realm [sipr.domain] table [subscriber] flags [1]
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth [api.c:96]: pre_auth(): auth: digest-algo: MD5 parsed value: 1
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_val.c:163]: db_postgres_val2str(): PQescapeStringConn: in: 4 chars, out: 4 chars
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_dbase.c:230]: db_postgres_submit_query(): sending query ok: 0x7fc2569d69e8 (2) - [select password from subscriber where username='1001']
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:118]: db_new_result(): allocate 56 bytes for result set at 0x7fc256a42698
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_dbase.c:509]: db_postgres_store_result(): 0x7fc2569d69e8 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x1d85300)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_res.c:108]: db_postgres_get_columns(): 1 columns returned from the query
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:156]: db_allocate_columns(): allocate 8 bytes for result names at 0x7fc256a23088
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:167]: db_allocate_columns(): allocate 4 bytes for result types at 0x7fc256a21418
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_res.c:126]: db_postgres_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7fc256a37478
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_res.c:133]: db_postgres_get_columns(): RES_NAMES(0x7fc256a37478)[0]=[password]
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_res.c:166]: db_postgres_get_columns(): use DB1_STRING result type
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_res.c:211]: db_postgres_convert_rows(): no rows returned from the query
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: db_postgres [km_dbase.c:390]: db_postgres_free_query(): PQclear(0x1d85300) result set
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth_db [authorize.c:196]: get_ha1(): no result for user '1001@'
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:81]: db_free_columns(): freeing 1 columns
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:85]: db_free_columns(): freeing RES_NAMES[0] at 0x7fc256a37478
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:94]: db_free_columns(): freeing result names at 0x7fc256a23088
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:99]: db_free_columns(): freeing result types at 0x7fc256a21418
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [db_res.c:136]: db_free_result(): freeing result set at 0x7fc256a42698
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth [challenge.c:127]: get_challenge_hf(): build_challenge_hf: realm='sipr.domain'
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: auth [challenge.c:269]: get_challenge_hf(): auth: 'WWW-Authenticate: Digest realm="sipr.domain", nonce="VTc+2FU3PawuhZiUHLXCW5khAX+Oueek"#015#012'
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: sl [sl.c:296]: send_reply(): reply in stateless mode (sl)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [msg_translator.c:206]: check_via_address(): check_via_address(192.168.254.12, 192.168.254.12, 0)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [usr_avp.c:643]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)
Apr 22 08:20:28 host-sipr /usr/sbin/kamailio[26616]: DEBUG: <core> [receive.c:298]: receive_msg(): receive_msg: cleaning up

After this last line, I’ve got, these lines, constantly repeated :

Apr 22 08:22:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: <core> [db_res.c:118]: db_new_result(): allocate 56 bytes for result set at 0x7fc256a37298
Apr 22 08:22:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: db_postgres [km_dbase.c:509]: db_postgres_store_result(): 0x7fc256a1be10 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x1d85300)
Apr 22 08:22:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: db_postgres [km_dbase.c:390]: db_postgres_free_query(): PQclear(0x1d85300) result set
Apr 22 08:22:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: <core> [db_res.c:81]: db_free_columns(): freeing 0 columns
Apr 22 08:22:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: <core> [db_res.c:136]: db_free_result(): freeing result set at 0x7fc256a37298
Apr 22 08:23:20 host-sipr /usr/sbin/kamailio[26617]: DEBUG: db_postgres [km_dbase.c:230]: db_postgres_submit_query(): sending query ok: 0x7fc256a1be10 (1) - [delete from location where expires<'2015-04-22 08:23:21' AND expires!='1970-01-01 01:00:00']


Thanks again for your help,

Gab