[Freeipa-users] migrate-ds aborts
Dmitri Pal
dpal at redhat.com
Fri Jan 16 20:59:46 UTC 2015
On 01/16/2015 02:21 PM, Quayle, Bill wrote:
>
>> -----Original Message-----
>> From: Martin Kosek [mailto:mkosek at redhat.com]
>> Sent: Friday, January 16, 2015 12:51 PM
>> To: Quayle, Bill; Ludwig Krispenz
>> Cc: 'freeipa-users at redhat.com'
>> Subject: Re: [Freeipa-users] migrate-ds aborts
>>
>> On 01/16/2015 04:48 PM, Quayle, Bill wrote:
>>> Thanks for looking into this!
>>>
>>> I was finally able to import all 11811 user records into IPA, but even now,
>> when I re-run the migrate, I get the same failure.
>>
>> How did you do it in the end? Simply by running migrate-ds command
>> multiple times or did you succeeded with the limits?
>>
> I re-ran migrate-ds about 30 times to complete the migration of users.
>>> I enabled debug in the default.cfg, and this is the tail of the httpd error_log:
>>>
>>> .
>>> .
>>> .
>>> [Fri Jan 16 09:28:29.046991 2015] [:error] [pid 14924] ipa: WARNING: GID
>> number 11 of migrated user andy does not point to a known group.
>>> [Fri Jan 16 09:28:29.051353 2015] [:error] [pid 14924] ipa: INFO:
>>> admin at IDMTEST.EXAMPLE.COM: migrate_ds(u'ldap://10.x.x.x:389',
>> u'********',
>> binddn=u'uid=me,ou=people,ou=agroup,dc=example,dc=com',
>> usercontainer=u'ou=people', groupcontainer=u'ou=groups',
>> userobjectclass=(u'person',), groupobjectclass=(u'groupOfUniqueNames',
>> u'groupOfNames'), userignoreobjectclass=None, userignoreattribute=None,
>> groupignoreobjectclass=None, groupignoreattribute=None,
>> groupoverwritegid=False, schema=u'RFC2307bis', continue=True,
>> basedn=u'ou=agroup,dc=example,dc=com', compat=False, version=u'2.65',
>> exclude_groups=None, exclude_users=None): NetworkError [Fri Jan 16
>> 09:28:29.051428 2015] [:error] [pid 14924] ipa: DEBUG: response:
>> NetworkError: cannot connect to 'ldap://10.x.x.x:389':
>>> [Fri Jan 16 09:28:29.054057 2015] [:error] [pid 14924] ipa: DEBUG: no
>>> session id in request, generating empty session data with
>>> id=c0d2c8b3803593b30684e15ff1f57e0e
>>> [Fri Jan 16 09:28:29.054173 2015] [:error] [pid 14924] ipa: DEBUG:
>>> store session: session_id=c0d2c8b3803593b30684e15ff1f57e0e
>>> start_timestamp=2015-01-16T09:28:29
>>> access_timestamp=2015-01-16T09:28:29
>>> expiration_timestamp=1969-12-31T18:00:00
>>> [Fri Jan 16 09:28:29.054395 2015] [:error] [pid 14924] ipa: DEBUG:
>> finalize_kerberos_acquisition: xmlserver
>> ccache_name="FILE:/run/httpd/krbcache/krb5cc_apache_zTGsku"
>> session_id="c0d2c8b3803593b30684e15ff1f57e0e"
>>> [Fri Jan 16 09:28:29.054463 2015] [:error] [pid 14924] ipa: DEBUG: reading
>> ccache data from file "/run/httpd/krbcache/krb5cc_apache_zTGsku"
>>> [Fri Jan 16 09:28:29.054851 2015] [:error] [pid 14924] ipa: DEBUG:
>>> get_credential_times:
>>> principal=HTTP/myipatestserver.example.com at IDMTEST.EXAMPLE.COM,
>>> authtime=01/15/15 16:44:10, starttime=01/15/15 16:44:17,
>>> endtime=01/16/15 16:44:04, renew_till=12/31/69 18:00:00 [Fri Jan 16
>>> 09:28:29.055014 2015] [:error] [pid 14924] ipa: DEBUG: KRB5_CCache
>>> FILE:/run/httpd/krbcache/krb5cc_apache_zTGsku endtime=1421448244
>>> (01/16/15 16:44:04) [Fri Jan 16 09:28:29.055109 2015] [:error] [pid
>>> 14924] ipa: DEBUG: set_session_expiration_time:
>>> duration_type=inactivity_timeout duration=1200 max_age=1421447944
>>> expiration=1421423309.06 (2015-01-16T09:48:29) [Fri Jan 16
>>> 09:28:29.055217 2015] [:error] [pid 14924] ipa: DEBUG: store session:
>>> session_id=c0d2c8b3803593b30684e15ff1f57e0e
>>> start_timestamp=2015-01-16T09:28:29
>>> access_timestamp=2015-01-16T09:28:29
>>> expiration_timestamp=2015-01-16T09:48:29
>>> [Fri Jan 16 09:28:29.055806 2015] [:error] [pid 14924] ipa: DEBUG:
>>> Destroyed connection context.ldap2_140392345753040 [Fri Jan 16
>>> 09:28:29.056471 2015] [:error] [pid 14924] ipa: DEBUG: Destroyed
>>> connection context.ldap2
>>>
>>> One thing that is also confusing me, is that I am getting this error:
>>> [Fri Jan 16 09:28:29.007575 2015] [:error] [pid 14924] ipa: WARNING: GID
>> number 11 of migrated user anyone does not point to a known group.
>>
>> migrate-ds command runs a search against the migrated OpenLDAP database
>> and tries to find a group with gidNumber 11. When it fails to locate it, it
>> reports this error. Do you have all the groups in DN
>> "ou=people,ou=agroup,dc=example,dc=com"?
>>
> Groups are in "ou=groups,ou=agroup,dc=example,dc=com"
> I use --base-dn="ou=agroup,dc=example,dc=com" as an option to migrate-ds
>>> And it never migrates my groups. The ou=Groups is used in my source
>> openLDAP tree, so I'm not sure why it wouldn't migrate.
>>
>> If i crashes during user migration, it won't even continue with groups. I know
>> this is not a proper fix, but you could make sure the user migration part does
>> not find anything (e.g. with --user-objectclass=foo) and using --continue
>> option. Then it will jump directly to group migration.
>>
> I had actually already tried doing that. I just re-tried using the debug=True, and here's the contents of error_log:
> [Fri Jan 16 13:07:42.819342 2015] [:error] [pid 15335] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
> [Fri Jan 16 13:07:42.819462 2015] [:error] [pid 15335] ipa: DEBUG: WSGI xmlserver_session.__call__:
> [Fri Jan 16 13:07:42.819649 2015] [:error] [pid 15335] ipa: DEBUG: found session cookie_id = 7efb4fc24d37b7fe064fa2a4f0af447b
> [Fri Jan 16 13:07:42.819926 2015] [:error] [pid 15335] ipa: DEBUG: found session data in cache with id=7efb4fc24d37b7fe064fa2a4f0af447b
> [Fri Jan 16 13:07:42.820031 2015] [:error] [pid 15335] ipa: DEBUG: xmlserver_session.__call__: session_id=7efb4fc24d37b7fe064fa2a4f0af447b start_timestamp=2015-01-16T13:06:02 access_timestamp=2015-01-16T13:07:42 expiration_timestamp=2015-01-16T13:26:02
> [Fri Jan 16 13:07:42.820113 2015] [:error] [pid 15335] ipa: DEBUG: storing ccache data into file "/var/run/ipa_memcached/krbcc_15335"
> [Fri Jan 16 13:07:42.820724 2015] [:error] [pid 15335] ipa: DEBUG: get_credential_times: principal=HTTP/testserver.example.com at IDMTEST.EXAMPLE.COM, authtime=01/15/15 16:44:10, starttime=01/15/15 16:44:17, endtime=01/16/15 16:44:04, renew_till=12/31/69 18:00:00
> [Fri Jan 16 13:07:42.821070 2015] [:error] [pid 15335] ipa: DEBUG: get_credential_times: principal=HTTP/testserver.example.com at IDMTEST.EXAMPLE.COM, authtime=01/15/15 16:44:10, starttime=01/15/15 16:44:17, endtime=01/16/15 16:44:04, renew_till=12/31/69 18:00:00
> [Fri Jan 16 13:07:42.821370 2015] [:error] [pid 15335] ipa: DEBUG: KRB5_CCache FILE:/var/run/ipa_memcached/krbcc_15335 endtime=1421448244 (01/16/15 16:44:04)
> [Fri Jan 16 13:07:42.821480 2015] [:error] [pid 15335] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1421447944 expiration=1421436462.82 (2015-01-16T13:27:42)
> [Fri Jan 16 13:07:42.821539 2015] [:error] [pid 15335] ipa: DEBUG: WSGI xmlserver.__call__:
> [Fri Jan 16 13:07:42.850018 2015] [:error] [pid 15335] ipa: DEBUG: Created connection context.ldap2
> [Fri Jan 16 13:07:42.850117 2015] [:error] [pid 15335] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
> [Fri Jan 16 13:07:42.851403 2015] [:error] [pid 15335] ipa: DEBUG: raw: migrate_ds(u'ldap://10.x.x.x:389', u'********', binddn=u'uid=me,ou=people,ou=agroup,dc=example,dc=com', usercontainer=u'ou=people', groupcontainer=u'ou=groups', userobjectclass=(u'foo',), groupobjectclass=(u'groupOfUniqueNames', u'groupOfNames'), userignoreobjectclass=None, userignoreattribute=None, groupignoreobjectclass=None, groupignoreattribute=None, groupoverwritegid=False, schema=u'RFC2307bis', continue=True, basedn=u'ou=agroup,dc=example,dc=com', compat=False, version=u'2.65', exclude_groups=None, exclude_users=None)
> [Fri Jan 16 13:07:42.852159 2015] [:error] [pid 15335] ipa: DEBUG: migrate_ds(u'ldap://10.x.x.x:389', u'********', binddn=ipapython.dn.DN('uid=me,ou=people,ou=agroup,dc=example,dc=com'), usercontainer=ipapython.dn.DN('ou=people'), groupcontainer=ipapython.dn.DN('ou=groups'), userobjectclass=(u'foo',), groupobjectclass=(u'groupOfUniqueNames', u'groupOfNames'), userignoreobjectclass=None, userignoreattribute=None, groupignoreobjectclass=None, groupignoreattribute=None, groupoverwritegid=False, schema=u'RFC2307bis', continue=True, basedn=ipapython.dn.DN('ou=agroup,dc=example,dc=com'), compat=False, version=u'2.65', exclude_groups=None, exclude_users=None)
> [Fri Jan 16 13:07:42.933433 2015] [:error] [pid 15335] ipa: DEBUG: Created connection context.ldap2_140625322494032
> [Fri Jan 16 13:07:42.944655 2015] [:error] [pid 15335] ipa: ERROR: non-public: UnboundLocalError: local variable 'pkey' referenced before assignment
> [Fri Jan 16 13:07:42.944666 2015] [:error] [pid 15335] Traceback (most recent call last):
> [Fri Jan 16 13:07:42.944668 2015] [:error] [pid 15335] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 333, in wsgi_execute
> [Fri Jan 16 13:07:42.944670 2015] [:error] [pid 15335] result = self.Command[name](*args, **options)
> [Fri Jan 16 13:07:42.944671 2015] [:error] [pid 15335] File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 436, in __call__
> [Fri Jan 16 13:07:42.944673 2015] [:error] [pid 15335] ret = self.run(*args, **options)
> [Fri Jan 16 13:07:42.944683 2015] [:error] [pid 15335] File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 755, in run
> [Fri Jan 16 13:07:42.944686 2015] [:error] [pid 15335] result = self.execute(*args, **options)
> [Fri Jan 16 13:07:42.944687 2015] [:error] [pid 15335] File "/usr/lib/python2.7/site-packages/ipalib/plugins/migration.py", line 894, in execute
> [Fri Jan 16 13:07:42.944689 2015] [:error] [pid 15335] ldap, config, ds_ldap, ds_base_dn, options
> [Fri Jan 16 13:07:42.944691 2015] [:error] [pid 15335] File "/usr/lib/python2.7/site-packages/ipalib/plugins/migration.py", line 843, in migrate
> [Fri Jan 16 13:07:42.944692 2015] [:error] [pid 15335] _update_default_group(ldap, pkey, config, context, True)
> [Fri Jan 16 13:07:42.944694 2015] [:error] [pid 15335] UnboundLocalError: local variable 'pkey' referenced before assignment
> [Fri Jan 16 13:07:42.944888 2015] [:error] [pid 15335] ipa: INFO: admin at IDMTEST.EXAMPLE.COM: migrate_ds(u'ldap://10.x.x.x:389', u'********', binddn=u'uid=me,ou=people,ou=agroup,dc=example,dc=com', usercontainer=u'ou=people', groupcontainer=u'ou=groups', userobjectclass=(u'foo',), groupobjectclass=(u'groupOfUniqueNames', u'groupOfNames'), userignoreobjectclass=None, userignoreattribute=None, groupignoreobjectclass=None, groupignoreattribute=None, groupoverwritegid=False, schema=u'RFC2307bis', continue=True, basedn=u'ou=agroup,dc=example,dc=com', compat=False, version=u'2.65', exclude_groups=None, exclude_users=None): UnboundLocalError
> [Fri Jan 16 13:07:42.944952 2015] [:error] [pid 15335] ipa: DEBUG: response: InternalError: an internal error has occurred
> [Fri Jan 16 13:07:42.945645 2015] [:error] [pid 15335] ipa: DEBUG: Destroyed connection context.ldap2
> [Fri Jan 16 13:07:42.945757 2015] [:error] [pid 15335] ipa: DEBUG: Destroyed connection context.ldap2_140625322494032
> [Fri Jan 16 13:07:42.945846 2015] [:error] [pid 15335] ipa: DEBUG: reading ccache data from file "/var/run/ipa_memcached/krbcc_15335"
> [Fri Jan 16 13:07:42.946019 2015] [:error] [pid 15335] ipa: DEBUG: store session: session_id=7efb4fc24d37b7fe064fa2a4f0af447b start_timestamp=2015-01-16T13:06:02 access_timestamp=2015-01-16T13:07:42 expiration_timestamp=2015-01-16T13:27:42
>
>> I am still thinking it would make sense to also check the migrated OpenLDAP
>> logs and see if there is anything interesting when the migration breaks.
> I've been watching the logs on the OpenLDAP servers, and they just see the connection close.
We would probably need Rob to take a look at this but my gut feeling
based on the internal error above is that there is some data
inconsistency in one (or more) of your entries that we choke on.
For example an entry does not have a proper object class and thus a
mandatory attribute we expect is missing.
>
> Thanks again,
> Bill
>
>> HTH,
>> Martin
>>
>>> Bill
>>> -----Original Message-----
>>> From: Martin Kosek [mailto:mkosek at redhat.com]
>>> Sent: Friday, January 16, 2015 2:25 AM
>>> To: Ludwig Krispenz
>>> Cc: Quayle, Bill; 'freeipa-users at redhat.com'
>>> Subject: Re: [Freeipa-users] migrate-ds aborts
>>>
>>> On 01/16/2015 09:14 AM, Ludwig Krispenz wrote:
>>>> On 01/16/2015 08:43 AM, Martin Kosek wrote:
>>>>> On 01/15/2015 06:31 PM, Quayle, Bill wrote:
>>>>>> I am migrating an openLDAP tree into ipa, and when I run ipa
>>>>>> migrate-ds, the migration aborts after roughly 36 seconds with:
>>>>>>
>>>>>> ipa: ERROR: cannot connect to 'ldap://10.x.x.x:389':
>>>>>>
>>>>>> It has transferred 9762 records, but seems to hit a timeout that
>>>>>> causes it to stop.
>>>>>>
>>>>>> I've run it in debug mode, which only provides this:
>>>>>>
>>>>>> ipa: DEBUG: Starting external process
>>>>>>
>>>>>> ipa: DEBUG: args=keyctl pupdate 774698354
>>>>>>
>>>>>> ipa: DEBUG: Process finished, return code=0
>>>>>>
>>>>>> ipa: DEBUG: stdout=
>>>>>>
>>>>>> ipa: DEBUG: stderr=
>>>>>>
>>>>>> ipa: DEBUG: Caught fault 907 from server
>>>>>> https://foo.example.com/ipa/session/xml: cannot connect to
>>>>>> 'ldap://10.x.x.x:389':
>>>>>>
>>>>>> ipa: DEBUG: Destroyed connection context.xmlclient
>>>>>>
>>>>>> ipa: ERROR: cannot connect to 'ldap://10.x.x.x:389':
>>>>>>
>>>>>> Initially, it had transferred 2000 records and stopped, until I set
>>>>>> nsslapd-sizelimit in cn=config:
>>>>>>
>>>>>> nsslapd-sizelimit: 20000
>>>>>>
>>>>>> I then re-ran the migration a dozen times, each time it would
>>>>>> transfer more records, but would always time out at around the 36
>>>>>> second mark. Now that I'm at 9762 records, it seems to have reached a
>> peak.
>>>>>> I suspect this is another tunable, but haven't been able to find
>>>>>> it, any document that mentions it, or anyone else hitting this issue.
>>>>>>
>>>>>> RHEL 7.0 server
>>>>>>
>>>>>> idM ipa-server-3.3.3-28
>>>>>>
>>>>>> source is RHEL 6.5 running openldap-2.4.23-34
>>>>>>
>>>>>> command used to migrate:
>>>>>>
>>>>>> ipa migrate-ds --continue --bind-
>> dn="uid=me,ou=people,ou=foo,dc=example,dc=com"
>>>>>> --base-dn="ou=foo,dc=example,dc=com" ldap://10.x.x.x:389
>>>>>>
>>>>>> *Cheers,*
>>>>>>
>>>>>> *-Bill*
>>>>> Ludwig, do you know? I am just thinking it may be also caused by
>>>>> some form of timelimit, as mentioned in
>>>>>
>>>>> https://access.redhat.com/documentation/en-
>> US/Red_Hat_Directory_Serv
>>>>> e
>>>>> r/8.2/html/Administration_Guide/User_Account_Management-
>> Setting_Reso
>>>>> u rce_Limits_Based_on_the_Bind_DN.html
>>>>>
>>>>>
>>>>> (those apply both for bind DNs and global cn=config). Maybe
>>>>> nsslapd-timelimit could be increased? Although I saw the default is
>>>>> 3600, I assume it means 1 hour, i.e. not being the root cause.
>>>> we need the access and error logs from DS, if it is a DS limit it
>>>> should be seen in the err code.
>>> +1
>>>
>>>> Could it be that migrate-ds has it's own limit waiting for a repsponse from
>> DS ?
>>> The search itself in migrate-ds is limit-less:
>>>
>>> try:
>>> entries, truncated = ds_ldap.find_entries(
>>> search_filter, ['*'], search_bases[ldap_obj_name],
>>> ds_ldap.SCOPE_ONELEVEL,
>>> time_limit=0, size_limit=-1,
>>> search_refs=True # migrated DS may contain search
>>> references
>>> )
>>> except...
>>>
>>> Bill, I am wondering, could you add debug=True to /etc/ipa/default.conf on
>> your server, reload the httpd process and re-run the migration? It should
>> print additional debugging information that may help us.
>>> Martin
>>>
>>> ________________________________
>>>
>>>
>>> CONFIDENTIALITY AND SECURITY NOTICE
>>>
>>> The contents of this message and any attachments may be confidential and
>> proprietary. If you are not an intended recipient, please inform the sender of
>> the transmission error and delete this message immediately without reading,
>> distributing or copying the contents.
>
--
Thank you,
Dmitri Pal
Sr. Engineering Manager IdM portfolio
Red Hat, Inc.
More information about the Freeipa-users
mailing list