#8224 hostgroup_add_member: did not add member
Closed: invalid by schlitzered. Opened by schlitzered.

Issue

we have some automation, that will put hosts into host groups, using the "hostgroup_add_member" RPC function.

we just found one case, where the call completed successfully, but the host did not actually make it into the hostgroup. here is the relevant log message:

apache error log:
(on ipa-2.example.com)
[Wed Mar 11 11:18:43.262333 2020] [:error] [pid 94481] ipa: INFO: [xmlserver_session] cwfm_aws.prod.us-east-1.aws@LINUX.EXAMPLE.COM: host_add(u'i-example-1.dev.us-east-1.aws.linux.example.com', random=1, setattr=(), force=1, version=u'2.51'): SUCCESS

(on ipa-1.example.com)
[Wed Mar 11 11:18:49.008503 2020] [:error] [pid 75001] ipa: INFO: [jsonserver_session] awslambda@LINUX.EXAMPLE.COM: hostgroup_add_member(u'aws_micro_account_xxx', all=True, raw=False, version=u'2.231', no_members=False, host=u'i-example-1.dev.us-east-1.aws.linux.example.com'): SUCCESS

apache access log:
x.x.x.x - awslambda@LINUX.EXAMPLE.COM [11/Mar/2020:11:18:48 -0400] "POST /ipa/session/json HTTP/1.1" 200 460

adding the host manually worked, also the automated process usually works.

is it maybe a timing issue, between creation of the host, and adding it to a host group? not sure but maybe ipa-2.example.com did not in time replicate the data of host creation to ipa-1.example.com, where the command hostgroup_add_member was executed.

Steps to Reproduce

  1. not reproducible

Actual behavior

host was not added to hostgroup

Expected behavior

host is always added to hostgroup, or at least an error message should be created

Version/Release/Distribution

[root@ipa-1.prod.va.dc httpd]$ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
package freeipa-server is not installed
package freeipa-client is not installed
ipa-server-4.6.5-11.el7_7.3.x86_64
ipa-client-4.6.5-11.el7_7.3.x86_64
389-ds-base-1.3.9.1-12.el7_7.x86_64
pki-ca-10.5.16-5.el7_7.noarch
krb5-server-1.15.1-37.el7_7.2.x86_64


How about 389-ds access logs for this entry?

Replication shouldn't be a factor since the server queries itself to see if a candidate member exists.

the ldap access log has already been rotated. seems like we do not even have 1 day worth of logs.

since i am unable to find a logrotate config for 389-ds, how can i adjust logrotate settings, and maybe add compression for rotated logs?

There should be an access. created by the rotation.

yes, there is, but there are so many logs, that each logfile only contains
2-3h worth of data

-rw------- 1 dirsrv dirsrv 26384069 Mar 12 10:01 access
-rw------- 1 dirsrv dirsrv 105115726 Mar 12 02:15 access.20200311-234934
-rw------- 1 dirsrv dirsrv 104858149 Mar 12 04:43 access.20200312-021605
-rw------- 1 dirsrv dirsrv 105255753 Mar 12 07:02 access.20200312-044336
-rw------- 1 dirsrv dirsrv 105202646 Mar 12 09:25 access.20200312-070308

how can i adjust the log rotation configuration of 389-ds?

Am Do., 12. M=C3=A4rz 2020 um 14:58 Uhr schrieb Rob Crittenden <pagure@pagu=
re.io

:

rcritten added a new comment to an issue you are following:
There should be an access.<date> created by the rotation.

To reply, visit the link below or just reply to this email
https://pagure.io/freeipa/issue/8224

https://access.redhat.com/documentation/en-us/red_hat_directory_server/10/html/administration_guide/configuring_logs

