Hide Forgot
Description of problem: Running ipa-server-install in Fedora rawhide container gets stuck at [45/47]: activating extdom plugin [46/47]: tuning directory server [47/47]: configuring directory to start on boot Done configuring directory server (dirsrv). Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes 30 seconds [1/31]: creating certificate server user [2/31]: configuring certificate server instance [3/31]: stopping certificate server instance to update CS.cfg [4/31]: backing up CS.cfg [5/31]: disabling nonces [6/31]: set up CRL publishing [7/31]: enable PKIX certificate path discovery and validation [8/31]: starting certificate server instance [9/31]: creating RA agent certificate database [10/31]: importing CA chain to RA certificate database [11/31]: fixing RA database permissions [12/31]: setting up signing cert profile [13/31]: setting audit signing renewal to 2 years [14/31]: restarting certificate server [15/31]: requesting RA certificate from CA [16/31]: issuing RA agent certificate [17/31]: adding RA agent as a trusted user [18/31]: authorizing RA to modify profiles [19/31]: authorizing RA to manage lightweight CAs [20/31]: Ensure lightweight CAs container exists [21/31]: configure certmonger for renewals [22/31]: configure certificate renewals [23/31]: configure RA certificate renewal [24/31]: configure Server-Cert certificate renewal [25/31]: Configure HTTP to proxy connections [26/31]: restarting certificate server [27/31]: migrating certificate profiles to LDAP Version-Release number of selected component (if applicable): freeipa-server-4.4.2-2.fc26.x86_64 pki-server-10.3.5-8.fc26.noarch How reproducible: Deterministic. Steps to Reproduce: 1. Run container build with Dockerfile.fedora-rawhide from https://github.com/adelton/docker-freeipa Actual results: The start does not proceed beyond [27/31]: migrating certificate profiles to LDAP Expected results: Initial configuration finishes correctly. Additional info:
Running journalctl -f in the container shows Nov 16 12:13:50 ipa.example.test server[1819]: Creating session 7B06ABD5CC69766270656B2539C5D25C Nov 16 12:13:50 ipa.example.test server[1819]: Principal: GenericPrincipal[ipara(Certificate Manager Agents,Registration Manager Agents,)] Nov 16 12:13:50 ipa.example.test server[1819]: Nov 16, 2016 12:13:50 PM org.jboss.resteasy.core.registry.SegmentNode match Nov 16 12:13:50 ipa.example.test server[1819]: WARN: RESTEASY002142: Multiple resource methods match request "POST /profiles/raw". Selecting one. Matching methods: [public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.createProfileRaw(byte[]), public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.modifyProfileState(java.lang.String,java.lang.String)] Nov 16 12:13:50 ipa.example.test server[1819]: SSLAuthenticatorWithFallback: Authenticate with client certificate authentication Nov 16 12:13:50 ipa.example.test server[1819]: Destroying session B166E0508031A32CEFB01332B12E112E Nov 16 12:13:50 ipa.example.test server[1819]: Exception in thread "http-bio-8443-exec-15" java.lang.OutOfMemoryError: unable to create new native thread Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.start0(Native Method) Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.start(Thread.java:714) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor.processWorkerExit(ThreadPoolExecutor.java:1018) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) Nov 16 12:13:50 ipa.example.test server[1819]: at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.run(Thread.java:745) Nov 16 12:13:50 ipa.example.test server[1819]: SSLAuthenticatorWithFallback: Authenticate with client certificate authentication Nov 16 12:13:50 ipa.example.test server[1819]: Creating session 75143B3515C17C5C01E4AF552DA039D0 Nov 16 12:13:50 ipa.example.test server[1819]: Principal: GenericPrincipal[ipara(Certificate Manager Agents,Registration Manager Agents,)] Nov 16 12:13:50 ipa.example.test server[1819]: Exception in thread "http-bio-8443-Acceptor-0" java.lang.OutOfMemoryError: unable to create new native thread Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.start0(Native Method) Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.start(Thread.java:714) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950) Nov 16 12:13:50 ipa.example.test server[1819]: at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1357) Nov 16 12:13:50 ipa.example.test server[1819]: at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:161) Nov 16 12:13:50 ipa.example.test server[1819]: at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:141) Nov 16 12:13:50 ipa.example.test server[1819]: at org.apache.tomcat.util.net.JIoEndpoint.processSocket(JIoEndpoint.java:500) Nov 16 12:13:50 ipa.example.test server[1819]: at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:203) Nov 16 12:13:50 ipa.example.test server[1819]: at java.lang.Thread.run(Thread.java:745)
The /var/log/pki/pki-tomcat/catalina.2016-11-16.log ends with 16-Nov-2016 12:13:49.476 INFO [http-bio-8443-exec-2] org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.processApplication RESTEASY002215: Adding singleton provider org.dogtagpki.server.rest.SessionContextInterceptor from Application class org.dogtagpki.server.ca.rest.CAApplication 16-Nov-2016 12:13:49.477 INFO [http-bio-8443-exec-2] org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.processApplication RESTEASY002215: Adding singleton provider org.dogtagpki.server.rest.AuthMethodInterceptor from Application class org.dogtagpki.server.ca.rest.CAApplication 16-Nov-2016 12:13:49.478 INFO [http-bio-8443-exec-2] org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.processApplication RESTEASY002215: Adding singleton provider org.dogtagpki.server.rest.ACLInterceptor from Application class org.dogtagpki.server.ca.rest.CAApplication 16-Nov-2016 12:13:49.478 INFO [http-bio-8443-exec-2] org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.processApplication RESTEASY002215: Adding singleton provider org.dogtagpki.server.rest.MessageFormatInterceptor from Application class org.dogtagpki.server.ca.rest.CAApplication 16-Nov-2016 12:13:50.014 WARN [http-bio-8443-exec-3] org.jboss.resteasy.core.registry.SegmentNode.match RESTEASY002142: Multiple resource methods match request "POST /profiles/raw". Selecting one. Matching methods: [public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.createProfileRaw(byte[]), public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.modifyProfileState(java.lang.String,java.lang.String)] 16-Nov-2016 12:13:50.378 WARN [http-bio-8443-exec-11] org.jboss.resteasy.core.registry.SegmentNode.match RESTEASY002142: Multiple resource methods match request "POST /profiles/raw". Selecting one. Matching methods: [public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.createProfileRaw(byte[]), public abstract javax.ws.rs.core.Response com.netscape.certsrv.profile.ProfileResource.modifyProfileState(java.lang.String,java.lang.String)]
The /var/log/ipaserver-install.log ends with 2016-11-16T12:13:50Z DEBUG request POST https://ipa.example.test:8443/ca/rest/profiles/raw 2016-11-16T12:13:50Z DEBUG request body 'desc=This certificate profile is for enrolling user certificates with S/MIME capabilities extension - OID: 1.2.840.113549.1.9.15\nvisible=true\nenable=true\nenableBy=admin\nname=Manual User Dual-Use S/MIME capabilities Certificate Enrollment\nauth.class_id=\ninput.list=i1,i2,i3\ninput.i1.class_id=keyGenInputImpl\ninput.i2.class_id=subjectNameInputImpl\ninput.i3.class_id=submitterInfoInputImpl\noutput.list=o1\noutput.o1.class_id=certOutputImpl\npolicyset.list=userCertSet\npolicyset.userCertSet.list=1,10,2,3,4,5,6,7,8,9,11\npolicyset.userCertSet.1.constraint.class_id=subjectNameConstraintImpl\npolicyset.userCertSet.1.constraint.name=Subject Name Constraint\npolicyset.userCertSet.1.constraint.params.pattern=UID=.*\npolicyset.userCertSet.1.constraint.params.accept=true\npolicyset.userCertSet.1.default.class_id=userSubjectNameDefaultImpl\npolicyset.userCertSet.1.default.name=Subject Name Default\npolicyset.userCertSet.1.default.params.name=\npolicyset.userCertSet.10.constraint.class_id=renewGracePeriodConstraintImpl\npolicyset.userCertSet.10.constraint.name=Renewal Grace Period Constraint\npolicyset.userCertSet.10.constraint.params.renewal.graceBefore=30\npolicyset.userCertSet.10.constraint.params.renewal.graceAfter=30\npolicyset.userCertSet.10.default.class_id=noDefaultImpl\npolicyset.userCertSet.10.default.name=No Default\npolicyset.userCertSet.2.constraint.class_id=validityConstraintImpl\npolicyset.userCertSet.2.constraint.name=Validity Constraint\npolicyset.userCertSet.2.constraint.params.range=365\npolicyset.userCertSet.2.constraint.params.notBeforeCheck=false\npolicyset.userCertSet.2.constraint.params.notAfterCheck=false\npolicyset.userCertSet.2.default.class_id=validityDefaultImpl\npolicyset.userCertSet.2.default.name=Validity Default\npolicyset.userCertSet.2.default.params.range=180\npolicyset.userCertSet.2.default.params.startTime=0\npolicyset.userCertSet.3.constraint.class_id=keyConstraintImpl\npolicyset.userCertSet.3.constraint.name=Key Constraint\npolicyset.userCertSet.3.constraint.params.keyType=-\npolicyset.userCertSet.3.constraint.params.keyParameters=1024,2048,3072,4096,nistp256,nistp384,nistp521\npolicyset.userCertSet.3.default.class_id=userKeyDefaultImpl\npolicyset.userCertSet.3.default.name=Key Default\npolicyset.userCertSet.4.constraint.class_id=noConstraintImpl\npolicyset.userCertSet.4.constraint.name=No Constraint\npolicyset.userCertSet.4.default.class_id=authorityKeyIdentifierExtDefaultImpl\npolicyset.userCertSet.4.default.name=Authority Key Identifier Default\npolicyset.userCertSet.5.constraint.class_id=noConstraintImpl\npolicyset.userCertSet.5.constraint.name=No Constraint\npolicyset.userCertSet.5.default.class_id=authInfoAccessExtDefaultImpl\npolicyset.userCertSet.5.default.name=AIA Extension Default\npolicyset.userCertSet.5.default.params.authInfoAccessADEnable_0=true\npolicyset.userCertSet.5.default.params.authInfoAccessADLocationType_0=URIName\npolicyset.userCertSet.5.default.params.authInfoAccessADLocation_0=\npolicyset.userCertSet.5.default.params.authInfoAccessADMethod_0=1.3.6.1.5.5.7.48.1\npolicyset.userCertSet.5.default.params.authInfoAccessCritical=false\npolicyset.userCertSet.5.default.params.authInfoAccessNumADs=1\npolicyset.userCertSet.6.constraint.class_id=keyUsageExtConstraintImpl\npolicyset.userCertSet.6.constraint.name=Key Usage Extension Constraint\npolicyset.userCertSet.6.constraint.params.keyUsageCritical=true\npolicyset.userCertSet.6.constraint.params.keyUsageDigitalSignature=true\npolicyset.userCertSet.6.constraint.params.keyUsageNonRepudiation=true\npolicyset.userCertSet.6.constraint.params.keyUsageDataEncipherment=false\npolicyset.userCertSet.6.constraint.params.keyUsageKeyEncipherment=true\npolicyset.userCertSet.6.constraint.params.keyUsageKeyAgreement=false\npolicyset.userCertSet.6.constraint.params.keyUsageKeyCertSign=false\npolicyset.userCertSet.6.constraint.params.keyUsageCrlSign=false\npolicyset.userCertSet.6.constraint.params.keyUsageEncipherOnly=false\npolicyset.userCertSet.6.constraint.params.keyUsageDecipherOnly=false\npolicyset.userCertSet.6.default.class_id=keyUsageExtDefaultImpl\npolicyset.userCertSet.6.default.name=Key Usage Default\npolicyset.userCertSet.6.default.params.keyUsageCritical=true\npolicyset.userCertSet.6.default.params.keyUsageDigitalSignature=true\npolicyset.userCertSet.6.default.params.keyUsageNonRepudiation=true\npolicyset.userCertSet.6.default.params.keyUsageDataEncipherment=false\npolicyset.userCertSet.6.default.params.keyUsageKeyEncipherment=true\npolicyset.userCertSet.6.default.params.keyUsageKeyAgreement=false\npolicyset.userCertSet.6.default.params.keyUsageKeyCertSign=false\npolicyset.userCertSet.6.default.params.keyUsageCrlSign=false\npolicyset.userCertSet.6.default.params.keyUsageEncipherOnly=false\npolicyset.userCertSet.6.default.params.keyUsageDecipherOnly=false\npolicyset.userCertSet.7.constraint.class_id=noConstraintImpl\npolicyset.userCertSet.7.constraint.name=No Constraint\npolicyset.userCertSet.7.default.class_id=extendedKeyUsageExtDefaultImpl\npolicyset.userCertSet.7.default.name=Extended Key Usage Extension Default\npolicyset.userCertSet.7.default.params.exKeyUsageCritical=false\npolicyset.userCertSet.7.default.params.exKeyUsageOIDs=1.3.6.1.5.5.7.3.2,1.3.6.1.5.5.7.3.4\npolicyset.userCertSet.8.constraint.class_id=noConstraintImpl\npolicyset.userCertSet.8.constraint.name=No Constraint\npolicyset.userCertSet.8.default.class_id=subjectAltNameExtDefaultImpl\npolicyset.userCertSet.8.default.name=Subject Alt Name Constraint\npolicyset.userCertSet.8.default.params.subjAltNameExtCritical=false\npolicyset.userCertSet.8.default.params.subjAltExtType_0=RFC822Name\npolicyset.userCertSet.8.default.params.subjAltExtPattern_0=$request.requestor_email$\npolicyset.userCertSet.8.default.params.subjAltExtGNEnable_0=true\npolicyset.userCertSet.8.default.params.subjAltNameNumGNs=1\npolicyset.userCertSet.9.constraint.class_id=signingAlgConstraintImpl\npolicyset.userCertSet.9.constraint.name=No Constraint\npolicyset.userCertSet.9.constraint.params.signingAlgsAllowed=SHA1withRSA,SHA256withRSA,SHA512withRSA,MD5withRSA,MD2withRSA,SHA1withEC,SHA256withEC,SHA384withRSA,SHA384withEC,SHA512withEC\npolicyset.userCertSet.9.default.class_id=signingAlgDefaultImpl\npolicyset.userCertSet.9.default.name=Signing Alg\npolicyset.userCertSet.9.default.params.signingAlg=-\npolicyset.userCertSet.11.constraint.class_id=noConstraintImpl\npolicyset.userCertSet.11.constraint.name=No Constraint\npolicyset.userCertSet.11.default.class_id=genericExtDefaultImpl\npolicyset.userCertSet.11.default.name=Generic Extension\npolicyset.userCertSet.11.default.params.genericExtOID=1.2.840.113549.1.9.15\npolicyset.userCertSet.11.default.params.genericExtData=3067300B06092A864886F70D010105300B06092A864886F70D01010B300B06092A864886F70D01010C300B06092A864886F70D01010D300A06082A864886F70D0307300B0609608648016503040102300B060960864801650304012A300B06092A864886F70D010101\nprofileId=caUserSMIMEcapCert\nclassId=caEnrollImpl\n' 2016-11-16T12:13:50Z DEBUG NSSConnection init ipa.example.test 2016-11-16T12:13:50Z DEBUG Connecting: 172.17.0.2 even if it's now Wed Nov 16 12:20:42 UTC 2016.
Judging from the "java.lang.OutOfMemoryError: unable to create new native thread", it looks like you ran out of memory. Could you increase the memory in the container and try again?
I haven't hit this issue for the past couple of days of heavy testing of fedora:rawhide-based IPA installations. The processes in container are not memory-limited by default so I don't think increasing the memory in container would help.
I spoke too fast. I don't see the problem when running containers on Fedora 25 host but I see it when running on Fedora 24 host. The process which reports those OOM error is sitting there just fine in the container: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1698 pkiuser 20 0 3574500 531088 20380 S 0.0 13.1 0:19.52 java Maybe the process somehow tries to determine the free memory and fails on older OS?
I can confirm that I can see similar behavior using martbab/freeipa-fedora-test-runner:master-latest image (F25) on my laptop (F24), although my setup gets stuck on alternately on "[10/29]: requesting RA certificate from CA" and "27/31]: migrating certificate profiles to LDAP". Nevertheless, investigating journal log reports the same exception as in Jan's case: {{{ Dec 01 16:36:52 master.ipa.test server[32404]: Principal: GenericPrincipal[ipara(Certificate Manager Agents,Registration Manager Agents,)] Dec 01 16:36:52 master.ipa.test server[32404]: Exception in thread "http-bio-8443-Acceptor-0" java.lang.OutOfMemoryError: unable to create new native thread Dec 01 16:36:52 master.ipa.test server[32404]: at java.lang.Thread.start0(Native Method) Dec 01 16:36:52 master.ipa.test server[32404]: at java.lang.Thread.start(Thread.java:714) Dec 01 16:36:52 master.ipa.test server[32404]: at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950) Dec 01 16:36:52 master.ipa.test server[32404]: at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1357) Dec 01 16:36:52 master.ipa.test server[32404]: at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:161) Dec 01 16:36:52 master.ipa.test server[32404]: at org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:141) Dec 01 16:36:52 master.ipa.test server[32404]: at org.apache.tomcat.util.net.JIoEndpoint.processSocket(JIoEndpoint.java:500) Dec 01 16:36:52 master.ipa.test server[32404]: at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:203) Dec 01 16:36:52 master.ipa.test server[32404]: at java.lang.Thread.run(Thread.java:745) }}}
It is caused by java not being able to get any more threads from the OS and blocking (happens around 73 or 74 threads, which is not abnormal for pki-tomcatd). I don't know enough about systemd/cgroups/Docker to fully comprehend the problem but see discussion at http://unix.stackexchange.com/questions/253903/creating-threads-fails-with-resource-temporarily-unavailable-with-4-3-kernel/255603#255603. Apparently Docker 1.12 (which is in f25; f24 has 1.10) has better defaults.
As it is docker issue, moving from bare IPA. I don't know if it should be in ipa-docker or docker itself.
I'm not happy about the product change from Fedora to RHEL. Do we have a reproducer for this issue in RHEL? If we do, let's clone this bugzilla for RHEL, but let's also keep the original to track fix in Fedora. Could you change the product back to Fedora?
I'm fine with keeping it in Fedora, but primarily, it is not a bug in IPA component. What Fedora component it should belong?
No idea. Maybe we need new freeipa-server-docker component for containerization of Fedora bits?
The code is developed at https://github.com/freeipa/freeipa-container It would make sense to use its issue tracker. And optionally use Fedora's ipa component only as a tracker
It's unknown if this bug is still valid. Also it doesn't belong to ipa-server-docker compoonent on RHEL nor freeipa component on Fedora. If the bug is still valid please open a bug on https://github.com/freeipa/freeipa-container or FreeIPA pagure issue tracker.
I don't think upstream tracker is particularly good place for an issue which seems to be specific for a particular version of OS.