On 01/16/2015 11:38 PM, Rob Crittenden wrote: > Dmitri Pal wrote: >> On 01/16/2015 02:21 PM, Quayle, Bill wrote: >>> >>>> -----Original Message----- >>>> From: Martin Kosek [mailto:mko...@redhat.com] >>>> Sent: Friday, January 16, 2015 12:51 PM >>>> To: Quayle, Bill; Ludwig Krispenz >>>> Cc: 'freeipa-users@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: >>>>> ad...@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....@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....@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....@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: >>> ad...@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.
+1 > > 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). I think I have pretty clear understanding how the pkey exception is thrown: https://fedorahosted.org/freeipa/ticket/4846 But this one is not related to the main root cause of these migration issues, unfortunately. > > Any chance you can provide a small ldif of an entry that is failing? +1 Additional details in my other reply in this thread. Martin -- 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
