[Freeipa-users] migrate-ds aborts

Fri Jan 16 22:38:20 UTC 2015

Dmitri Pal wrote:
> 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.

I'm with Martin. I think we need to see the access log of the server
being migrated from so we can see the exactly queries and results.

The exception being thrown is rather unusual and the only way I can see
that it could happen is if all the entries were either search references
or had invalid DN formatting (or a combination of the two).

Any chance you can provide a small ldif of an entry that is failing?

rob