Bug 2057070 - Improve password policy debug logging
Summary: Improve password policy debug logging
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Directory Server
Classification: Red Hat
Component: 389-ds-base
Version: 12.0
Hardware: Unspecified
OS: Unspecified
high
medium
Target Milestone: DS12.3
: dirsrv-12.3
Assignee: mreynolds
QA Contact: LDAP QA Team
Evgenia Martynyuk
URL:
Whiteboard: sync-to-jira
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-02-22 17:00 UTC by mreynolds
Modified: 2023-05-31 10:18 UTC (History)
7 users (show)

Fixed In Version: redhat-ds-12-9020020221130212339.1674d57
Doc Type: Enhancement
Doc Text:
.The NUNC_STANS error logging level was replaced by the new `1048576` logging level Previously, you could not easily debug password policy issues. With the new `1048576` logging level for the error log, you can now check the following password policy information: * Which local policy rejects or allows a password update. * The exact syntax violation.
Clone Of:
Environment:
Last Closed: 2023-05-30 09:40:35 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
PWDPOLICY_DEBUG messages (3.68 KB, text/plain)
2023-02-10 14:57 UTC, Viktor Ashirov
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github 389ds 389-ds-base issues 3061 0 None open Improve password policy debug logging 2022-02-22 18:20:53 UTC
Red Hat Issue Tracker IDMDS-2031 0 None None None 2022-02-22 17:12:50 UTC
Red Hat Issue Tracker IDMDS-2776 0 None None None 2023-02-09 11:14:39 UTC
Red Hat Product Errata RHBA-2023:3344 0 None None None 2023-05-30 09:41:09 UTC

Description mreynolds 2022-02-22 17:00:54 UTC
Description of problem:

Currently there is no way to easily debug password policy issues. Trying to figure out which local policy rejected the password, or what syntax was actually violated is not possible.

We should:

1. Improve the client message to be more precise (which also ends up in the access log)

2. Add a new error log level for password policy debugging. 

    - Report on things like:
          - Which local policy is rejecting or allowing a password update
          - Information on the exact syntax violation

Comment 1 mreynolds 2022-02-22 17:02:05 UTC
Upstream ticket:

https://github.com/389ds/389-ds-base/issues/3061

Comment 2 mreynolds 2022-10-06 18:08:32 UTC
Documentation only needs to update the error log levels:

Error log logging level:  1048576   ---> this replaces the NUNC_STANS logging level

Comment 3 Viktor Ashirov 2023-02-10 14:56:28 UTC
Automated test passed:
============================================= test session starts =============================================
platform linux -- Python 3.9.16, pytest-6.2.2, py-1.10.0, pluggy-0.13.1 -- /usr/bin/python3
cachedir: .pytest_cache
389-ds-base: 2.2.6-1.module+el9dsrv+17949+63c5b04e
nss: 3.79.0-14.el9_0
nspr: 4.34.0-14.el9_0
openldap: 2.6.2-3.el9
cyrus-sasl: not installed
FIPS: disabled
rootdir: /root/ds/dirsrvtests, configfile: pytest.ini
collected 1 item

dirsrvtests/tests/suites/password/pwdPolicy_logging_test.py::test_debug_logging PASSED                  [100%]

======================================== 1 passed in 226.09s (0:03:46) ========================================

And I ran all password policy related tests with log level 1048576 enabled.
There are some inconsistencies in the log messages, that might affect log parsing (i.e. for monitoring systems):
1. Mixed first letter case, see attached file

2. Double space before "Entry:"
Account is locked and requires administrator reset.  Entry (uid=dbyers,ou=people,dc=example,dc=com) Policy (Global)
(also this message is a bit confusing, in the source right above it says: "Exceed password retry limit. Contact system administrator to reset.")
password retry limit exceeded.  Entry (uid=tuser,ou=people,dc=example,dc=com) Policy (Global)
user is not allowed to change password.  Entry (uid=dbyers,ou=People,dc=example,dc=com) Policy (Global)

3. Dot at the end of the message
update pwdTPRUseCount=1 on entry (uid=jdoe1,ou=people,dc=example,dc=com) policy (Global).

