[Freeipa-users] ipa-dnskeysyncd not starting

Mon Dec 19 21:03:13 UTC 2016

2016-12-19 18:53 GMT+01:00 Martin Basti <mbasti at redhat.com>:

>
>
> On 19.12.2016 17:51, Rob Verduijn wrote:
>
> 2016-12-19 17:06 GMT+01:00 Martin Basti <mbasti at redhat.com>:
>
>>
>>
>> On 19.12.2016 16:27, Rob Verduijn wrote:
>>
>>
>>
>> 2016-12-19 16:07 GMT+01:00 Rob Verduijn <rob.verduijn at gmail.com>:
>>
>>>
>>>
>>>
>>> 2016-12-19 15:52 GMT+01:00 Petr Spacek <pspacek at redhat.com>:
>>>
>>>> On 19.12.2016 14:07, Rob Verduijn wrote:
>>>> > Hello,
>>>> >
>>>> > I'm running ipa on centos 7.3 with the latest patches applied.
>>>> >
>>>> > It seem to run fine however the ipa-dnskeysyncd keeps failing to
>>>> start and
>>>> > I keep seeing this message in my logs:
>>>> >
>>>> > ipa-dnskeysyncd[25663]: ipa         : INFO     LDAP bind...
>>>> > python2[25663]: GSSAPI client step 1
>>>> > python2[25663]: GSSAPI client step 1
>>>> > ns-slapd[2569]: GSSAPI server step 1
>>>> > python2[25663]: GSSAPI client step 1
>>>> > ns-slapd[2569]: GSSAPI server step 2
>>>> > python2[25663]: GSSAPI client step 2
>>>> > ns-slapd[2569]: GSSAPI server step 3
>>>> > ipa-dnskeysyncd[25663]: ipa         : INFO     Commencing sync process
>>>> > ipa-dnskeysyncd[25663]: ipa.ipapython.dnssec.keysyncer.KeySyncer:
>>>> INFO
>>>> > Initial LDAP dump is done, sychronizing with ODS and BIND
>>>> > python2[25674]: GSSAPI client step 1
>>>> > python2[25674]: GSSAPI client step 1
>>>> > ns-slapd[2569]: GSSAPI server step 1
>>>> > python2[25674]: GSSAPI client step 1
>>>> > ns-slapd[2569]: GSSAPI server step 2
>>>> > python2[25674]: GSSAPI client step 2
>>>> > ns-slapd[2569]: GSSAPI server step 3
>>>> > ipa-dnskeysyncd[25663]: Traceback (most recent call last):
>>>> > ipa-dnskeysyncd[25663]: File "/usr/libexec/ipa/ipa-dnskeysyncd",
>>>> line 110,
>>>> > in <module>
>>>> > ipa-dnskeysyncd[25663]: while ldap_connection.syncrepl_poll(all=1,
>>>> > msgid=ldap_search):
>>>> > ipa-dnskeysyncd[25663]: File
>>>> > "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 405, in
>>>> > syncrepl_poll
>>>> > ipa-dnskeysyncd[25663]: self.syncrepl_refreshdone()
>>>> > ipa-dnskeysyncd[25663]: File
>>>> > "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py",
>>>> line 115,
>>>> > in syncrepl_refreshdone
>>>> > ipa-dnskeysyncd[25663]: self.hsm_replica_sync()
>>>> > ipa-dnskeysyncd[25663]: File
>>>> > "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py",
>>>> line 181,
>>>> > in hsm_replica_sync
>>>> > ipa-dnskeysyncd[25663]: ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
>>>> > ipa-dnskeysyncd[25663]: File
>>>> > "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 494,
>>>> in run
>>>> > ipa-dnskeysyncd[25663]: raise CalledProcessError(p.returncode,
>>>> arg_string,
>>>> > str(output))
>>>> > ipa-dnskeysyncd[25663]: subprocess.CalledProcessError: Command
>>>> > '/usr/libexec/ipa/ipa-dnskeysync-replica' returned non-zero exit
>>>> status 1
>>>> > systemd[1]: ipa-dnskeysyncd.service: main process exited, code=exited,
>>>> > status=1/FAILURE
>>>> > systemd[1]: Unit ipa-dnskeysyncd.service entered failed state.
>>>> > systemd[1]: ipa-dnskeysyncd.service failed.
>>>> >
>>>> > for some reason the ipa-dnskeysyncd keeops crashing.
>>>> > Anybody know where to start looking for this one ?
>>>>
>>>> Please raise the debug level so we can see something in the logs:
>>>>
>>>> http://www.freeipa.org/page/Troubleshooting#ipa_command_cras
>>>> hes_or_returns_no_data
>>>>
>>>> --
>>>> Petr^2 Spacek
>>>>
>>>> --
>>>> Manage your subscription for the Freeipa-users mailing list:
>>>> https://www.redhat.com/mailman/listinfo/freeipa-users
>>>> Go to http://freeipa.org for more info on the project
>>>>
>>>
>>> Hello,
>>>
>>> The file /etc/ipa/ipa.conf or the file /etc/ipa/server.conf do not exist
>>> on my system.
>>> How to set debugging in this case ?
>>>
>>> Rob
>>>
>>
>> I've set the debug level in /etc/ipa/default.conf
>>
>> now I get this output
>>  systemd[1]: ipa-dnskeysyncd.service: main process exited, code=exited,
>> status=1/FAILURE
>>  systemd[1]: Unit ipa-dnskeysyncd.service entered failed state.
>>  systemd[1]: ipa-dnskeysyncd.service failed.
>>  systemd[1]: ipa-dnskeysyncd.service holdoff time over, scheduling
>> restart.
>>  systemd[1]: Started IPA key daemon.
>>  systemd[1]: Starting IPA key daemon...
>>  ipa-dnskeysyncd[30568]: ipa         : INFO     LDAP bind...
>>  python2[30568]: GSSAPI client step 1
>>  python2[30568]: GSSAPI client step 1
>>  ns-slapd[26744]: GSSAPI server step 1
>>  python2[30568]: GSSAPI client step 1
>>  ns-slapd[26744]: GSSAPI server step 2
>>  python2[30568]: GSSAPI client step 2
>>  ns-slapd[26744]: GSSAPI server step 3
>>  ipa-dnskeysyncd[30568]: ipa         : INFO     Commencing sync process
>>  ipa-dnskeysyncd[30568]: ipa.ipapython.dnssec.keysyncer.KeySyncer:
>> INFO     Initial LDAP dump is done, sychronizing with ODS and BIND
>>  python2[30579]: GSSAPI client step 1
>>  python2[30579]: GSSAPI client step 1
>>  ns-slapd[26744]: GSSAPI server step 1
>>  python2[30579]: GSSAPI client step 1
>>  ns-slapd[26744]: GSSAPI server step 2
>>  python2[30579]: GSSAPI client step 2
>>  ns-slapd[26744]: GSSAPI server step 3
>>  python2[30579]: ObjectStore.cpp(59): Failed to enumerate object store in
>> /var/lib/softhsm/tokens/
>>  python2[30579]: SoftHSM.cpp(476): Could not load the object store
>>  ipa-dnskeysyncd[30568]: Traceback (most recent call last):
>>  ipa-dnskeysyncd[30568]: File "/usr/libexec/ipa/ipa-dnskeysyncd", line
>> 110, in <module>
>>  ipa-dnskeysyncd[30568]: while ldap_connection.syncrepl_poll(all=1,
>> msgid=ldap_search):
>>  ipa-dnskeysyncd[30568]: File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py",
>> line 405, in syncrepl_poll
>>  ipa-dnskeysyncd[30568]: self.syncrepl_refreshdone()
>>  ipa-dnskeysyncd[30568]: File "/usr/lib/python2.7/site-packa
>> ges/ipapython/dnssec/keysyncer.py", line 115, in syncrepl_refreshdone
>>  ipa-dnskeysyncd[30568]: self.hsm_replica_sync()
>>  ipa-dnskeysyncd[30568]: File "/usr/lib/python2.7/site-packa
>> ges/ipapython/dnssec/keysyncer.py", line 181, in hsm_replica_sync
>>  ipa-dnskeysyncd[30568]: ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
>>  ipa-dnskeysyncd[30568]: File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py",
>> line 494, in run
>>  ipa-dnskeysyncd[30568]: raise CalledProcessError(p.returncode,
>> arg_string, str(output))
>>  ipa-dnskeysyncd[30568]: subprocess.CalledProcessError: Command
>> '/usr/libexec/ipa/ipa-dnskeysync-replica' returned non-zero exit status
>>
>>
>>
>>
>> Hello, do you have selinux in enforcing mode? Any AVCs ?
>>
>> Martin
>>
>
>
> yes
>
> but ipa-dnskeysyncd still fails to start when selinux is in permissive mode
>
> I did :
> ipactl stop
> setenforce 0
> service auditd rotate
> ipactl start
>
> and see one avc denied
> type=AVC msg=audit(1482164681.053:5195): avc:  denied  { read } for
> pid=1993 comm="ipa-dnskeysync-" name="tokens" dev="dm-7" ino=16818968
> scontext=system_u:system_r:ipa_dnskey_t:s0 tcontext=system_u:object_r:named_cache_t:s0
> tclass=dir
>
> I gues that is one little bit of selinux that needs adjustment,
>
> however there is still no running ipa-dnskeysyncd.
>
> I found that this error appears before the previous one.
>
> ipa-dnskeysyncd[1981]: ipa: DEBUG: ipaserver.plugins.virtual is not a
> valid plugin module
> ipa-dnskeysyncd[1981]: ipa: DEBUG: importing plugin module
> ipaserver.plugins.xmlserver
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Kerberos principal:
> ipa-dnskeysyncd/freeipa01.tjako.thuis
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Initializing principal
> ipa-dnskeysyncd/freeipa01.tjako.thuis using keytab /etc/ipa/dnssec/ipa-
> dnskeysyncd.keytab
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    using ccache
> /tmp/ipa-dnskeysync-replica.ccache
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Attempt 1/5: success
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Got TGT
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Connecting to LDAP
> ipa-dnskeysyncd[1981]: ipa         : DEBUG    Connected
> ipa-dnskeysyncd[1981]: Traceback (most recent call last):
> ipa-dnskeysyncd[1981]: File "/usr/libexec/ipa/ipa-dnskeysync-replica",
> line 159, in <module>
> ipa-dnskeysyncd[1981]: open(paths.DNSSEC_SOFTHSM_PIN).read())
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/dnssec/localhsm.py", line 95, in __init__
> ipa-dnskeysyncd[1981]: self.p11 = _ipap11helper.P11_Helper(slot, pin,
> library)
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/p11helper.py", line 837, in __init__
> ipa-dnskeysyncd[1981]: check_return_value(rv, "open session")
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/p11helper.py", line 576, in check_return_value
> ipa-dnskeysyncd[1981]: raise Error(errmsg)
> ipa-dnskeysyncd[1981]: ipapython.p11helper.Error: Error at open session:
> 0xe1
> ipa-dnskeysyncd[1981]: Exception AttributeError: "'LocalHSM' object has no
> attribute 'p11'" in <bound method LocalHSM.__del__ of
> <ipapython.dnssec.localhsm.LocalHSM object at 0x5ec92d0>> ignored
> ipa-dnskeysyncd[1981]: Traceback (most recent call last):
> ipa-dnskeysyncd[1981]: File "/usr/libexec/ipa/ipa-dnskeysyncd", line 110,
> in <module>
> ipa-dnskeysyncd[1981]: while ldap_connection.syncrepl_poll(all=1,
> msgid=ldap_search):
> ipa-dnskeysyncd[1981]: File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py",
> line 405, in syncrepl_poll
> ipa-dnskeysyncd[1981]: self.syncrepl_refreshdone()
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/dnssec/keysyncer.py", line 115, in syncrepl_refreshdone
> ipa-dnskeysyncd[1981]: self.hsm_replica_sync()
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/dnssec/keysyncer.py", line 181, in hsm_replica_sync
> ipa-dnskeysyncd[1981]: ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
> ipa-dnskeysyncd[1981]: File "/usr/lib/python2.7/site-
> packages/ipapython/ipautil.py", line 494, in run
> ipa-dnskeysyncd[1981]: raise CalledProcessError(p.returncode, arg_string,
> str(output))
> ipa-dnskeysyncd[1981]: subprocess.CalledProcessError: Command
> '/usr/libexec/ipa/ipa-dnskeysync-replica' returned non-zero exit status 1
> systemd[1]: ipa-dnskeysyncd.service: main process exited, code=exited,
> status=1/FAILURE
> systemd[1]: Unit ipa-dnskeysyncd.service entered failed state.
> systemd[1]: ipa-dnskeysyncd.service failed.
>
>
>
> Selinux caused that key has not been created in HSM database, you have to
> temporarily set selinux to permisive, and run ipa-dns-install again to fix
> it.
>
> Martin
>

Thanx
That seemed to do the trick.

Two more questions.

Now I even have more  AVC deny  records (same kind as before)
type=AVC msg=audit(1482164681.053:5195): avc:  denied  { read } for
pid=1993 comm="ipa-dnskeysync-" name="tokens" dev="dm-7" ino=16818968
scontext=system_u:system_r:ipa_dnskey_t:s0
tcontext=system_u:object_r:named_cache_t:s0
tclass=dir

How do I deal with those, I don't want to break it again by turning on
enforcing mode again.
Will a simple audit2allow do ? Or is there a better way ?

Second question.
I now have a ton off these messages in my logs:
DSRetroclPlugin - delete_changerecord: could not delete change record<5
digit number> (rc: 32)

What are those, is that a journal being replayed ?

Cheers
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20161219/c4d4ca0f/attachment.htm>