Hi,

you can try to use 65536 for error log level. I suspect that the entry you're trying to add contains an attribute that should be unique across the whole LDAP database but that already exists. Could you share the audit log, maybe something in the entry will stand out?

flo

On Tue, Mar 8, 2022 at 11:37 AM Charles P <pillarama@gmail.com> wrote:
Hi Flo,
  Thanks so much for your detailed and fast response. I'm using "reply
all" - is that the correct action here?Or should I just be replying to
freeipa-users only? I didn't see anything about it in the list
guidelines...

I tried my best to do what you suggested:


> In order to diagnose the DuplicateEntry issue, you can have a look at 389ds log files in /var/log/dirsrv/slapd-<DOMAIN>. The access file contains the access log and you should see an ADD operation with the dn of the user you're trying to create.

> Once you have located the line, note the conn=xx number as well as the op=yy number and look for the result of this operation, with the same conn= and op= values:
In the access_log I can see the searches taking place:
8/Mar/2022:19:16:12.259426408 +101800] conn=3123 fd=95 slot=95
connection from 192.168.100.130 to 192.168.100.130
[08/Mar/2022:19:16:12.262755827 +101800] conn=3123 op=0 BIND dn=""
method=sasl version=3 mech=GSS-SPNEGO
[08/Mar/2022:19:16:12.265064697 +101800] conn=3123 op=0 RESULT err=0
tag=97 nentries=0 wtime=0.000201096 optime=0.002320006
etime=0.002518948
dn="uid=admin,cn=users,cn=accounts,dc=[removed],dc=net"
[08/Mar/2022:19:16:12.268399248 +101800] conn=3123 op=1 SRCH
base="cn=ipaconfig,cn=etc,dc=[removed],dc=net" scope=0
filter="(objectClass=*)" attrs=ALL
[08/Mar/2022:19:16:12.269620613 +101800] conn=3123 op=1 RESULT err=0
tag=101 nentries=1 wtime=0.000106498 optime=0.001222174
etime=0.001326049
[08/Mar/2022:19:16:12.271806550 +101800] conn=3123 op=2 SRCH
base="uid=mynewuser,cn=deleted
users,cn=accounts,cn=provisioning,dc=[removed],dc=net" scope=0
filter="(objectClass=*)" attrs="distinguishedName"
[08/Mar/2022:19:16:12.272126465 +101800] conn=3123 op=2 RESULT err=32
tag=101 nentries=0 wtime=0.000093627 optime=0.000321737
etime=0.000412649
[08/Mar/2022:19:16:12.273027239 +101800] conn=3123 op=3 SRCH
base="cn=UPG Definition,cn=Definitions,cn=Managed
Entries,cn=etc,dc=[removed],dc=net" scope=0 filter="(objectClass=*)"
attrs="* aci"
[08/Mar/2022:19:16:12.273566108 +101800] conn=3123 op=3 RESULT err=0
tag=101 nentries=1 wtime=0.000098087 optime=0.000540082
etime=0.000635405
[08/Mar/2022:19:16:12.274714387 +101800] conn=3123 op=4 SRCH
base="cn=mynewuser,cn=groups,cn=accounts,dc=[removed],dc=net" scope=0
filter="(objectClass=*)" attrs="distinguishedName"
[08/Mar/2022:19:16:12.275024708 +101800] conn=3123 op=4 RESULT err=32
tag=101 nentries=0 wtime=0.000095170 optime=0.000311745
etime=0.000404349
[08/Mar/2022:19:16:12.281628405 +101800] conn=3123 op=5 ADD
dn="uid=mynewuser,cn=users,cn=accounts,dc=[removed],dc=net", add
values for type objectClass failed
[08/Mar/2022:19:16:12.281702770 +101800] conn=3123 op=5 RESULT err=20
tag=105 nentries=0 wtime=-4219620.593567071 optime=4219619.406721314
etime=0.000285773
[08/Mar/2022:19:16:12.282506634 +101800] conn=3123 op=6 UNBIND
[08/Mar/2022:19:16:12.282534963 +101800] conn=3123 op=6 fd=95 closed error - U1

Results are err=32 (noSuchObject) when searching for the user first
and then err=20 (attributeOrValueExists) when trying to add it....
Hmmm. Seems odd to me.


> If the log file doesn't contain enough details, there are also additional steps that can help:
> - increase the error log level as described in https://access.redhat.com/documentation/en-us/red_hat_directory_server/11/html/configuration_command_and_file_reference/core_server_configuration_reference#cnconfig-nsslapd_errorlog_level_Error_Log_Level
> - enable the audit log as described in https://access.redhat.com/documentation/en-us/red_hat_directory_server/11/html/configuration_command_and_file_reference/core_server_configuration_reference#cnconfig-nsslapd_auditlog_logging_enabled_Audit_Log_Enable_Logging
>
So I tried to increase the log level and enable the audit log. I did
some reading and then the following actions, I'm not 100% sure if this
was correct, but it seemed successful:

# ldapmodify -x -D "cn=directory manager" -W
Enter LDAP Password:
dn: cn=config
changetype: modify
replace: nsslapd-errorlog-level
nsslapd-errorlog-level: 1024
[CTRL-D]
modifying entry "cn=config"
(And repeat for nsslapd-auditlog-logging-enabled: on)

# ldapsearch -H ldap://$HOSTNAME -D 'cn=Directory Manager' -W -x -s
base -b 'cn=config' | grep errorlog
Enter LDAP Password:
nsslapd-errorlog-level: 128
nsslapd-errorlog-logging-enabled: on
[...]


I tried with various levels, but strangely above 128 I get no log
entries at all in error_log and from 128 and below I get thousands.
Every single line seems to be prefixed with NSACLPlugin and nothing
looked useful to my eye...

/var/log/dirsrv/slapd-[REMOVED]-NET/errors
[08/Mar/2022:20:39:51.039696183 +101800] - DEBUG - NSACLPlugin - ACI
type:(compare search read write delete add self target_attr acltxt
target_attr_not allow_rule )
[08/Mar/2022:20:39:51.040371707 +101800] - DEBUG - NSACLPlugin - ACI
RULE type:(groupdn )
[08/Mar/2022:20:39:51.041071014 +101800] - DEBUG - NSACLPlugin -
Slapi_Entry DN:dc=[removed],dc=net
[08/Mar/2022:20:39:51.041730833 +101800] - DEBUG - NSACLPlugin -
***END ACL INFO*****************************
[08/Mar/2022:20:39:51.042491716 +101800] - DEBUG - NSACLPlugin -
acl__scan_for_acis - Num of ALLOW Handles:3, DENY handles:0
[08/Mar/2022:20:39:51.043154236 +101800] - DEBUG - NSACLPlugin -
acl_access_allowed - Processed attr:uid for
entry:uid=postfix,cn=users,cn=accounts,dc=[removed],dc=net
[08/Mar/2022:20:39:51.043930791 +101800] - DEBUG - NSACLPlugin -
acl__TestRights - 1. Evaluating ALLOW aci(93) " "permission:System:
Read User Standard Attributes""
[08/Mar/2022:20:39:51.044651773 +101800] - DEBUG - NSACLPlugin -
acl__TestRights - Found SEARCH ALLOW in cache

Did I enable the debug logging correctly?

Thanks

Pillarama