[OpenSIPS-Users] Cannot get registration to work with v3.2.8??
Bob Atkins
bob at digilink.net
Wed Sep 7 19:46:45 UTC 2022
Iancu,
Thank you!! You identified the problem. Turns out that I had failed to
add the IP for the OpenSIPS proxy to a firewall that was blocking the
response from this new sip server (facepalm) to the device :-(
So, once I fixed the firewall I thought that would be it... Not my luck.
Now it is challenging and /_*rejecting!*_/ The HA1 is failing to
compare! But the passwords are correct! Now I am really mystified.
I created identical DB entries for this unit in both the original
OpenSER system and the OpenSIPS system.
Registration to the OpenSER system works perfectly - HA1 validates. When
I change the sip server to the new system, to OpenSIPS system fails due
to mismatched HA1. Whaaa.... ?!?!
Mismatched HA1 would imply a password failure but I have absolutely,
positively verified the passwords in both database entries and the
/_*only*_/ thing I change on the device is the sip server. It should
just register on the new system. I have attached packet capture of the
transaction between the device and teh OpenSIPSs system.
I have absolutely, positively copied and pasted (no trailing nl or
spaces) and verified that the passwords are the same in both databases
and also the same on the device.
OpenSER DB subscriber entery
phplib_id username domain password first_name last_name phone
email_address datetime_created datetime_modified confirmation flag
sendnotification greeting ha1 ha1b allow_find timezone rpid domn
uuid customerID customerName
3105738133 3105738133 digilink.net XXXXXXXX PPC Home Fax 3105738133
7/5/2012 16:36 11/7/2021 13:58
o
0 \N \N \N \N 72 DigiLink Internet Services
OpenSIPS DB subscriber entry
id username domain password cr_preferred_carrier first_name
last_name phone email_address datetime_created datetime_modified
confirmation flag sendnotification greeting allow_find timezone
customerID customerName ha1 ha1_sha256 ha1_sha512t256 rpid
1 3105738133 digidial XXXXXXXX \N PPC Home Fax 3105738133
bob at planeparts.com 7/5/2012 16:36 11/7/2021 13:58
0
72 DigiLink Internet Services \N
Registration code:
OpenSER system:
modparam("auth_db", "calculate_ha1", yes)
modparam("auth_db", "password_column", "password")
if (method=="REGISTER") {
#xlog("L_INFO","[$rm][$ft][$tt] Processing
registration");
if (!www_authorize("digilink.net", "subscriber")) {
#xlog("L_INFO","[$rm][$ft][$tt]
Challenging peer");
www_challenge("digilink.net", "0");
exit;
};
xlog("L_INFO","[$rm][$ft][$tt] Registered $fu from
$si");
save("location");
exit;
};
==============
OpenSIPS system
#### AUTH Db module
loadmodule "auth.so"
loadmodule "auth_db.so"
modparam("auth_db", "calculate_ha1", 1)
modparam("auth_db", "use_domain", 1)
modparam("auth_db", "user_column", "username")
modparam("auth_db", "password_column", "password")
modparam("auth_db", "load_credentials", "")
if (is_method("REGISTER")) {
xlog("L_INFO", "REGISTER: [$tu] request from [$si]");
xlog("L_INFO","[$ft][$au]@[$ad] - Processing registration");
xlog("L_INFO", "REGISTER: www_authorize returned [$var(x)]
to authenticate with [$rU]$ru credential");
if (!www_authorize("digilink.net", "subscriber")) {
xlog("L_INFO","CHALLENGE: [$ft][$tt]");
www_challenge("digilink.net","auth","MD5");
exit;
} else {
xlog("L_ALERT", "REGISTER: URI [$tu][$rU]$ru credential
from [$si] - FAILED!");
sl_send_reply(403, "Not Authorized!");
exit;
}
xlog("L_INFO", "REGISTER: URI [$tu] - [$rm][$ft][$tt]
Registered $fu from $si");
save("location");
exit;
}
Debug output:
Sep 7 09:42:09 [5640] DBG:core:parse_msg: SIP Request:
Sep 7 09:42:09 [5640] DBG:core:parse_msg: method: <REGISTER>
Sep 7 09:42:09 [5640] DBG:core:parse_msg: uri: <sip:sip.rs.digidial.net>
Sep 7 09:42:09 [5640] DBG:core:parse_msg: version: <SIP/2.0>
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 7 09:42:09 [5640] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bK-b316ab8b>; state=16
Sep 7 09:42:09 [5640] DBG:core:parse_via: end of header reached, state=5
Sep 7 09:42:09 [5640] DBG:core:parse_headers: via found,
flags=ffffffffffffffff
Sep 7 09:42:09 [5640] DBG:core:parse_headers: this is the first via
Sep 7 09:42:09 [5640] DBG:core:_parse_to: end of header reached, state=10
Sep 7 09:42:09 [5640] DBG:core:_parse_to: display={"PPC Fax"},
ruri={sip:3105738133 at sip.rs.digidial.net}
Sep 7 09:42:09 [5640] DBG:core:get_hdr_field: <To> [48];
uri=[sip:3105738133 at sip.rs.digidial.net]
Sep 7 09:42:09 [5640] DBG:core:get_hdr_field: to body ["PPC Fax"
<sip:3105738133 at sip.rs.digidial.net>
]
Sep 7 09:42:09 [5640] DBG:core:get_hdr_field: cseq <CSeq>: <86966>
<REGISTER>
Sep 7 09:42:09 [5640] DBG:core:get_hdr_field: content_length=0
Sep 7 09:42:09 [5640] DBG:core:get_hdr_field: found end of header
Sep 7 09:42:09 [5640] DBG:core:receive_msg: After parse_msg...
Sep 7 09:42:09 [5640] DBG:core:receive_msg: preparing to run routing
scripts...
Sep 7 09:42:09 [5640] DBG:pike:mark_node: search on branch 205
(top=0x7f90f8b40bd8)
Sep 7 09:42:09 [5640] DBG:pike:mark_node: only first 1 were matched!
Sep 7 09:42:09 [5640] DBG:pike:pike_check_req: src IP
[205.147.62.19],node=0x7f90f8b40bd8; hits=[0,3],[0,0] node_flags=2
func_flags=8
Sep 7 09:42:09 [5640] DBG:maxfwd:is_maxfwd_present: value = 70
Sep 7 09:42:09 [5640] DBG:core:comp_scriptvar: int 27: 833 / 2048
Sep 7 09:42:09 [5640] DBG:core:parse_to_param: tag=30079e2fdf731b79o1
Sep 7 09:42:09 [5640] DBG:core:parse_to_param: end of header reached,
state=11
Sep 7 09:42:09 [5640] DBG:core:_parse_to: end of header reached, state=29
Sep 7 09:42:09 [5640] DBG:core:_parse_to: display={"PPC Fax"},
ruri={sip:3105738133 at sip.rs.digidial.net}
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=78
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=200
Sep 7 09:42:09 [5640] DBG:rr:find_first_route: No Route headers found
Sep 7 09:42:09 [5640] DBG:rr:loose_route: There is no Route HF
... [snip]
Sep 7 09:42:09 [5640] Unknown source [205.147.62.19]:
[sip:3105738133 at sip.rs.digidial.net] request
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 7 09:42:09 [5640] DBG:core:parse_params: Parsing params
for:[expires=300]
Sep 7 09:42:09 [5640] REGISTER: [sip:3105738133 at sip.rs.digidial.net]
request from [205.147.62.19]
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=14000
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=14000
Sep 7 09:42:09 [5640] [30079e2fdf731b79o1][3105738133]@[<null>] -
Processing registration
Sep 7 09:42:09 [5640] REGISTER: www_authorize returned [<null>] to
authenticate with [<null>]sip:sip.rs.digidial.net credentialSep 7
09:42:09 [5640] DBG:auth:pre_auth: nonce index= 1
Sep 7 09:42:09 [5640] DBG:db_mysql:has_stmt_ctx: ctx found for subscriber
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_do_prepared_query:
conn=0x7f90fa86ac90 (tail=140260655146496) MC=0x7f90fa86a698
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_do_prepared_query: set
values for the statement run
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_val2bind: added val (0):
len=10; type=254; is_null=0
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_val2bind: added val (1):
len=12; type=254; is_null=0
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Sep 7 09:42:09 [5640] DBG:db_mysql:mysql_raise_event: MySQL status has
not changed: connected
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_do_prepared_query: prepared
statement has 1 columns in result
Sep 7 09:42:09 [5640] DBG:core:db_new_result: allocate 48 bytes for
result set at 0x7f90fa86cb98
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_get_columns: 1 columns
returned from the query
Sep 7 09:42:09 [5640] DBG:core:db_allocate_columns: allocate 28 bytes
for result columns at 0x7f90fa86d480
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7f90fa86d488)[0]=[ha1]
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_get_columns: use DB_STRING
result type
Sep 7 09:42:09 [5640] DBG:core:db_allocate_rows: allocate 48 bytes for
result rows and values at 0x7f90fa86c170
Sep 7 09:42:09 [5640] DBG:db_mysql:db_mysql_str2val: converting STRING []
Sep 7 09:42:09 [5640] DBG:auth_db:get_ha1: _*HA1 string calculated:
115137ac8cc974c418c92e51dfb4fffb*_
Sep 7 09:42:09 [5640] DBG:auth:check_response: *_our result =
'841dc25d395e34bab3c0251e200b38f9'_*
Sep 7 09:42:09 [5640] DBG:auth:check_response: _*authorization failed*_
Sep 7 09:42:09 [5640] DBG:core:db_free_columns: freeing result columns
at 0x7f90fa86d480
Sep 7 09:42:09 [5640] DBG:core:db_free_rows: freeing 1 rows
Sep 7 09:42:09 [5640] DBG:core:db_free_row: freeing row values at
0x7f90fa86c180
Sep 7 09:42:09 [5640] DBG:core:db_free_rows: freeing rows at 0x7f90fa86c170
Sep 7 09:42:09 [5640] DBG:core:db_free_result: freeing result set at
0x7f90fa86cb98
Sep 7 09:42:09 [5640] DBG:core:pv_get_xto_attr: no Tag parameter
Sep 7 09:42:09 [5640] CHALLENGE: [30079e2fdf731b79o1][<null>]Sep 7
09:42:09 [5640] DBG:auth:reserve_nonce_index: second= 13, sec_monit=
-1, index= 2
Sep 7 09:42:09 [5640] DBG:auth:challenge: nonce index= 2
Sep 7 09:42:09 [5640] DBG:auth:build_auth_hf: 'WWW-Authenticate: Digest
realm="digilink.net",
nonce="jc2ceYLP1dzX+qS8Erm1zKIihYg6b953YdAZIa38dj4A", qop="auth",
algorithm=MD5'
Sep 7 09:42:09 [5640] DBG:core:MD5StringArray: MD5 calculated:
a7216245b8ac903b73694b3c3949959b
Sep 7 09:42:09 [5640] DBG:core:parse_headers: flags=ffffffffffffffff
Sep 7 09:42:09 [5640] DBG:core:destroy_avp_list: destroying list (nil)
Sep 7 09:42:09 [5640] DBG:core:receive_msg: cleaning up
--
*Bob Atkins *
/President/CEO/
*DigiLink, Inc. <http://www.digilink.net>*
Business Inter-net-working
*/The Cure for the Common ISP!/*
Phone: (310) 577-9450
Fax: (310) 577-3360
eMail: bob at digilink.net
On 9/6/2022 11:16 PM, Bogdan-Andrei Iancu wrote:
> Hi Bob,
>
> Well, the logs cover only the challenge part, the handling of the
> REGISTER without any credentials - this is the first normal step in
> the digest auth process.
>
> As per log, no Auth hdrs are found in the incoming REGISTER and a
> challenge reply is built and sent back (see the last log line below):
>
> Sep 6 11:34:42 [4299] DBG:core:pv_get_authattr: no
> [Proxy-]Authorization header
> Sep 6 11:34:42 [4299] [e5f4a8407663e4f7a3970][<null>]@[<null>] -
> Processing registrationSep 6 11:34:42 [4299] DBG:core:parse_headers:
> flags=4000
> Sep 6 11:34:42 [4299] DBG:auth:pre_auth: credentials with given realm
> not found
> Sep 6 11:34:42 [4299] DBG:auth:reserve_nonce_index: second= 19,
> sec_monit= 22, index= 36
> Sep 6 11:34:42 [4299] DBG:auth:challenge: nonce index= 36
> Sep 6 11:34:42 [4299] DBG:auth:build_auth_hf: 'WWW-Authenticate:
> Digest realm="23.253.166.155",
> nonce="945VEH4DrBNkbwzJOMTyiEbNih+ChrtOdEF1sn9J0QAA", qop="auth",
> algorithm=MD5
>
> But normally it should be a second incoming REGISTER (as response to
> the challenge) with credentials this time. Do you have the logs from
> both REGISTER requests and eventually the SIP capture for them?
>
> Best regards,
> Bogdan-Andrei Iancu
>
> OpenSIPS Founder and Developer
> https://www.opensips-solutions.com
> OpenSIPS Summit 27-30 Sept 2022, Athens
> https://www.opensips.org/events/Summit-2022Athens/
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20220907/fddabb29/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ATA-OpenSIPS-reg-failure.pkt.pcap
Type: application/octet-stream
Size: 24840 bytes
Desc: not available
URL: <http://lists.opensips.org/pipermail/users/attachments/20220907/fddabb29/attachment-0001.obj>
More information about the Users
mailing list