okay, i have now set the following on one of the IdM servers, lets see if this is doing the right thing:

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logminfreediskspace
nsslapd-accesslog-logminfreediskspace: 10240

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logmaxdiskspace
nsslapd-accesslog-logmaxdiskspace: 40960

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-maxlogsperdir
nsslapd-accesslog-maxlogsperdir: 168

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-maxlogsize
nsslapd-accesslog-maxlogsize: 1024

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logrotationtime
nsslapd-accesslog-logrotationtime: 1

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logrotationtimeunit
nsslapd-accesslog-logrotationtimeunit: hour

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logrotationsync-enabled
nsslapd-accesslog-logrotationsync-enabled: on

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logrotationsynchour
nsslapd-accesslog-logrotationsynchour: 23

dn: cn=config
changetype: modify
replace: nsslapd-accesslog-logrotationsyncmin
nsslapd-accesslog-logrotationsyncmin: 59

i hope this will give me 7x24 logfiles, with each logfile being max 1GB, so hopefully a week of logs.

btw, is there a way to do compression? if not i will raise a feature request for this.

I don't know but you'd need to raise this type of RFE directly with the 389 project.

ok, i created a feature request in the 389 project

i just had the same issue again, but this time, i have the ldap logs:

apache access log:
10.128.169.54 - awslambda@LINUX.EXAMPLE.COM [26/Mar/2020:15:27:46 -0400] "POST /ipa/session/json HTTP/1.1" 200 446

apache error log:
[Thu Mar 26 15:27:46.203743 2020] [:error] [pid 28786] ipa: INFO: [jsonserver_session] awslambda@LINUX.EXAMPLE.COM: hostgroup_add_member(u'aws_micro_account_XXX', all=True, raw=False, version=u'2.235', no_members=False, host=u'i-XXX-1.dev.us-east-1.aws.linux.example.com'): SUCCESS

