Troubleshooting ipa commands: read Apache error log and 389-ds access log

IdM includes an internal LDAP directory server instance where all the IdM information is stored: 389-ds. For instance the user and host entries reside in 389-ds as LDAP entries..

Most of the ipa commands are either reading or writing data in 389-ds. When an ipa command fails, 389-ds access log is really useful in order to understand if the failure is related to an issue in the LDAP server. This post will show how to used both Apache log and 389-ds access log to troubleshoot an issue.

Issue description

A Bugzilla reports that the command ipa domainlevel set behaves badly when the user tries to change the domain level but specifies the current level by mistake:

$ ipa domainlevel-get
-----------------------
Current domain level: 1
-----------------------
$ ipa domainlevel-set 0
ipa: ERROR: Domain Level cannot be lowered.

This result is expected as it is not possible to lower the current domain level.

$ ipa domainlevel-set 1
ipa: ERROR: Domain Level cannot be raised to 1, server master.example.com does not support it.

This result is wrong, as the domain level is already 1 and the following output is expected:

$ ipa domainlevel-set 1
ipa: ERROR: no modifications to be performed

Reading httpd error logs

By default, httpd error logs do not provide a lot of information (only messages with INFO or above). The logging level needs to be raised in order to have a hint of the root cause:

Create a file /etc/ipa/server.conf with the following content:

$ cat /etc/ipa/server.conf
[global]
debug=True

Restart FreeIPA stack:

$ ipactl restart
Restarting Directory Service
Restarting krb5kdc Service
Restarting kadmin Service
Restarting named Service
Restarting httpd Service
Restarting ipa-custodia Service
Restarting ipa-otpd Service
Restarting ipa-dnskeysyncd Service
Starting pki-tomcatd Service
ipa: INFO: The ipactl command was successful

Re-run the ipa domainlevel-set 1 command, more information will get written in httpd error log:

$ tail -f /var/log/httpd/error_log [...] ipa: DEBUG: WSGI wsgi_dispatch.__call__: [...] ipa: DEBUG: WSGI jsonserver.__call__: [...] ipa: DEBUG: KerberosWSGIExecutioner.__call__: [...] ipa: DEBUG: Created connection context.ldap2_139798041384160 [...] ipa: DEBUG: WSGI WSGIExecutioner.__call__: [...] ipa: DEBUG: raw: domainlevel_set(1, version='2.230') [...] ipa: DEBUG: domainlevel_set(1, version='2.230') [...] ipa: DEBUG: retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-DOMAIN-COM.socket conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f25440f1208> [...] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last): [...] File "/usr/lib/python3.7/site-packages/ipaserver/rpcserver.py", line 370, in wsgi_execute [...] result = command(*args, **options) [...] File "/usr/lib/python3.7/site-packages/ipalib/frontend.py", line 450, in __call__ [...] return self.__do_call(*args, **options) [...] File "/usr/lib/python3.7/site-packages/ipalib/frontend.py", line 478, in __do_call [...] ret = self.run(*args, **options) [...] File "/usr/lib/python3.7/site-packages/ipalib/frontend.py", line 800, in run [...] return self.execute(*args, **options) [...] File "/usr/lib/python3.7/site-packages/ipaserver/plugins/domainlevel.py", line 156, in execute [...] raise errors.InvalidDomainLevelError(reason=message) [...] ipalib.errors.InvalidDomainLevelError: Domain Level cannot be raised to 1, server master.domain.com does not support it. [...] [...] ipa: INFO: [jsonserver_kerb] host/master.domain.com@DOMAIN.COM: domainlevel_set/1(1, version='2.230'): InvalidDomainLevelError [...] ipa: DEBUG: Destroyed connection context.ldap2_139798041384160

The log displays the command that was run and its parameters:

[...] ipa: DEBUG: raw: domainlevel_set(1, version='2.230') [...] ipa: DEBUG: domainlevel_set(1, version='2.230')

and also the result:

[...] ipa: INFO: [jsonserver_kerb] host/master.domain.com@DOMAIN.COM: domainlevel_set/1(1, version='2.230'): InvalidDomainLevelError

