Re: [Freeipa-users] migrate-ds aborts

Dmitri Pal Fri, 16 Jan 2015 13:05:48 -0800

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 feelingbased on the internal error above is that there is some datainconsistency in one (or more) of your entries that we choke on.For example an entry does not have a proper object class and thus amandatory attribute we expect is missing.


Thanks again,
Bill

HTH,
Martin

Bill
-----Original Message-----
From: Martin Kosek [mailto:mko...@redhat.com]
Sent: Friday, January 16, 2015 2:25 AM
To: Ludwig Krispenz
Cc: Quayle, Bill; 'freeipa-users@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.

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

Re: [Freeipa-users] migrate-ds aborts

Reply via email to