dirsrv:
[26/Mar/2020:15:27:46.075964377 -0400] conn=6333769 fd=551 slot=551 connection from 172.20.58.65 to 172.20.58.65
[26/Mar/2020:15:27:46.086789294 -0400] conn=6333769 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO
[26/Mar/2020:15:27:46.153155238 -0400] conn=6333769 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0066722492 dn="uid=awslambda,cn=users,cn=accounts,dc=linux,dc=example,dc=com"
[26/Mar/2020:15:27:46.163221019 -0400] conn=6333769 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=)" attrs=ALL
[26/Mar/2020:15:27:46.164010445 -0400] conn=6333769 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0001537646
[26/Mar/2020:15:27:46.165872323 -0400] conn=6333769 op=2 SRCH base="fqdn=i-XXX-1.dev.us-east-1.aws.linux.example.com,cn=computers,cn=accounts,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=
)" attrs=""
[26/Mar/2020:15:27:46.166300563 -0400] conn=6333769 op=2 RESULT err=32 tag=101 nentries=0 etime=0.0000698490
[26/Mar/2020:15:27:46.167965687 -0400] conn=6333769 op=3 SRCH base="cn=computers,cn=accounts,dc=linux,dc=example,dc=com" scope=2 filter="(&(&(objectClass=ipaobject)(objectClass=nshost)(objectClass=ipahost)(objectClass=pkiuser)(objectClass=ipaservice))(serverHostName=i-XXX-1.dev.us-east-1.aws.linux.example.com))" attrs=""
[26/Mar/2020:15:27:46.169018501 -0400] conn=6333769 op=3 RESULT err=0 tag=101 nentries=0 etime=0.0001336885
[26/Mar/2020:15:27:46.171208720 -0400] conn=6333769 op=4 SRCH base="fqdn=i-XXX-1.dev.us-east-1.aws.linux.example.com,cn=computers,cn=accounts,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=)" attrs=""
[26/Mar/2020:15:27:46.171420281 -0400] conn=6333769 op=4 RESULT err=32 tag=101 nentries=0 etime=0.0001465313
[26/Mar/2020:15:27:46.172540314 -0400] conn=6333769 op=5 SRCH base="cn=aws_micro_account_XXX,cn=hostgroups,cn=accounts,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=
)" attrs="memberofindirect cn memberOf * member memberindirect description aci"
[26/Mar/2020:15:27:46.172956453 -0400] conn=6333769 op=5 RESULT err=0 tag=101 nentries=1 etime=0.0000681452
[26/Mar/2020:15:27:46.174312075 -0400] conn=6333769 op=6 SRCH base="dc=linux,dc=example,dc=com" scope=2 filter="(&(member=)(memberOf=cn=aws_micro_account_XXX,cn=hostgroups,cn=accounts,dc=linux,dc=example,dc=com))" attrs="member"
[26/Mar/2020:15:27:46.187336349 -0400] conn=6333769 op=6 RESULT err=0 tag=101 nentries=0 etime=0.0013306211 notes=P pr_idx=0 pr_cookie=-1
[26/Mar/2020:15:27:46.188227774 -0400] conn=6333769 op=7 SRCH base="dc=linux,dc=example,dc=com" scope=2 filter="(|(member=cn=aws_micro_account_XXX,cn=hostgroups,cn=accounts,dc=linux,dc=example,dc=com)(memberUser=cn=aws_micro_account_XXX,cn=hostgroups,cn=accounts,dc=linux,dc=example,dc=com)(memberHost=cn=aws_micro_account_XXX,cn=hostgroups,cn=accounts,dc=linux,dc=example,dc=com))" attrs=""
[26/Mar/2020:15:27:46.199384085 -0400] conn=6333769 op=7 RESULT err=0 tag=101 nentries=3 etime=0.0011436526 notes=P pr_idx=0 pr_cookie=-1
[26/Mar/2020:15:27:46.200509372 -0400] conn=6333769 op=8 SRCH base="cn=aws_micro_account_XXX,cn=ng,cn=alt,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=mepmanagedentry)" attrs=""
[26/Mar/2020:15:27:46.200678181 -0400] conn=6333769 op=8 RESULT err=0 tag=101 nentries=1 etime=0.0000242703
[26/Mar/2020:15:27:46.201584101 -0400] conn=6333769 op=9 SRCH base="ipaUniqueID=6ed49f70-3239-11ea-83b1-0050568d21e9,cn=sudorules,cn=sudo,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=
)" attrs="cn"
[26/Mar/2020:15:27:46.201847891 -0400] conn=6333769 op=9 RESULT err=0 tag=101 nentries=1 etime=0.0000338638
[26/Mar/2020:15:27:46.202698901 -0400] conn=6333769 op=10 SRCH base="ipaUniqueID=6e5f90c2-3239-11ea-9001-0050568d21e9,cn=hbac,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=*)" attrs="cn"
[26/Mar/2020:15:27:46.202931874 -0400] conn=6333769 op=10 RESULT err=0 tag=101 nentries=1 etime=0.0000300591
[26/Mar/2020:15:27:46.204492199 -0400] conn=6333769 op=11 UNBIND
[26/Mar/2020:15:27:46.204519369 -0400] conn=6333769 op=11 fd=551 closed - U1

Looks like the host being added as a member does not exist.

[26/Mar/2020:15:27:46.165872323 -0400] conn=6333769 op=2 SRCH base="fqdn=i-XXX-1.dev.us-east-1.aws.linux.example.com,cn=computers,cn=accounts,dc=linux,dc=example,dc=com" scope=0 filter="(objectClass=)" attrs=""
[26/Mar/2020:15:27:46.166300563 -0400] conn=6333769 op=2 RESULT err=32 tag=101 nentries=0 etime=0.0000698490

err32 == not found

The add/remove members commands only fail if the attempt to add/remove completely failed. Failing to add/remove a single member is not considered a failure and is reported in the output.

ahh okay, so this might be a timing/replication issue, because the host was created in a different IdM server.

okay, i will extend the logging in the code, to check the actual result in a case like this, so i can simply add some retries in my code.

I'd suggest you also look to see if you can lever automember to handle this automatically. It would alleviate any issues with replication delay.

Metadata Update from @schlitzered:
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)

Metadata