[Freeipa-users] migrate-ds aborts

Mon Jan 19 08:51:48 UTC 2015

On 01/16/2015 08: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.

Hm, this is definitely not how the migrate-ds is supposed work :-/ I wish we
can find the problem to avoid such difficulties for other users.

...
>>> 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

Right, sorry - I see I mistyped the DN. Does the container then contain a group
with gidNumber 11? It would explain the error you were asking about.

>>
>>> 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.

Maybe your groups use some scheme that migrate-ds does not recognize as group.
Can you show an example/LDIF of a group stored in ou=Groups?

migrate-ds will search for groups with this default filter BTW:

(&(|(objectClass=groupofuniquenames)(objectClass=groupofnames))(cn=*))

>>
>> 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:

Ah. Yes, this revealed one error, although this one just means that neither
user or group search did not return any errors. I created a ticket for it:

https://fedorahosted.org/freeipa/ticket/4846

The fix for this will be easy, but it will not fix the actual root cause of the
migration problems you are hitting

> [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.

access log excerpt may help, if it contains any error logs we could use. I was
also thinking it would be also useful to know which LDAP search exactly failed
as it is not clear from the error. If you modify the FreeIPA server this way:

# cp /usr/lib/python2.7/site-packages/ipaserver/rpcserver.py
/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py.bkp
# sed -i "s/error = e$/error = e\n            import traceback\n
traceback.print_exc()/" /usr/lib/python2.7/site-packages/ipaserver/rpcserver.py
# service httpd restart

The traceback of where the NetworkError is raised should be added to
/var/log/httpd/error_log.