Bug 1376057

Summary: Misleading error messages for wrong replica credentials
Product: Red Hat Enterprise Linux 7 Reporter: Sankar Ramalingam <sramling>
Component: 389-ds-baseAssignee: Noriko Hosoi <nhosoi>
Status: CLOSED CURRENTRELEASE QA Contact: Viktor Ashirov <vashirov>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.4CC: mreynolds, nkinder, rmeggins, sramling
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-12-07 18:06:50 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Sankar Ramalingam 2016-09-14 14:35:09 UTC
Description of problem:
While verifying bug #1370300, I encountered misleading error messages. DS error log shows "error 49 invalid credentials, as well error 0, success" for passing invalid credentials to nsDS5ReplicaBindDN and nsDS5ReplicaCredentials

Version-Release number of selected component (if applicable): 389-ds-base-1.3.5.10-10

How reproducible: Consistently when passing invalid credentials to Replication agreement.

Steps to Reproduce:
1. Setup 2 way MMR.
2. Check the entries are synced across masters.
3. Change the credentials for replication agreement.
[root@ratangad MMR_WINSYNC]# PORT=1189 ; /usr/bin/ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 << EOF
dn: cn=1189_to_2626_on_ratangad.eng.blr.redhat.com,cn=replica,cn=dc\3Dpasssync\2Cdc\3Dcom,cn=mapping tree,cn=config
replace: nsDS5ReplicaCredentials
nsDS5ReplicaCredentials: InvalidPW123
EOF

modifying entry "cn=1189_to_2626_on_ratangad.eng.blr.redhat.com,cn=replica,cn=dc\3Dpasssync\2Cdc\3Dcom,cn=mapping tree,cn=config"

[root@ratangad MMR_WINSYNC]# PORT=1189 ; /usr/bin/ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 << EOF
dn: cn=1189_to_14089_on_ratangad.eng.blr.redhat.com,cn=replica,cn=dc\3Dpasssync\2Cdc\3Dcom,cn=mapping tree,cn=config
replace: nsDS5ReplicaBindDN
nsDS5ReplicaBindDN: cn=WrongDN_Repl,cn=config
EOF                                           
modifying entry "cn=1189_to_14089_on_ratangad.eng.blr.redhat.com,cn=replica,cn=dc\3Dpasssync\2Cdc\3Dcom,cn=mapping tree,cn=config"


Initialize the replica again to check if error logs print error 49(Invalid credentials) or error 32(Entry doesn't exist).

Actual results: Error log prints "error 0 success" along with the relevant error message. This is misleading whether the replica initialization is successful or not.


Expected results: Error log prints only relevant messages. It should avoid printing irrelevant messages.


Additional info: 

[14/Sep/2016:16:43:47.323809796 +051800] slapi_ldap_bind - Error: could not bind id [cn=SyncManager,cn=config] authentication mechanism [SIMPLE]: error 49 (Invalid credentials) errno 0 (Success)
[14/Sep/2016:16:43:47.359207135 +051800] slapi_ldap_bind - Error: could not send bind request for id [cn=SyncManager,cn=config] authentication mechanism [SIMPLE]: error -1 (Can't contact LDAP server), system error -5987 (Invalid function argument.), network error 107 (Transport endpoint is not connected, host "ratangad.eng.blr.redhat.com:9989")
[14/Sep/2016:16:43:47.467012608 +051800] slapi_ldap_bind - Error: could not bind id [cn=SyncManagerNN,cn=config] authentication mechanism [SIMPLE]: error 32 (No such object) errno 0 (Success)
[14/Sep/2016:16:43:47.625316253 +051800] slapi_ldap_bind - Error: could not bind id [cn=SyncManager,cn=config] authentication mechanism [SIMPLE]: error 49 (Invalid credentials) errno 0 (Success)

Comment 2 Noriko Hosoi 2016-09-14 16:09:13 UTC
Indeed, it could be misleading:

> [14/Sep/2016:16:43:47.323809796 +051800] slapi_ldap_bind - Error: could not bind id [cn=SyncManager,cn=config] authentication mechanism [SIMPLE]: error 49 (Invalid credentials) errno 0 (Success)

The issue is, the error 49 is from the Directory server's level (ACL), not from the system level (errno).  In the system level, there is no problem.

1223   slapi_log_error(SLAPI_LOG_FATAL, LOG_ERR, "slapi_ldap_bind",
1224        "Error: could not bind id "
1225        "[%s] authentication mechanism [%s]: error %d (%s) errno %d (%s)\n",
1226        bindid ? bindid : "(anon)",
1227        mech ? mech : "SIMPLE",
1228        rc, ldap_err2string(rc), errno, slapd_system_strerror(errno));

For instance, we could replace "errno" with "system error".  Or even we could suppress "errno %d (%s)" part if errno is 0.

But I believe this is not a new issue and this is not a blocker bug.  Plus there are more places having the similar log messages.

I propose to push this to 7.5.

Comment 3 Noriko Hosoi 2016-09-14 16:10:12 UTC
^7.5^7.4^ :p

Comment 4 Sankar Ramalingam 2016-10-11 10:09:09 UTC
(In reply to Noriko Hosoi from comment #2)
> Indeed, it could be misleading:
> 
> > [14/Sep/2016:16:43:47.323809796 +051800] slapi_ldap_bind - Error: could not bind id [cn=SyncManager,cn=config] authentication mechanism [SIMPLE]: error 49 (Invalid credentials) errno 0 (Success)
> 
> The issue is, the error 49 is from the Directory server's level (ACL), not
> from the system level (errno).  In the system level, there is no problem.
> 
> 1223   slapi_log_error(SLAPI_LOG_FATAL, LOG_ERR, "slapi_ldap_bind",
> 1224        "Error: could not bind id "
> 1225        "[%s] authentication mechanism [%s]: error %d (%s) errno %d
> (%s)\n",
> 1226        bindid ? bindid : "(anon)",
> 1227        mech ? mech : "SIMPLE",
> 1228        rc, ldap_err2string(rc), errno, slapd_system_strerror(errno));
> 
> For instance, we could replace "errno" with "system error".  Or even we
> could suppress "errno %d (%s)" part if errno is 0.
> 
> But I believe this is not a new issue and this is not a blocker bug.  Plus
> there are more places having the similar log messages.
I agree with your Noriko.
> 
> I propose to push this to 7.5.

Comment 5 mreynolds 2016-12-07 18:06:50 UTC
This was fixed upstream via: https://fedorahosted.org/389/ticket/48978 and will be included in 7.4 (389-ds-base-1.3.6)