[OPENAM-9749] Resource leak in ssoadm's audit logging Created: 27/Sep/16  Updated: 10/Oct/17  Resolved: 10/Oct/17

Status: Resolved
Project: OpenAM
Component/s: ssoadm
Affects Version/s: 13.5.0
Fix Version/s: 13.5.1, 14.0.0

Type: Bug Priority: Major
Reporter: Sam Phua Assignee: Peter Major [X] (Inactive)
Resolution: Fixed Votes: 0
Labels: EDISON
Remaining Estimate: 0h
Time Spent: 3h
Original Estimate: 0h

Attachments: File first-stage.json     File generate-policy.sh     File mypolicy.json    
Issue Links:
Duplicate
is duplicated by OPENAM-10453 ssoadm fails on multi-core machines Resolved
Regression
caused OPENAM-10125 LogWriter.<clinit> throws Guice error Resolved
Target Version/s:
Sprint: AM Sustaining Sprint 28, AM Sustaining Sprint 43
Needs backport:
No
Support Ticket IDs:
Needs QA verification:
No
Functional tests:
No
Are the reproduction steps defined?:
Yes and I used the same an in the description

 Description   

Create a json policy file with around 500 policies

Run the following command

/SSOadmin13.5.0/openam/bin/ssoadm policy-import --realm / --servername "http://openam.internal.example.com:8080/openam"  --jsonfile /work/mypolicy.json --adminid amadmin --password-file /home/iplanet/pass.txt

The following OOM exception will be observed

Exception in thread "pool-403-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "pool-404-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "pool-405-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "pool-406-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "pool-408-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
Exception in thread "pool-409-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:714)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
	at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
	at java.lang.Thread.run(Thread.java:745)
{
  "RESOURCE_TYPE" : {
    "UPDATE_SUCCESS" : {
      "count" : 1
    }
  },
  "POLICY" : {
    "CREATE_SUCCESS" : {
      "count" : 405
    }
  },
  "APPLICATION" : {
    "UPDATE_SUCCESS" : {
      "count" : 1
    }
  }

Workaround is to import the policies using XACML Format



 Comments   
Comment by Peter Major [X] (Inactive) [ 28/Sep/16 ]

The resource leak was actually within the audit log portion of ssoadm. Firstly the Response objects weren't closed, which meant that http-client async processing threads stayed around expecting further data, secondly a new Client object with a new HttpClientHandler object was used, but the HttpClientHandler objects are meant to be closed as well. The solution was to close the response in LogWriter and ensure that the Client object was retrieved via CloseableHttpClientProvider.

Comment by Andrew Dunn [X] (Inactive) [ 11/Oct/16 ]

Running several hundred batch "create-agent" commands in a row can result in ssoadm debug IdRepo:

ERROR: IdRemoteServicesImpl.processException(): caught remote/un-known exception -
java.net.SocketException: Too many open files

And failed command in batch status file.

127 create-agent --realm test10 --agenttype OAuth2Client --agentname agent1690 --datafile props

It's assumed this is due to the resource leak describe here.

An effective workaround is to append "--nolog" to the ssoadm do-batch command.

Comment by C-Weng C [ 12/Oct/16 ]

Current OPENAM-9749 Logwriter fix (dcf45fb08ee1) causes issue when running ssoadm.jsp (for things like list-xacml/export-policies). Reverting/undoing the LogWriter class and issue is gone. (ie: So with the fix ssoadm.jsp is no working anymore)

org.apache.jasper.JasperException: com.google.inject.ConfigurationException: Guice configuration errors:

1) Could not find a suitable constructor in org.forgerock.http.Client. Classes must have either one (and only one) constructor annotated with @Inject or a zero-argument constructor that is not private.
  at org.forgerock.http.Client.class(Unknown Source)
  while locating org.forgerock.http.Client
    for parameter 0 at org.forgerock.openam.cli.entitlement.PolicyExport.<init>(Unknown Source)
  while locating org.forgerock.openam.cli.entitlement.PolicyExport

1 error
	org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:555)
	org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:476)
	org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:396)
	org.apache.jasper.servlet.JspServlet.service(JspServlet.java:340)
	javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	org.forgerock.openam.validation.ResponseValidationFilter.doFilter(ResponseValidationFilter.java:44)
	com.sun.identity.setup.AMSetupFilter.doFilter(AMSetupFilter.java:111)
	org.forgerock.openam.audit.context.AuditContextFilter.doFilter(AuditContextFilter.java:51)
	org.forgerock.openam.audit.servlet.AuditAccessServletFilter.doFilter(AuditAccessServletFilter.java:62)
