Hi folks,
something got corrupted in my ldap database (again). After running
% ipa user-mod --rename=bobk bobs
I get
% getent passwd bobs % getent passwd bobk %
The UID became unusable. (Highly painful, because this user is cut off from EMails.) This is what I see:
% ipa user-find bobs -------------- 1 user matched -------------- User login: bobk First name: Bob Last name: S Home directory: /home/bobs Login shell: /bin/bash Principal alias: bobk@EXAMPLE.DE Email address: bobs@example.de UID: 1032 GID: 100 Account disabled: False ---------------------------- Number of entries returned 1 ----------------------------
% ipa user-find bobk --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
% ipa user-find --login bobk --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
% ipa user-find --login bobs --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
Neither login name is found. Using ldap some data is still available:
% ldapsearch -LLL -Y GSSAPI -b cn=users,cn=accounts,dc=example,dc=de '(uid=bobs)'
dn: uid=bobk,cn=users,cn=accounts,dc=example,dc=de gecos: Bob S displayName: Bob S krbPrincipalName: bobk@EXAMPLE.DE mepManagedEntry: cn=bobk,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=ipausers,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=projects,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=develop,cn=groups,cn=accounts,dc=example,dc=de uid: bobk krbLastSuccessfulAuth: 20180607201703Z krbLoginFailedCount: 0 krbLastFailedAuth: 20180606135524Z ipaUniqueID: 35292e46-ad70-11e5-8123-0016cc46e69a givenName: Bob mail: bobs@example.de homeDirectory: /home/bobs sn: S gidNumber: 100 initials: JS uidNumber: 1032 loginShell: /bin/bash objectClass: ipaobject objectClass: person objectClass: top objectClass: ipasshuser objectClass: inetorgperson objectClass: organizationalperson objectClass: krbticketpolicyaux objectClass: krbprincipalaux objectClass: inetuser objectClass: posixaccount objectClass: ipaSshGroupOfPubKeys objectClass: mepOriginEntry cn: Bob S krbLastPwdChange: 20160104091328Z krbPasswordExpiration: 20400825091328Z krbExtraData:: AAK4N4pWanNjaHVsdGVAQUlYSUdPLkRFAA== krbLastAdminUnlock: 20160314150305Z
% ldapsearch -LLL -Y GSSAPI -b cn=users,cn=accounts,dc=example,dc=de '(uid=bobk)' %
Using jxplorer I see the entry for "bobk" (on 2 replicas), but if I try to look inside I get an error popup "unable to perform read operation". On the other 4 replicas I see "bobs" (no problem here).
WTH? How can I cleanup this mess?
Every helpful comment is highly appreciated Harri
PS: Running
ipa-replica-manage force-sync --from ipa0.example.de
to sync a "good" replica to a bad one did not help.
Hi Harald,
anything noticeable in the error logs when the problem occurred ? (DB_DEADLOCK)
best regards thierry
On 06/20/2018 02:56 PM, Harald Dunkel via FreeIPA-users wrote:
Hi folks,
something got corrupted in my ldap database (again). After running
% ipa user-mod --rename=bobk bobs
I get
% getent passwd bobs % getent passwd bobk %
The UID became unusable. (Highly painful, because this user is cut off from EMails.) This is what I see:
% ipa user-find bobs -------------- 1 user matched -------------- User login: bobk First name: Bob Last name: S Home directory: /home/bobs Login shell: /bin/bash Principal alias: bobk@EXAMPLE.DE Email address: bobs@example.de UID: 1032 GID: 100 Account disabled: False ---------------------------- Number of entries returned 1 ----------------------------
% ipa user-find bobk --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
% ipa user-find --login bobk --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
% ipa user-find --login bobs --------------- 0 users matched --------------- ---------------------------- Number of entries returned 0 ----------------------------
Neither login name is found. Using ldap some data is still available:
% ldapsearch -LLL -Y GSSAPI -b cn=users,cn=accounts,dc=example,dc=de '(uid=bobs)'
dn: uid=bobk,cn=users,cn=accounts,dc=example,dc=de gecos: Bob S displayName: Bob S krbPrincipalName: bobk@EXAMPLE.DE mepManagedEntry: cn=bobk,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=ipausers,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=projects,cn=groups,cn=accounts,dc=example,dc=de memberOf: cn=develop,cn=groups,cn=accounts,dc=example,dc=de uid: bobk krbLastSuccessfulAuth: 20180607201703Z krbLoginFailedCount: 0 krbLastFailedAuth: 20180606135524Z ipaUniqueID: 35292e46-ad70-11e5-8123-0016cc46e69a givenName: Bob mail: bobs@example.de homeDirectory: /home/bobs sn: S gidNumber: 100 initials: JS uidNumber: 1032 loginShell: /bin/bash objectClass: ipaobject objectClass: person objectClass: top objectClass: ipasshuser objectClass: inetorgperson objectClass: organizationalperson objectClass: krbticketpolicyaux objectClass: krbprincipalaux objectClass: inetuser objectClass: posixaccount objectClass: ipaSshGroupOfPubKeys objectClass: mepOriginEntry cn: Bob S krbLastPwdChange: 20160104091328Z krbPasswordExpiration: 20400825091328Z krbExtraData:: AAK4N4pWanNjaHVsdGVAQUlYSUdPLkRFAA== krbLastAdminUnlock: 20160314150305Z
% ldapsearch -LLL -Y GSSAPI -b cn=users,cn=accounts,dc=example,dc=de '(uid=bobk)' %
Using jxplorer I see the entry for "bobk" (on 2 replicas), but if I try to look inside I get an error popup "unable to perform read operation". On the other 4 replicas I see "bobs" (no problem here).
WTH? How can I cleanup this mess?
Every helpful comment is highly appreciated Harri _______________________________________________ FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
Hi Thierry,
On 6/20/18 3:31 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,
anything noticeable in the error logs when the problem occurred ? (DB_DEADLOCK)
I found something in the slapd error log files on the bad replicas (attached).
Other replicas show tons of lines like
: [16/Jun/2018:20:48:14.959827920 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028228 (rc: 32) [16/Jun/2018:20:48:14.962389856 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028229 (rc: 32) [16/Jun/2018:20:48:14.971465364 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028230 (rc: 32) [16/Jun/2018:20:48:14.979659148 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028231 (rc: 32) [16/Jun/2018:20:48:14.988140501 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028232 (rc: 32) [16/Jun/2018:20:48:14.992190747 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028233 (rc: 32) [16/Jun/2018:20:48:15.000092668 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028234 (rc: 32) [16/Jun/2018:20:48:15.008352154 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028235 (rc: 32) :
some of them are months old, but we got "real" problems just today (at about 12:20).
Any idea?
Regards Harri
Hi Harald,
I wonder if error on ipa1 can not be part of the problem
[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
The MODRDN failed, that would explain why 'uid=bobs' remained in the index (and findable via search) But this does not explain how RDN and entry itself was changed.
Could you provide the access logs (ipa1) around that time ?
best regards thierry
On 06/20/2018 04:34 PM, Harald Dunkel via FreeIPA-users wrote:
Hi Thierry,
On 6/20/18 3:31 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,
anything noticeable in the error logs when the problem occurred ? (DB_DEADLOCK)
I found something in the slapd error log files on the bad replicas (attached).
Other replicas show tons of lines like
: [16/Jun/2018:20:48:14.959827920 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028228 (rc: 32) [16/Jun/2018:20:48:14.962389856 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028229 (rc: 32) [16/Jun/2018:20:48:14.971465364 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028230 (rc: 32) [16/Jun/2018:20:48:14.979659148 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028231 (rc: 32) [16/Jun/2018:20:48:14.988140501 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028232 (rc: 32) [16/Jun/2018:20:48:14.992190747 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028233 (rc: 32) [16/Jun/2018:20:48:15.000092668 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028234 (rc: 32) [16/Jun/2018:20:48:15.008352154 +0200] - ERR - DSRetroclPlugin - delete_changerecord: could not delete change record 4028235 (rc: 32) :
some of them are months old, but we got "real" problems just today (at about 12:20).
Any idea?
Regards Harri
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
Hi Thierry,
On 6/20/18 6:02 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,
I wonder if error on ipa1 can not be part of the problem
[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
The MODRDN failed, that would explain why 'uid=bobs' remained in the index (and findable via search) But this does not explain how RDN and entry itself was changed.
Could you provide the access logs (ipa1) around that time ?
Sure, see attachment. Hope this helps.
Regards Harri
Hi Harald,
Sorry to be back late.
The MODRDN failed
[20/Jun/2018:12:16:26.438676865 +0200] conn=2464250 fd=417 slot=417 connection from 172.19.96.3 to 172.19.96.3 [20/Jun/2018:12:16:26.444420018 +0200] conn=2464250 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO [20/Jun/2018:12:16:26.449637703 +0200] conn=2464250 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=admin,cn=users,cn=accounts,dc=example,dc=de" [20/Jun/2018:12:16:26.451161509 +0200] conn=2464250 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs=ALL [20/Jun/2018:12:16:26.451753066 +0200] conn=2464250 op=1 RESULT err=0 tag=101 nentries=1 etime=0 [20/Jun/2018:12:16:26.452751904 +0200] conn=2464250 op=2 SRCH base="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs="distinguishedName" [20/Jun/2018:12:16:26.452983629 +0200] conn=2464250 op=2 RESULT err=0 tag=101 nentries=1 etime=0 [20/Jun/2018:12:16:26.453499505 +0200] conn=2464250 op=3 SRCH base="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" scope=0 filter="(objectClass=*)" attrs="krbPrincipalName krbCanonicalName" [20/Jun/2018:12:16:26.453742775 +0200] conn=2464250 op=3 RESULT err=0 tag=101 nentries=1 etime=0 [20/Jun/2018:12:16:26.456729268 +0200] conn=2464250 op=4 MODRDN dn="uid=bobs,cn=users,cn=accounts,dc=example,dc=de" newrdn="uid=bobk" newsuperior="(null)" [20/Jun/2018:12:16:31.890761679 +0200] conn=2464250 op=4 RESULT err=1 tag=109 nentries=0 etime=5 csn=5b2a297c000900040000 [20/Jun/2018:12:16:31.892091985 +0200] conn=2464250 op=5 UNBIND [20/Jun/2018:12:16:31.892112732 +0200] conn=2464250 op=5 fd=417 closed - U1
While quite "intensive" read activity were around changelog
[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE [20/Jun/2018:12:16:31.890841336 +0200] - ERR - agmt="cn=meToipabak.ac.example.de" (ipabak:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.895854088 +0200] - ERR - agmt="cn=meToipa2.example.de" (ipa2:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.899133027 +0200] - ERR - agmt="cn=meToipa3.example.de" (ipa3:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.910014989 +0200] - ERR - agmt="cn=meToipa4.example.de" (ipa4:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.918932212 +0200] - ERR - agmt="cn=meToipabak.ac.example.de" (ipabak:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.922221449 +0200] - ERR - agmt="cn=meToipa2.example.de" (ipa2:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.934273432 +0200] - ERR - agmt="cn=meToipa3.example.de" (ipa3:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized. [20/Jun/2018:12:16:31.942328998 +0200] - ERR - agmt="cn=meToipa4.example.de" (ipa4:389) - clcache_load_buffer - Can't locate CSN 5b2a297c000500040000 in the changelog (DB rc=-30988). If replication stops, the consumer may need to be reinitialized.
There is not enough detail to confirm but my feeling is that the MODRDN (write) failed to update the changelog because of many replication agreements (read) competing with it. It retried several times but without success so the full txn was aborted.
I think this can be mitigate with appropriate deadlock policy (nsslapd-db-deadlock-policy: 6 for example).
Now it broke the index and that is really unexpected (even after a db_deadlock). It worth to try to reproduce.
thanks for your help
best regards thierry
On 06/20/2018 08:14 PM, Harald Dunkel via FreeIPA-users wrote:
Hi Thierry,
On 6/20/18 6:02 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,
I wonder if error on ipa1 can not be part of the problem
[20/Jun/2018:12:16:31.885644563 +0200] - ERR - ldbm_back_modrdn - SLAPI_PLUGIN_BE_TXN_POST_MODRDN_FN plugin returned error but did not set SLAPI_RESULT_CODE
The MODRDN failed, that would explain why 'uid=bobs' remained in the index (and findable via search) But this does not explain how RDN and entry itself was changed.
Could you provide the access logs (ipa1) around that time ?
Sure, see attachment. Hope this helps.
Regards Harri
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
Hi Thierry,
On 6/21/18 7:19 PM, thierry bordaz via FreeIPA-users wrote:
Hi Harald,
Sorry to be back late.
There is not enough detail to confirm but my feeling is that the MODRDN (write) failed to update the changelog because of many replication agreements (read) competing with it. It retried several times but without success so the full txn was aborted.
I think this can be mitigate with appropriate deadlock policy (nsslapd-db-deadlock-policy: 6 for example).
Now it broke the index and that is really unexpected (even after a db_deadlock). It worth to try to reproduce.
thanks for your help
I am not sure what that means, but point is that I have a corrupted entry in 2 of 6 replicas. jxplorer refuses to touch this entry. How can I fix this?
If the "transaction" was aborted, how comes that the ldap databases differ? Ain't this the definition for "not having a transaction"?
I found something new: "ipa-replica-manage list-ruv" shows an error
# ipa-replica-manage list-ruv
unable to decode: {replica 7} 58809c7c000300070000 58809c7c000300070000 Replica Update Vectors: ipa0.example.de:389: 12 ipa2.example.de:389: 5 ipa1.example.de:389: 4 ipa4.example.de:389: 8 ipa3.example.de:389: 6 ipabak.ac.example.de:389: 13 Certificate Server Replica Update Vectors: ipa0.example.de:389: 1095 ipa2.example.de:389: 97 ipa1.example.de:389: 96 ipabak.ac.example.de:389: 1090
# ipa-replica-manage clean-ruv 7
unable to decode: {replica 7} 58809c7c000300070000 58809c7c000300070000 Replica ID 7 not found
Every helpful hint how to fix this is highly appreciated Harri
Hi folks,
I managed to get rid of the corrupted entry and to create a new user account. But there are still problems. The upgrade from Centos 7.4 to 7.5 got stuck for 5 to 10 minutes.
: Installing : libxkbcommon-0.7.1-1.el7.x86_64 297/787 Updating : adwaita-cursor-theme-3.26.0-1.el7.noarch 298/787 Updating : adwaita-icon-theme-3.26.0-1.el7.noarch 299/787 Updating : perl-Getopt-Long-2.40-3.el7.noarch 300/787 Updating : 389-ds-base-1.3.7.5-21.el7_5.x86_64 301/787 warning: /etc/sysconfig/dirsrv.systemd created as /etc/sysconfig/dirsrv.systemd.rpmnew Updating : slapi-nis-0.56.0-8.el7.x86_64 302/787 Updating : ipa-server-4.5.4-10.el7.centos.1.x86_64 303/787 Job for certmonger.service failed because a fatal signal was delivered to the control process. See "systemctl status certmonger.service" and "journalctl -xe" for details. Job for dbus.service failed. See "systemctl status dbus.service" and "journalctl -xe" for details. Updating : linux-firmware-20180220-62.2.git6d51311.el7_5.noarch 304/787 Installing : kernel-3.10.0-862.3.3.el7.x86_64 305/787 Installing : kmod-kvdo-6.1.0.168-16.el7_5.x86_64 306/787 Updating : 2:vim-filesystem-7.4.160-4.el7.x86_64 307/787 Updating : libgcc-4.8.5-28.el7_5.1.i686 308/787 Updating : 2:vim-common-7.4.160-4.el7.x86_64 309/787 :
After a reboot I got this in the ldap error log on ipa1:
[23/Jun/2018:10:58:55.823078141 +0200] - INFO - slapd_extract_cert - CA CERT NAME: CN=example Root CA,OU=example Certificate Authority,O=example AG,C=DE [23/Jun/2018:10:58:55.829958313 +0200] - INFO - slapd_extract_cert - CA CERT NAME: EXAMPLE.DE IPA CA [23/Jun/2018:10:58:55.842015522 +0200] - INFO - slapd_extract_cert - CA CERT NAME: EXAMPLE.DE IPA CA [23/Jun/2018:10:58:55.846444407 +0200] - WARN - Security Initialization - SSL alert: Sending pin request to SVRCore. You may need to run systemd-tty-ask-password-agent to provide the password. [23/Jun/2018:10:58:55.861363768 +0200] - INFO - slapd_extract_cert - SERVER CERT NAME: Server-Cert [23/Jun/2018:10:58:55.874174785 +0200] - INFO - Security Initialization - SSL info: Enabling default cipher set. [23/Jun/2018:10:58:55.887702841 +0200] - INFO - Security Initialization - SSL info: Configured NSS Ciphers [23/Jun/2018:10:58:55.891044528 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: enabled [23/Jun/2018:10:58:55.894701167 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled [23/Jun/2018:10:58:55.899981889 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256: enabled [23/Jun/2018:10:58:55.904520090 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled [23/Jun/2018:10:58:55.907593077 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled [23/Jun/2018:10:58:55.911141652 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled [23/Jun/2018:10:58:55.914589181 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled [23/Jun/2018:10:58:55.918208985 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled [23/Jun/2018:10:58:55.921672628 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled [23/Jun/2018:10:58:55.924819609 +0200] - INFO - Security Initialization - SSL info: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled [23/Jun/2018:10:58:55.938295406 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled [23/Jun/2018:10:58:55.941875247 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled [23/Jun/2018:10:58:55.953854096 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_DSS_WITH_AES_256_CBC_SHA: enabled [23/Jun/2018:10:58:55.957446420 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled [23/Jun/2018:10:58:55.961207905 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled [23/Jun/2018:10:58:55.964835089 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled [23/Jun/2018:10:58:55.968648505 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled [23/Jun/2018:10:58:55.972318327 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_DSS_WITH_AES_128_CBC_SHA: enabled [23/Jun/2018:10:58:55.976103831 +0200] - INFO - Security Initialization - SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled [23/Jun/2018:10:58:55.979671357 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_256_GCM_SHA384: enabled [23/Jun/2018:10:58:55.983360224 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_256_CBC_SHA: enabled [23/Jun/2018:10:58:55.986669322 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_256_CBC_SHA256: enabled [23/Jun/2018:10:58:55.990993340 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_128_GCM_SHA256: enabled [23/Jun/2018:10:58:55.996227069 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_128_CBC_SHA: enabled [23/Jun/2018:10:58:56.000432620 +0200] - INFO - Security Initialization - SSL info: TLS_RSA_WITH_AES_128_CBC_SHA256: enabled [23/Jun/2018:10:58:56.004412052 +0200] - INFO - Security Initialization - SSL info: TLS_AES_128_GCM_SHA256: enabled [23/Jun/2018:10:58:56.008280628 +0200] - INFO - Security Initialization - SSL info: TLS_CHACHA20_POLY1305_SHA256: enabled [23/Jun/2018:10:58:56.012133732 +0200] - INFO - Security Initialization - SSL info: TLS_AES_256_GCM_SHA384: enabled [23/Jun/2018:10:58:56.024303625 +0200] - INFO - Security Initialization - slapd_ssl_init2 - Configured SSL version range: min: TLS1.0, max: TLS1.2 [23/Jun/2018:10:58:56.051546046 +0200] - INFO - main - 389-Directory/1.3.7.5 B2018.136.418 starting up [23/Jun/2018:10:58:56.120225992 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.166848194 +0200] - WARN - default_mr_indexer_create - Plugin [caseIgnoreIA5Match] does not handle caseExactIA5Match [23/Jun/2018:10:58:56.193231624 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.254850712 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.310858090 +0200] - NOTICE - ldbm_back_start - found 16161216k physical memory [23/Jun/2018:10:58:56.318314433 +0200] - NOTICE - ldbm_back_start - found 14213904k available [23/Jun/2018:10:58:56.322812389 +0200] - NOTICE - ldbm_back_start - cache autosizing: db cache: 646448k [23/Jun/2018:10:58:56.326409238 +0200] - NOTICE - ldbm_back_start - cache autosizing: userRoot entry cache (3 total): 327680k [23/Jun/2018:10:58:56.331203527 +0200] - NOTICE - ldbm_back_start - cache autosizing: userRoot dn cache (3 total): 65536k [23/Jun/2018:10:58:56.335162194 +0200] - NOTICE - ldbm_back_start - cache autosizing: ipaca entry cache (3 total): 327680k [23/Jun/2018:10:58:56.340161529 +0200] - NOTICE - ldbm_back_start - cache autosizing: ipaca dn cache (3 total): 65536k [23/Jun/2018:10:58:56.343711751 +0200] - NOTICE - ldbm_back_start - cache autosizing: changelog entry cache (3 total): 327680k [23/Jun/2018:10:58:56.349369943 +0200] - NOTICE - ldbm_back_start - cache autosizing: changelog dn cache (3 total): 65536k [23/Jun/2018:10:58:56.353364700 +0200] - NOTICE - ldbm_back_start - total cache size: 1869922959 B; [23/Jun/2018:10:58:56.358472005 +0200] - NOTICE - dblayer_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database. [23/Jun/2018:10:58:58.857681437 +0200] - ERR - nis-plugin - scheduled nis-plugin tree scan in about 5 seconds after the server startup! [23/Jun/2018:10:58:58.865552019 +0200] - ERR - schema-compat-plugin - scheduled schema-compat-plugin tree scan in about 5 seconds after the server startup! [23/Jun/2018:10:58:58.877191957 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.880854587 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=keys,cn=sec,cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.884103915 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.887243214 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.890474842 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=groups,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.893633261 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=computers,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.906901814 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=ng,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.910179620 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target ou=sudoers,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.913705495 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=users,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.917105354 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.920459719 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.923825413 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.927130994 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.930416966 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.933690832 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.937030149 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.941587038 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.945610436 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.948794736 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.952187805 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.965228551 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.977526637 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=ad,cn=etc,dc=example,dc=de does not exist [23/Jun/2018:10:58:59.059148942 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=automember rebuild membership,cn=tasks,cn=config does not exist [23/Jun/2018:10:58:59.065451747 +0200] - ERR - cos-plugin - cos_dn_defs_cb - Skipping CoS Definition cn=Password Policy,cn=accounts,dc=example,dc=de--no CoS Templates found, which should be added before the CoS Definition. [23/Jun/2018:10:58:59.126470240 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.390313225 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.395043283 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.667662575 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.672025982 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.686194564 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.697840642 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding the replication changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.704164352 +0200] - NOTICE - NSMMReplicationPlugin - changelog program - _cl5ConstructRUV - Rebuilding replication changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.718621878 +0200] - WARN - NSMMReplicationPlugin - replica_check_for_data_reload - Disorderly shutdown for replica dc=example,dc=de. Check if DB RUV needs to be updated [23/Jun/2018:10:58:59.731648339 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.739460046 +0200] - WARN - NSMMReplicationPlugin - replica_check_for_data_reload - Disorderly shutdown for replica o=ipaca. Check if DB RUV needs to be updated [23/Jun/2018:10:58:59.746372774 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.753714299 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.760457528 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.763682555 +0200] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests [23/Jun/2018:10:58:59.768052097 +0200] - INFO - slapd_daemon - Listening on All Interfaces port 636 for LDAPS requests [23/Jun/2018:10:58:59.771314808 +0200] - INFO - slapd_daemon - Listening on /var/run/slapd-EXAMPLE-DE.socket for LDAPI requests [23/Jun/2018:10:58:59.774558043 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:58:59.777970184 +0200] - ERR - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=masterAgreement1-ipa2.example.de-pki-tomcat" (ipa2:389) - Replication bind with SIMPLE auth failed: LDAP error -11 (Connect error) (error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed (self signed certificate in certificate chain)) [23/Jun/2018:10:58:59.810189785 +0200] - ERR - nis-plugin - nis-plugin tree scan will start in about 5 seconds! [23/Jun/2018:10:58:59.814626534 +0200] - ERR - schema-compat-plugin - schema-compat-plugin tree scan will start in about 5 seconds! [23/Jun/2018:10:59:02.848795335 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:05.464588727 +0200] - ERR - schema-compat-plugin - warning: no entries set up under cn=computers, cn=compat,dc=example,dc=de [23/Jun/2018:10:59:05.477625182 +0200] - ERR - schema-compat-plugin - Finished plugin initialization. [23/Jun/2018:10:59:06.191245171 +0200] - ERR - nis-plugin - warning: no entries in domain=example.de,map=ethers.byname [23/Jun/2018:10:59:06.204461031 +0200] - ERR - nis-plugin - warning: no entries in domain=example.de,map=ethers.byaddr [23/Jun/2018:10:59:06.219354580 +0200] - ERR - nis-plugin - Finished plugin initialization. [23/Jun/2018:10:59:08.457412392 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:20.831326274 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:44.073335894 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:11:00:32.217779083 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) : :
Apparently certmonger is still not working:
# systemctl status certmonger.service * certmonger.service - Certificate monitoring and PKI enrollment Loaded: loaded (/usr/lib/systemd/system/certmonger.service; enabled; vendor preset: disabled) Active: failed (Result: timeout) since Sat 2018-06-23 11:00:13 CEST; 42min ago Process: 340 ExecStart=/usr/sbin/certmonger -S -p /var/run/certmonger.pid -n $OPTS (code=exited, status=0/SUCCESS) Main PID: 340 (code=exited, status=0/SUCCESS)
Jun 23 10:58:43 ipa1.aixigo.de systemd[1]: Starting Certificate monitoring and PKI enrollment... Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: certmonger.service start operation timed out. Terminating. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: Failed to start Certificate monitoring and PKI enrollment. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: Unit certmonger.service entered failed state. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: certmonger.service failed.
I cannot stop or restart it either:
[root@ipa1 pki-tomcat]# systemctl stop certmonger.service Error getting authority: Error initializing authority: Could not connect: Connection refused (g-io-error-quark, 39) [root@ipa1 pki-tomcat]# systemctl restart certmonger.service Error getting authority: Error initializing authority: Could not connect: Connection refused (g-io-error-quark, 39) Job for certmonger.service failed because a timeout was exceeded. See "systemctl status certmonger.service" and "journalctl -xe" for details.
"ps -ef --forest" shows a systemd-tty-ask-password-agent:
root 343 1 0 10:58 ? 00:00:00 /usr/sbin/sshd -D root 1150 343 0 10:59 ? 00:00:00 _ sshd: root@pts/4 root 1157 1150 0 10:59 pts/4 00:00:00 | _ -bash root 2725 1157 0 11:44 pts/4 00:00:00 | _ systemctl restart certmonger.service root 2726 2725 0 11:44 pts/4 00:00:00 | _ /usr/bin/systemd-tty-ask-password-agent --watch root 2727 2725 0 11:44 pts/4 00:00:00 | _ [pkttyagent] <defunct>
Whose password is it asking for? And why don't I see a prompt? I would highly prefer if these freeipa host could reboot unattended.
Every helpful comment is highly appreciated Harri
Harald Dunkel via FreeIPA-users wrote:
Hi folks,
I managed to get rid of the corrupted entry and to create a new user account. But there are still problems. The upgrade from Centos 7.4 to 7.5 got stuck for 5 to 10 minutes.
: Installing : libxkbcommon-0.7.1-1.el7.x86_64 297/787 Updating : adwaita-cursor-theme-3.26.0-1.el7.noarch 298/787 Updating : adwaita-icon-theme-3.26.0-1.el7.noarch 299/787 Updating : perl-Getopt-Long-2.40-3.el7.noarch 300/787 Updating : 389-ds-base-1.3.7.5-21.el7_5.x86_64 301/787 warning: /etc/sysconfig/dirsrv.systemd created as /etc/sysconfig/dirsrv.systemd.rpmnew Updating : slapi-nis-0.56.0-8.el7.x86_64 302/787 Updating : ipa-server-4.5.4-10.el7.centos.1.x86_64 303/787 Job for certmonger.service failed because a fatal signal was delivered to the control process. See "systemctl status certmonger.service" and "journalctl -xe" for details. Job for dbus.service failed. See "systemctl status dbus.service" and "journalctl -xe" for details. Updating : linux-firmware-20180220-62.2.git6d51311.el7_5.noarch 304/787 Installing : kernel-3.10.0-862.3.3.el7.x86_64 305/787 Installing : kmod-kvdo-6.1.0.168-16.el7_5.x86_64 306/787 Updating : 2:vim-filesystem-7.4.160-4.el7.x86_64 307/787 Updating : libgcc-4.8.5-28.el7_5.1.i686 308/787 Updating : 2:vim-common-7.4.160-4.el7.x86_64 309/787 :
After a reboot I got this in the ldap error log on ipa1:
[23/Jun/2018:10:58:55.823078141 +0200] - INFO - slapd_extract_cert - CA CERT NAME: CN=example Root CA,OU=example Certificate Authority,O=example AG,C=DE [23/Jun/2018:10:58:55.829958313 +0200] - INFO - slapd_extract_cert - CA CERT NAME: EXAMPLE.DE IPA CA [23/Jun/2018:10:58:55.842015522 +0200] - INFO - slapd_extract_cert - CA CERT NAME: EXAMPLE.DE IPA CA [23/Jun/2018:10:58:55.846444407 +0200] - WARN - Security Initialization
- SSL alert: Sending pin request to SVRCore. You may need to run
systemd-tty-ask-password-agent to provide the password. [23/Jun/2018:10:58:55.861363768 +0200] - INFO - slapd_extract_cert - SERVER CERT NAME: Server-Cert [23/Jun/2018:10:58:55.874174785 +0200] - INFO - Security Initialization
- SSL info: Enabling default cipher set.
[23/Jun/2018:10:58:55.887702841 +0200] - INFO - Security Initialization
- SSL info: Configured NSS Ciphers
[23/Jun/2018:10:58:55.891044528 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384: enabled
[23/Jun/2018:10:58:55.894701167 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA: enabled
[23/Jun/2018:10:58:55.899981889 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256: enabled
[23/Jun/2018:10:58:55.904520090 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[23/Jun/2018:10:58:55.907593077 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA: enabled
[23/Jun/2018:10:58:55.911141652 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[23/Jun/2018:10:58:55.914589181 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA: enabled
[23/Jun/2018:10:58:55.918208985 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[23/Jun/2018:10:58:55.921672628 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[23/Jun/2018:10:58:55.924819609 +0200] - INFO - Security Initialization
- SSL info: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA: enabled
[23/Jun/2018:10:58:55.938295406 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_256_GCM_SHA384: enabled
[23/Jun/2018:10:58:55.941875247 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA: enabled
[23/Jun/2018:10:58:55.953854096 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_DSS_WITH_AES_256_CBC_SHA: enabled
[23/Jun/2018:10:58:55.957446420 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256: enabled
[23/Jun/2018:10:58:55.961207905 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_128_GCM_SHA256: enabled
[23/Jun/2018:10:58:55.964835089 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256: enabled
[23/Jun/2018:10:58:55.968648505 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA: enabled
[23/Jun/2018:10:58:55.972318327 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_DSS_WITH_AES_128_CBC_SHA: enabled
[23/Jun/2018:10:58:55.976103831 +0200] - INFO - Security Initialization
- SSL info: TLS_DHE_RSA_WITH_AES_128_CBC_SHA256: enabled
[23/Jun/2018:10:58:55.979671357 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_256_GCM_SHA384: enabled
[23/Jun/2018:10:58:55.983360224 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_256_CBC_SHA: enabled
[23/Jun/2018:10:58:55.986669322 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_256_CBC_SHA256: enabled
[23/Jun/2018:10:58:55.990993340 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_128_GCM_SHA256: enabled
[23/Jun/2018:10:58:55.996227069 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_128_CBC_SHA: enabled
[23/Jun/2018:10:58:56.000432620 +0200] - INFO - Security Initialization
- SSL info: TLS_RSA_WITH_AES_128_CBC_SHA256: enabled
[23/Jun/2018:10:58:56.004412052 +0200] - INFO - Security Initialization
- SSL info: TLS_AES_128_GCM_SHA256: enabled
[23/Jun/2018:10:58:56.008280628 +0200] - INFO - Security Initialization
- SSL info: TLS_CHACHA20_POLY1305_SHA256: enabled
[23/Jun/2018:10:58:56.012133732 +0200] - INFO - Security Initialization
- SSL info: TLS_AES_256_GCM_SHA384: enabled
[23/Jun/2018:10:58:56.024303625 +0200] - INFO - Security Initialization
- slapd_ssl_init2 - Configured SSL version range: min: TLS1.0, max: TLS1.2
[23/Jun/2018:10:58:56.051546046 +0200] - INFO - main - 389-Directory/1.3.7.5 B2018.136.418 starting up [23/Jun/2018:10:58:56.120225992 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.166848194 +0200] - WARN - default_mr_indexer_create - Plugin [caseIgnoreIA5Match] does not handle caseExactIA5Match [23/Jun/2018:10:58:56.193231624 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.254850712 +0200] - INFO - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [23/Jun/2018:10:58:56.310858090 +0200] - NOTICE - ldbm_back_start - found 16161216k physical memory [23/Jun/2018:10:58:56.318314433 +0200] - NOTICE - ldbm_back_start - found 14213904k available [23/Jun/2018:10:58:56.322812389 +0200] - NOTICE - ldbm_back_start - cache autosizing: db cache: 646448k [23/Jun/2018:10:58:56.326409238 +0200] - NOTICE - ldbm_back_start - cache autosizing: userRoot entry cache (3 total): 327680k [23/Jun/2018:10:58:56.331203527 +0200] - NOTICE - ldbm_back_start - cache autosizing: userRoot dn cache (3 total): 65536k [23/Jun/2018:10:58:56.335162194 +0200] - NOTICE - ldbm_back_start - cache autosizing: ipaca entry cache (3 total): 327680k [23/Jun/2018:10:58:56.340161529 +0200] - NOTICE - ldbm_back_start - cache autosizing: ipaca dn cache (3 total): 65536k [23/Jun/2018:10:58:56.343711751 +0200] - NOTICE - ldbm_back_start - cache autosizing: changelog entry cache (3 total): 327680k [23/Jun/2018:10:58:56.349369943 +0200] - NOTICE - ldbm_back_start - cache autosizing: changelog dn cache (3 total): 65536k [23/Jun/2018:10:58:56.353364700 +0200] - NOTICE - ldbm_back_start - total cache size: 1869922959 B; [23/Jun/2018:10:58:56.358472005 +0200] - NOTICE - dblayer_start - Detected Disorderly Shutdown last time Directory Server was running, recovering database. [23/Jun/2018:10:58:58.857681437 +0200] - ERR - nis-plugin - scheduled nis-plugin tree scan in about 5 seconds after the server startup! [23/Jun/2018:10:58:58.865552019 +0200] - ERR - schema-compat-plugin - scheduled schema-compat-plugin tree scan in about 5 seconds after the server startup! [23/Jun/2018:10:58:58.877191957 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.880854587 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=keys,cn=sec,cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.884103915 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.887243214 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.890474842 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=groups,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.893633261 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=computers,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.906901814 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=ng,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.910179620 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target ou=sudoers,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.913705495 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=users,cn=compat,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.917105354 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.920459719 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.923825413 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.927130994 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.930416966 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.933690832 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.937030149 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.941587038 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.945610436 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.948794736 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.952187805 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=vaults,cn=kra,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.965228551 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=dns,dc=example,dc=de does not exist [23/Jun/2018:10:58:58.977526637 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=ad,cn=etc,dc=example,dc=de does not exist [23/Jun/2018:10:58:59.059148942 +0200] - ERR - NSACLPlugin - acl_parse - The ACL target cn=automember rebuild membership,cn=tasks,cn=config does not exist [23/Jun/2018:10:58:59.065451747 +0200] - ERR - cos-plugin - cos_dn_defs_cb - Skipping CoS Definition cn=Password Policy,cn=accounts,dc=example,dc=de--no CoS Templates found, which should be added before the CoS Definition. [23/Jun/2018:10:58:59.126470240 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding the replication
changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.390313225 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding replication
changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.395043283 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding the replication
changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.667662575 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding replication
changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.672025982 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding the replication
changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.686194564 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding replication
changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.697840642 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding the replication
changelog RUV, this may take several minutes... [23/Jun/2018:10:58:59.704164352 +0200] - NOTICE - NSMMReplicationPlugin
- changelog program - _cl5ConstructRUV - Rebuilding replication
changelog RUV complete. Result 0 (Success) [23/Jun/2018:10:58:59.718621878 +0200] - WARN - NSMMReplicationPlugin - replica_check_for_data_reload - Disorderly shutdown for replica dc=example,dc=de. Check if DB RUV needs to be updated [23/Jun/2018:10:58:59.731648339 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.739460046 +0200] - WARN - NSMMReplicationPlugin - replica_check_for_data_reload - Disorderly shutdown for replica o=ipaca. Check if DB RUV needs to be updated [23/Jun/2018:10:58:59.746372774 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.753714299 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.760457528 +0200] - ERR - set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.example.de@EXAMPLE.DE] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm) [23/Jun/2018:10:58:59.763682555 +0200] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests [23/Jun/2018:10:58:59.768052097 +0200] - INFO - slapd_daemon - Listening on All Interfaces port 636 for LDAPS requests [23/Jun/2018:10:58:59.771314808 +0200] - INFO - slapd_daemon - Listening on /var/run/slapd-EXAMPLE-DE.socket for LDAPI requests [23/Jun/2018:10:58:59.774558043 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:58:59.777970184 +0200] - ERR - NSMMReplicationPlugin - bind_and_check_pwp - agmt="cn=masterAgreement1-ipa2.example.de-pki-tomcat" (ipa2:389) - Replication bind with SIMPLE auth failed: LDAP error -11 (Connect error) (error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed (self signed certificate in certificate chain)) [23/Jun/2018:10:58:59.810189785 +0200] - ERR - nis-plugin - nis-plugin tree scan will start in about 5 seconds! [23/Jun/2018:10:58:59.814626534 +0200] - ERR - schema-compat-plugin - schema-compat-plugin tree scan will start in about 5 seconds! [23/Jun/2018:10:59:02.848795335 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:05.464588727 +0200] - ERR - schema-compat-plugin - warning: no entries set up under cn=computers, cn=compat,dc=example,dc=de [23/Jun/2018:10:59:05.477625182 +0200] - ERR - schema-compat-plugin - Finished plugin initialization. [23/Jun/2018:10:59:06.191245171 +0200] - ERR - nis-plugin - warning: no entries in domain=example.de,map=ethers.byname [23/Jun/2018:10:59:06.204461031 +0200] - ERR - nis-plugin - warning: no entries in domain=example.de,map=ethers.byaddr [23/Jun/2018:10:59:06.219354580 +0200] - ERR - nis-plugin - Finished plugin initialization. [23/Jun/2018:10:59:08.457412392 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:20.831326274 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:10:59:44.073335894 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) [23/Jun/2018:11:00:32.217779083 +0200] - ERR - slapi_ldap_bind - Error: could not send startTLS request: error -11 (Connect error) : :
Apparently certmonger is still not working:
# systemctl status certmonger.service
- certmonger.service - Certificate monitoring and PKI enrollment
Loaded: loaded (/usr/lib/systemd/system/certmonger.service; enabled; vendor preset: disabled) Active: failed (Result: timeout) since Sat 2018-06-23 11:00:13 CEST; 42min ago Process: 340 ExecStart=/usr/sbin/certmonger -S -p /var/run/certmonger.pid -n $OPTS (code=exited, status=0/SUCCESS) Main PID: 340 (code=exited, status=0/SUCCESS)
Jun 23 10:58:43 ipa1.aixigo.de systemd[1]: Starting Certificate monitoring and PKI enrollment... Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: certmonger.service start operation timed out. Terminating. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: Failed to start Certificate monitoring and PKI enrollment. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: Unit certmonger.service entered failed state. Jun 23 11:00:13 ipa1.aixigo.de systemd[1]: certmonger.service failed.
I cannot stop or restart it either:
[root@ipa1 pki-tomcat]# systemctl stop certmonger.service Error getting authority: Error initializing authority: Could not connect: Connection refused (g-io-error-quark, 39) [root@ipa1 pki-tomcat]# systemctl restart certmonger.service Error getting authority: Error initializing authority: Could not connect: Connection refused (g-io-error-quark, 39) Job for certmonger.service failed because a timeout was exceeded. See "systemctl status certmonger.service" and "journalctl -xe" for details.
"ps -ef --forest" shows a systemd-tty-ask-password-agent:
root 343 1 0 10:58 ? 00:00:00 /usr/sbin/sshd -D root 1150 343 0 10:59 ? 00:00:00 _ sshd: root@pts/4 root 1157 1150 0 10:59 pts/4 00:00:00 | _ -bash root 2725 1157 0 11:44 pts/4 00:00:00 | _ systemctl restart certmonger.service root 2726 2725 0 11:44 pts/4 00:00:00 | _ /usr/bin/systemd-tty-ask-password-agent --watch root 2727 2725 0 11:44 pts/4 00:00:00 | _ [pkttyagent] <defunct>
Whose password is it asking for? And why don't I see a prompt? I would highly prefer if these freeipa host could reboot unattended.
We'd need to see what certs are being tracked, getcert list.
rob
Hi Rob,
On 6/25/18 4:53 PM, Rob Crittenden via FreeIPA-users wrote:
We'd need to see what certs are being tracked, getcert list.
This gets stuck, too:
[root@ipa1 ~]# getcert list Error org.freedesktop.DBus.Error.TimedOut
I found https://bugzilla.redhat.com/show_bug.cgi?id=1519206, but the conclusion ("please reboot") is not helpful. I did.
On an ipa replica still running CentOS 7.4 I get the attached list of certificates. Hope this helps.
Regards Harri
Harald Dunkel via FreeIPA-users wrote:
Hi Rob,
On 6/25/18 4:53 PM, Rob Crittenden via FreeIPA-users wrote:
We'd need to see what certs are being tracked, getcert list.
This gets stuck, too:
[root@ipa1 ~]# getcert list Error org.freedesktop.DBus.Error.TimedOut
I found https://bugzilla.redhat.com/show_bug.cgi?id=1519206, but the conclusion ("please reboot") is not helpful. I did.
The dbus developers don't think it should ever be restarted mid-stream. I suppose they have their reasons.
I'd need to see the contents of /var/lib/certmonger/requests/* to try to figure out what is bogging things down.
NOTE: THERE MAY BE EMBEDDED PASSWORDS IN THOSE FILES. PLEASE DO NOT PASTE TO A PUBLIC LIST.
But I do need to see whether there is a PIN at all so for any key_pin= just replace with key_pin=XXXXXXX or something.
On an ipa replica still running CentOS 7.4 I get the attached list of certificates. Hope this helps.
The certs on one system don't affect another.
rob
Regards Harri
FreeIPA-users mailing list -- freeipa-users@lists.fedorahosted.org To unsubscribe send an email to freeipa-users-leave@lists.fedorahosted.org Fedora Code of Conduct: https://getfedora.org/code-of-conduct.html List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/freeipa-users@lists.fedorahost...
Hi Rob,
On 6/25/18 7:10 PM, Rob Crittenden via FreeIPA-users wrote:
Harald Dunkel via FreeIPA-users wrote:
I found https://bugzilla.redhat.com/show_bug.cgi?id=1519206, but the conclusion ("please reboot") is not helpful. I did.
The dbus developers don't think it should ever be restarted mid-stream. I suppose they have their reasons.
I am not sure what you mean by "restarted mid-stream". Does rpm know? Is there a risk at upgrade time?
I'd need to see the contents of /var/lib/certmonger/requests/* to try to figure out what is bogging things down.
NOTE: THERE MAY BE EMBEDDED PASSWORDS IN THOSE FILES. PLEASE DO NOT PASTE TO A PUBLIC LIST.
But I do need to see whether there is a PIN at all so for any key_pin= just replace with key_pin=XXXXXXX or something.
I see several files with a key_pin or Key_pin_file inside. I would prefer to send you these files in an encrypted EMail. What would you suggest? Do you have PGP?
Regards Harri
Harald Dunkel wrote:
Hi Rob,
On 6/25/18 7:10 PM, Rob Crittenden via FreeIPA-users wrote:
Harald Dunkel via FreeIPA-users wrote:
I found https://bugzilla.redhat.com/show_bug.cgi?id=1519206, but the conclusion ("please reboot") is not helpful. I did.
The dbus developers don't think it should ever be restarted mid-stream. I suppose they have their reasons.
I am not sure what you mean by "restarted mid-stream". Does rpm know? Is there a risk at upgrade time?
Basically never except on reboot.
I'd need to see the contents of /var/lib/certmonger/requests/* to try to figure out what is bogging things down.
NOTE: THERE MAY BE EMBEDDED PASSWORDS IN THOSE FILES. PLEASE DO NOT PASTE TO A PUBLIC LIST.
But I do need to see whether there is a PIN at all so for any key_pin= just replace with key_pin=XXXXXXX or something.
I see several files with a key_pin or Key_pin_file inside. I would prefer to send you these files in an encrypted EMail. What would you suggest? Do you have PGP?
Except for the pin the rest of the content is generally safe. My key is available in the MIT keyserver if you want to send it out of band.
rob
Regards Harri
freeipa-users@lists.fedorahosted.org
-
Harald Dunkel -
Harald Dunkel -
Rob Crittenden -
thierry bordaz