Bug 1449735
| Summary: | ipa-server-install fails with failed to create ds instance | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Jan Pazdziora (Red Hat) <jpazdziora> |
| Component: | freeipa | Assignee: | IPA Maintainers <ipa-maint> |
| Status: | CLOSED DUPLICATE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 26 | CC: | abokovoy, ipa-maint, jcholast, jhrozek, jpazdziora, pvoborni, rcritten, ssorce, tbordaz, tkrizek |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2017-05-18 15:17:25 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
I first though that it might be related to bug 1435122 which was reproducible on machines with low amount of memory e.g. 1GB. But that should be fixed in build 1.3.6.5-1 Thierry, any idea? DS was actually successfully created but startup last more than 2 hours [10/May/2017:13:55:10.969705294 +0200] - INFO - main - 389-Directory/1.3.6.5 B2017.117.158 starting up [10/May/2017:15:55:16.311119233 +0200] - ERR - ldbm_instance_config_cachememsize_set - force a minimal value 512000 ... [10/May/2017:15:55:17.448924606 +0200] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests It triggered IPA install timeout that shutdown DS 2017-05-10T11:55:07Z DEBUG args=/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ ... 2017-05-10T13:55:17Z DEBUG stdout=Error: timed out waiting for the server to start and write to /var/log/dirsrv/slapd-EXAMPLE-TEST/errors There is no detail (in the logs) what DS was doing between 13:55:10 and 15:55:17 According to beaker logs (http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2017/05/18512/1851263/3827184/55571909/272727415/test_log-ipa-install-topo-default-master-install-Master-in-Default-Topology-avc.log) We can see that the same DS process is having startup AVC for 2h time->Wed May 10 20:28:14 2017 type=AVC msg=audit(1494440894.398:316): avc: denied { search } for pid=9293 comm="ns-slapd" name="/" dev="cgroup" ino=1 scontext=system_u:system_r:dirsrv_t:s0 tcontext=system_u:object_r:cgroup_t:s0 tclass=dir permissive=0 ... time->Wed May 10 22:28:21 2017 type=AVC msg=audit(1494448101.027:353): avc: denied { search } for pid=9293 comm="ns-slapd" name="/" dev="cgroup" ino=1 scontext=system_u:system_r:dirsrv_t:s0 tcontext=system_u:object_r:cgroup_t:s0 tclass=dir permissive=0 I have a doubt it can be related to https://bugzilla.redhat.com/show_bug.cgi?id=1444864 (https://bugzilla.redhat.com/show_bug.cgi?id=1436689) In conclusion: - In order to eliminate the selinux policy bug, would you check policy >= selinux-policy-3.13.1-148.el7 - Else it needs to be reproduced and when it is hanging, it would require some pstack to know what DS is doing during those 2h startup I fail to reproduced with: freeipa-server-4.4.4-1.fc26.x86_64 389-ds-base-1.3.6.5-1.fc26.x86_64 selinux-policy-3.13.1-241.fc26.noarch The AVC messages (audit and error logs) do not happen with that version of selinux-policy. The problem (hang for 2h) was not systematic so even if I failed to reproduce it can not be 100% the hang was due to Selinux policy. IMHO we should close that bug as duplicate of https://bugzilla.redhat.com/show_bug.cgi?id=1436689, and reopen it if the hang situation happen again. If the hang occurs again, several pstacks of DS are required. *** This bug has been marked as a duplicate of bug 1436689 *** |
Description of problem: Running ipa-server-install fails at the stage [2/47]: creating directory server instance [error] RuntimeError: failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 ipa.ipapython.install.cli.install_tool(Server): ERROR failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 ipa.ipapython.install.cli.install_tool(Server): ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information Version-Release number of selected component (if applicable): freeipa-server-4.4.4-1.fc26.x86_64 389-ds-base-1.3.6.5-1.fc26.x86_64 How reproducible: Deterministic. Steps to Reproduce: 1. Run ipa-server-install. Actual results: ipa-server-install --setup-dns --forwarder=10.11.12.13 --hostname=ipa.example.test -r EXAMPLE.TEST -n example.test -p Secret123 -a Secret123 --ip-address=10.11.12.100 -U' Checking DNS domain example.test, please wait ... The log file for this installation can be found in /var/log/ipaserver-install.log ============================================================================== This program will set up the FreeIPA Server. This includes: * Configure a stand-alone CA (dogtag) for certificate management * Configure the Network Time Daemon (ntpd) * Create and configure an instance of Directory Server * Create and configure a Kerberos Key Distribution Center (KDC) * Configure Apache (httpd) * Configure DNS (bind) WARNING: conflicting time&date synchronization service 'chronyd' will be disabled in favor of ntpd Warning: skipping DNS resolution of host ipa.example.test Checking DNS domain example.test., please wait ... Checking DNS forwarders, please wait ... The IPA Master Server will be configured with: Hostname: ipa.example.test IP address(es): 10.11.12.100 Domain name: example.test Realm name: EXAMPLE.TEST BIND DNS server will be configured to serve IPA domain with: Forwarders: 10.11.12.13 Forward policy: only Reverse zone(s): No reverse zone Adding [10.11.12.100 ipa.example.test] to your /etc/hosts file Configuring NTP daemon (ntpd) [1/4]: stopping ntpd [2/4]: writing configuration [3/4]: configuring ntpd to start on boot [4/4]: starting ntpd Done configuring NTP daemon (ntpd). Configuring directory server (dirsrv). Estimated time: 1 minute [1/47]: creating directory server user [2/47]: creating directory server instance [error] RuntimeError: failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 ipa.ipapython.install.cli.install_tool(Server): ERROR failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 ipa.ipapython.install.cli.install_tool(Server): ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information Expected results: No errors. Additional info: ipaserver-install.log has ServerPort= 389 ServerIdentifier= EXAMPLE-TEST Suffix= dc=example,dc=test RootDN= cn=Directory Manager InstallLdifFile= /var/lib/dirsrv/boot.ldif inst_dir= /var/lib/dirsrv/scripts-EXAMPLE-TEST 2017-05-10T11:55:07Z DEBUG calling setup-ds.pl 2017-05-10T11:55:07Z DEBUG Starting external process 2017-05-10T11:55:07Z DEBUG args=/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ 2017-05-10T13:55:17Z DEBUG Process finished, return code=1 2017-05-10T13:55:17Z DEBUG stdout=Error: timed out waiting for the server to start and write to /var/log/dirsrv/slapd-EXAMPLE-TEST/errors[17/05/10:15:55:17] - [Setup] Info Could not start t he directory server using command '/bin/systemctl start dirsrv'. The last line from the error log was 'timeout'. Error: 0 Could not start the directory server using command '/bin/systemctl start dirsrv'. The last line from the error log was 'timeout'. Error: 0 [17/05/10:15:55:17] - [Setup] Fatal Error: Could not create directory server instance 'EXAMPLE-TEST'. Error: Could not create directory server instance 'EXAMPLE-TEST'. [17/05/10:15:55:17] - [Setup] Fatal Exiting . . . Log file is '-' Exiting . . . Log file is '-' 2017-05-10T13:55:17Z DEBUG stderr=Error: timed out waiting for the server to start and write to /var/log/dirsrv/slapd-EXAMPLE-TEST/errors 2017-05-10T13:55:17Z DEBUG Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 449, in start_creation run_step(full_msg, method) File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 439, in run_step method() File "/usr/lib/python2.7/site-packages/ipaserver/install/dsinstance.py", line 560, in __create_instance raise RuntimeError("failed to create ds instance %s" % e) RuntimeError: failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 2017-05-10T13:55:17Z DEBUG [error] RuntimeError: failed to create ds instance Command '/usr/sbin/setup-ds.pl --silent --logfile - -f /tmp/tmpEOf7LJ' returned non-zero exit status 1 2017-05-10T13:55:17Z DEBUG File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 172, in execute return_value = self.run() File "/usr/lib/python2.7/site-packages/ipapython/install/cli.py", line 318, in run cfgr.run() File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 310, in run in it. The /var/log/dirsrv/slapd-EXAMPLE-TEST/errors says 389-Directory/1.3.6.5 B2017.117.158 ipa.example.test:389 (/etc/dirsrv/slapd-EXAMPLE-TEST) [10/May/2017:13:55:08.236068775 +0200] - ERR - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [10/May/2017:13:55:08.258878379 +0200] - INFO - dblayer_instance_start - Import is running with nsslapd-db-private-import-mem on; No other process is allowed to access the database [10/May/2017:13:55:08.272277150 +0200] - INFO - check_and_set_import_cache - pagesize: 4096, available bytes 15967866880, process usage 21028864 [10/May/2017:13:55:08.284124048 +0200] - INFO - check_and_set_import_cache - Import allocates 6237448KB import cache. [10/May/2017:13:55:08.296280831 +0200] - NOTICE - dblayer_select_ncache - Setting ncache to: 2 to keep each chunk below 4Gbytes [10/May/2017:13:55:08.560205105 +0200] - INFO - import_main_offline - import userRoot: Beginning import job... [10/May/2017:13:55:08.571633234 +0200] - INFO - import_main_offline - import userRoot: Index buffering enabled with bucket size 100 [10/May/2017:13:55:08.772570169 +0200] - INFO - import_producer - import userRoot: Processing file "/var/lib/dirsrv/boot.ldif" [10/May/2017:13:55:08.787234883 +0200] - INFO - import_producer - import userRoot: Finished scanning file "/var/lib/dirsrv/boot.ldif" (1 entries) [10/May/2017:13:55:09.285747857 +0200] - INFO - import_monitor_threads - import userRoot: Workers finished; cleaning up... [10/May/2017:13:55:09.496642832 +0200] - INFO - import_monitor_threads - import userRoot: Workers cleaned up. [10/May/2017:13:55:09.511727013 +0200] - INFO - import_main_offline - import userRoot: Cleaning up producer thread... [10/May/2017:13:55:09.523692711 +0200] - INFO - import_main_offline - import userRoot: Indexing complete. Post-processing... [10/May/2017:13:55:09.535649538 +0200] - INFO - import_main_offline - import userRoot: Generating numsubordinates (this may take several minutes to complete)... [10/May/2017:13:55:09.559814064 +0200] - INFO - import_main_offline - import userRoot: Generating numSubordinates complete. [10/May/2017:13:55:09.571740930 +0200] - INFO - ldbm_get_nonleaf_ids - import userRoot: Gathering ancestorid non-leaf IDs... [10/May/2017:13:55:09.583652011 +0200] - INFO - ldbm_get_nonleaf_ids - import userRoot: Finished gathering ancestorid non-leaf IDs. [10/May/2017:13:55:09.607714010 +0200] - ERR - ldbm_ancestorid_new_idl_create_index - Nothing to do to build ancestorid index [10/May/2017:13:55:09.619558742 +0200] - INFO - ldbm_ancestorid_new_idl_create_index - import userRoot: Created ancestorid index (new idl). [10/May/2017:13:55:09.631541411 +0200] - INFO - import_main_offline - import userRoot: Flushing caches... [10/May/2017:13:55:09.643529248 +0200] - INFO - import_main_offline - import userRoot: Closing files... [10/May/2017:13:55:09.726116776 +0200] - INFO - dblayer_pre_close - All database threads now stopped [10/May/2017:13:55:09.739470290 +0200] - INFO - import_main_offline - import userRoot: Import complete. Processed 1 entries in 1 seconds. (1.00 entries/sec) [10/May/2017:13:55:10.836699623 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:13:55:10.860129697 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:13:55:10.872427840 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:13:55:10.884402756 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:13:55:10.896386333 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:13:55:10.914330165 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:13:55:10.969705294 +0200] - INFO - main - 389-Directory/1.3.6.5 B2017.117.158 starting up [10/May/2017:15:55:16.311119233 +0200] - ERR - ldbm_instance_config_cachememsize_set - force a minimal value 512000 [10/May/2017:15:55:16.330889136 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.342359379 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.354439197 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.366357333 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.378407608 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.390351655 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.402539588 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.414345628 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.426347923 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.438297627 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.450342315 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.462255561 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.487448220 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.504220674 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.516239242 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.528198305 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.540255145 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.552145344 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.564166915 +0200] - NOTICE - ldbm_back_start - found 16417692k physical memory [10/May/2017:15:55:16.576179057 +0200] - NOTICE - ldbm_back_start - found 15595716k avaliable [10/May/2017:15:55:16.588149294 +0200] - NOTICE - ldbm_back_start - cache autosizing: db cache: 524288k [10/May/2017:15:55:16.600349589 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.612132512 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.624174965 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.636100853 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.654101396 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.666034687 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.678020010 +0200] - NOTICE - ldbm_back_start - cache autosizing: userRoot entry cache (1 total): 1179648k [10/May/2017:15:55:16.708199686 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.719894819 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.731965488 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.743854988 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.755887105 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.767831431 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.780005326 +0200] - NOTICE - ldbm_back_start - total cache size: 1761607680 B; [10/May/2017:15:55:16.792152052 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.soft_limit_in_bytes". errno=13 [10/May/2017:15:55:16.809772170 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.soft_limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.821884953 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.limit_in_bytes". errno=13 [10/May/2017:15:55:16.839836188 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.857826535 +0200] - ERR - _spal_get_uint64_t_file - Unable to open file "/sys/fs/cgroup/memory/memory.usage_in_bytes". errno=13 [10/May/2017:15:55:16.875771414 +0200] - WARN - spal_meminfo_get - Unable to retrieve /sys/fs/cgroup/memory/memory.limit_in_bytes. There may be no cgroup support on this platform [10/May/2017:15:55:16.893912059 +0200] - INFO - dblayer_start - Resizing db cache size: 2092179456 -> 536870912 [10/May/2017:15:55:16.911653282 +0200] - INFO - dblayer_start - Resizing db cache count: 2 -> 0 [10/May/2017:15:55:17.448924606 +0200] - INFO - slapd_daemon - slapd started. Listening on All Interfaces port 389 for LDAP requests [10/May/2017:15:55:23.968521407 +0200] - INFO - op_thread_cleanup - slapd shutting down - signaling operation threads - op stack size 2 max work q size 1 max work q stack size 1 [10/May/2017:15:55:23.991318021 +0200] - INFO - slapd_daemon - slapd shutting down - closing down internal subsystems and plugins [10/May/2017:15:55:24.008223034 +0200] - INFO - dblayer_pre_close - Waiting for 4 database threads to stop [10/May/2017:15:55:24.282013018 +0200] - INFO - dblayer_pre_close - All database threads now stopped [10/May/2017:15:55:24.316153952 +0200] - INFO - ldbm_back_instance_set_destructor - Set of instances destroyed [10/May/2017:15:55:24.326321446 +0200] - INFO - connection_post_shutdown_cleanup - slapd shutting down - freed 1 work q stack objects - freed 2 op stack objects [10/May/2017:15:55:24.455671344 +0200] - INFO - main - slapd stopped.