root cause

com.google.inject.ConfigurationException: Guice configuration errors:

1) Could not find a suitable constructor in org.forgerock.http.Client. Classes must have either one (and only one) constructor annotated with @Inject or a zero-argument constructor that is not private.
  at org.forgerock.http.Client.class(Unknown Source)
  while locating org.forgerock.http.Client
    for parameter 0 at org.forgerock.openam.cli.entitlement.PolicyExport.<init>(Unknown Source)
  while locating org.forgerock.openam.cli.entitlement.PolicyExport

1 error
	com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:1004)
	com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:961)
	com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1013)
	org.forgerock.guice.core.InjectorHolder.getInstance(InjectorHolder.java:80)
	com.sun.identity.cli.SubCommand.execute(SubCommand.java:295)
	com.sun.identity.cli.CLIRequest.process(CLIRequest.java:217)
	com.sun.identity.cli.CLIRequest.process(CLIRequest.java:139)
	com.sun.identity.cli.CommandManager.serviceRequestQueue(CommandManager.java:576)
	com.sun.identity.cli.WebCLIHelper.processRequest(WebCLIHelper.java:151)
	com.sun.identity.cli.WebCLIHelper.getHTML(WebCLIHelper.java:92)
	org.apache.jsp.ssoadm_jsp._jspService(ssoadm_jsp.java:289)
	org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
	javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:438)
	org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:396)
	org.apache.jasper.servlet.JspServlet.service(JspServlet.java:340)
	javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	org.forgerock.openam.validation.ResponseValidationFilter.doFilter(ResponseValidationFilter.java:44)
	com.sun.identity.setup.AMSetupFilter.doFilter(AMSetupFilter.java:111)
	org.forgerock.openam.audit.context.AuditContextFilter.doFilter(AuditContextFilter.java:51)
	org.forgerock.openam.audit.servlet.AuditAccessServletFilter.doFilter(AuditAccessServletFilter.java:62)
com.google.inject.ConfigurationException: Guice configuration errors:

1) Could not find a suitable constructor in org.forgerock.http.Client. Classes must have either one (and only one) constructor annotated with @Inject or a zero-argument constructor that is not private.
  at org.forgerock.http.Client.class(Unknown Source)
  while locating org.forgerock.http.Client

1 error
	com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:1004)
	com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:961)
	com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1013)
	org.forgerock.guice.core.InjectorHolder.getInstance(InjectorHolder.java:80)
	com.sun.identity.cli.LogWriter.<clinit>(LogWriter.java:100)
	com.sun.identity.cli.AuthenticatedCommand.writeLog(AuthenticatedCommand.java:171)
	com.sun.identity.cli.entitlement.ListXACML.getPolicies(ListXACML.java:340)
	com.sun.identity.cli.entitlement.ListXACML.handleRequest(ListXACML.java:122)
	com.sun.identity.cli.SubCommand.execute(SubCommand.java:296)
	com.sun.identity.cli.CLIRequest.process(CLIRequest.java:217)
	com.sun.identity.cli.CLIRequest.process(CLIRequest.java:139)
	com.sun.identity.cli.CommandManager.serviceRequestQueue(CommandManager.java:576)
Comment by Philip Anderson [ 31/May/17 ]

Looks to still be a problem in 13.5.1-RC4

I ran the following using attached mypolicy.json :

./openam/bin/ssoadm policy-import --realm / --servername "http://am2.example.com:19081/openam" --jsonfile mypolicy.json --adminid amadmin --password-file /tmp/pwd.txt

Expected:

policies to be created and no errors

Actual:

371 policies created

Many OOM Errors

Exception in thread "pool-362-thread-1" java.lang.OutOfMemoryError: unable to create new native thread
 at java.lang.Thread.start0(Native Method)
 at java.lang.Thread.start(Thread.java:714)
 at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:336)
 at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:191)
 at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
 at java.lang.Thread.run(Thread.java:745)

followed by