4. Mixed separators before "Entry" (dot instead of colon)
Account is locked and requires administrator reset.  Entry (uid=dbyers,ou=people,dc=example,dc=com) Policy (Global)

5. Entry/Policy small case
Unsuccessful bind, increase pwdTPRUseCount = 1 (max 3) - entry (uid=jdoe1,ou=People,dc=example,dc=com) policy (Global)

6. Function name in the message (not sure, maybe it should be there, but it's the only one I encountered)
slapi_check_tpr_limits - attempt to bind with TPR password not yet valid (current=20230210133504Z, validity=20230210133514Z): Entry (uid=jdoe2,ou=people,dc=example,dc=com) Policy (Global)


Moving to ASSIGNED.

Comment 4 Viktor Ashirov 2023-02-10 14:57:23 UTC
Created attachment 1943356 [details]
PWDPOLICY_DEBUG messages

Comment 5 Viktor Ashirov 2023-04-24 07:58:00 UTC
Hi Mark,

this bug is in MODIFIED, but I can't find any changes upstream. And I don't see them in the latest build.
Shouldn't this bug be in the ASSIGNED state?

Thanks.

Comment 6 Viktor Ashirov 2023-05-09 11:33:45 UTC
Moving to ASSIGNED as it still needs to be addressed.

Comment 7 mreynolds 2023-05-16 15:01:14 UTC
(In reply to Viktor Ashirov from comment #5)
> Hi Mark,
> 
> this bug is in MODIFIED, but I can't find any changes upstream. And I don't
> see them in the latest build.
> Shouldn't this bug be in the ASSIGNED state?
> 
> Thanks.

It's there:

$ git checkout Directory_Server_12_2_0 
Switched to branch 'Directory_Server_12_2_0'
$ grep -r LDAP_DEBUG_PWDPOLICY *
servers/slapd/log.c:    LDAP_DEBUG_PWDPOLICY,  /* SLAPI_LOG_PWDPOLICY */
servers/slapd/proto-slap.h:#define LDAP_DEBUG_PWDPOLICY  0x00100000  /*   1048576 */


Moving bug back to ON_QA

Comment 8 Viktor Ashirov 2023-05-16 15:23:43 UTC
That's true, but I put bug to ASSIGNED in Comment #3 because of the inconsistencies in the log messages. Later you moved it to POST and I assumed these inconsistencies were fixed upstream.

Branch Directory_Server_12_2_0 doesn't contain fixes for these inconsistencies:
$ grep -r "reset.  Entry"
./ldap/servers/slapd/pw.c:                              "Account is locked and requires administrator reset.  Entry (%s) Policy (%s)\n",

Do you want me to open a new bug for this?

Comment 9 Evgenia Martynyuk 2023-05-16 15:38:30 UTC
Mark, could you please review the RN text in the DocText field? 

Thanks, 
Evgenia

Comment 10 Evgenia Martynyuk 2023-05-17 10:59:18 UTC
RN was reviewed by Viktor, sending to a peer review

Comment 11 mreynolds 2023-05-17 12:54:29 UTC
(In reply to Evgenia Martynyuk from comment #9)
> Mark, could you please review the RN text in the DocText field? 
> 
> Thanks, 
> Evgenia

Looks good

Comment 12 Evgenia Martynyuk 2023-05-18 12:43:51 UTC
RN text passed peer review. Thank you, Masha!

Comment 15 Viktor Ashirov 2023-05-19 15:39:02 UTC
Moving to VERIFIED.
Issues mentioned in Comment 3 will be addressed in a separate bug.

Comment 16 mreynolds 2023-05-22 12:20:37 UTC
Setting target to 12.3 to fix remaining issues...

Comment 17 Viktor Ashirov 2023-05-22 12:28:44 UTC
I've opened https://bugzilla.redhat.com/show_bug.cgi?id=2209047 for the remaining issues.

Let's move this back to VERIFIED as it has RN attached and is part of the erratum.

Comment 19 errata-xmlrpc 2023-05-30 09:40:35 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (redhat-ds:12 bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:3344


Note You need to log in before you can comment on or make changes to this bug.