The debug log shows a stack trace that can be examined, with the exact line where the failure occurred:

[...] File "/usr/lib/python3.7/site-packages/ipaserver/plugins/domainlevel.py", line 156, in execute [...] raise errors.InvalidDomainLevelError(reason=message)

The code around this line looks like the following:

# Check if every master supports the desired level for master in get_master_entries(ldap, self.api): supported = get_domainlevel_range(master) if supported.min > desired_value or supported.max < desired_value: message = _("Domain Level cannot be raised to {0}, server {1} " "does not support it." ).format(desired_value, master['cn'][0]) raise errors.InvalidDomainLevelError(reason=message)

The get_domainlevel_range function is defined in the same file:

def get_domainlevel_range(master_entry): try: return DomainLevelRange( int(master_entry['ipaMinDomainLevel'][0]), int(master_entry['ipaMaxDomainLevel'][0]) ) except KeyError: return DomainLevelRange(0, 0)

get_domainlevel_range is reading ipaMinDomainLevel and ipaMaxDomainLevel from the master_entry. If the attributes are missing, the default values are set to 0.

What is this master_entry, and how is it built? The get_master_entries function is also defined in the same file:

def get_master_entries(ldap, api): """ Returns list of LDAPEntries representing IPA masters. """ container_masters = DN( ('cn', 'masters'), ('cn', 'ipa'), ('cn', 'etc'), api.env.basedn ) masters, _dummy = ldap.find_entries( filter="(cn=*)", base_dn=container_masters, scope=ldap.SCOPE_ONELEVEL, paged_search=True, # we need to make sure to get all of them ) return masters

The function is simply performing a one-level search below cn=masters,cn=ipa,cn=etc,$BASEDN with a search filter “(cn=*)”. From there it’s easy to understand that the entries below cn=masters are supposed to contain the attributes ipaMinDomainLevel and ipaMaxDomainLevel.

389-ds logs will also help understand what happened for this search.

Reading 389-ds access logs

In a default IdM installation, 389-ds logs LDAP operations in /var/log/dirsv/slapd-DOMAIN-COM/access (the access logs is buffered).
To troubleshoot the problem, tail the access log and re-launch the command ipa domainlevel-set 1:

$ tail -f /var/log/dirsrv/slapd-DOMAIN-COM/access [...] conn=23 fd=102 slot=102 connection from 10.37.171.82 to 10.37.171.82 [...] conn=23 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO [...] conn=23 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0009926457 dn="fqdn=master.domain.com,cn=computers,cn=accounts,dc=domain,dc=com" [...] conn=23 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=domain,dc=com" scope=0 filter="(objectClass=*)" attrs=ALL [...] conn=23 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0002818162 [...] conn=23 op=2 SRCH base="cn=schema" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses" [...] conn=23 op=2 RESULT err=0 tag=101 nentries=1 etime=0.0134877660 [...] conn=23 op=3 SRCH base="cn=Domain Level,cn=ipa,cn=etc,dc=domain,dc=com" scope=0 filter="(objectClass=*)" attrs=ALL [...] conn=23 op=3 RESULT err=0 tag=101 nentries=1 etime=0.0001469752 [...] conn=23 op=4 SRCH base="cn=masters,cn=ipa,cn=etc,dc=domain,dc=com" scope=1 filter="(cn=*)" attrs=ALL [...] conn=23 op=4 RESULT err=0 tag=101 nentries=1 etime=0.0002024975 notes=P pr_idx=0 pr_cookie=-1 [...] conn=23 op=5 UNBIND [...] conn=23 op=5 fd=102 closed - U1

Let’s analyse the log from the beginning:

[...] conn=23 fd=102 slot=102 connection from 10.37.171.82 to 10.37.171.82

A LDAP client has opened a new connection (the client is running on the same machine as the server because the IP addresses are identical). In the following lines, the logs with an identical connection id (conn=23) will refer to operations sent using the same connection, meaning the same client.

[...] conn=23 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO

The first operation (with op=0) executed by the LDAP client is a BIND using Kerberos authentication (mech=GSS-SPNEGO). In order to see the operation’s result, one needs to find in the log a line with the same tuple (connection id, op id):

[...] conn=23 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0009926457 dn="fqdn=master.domain.com,cn=computers,cn=accounts,dc=domain,dc=com"

The logs show that the BIND was successful (RESULT err=0) and authenticated the connection as fqdn=master.domain.com,cn=computers,cn=accounts,dc=domain,dc=com. This is the host entry associated to the master. The kinit was probably done using kinit -kt /etc/krb5.keytab as this keytab contains the key for the local host.

Then the client performed a few searches, and it’s easy to spot the search performed by Apache server:

[...] conn=23 op=4 SRCH base="cn=masters,cn=ipa,cn=etc,dc=domain,dc=com" scope=1 filter="(cn=*)" attrs=ALL

This log corresponds to a one-level search (scope=1) on cn=masters,cn=ipa,cn=etc,$BASEDN (base=…) with the filter “(cn=*)”. The search returned success (RESULT err=0) and found a single entry (nentries=1):

[...] conn=23 op=4 RESULT err=0 tag=101 nentries=1 etime=0.0002024975 notes=P pr_idx=0 pr_cookie=-1

The log doesn’t show the content that was returned… But it’s possible to manually reproduce the search with a simple ldapsearch command:

$ kinit -kt /etc/krb5.keytab $ ldapsearch -LLL -o ldif-wrap=no -Y GSSAPI -b cn=masters,cn=ipa,cn=etc,dc=domain,dc=com -s one "(cn=*)" SASL/GSSAPI authentication started SASL username: host/master.domain.com@DOMAIN.COM SASL SSF: 256 SASL data security layer installed. dn: cn=master.domain.com,cn=masters,cn=ipa,cn=etc,dc=domain,dc=com objectClass: top objectClass: nsContainer objectClass: ipaReplTopoManagedServer objectClass: ipaConfigObject objectClass: ipaSupportedDomainLevelConfig cn: master.domain.com

The above content is exactly the same as the content returned to Apache server. There is no ipaMinDomainLevel or ipaMaxDomainLevel in this entry, meaning that the code considered instead the default value of (0,0) for (supported.min, supported.max):

  if supported.min > desired_value or supported.max < desired_value: message = _("Domain Level cannot be raised to {0}, server {1} " "does not support it." ).format(desired_value, master['cn'][0]) raise errors.InvalidDomainLevelError(reason=message)

With supported.max = 0, we have supported.max < desired_value and raise the Exception.

But why didn’t the ldap search return these attributes? The same request but authenticated as cn=Directory Manager will show the full entry content (access control do not apply to this user):

$ ldapsearch -D "cn=directory manager" -W -LLL -o ldif-wrap=no -b cn=masters,cn=ipa,cn=etc,dc=domain,dc=com -s one "(cn=*)" Enter LDAP Password: dn: cn=master.domain.com,cn=masters,cn=ipa,cn=etc,dc=domain,dc=com objectClass: top objectClass: nsContainer objectClass: ipaReplTopoManagedServer objectClass: ipaConfigObject objectClass: ipaSupportedDomainLevelConfig cn: master.domain.com ipaReplTopoManagedSuffix: dc=domain,dc=com ipaReplTopoManagedSuffix: o=ipaca ipaMinDomainLevel: 1 ipaMaxDomainLevel: 1

The LDAP entry contains these attributes but they are filtered out from the entry returned if the search is authenticated as the local host. This is probably a simple ACI issue. To prove this assumption, repeat the ipa domainlevel-set 1 command, but this time authenticated as admin, who has more read permissions than the local host:

$ kinit admin
Password for admin@DOMAIN.COM:
$ ipa domainlevel-set 1
ipa: ERROR: no modifications to be performed

The mystery is solved! The operation was performed with the wrong user and did not have enough permissions to execute successfully.

Conclusion

When one is able to read both Apache error log and 389-ds access log, it is often easy to spot the exact cause for an issue within ipa commands. 389-ds logs display the command and the authenticated user, allowing to replay the same operation in order to see the actual result returned by 389-ds.

Advertisement