com.sun.identity.cli.CLIException: org.forgerock.http.HttpApplicationException: Cannot create I/O Reactor
at com.sun.identity.cli.LogWriter.log(LogWriter.java:150)
at com.sun.identity.cli.AuthenticatedCommand.writeLog(AuthenticatedCommand.java:171)
at org.forgerock.openam.cli.entitlement.PolicyImport.auditEvent(PolicyImport.java:242)
at org.forgerock.openam.cli.entitlement.PolicyImport.createResource(PolicyImport.java:189)
at org.forgerock.openam.cli.entitlement.PolicyImport.updateOrCreateResource(PolicyImport.java:134)
at org.forgerock.openam.cli.entitlement.PolicyImport.importResources(PolicyImport.java:114)
at org.forgerock.openam.cli.entitlement.PolicyImport.handleResourceRequest(PolicyImport.java:86)
at org.forgerock.openam.cli.entitlement.JsonResourceCommand.handleRequest(JsonResourceCommand.java:68)
at com.sun.identity.cli.SubCommand.execute(SubCommand.java:296)
at com.sun.identity.cli.CLIRequest.process(CLIRequest.java:217)
at com.sun.identity.cli.CLIRequest.process(CLIRequest.java:139)
at com.sun.identity.cli.CommandManager.serviceRequestQueue(CommandManager.java:576)
at com.sun.identity.cli.CommandManager.<init>(CommandManager.java:173)
at com.sun.identity.cli.CommandManager.main(CommandManager.java:150)
Caused by: org.forgerock.http.HttpApplicationException: Cannot create I/O Reactor
at org.forgerock.http.apache.async.AsyncHttpClientProvider.newHttpClient(AsyncHttpClientProvider.java:159)
at org.forgerock.http.handler.HttpClientHandler.<init>(HttpClientHandler.java:194)
at org.forgerock.http.handler.HttpClientHandler.<init>(HttpClientHandler.java:172)
at com.sun.identity.cli.LogWriter.sendEvent(LogWriter.java:189)
at com.sun.identity.cli.LogWriter.logToAuditService(LogWriter.java:185)
at com.sun.identity.cli.LogWriter.log(LogWriter.java:148)
... 13 more
Caused by: org.apache.http.nio.reactor.IOReactorException: Failure opening selector
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.<init>(AbstractMultiworkerIOReactor.java:146)
at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init>(DefaultConnectingIOReactor.java:81)
at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init>(DefaultConnectingIOReactor.java:96)
at org.forgerock.http.apache.async.AsyncHttpClientProvider.newHttpClient(AsyncHttpClientProvider.java:157)
... 18 more
Caused by: java.io.IOException: Too many open files in system
at sun.nio.ch.IOUtil.makePipe(Native Method)
at sun.nio.ch.KQueueSelectorImpl.<init>(KQueueSelectorImpl.java:84)
at sun.nio.ch.KQueueSelectorProvider.openSelector(KQueueSelectorProvider.java:42)
at java.nio.channels.Selector.open(Selector.java:227)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.<init>(AbstractMultiworkerIOReactor.java:144)
... 21 more

 

Comment by Jeremy Cocks [ 18/Aug/17 ]

Note i can replicate Phil's findings using 13.5.1 / AM5 and 5.1. Output similar across all versions noted previously.

$ ~/ssoadm/openam/bin/ssoadm policy-import --realm / --servername "http://am5.example.com:8080/openam" --jsonfile mypolicy.json --adminid amadmin --password-file pw.txt

Process Request ...
Constructing Request Context...
Validating mandatory options...
Processing Sub Command ...
Exception in thread "main" com.google.inject.ConfigurationException: Guice configuration errors:

1) Could not find a suitable constructor in org.forgerock.http.Client. Classes must have either one (and only one) constructor annotated with @Inject or a zero-argument constructor that is not private.
  at org.forgerock.http.Client.class(Unknown Source)
  while locating org.forgerock.http.Client
    for parameter 0 at org.forgerock.openam.cli.entitlement.PolicyImport.<init>(Unknown Source)
  while locating org.forgerock.openam.cli.entitlement.PolicyImport

1 error
	at com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:1004)
	at com.google.inject.internal.InjectorImpl.getProvider(InjectorImpl.java:961)
	at com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1013)
	at org.forgerock.guice.core.InjectorHolder.getInstance(InjectorHolder.java:72)
	at com.sun.identity.cli.SubCommand.execute(SubCommand.java:295)
	at com.sun.identity.cli.CLIRequest.process(CLIRequest.java:217)
	at com.sun.identity.cli.CLIRequest.process(CLIRequest.java:139)
	at com.sun.identity.cli.CommandManager.serviceRequestQueue(CommandManager.java:581)
	at com.sun.identity.cli.CommandManager.<init>(CommandManager.java:178)
	at com.sun.identity.cli.CommandManager.main(CommandManager.java:155)
Comment by Peter Major [X] (Inactive) [ 10/Oct/17 ]

Given that 13.5.1 is now released, I'd say let's open a new issue for this if this is still happening. Chances are there is a different resource leak now.

Generated at Wed Sep 30 04:24:41 UTC 2020 using Jira 7.13.12#713012-sha1:6e07c38070d5191bbf7353952ed38f111754533a.