Invocation error: I/O error and bad Record MAC... closed connection

[DCS_JEFF]

We have a process that queries a postgres database, which returns quite a bit of data back to LiveCycle.  The process is failing with: ALC-DSC-003-000: com.adobe.idp.dsc.DSCInvocationException: Invocation error.

Caused by: org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
and
Caused by: javax.net.ssl.SSLException: bad record MAC

When the process fails, the connection to the postgres DB appears to be closed and never reconnects.  Any subsequent attempts give an error saying "This connection has been closed"

Does anyone have any thoughts on this?

Thank you in advance for any feedback.

-Jeff Wambach

[Darren]

Hi Jeff,

I would be looking at the timeout values for the JDBC connection on both LC and the Postgres side. You said its sending a large amount of data which I would also assume is a time consuming query. Try upping your datasource timeouts and on the database side (if possible) and see how that goes.

Darren

[DCS_JEFF]

OK...   we have added some parameters so the database can reconnect when the connection closes.   But, it turns out that the process actually works sometimes and not others.

We don't think it's a timeout issue because the process works for some that return much larger amounts of data and run for 30-40 seconds, but some that fail will fail very quickly (within a few seconds sometimes).  Then if you run the same process with the same input variables it works fine sometimes.

Has anyone else seen inconsistencies like this when running processes in LiveCycle?   Any thoughts as to why this would occur?

The Error log detail are as follows:

ALC-DSC-003-000: com.adobe.idp.dsc.DSCInvocationException: Invocation error.

at com.adobe.idp.dsc.component.impl.DefaultPOJOInvokerImpl.invoke(DefaultPOJOInvokerImpl.java:152)

at com.adobe.idp.dsc.interceptor.impl.InvocationInterceptor.intercept(InvocationInterceptor.java:140)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.DocumentPassivationInterceptor.intercept(DocumentPassivationInterceptor.java:53)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.transaction.interceptor.TransactionInterceptor$1.doInTransaction(TransactionInterceptor.java:74)

at com.adobe.idp.dsc.transaction.impl.ejb.adapter.EjbTransactionBMTAdapterBean.doBMT(EjbTransactionBMTAdapterBean.java:197)

at sun.reflect.GeneratedMethodAccessor681.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.jboss.invocation.Invocation.performCall(Invocation.java:386)

at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:233)

at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)

at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)

at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)

at org.jboss.ejb.plugins.AbstractTxInterceptorBMT.invokeNext(AbstractTxInterceptorBMT.java:173)

at org.jboss.ejb.plugins.TxInterceptorBMT.invoke(TxInterceptorBMT.java:77)

at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:173)

at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:228)

at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)

at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:97)

at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:81)

at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)

at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)

at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:650)

at org.jboss.ejb.Container.invoke(Container.java:1092)

at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:436)

at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:103)

at $Proxy302.doBMT(Unknown Source)

at com.adobe.idp.dsc.transaction.impl.ejb.EjbTransactionProvider.execute(EjbTransactionProvider.java:95)

at com.adobe.idp.dsc.transaction.interceptor.TransactionInterceptor.intercept(TransactionInterceptor.java:72)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.InvocationStrategyInterceptor.intercept(InvocationStrategyInterceptor.java:55)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.InvalidStateInterceptor.intercept(InvalidStateInterceptor.java:37)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.AuthorizationInterceptor.intercept(AuthorizationInterceptor.java:188)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.JMXInterceptor.intercept(JMXInterceptor.java:48)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.engine.impl.ServiceEngineImpl.invoke(ServiceEngineImpl.java:121)

at com.adobe.idp.dsc.routing.Router.routeRequest(Router.java:131)

at com.adobe.idp.dsc.provider.impl.base.AbstractMessageReceiver.routeMessage(AbstractMessageReceiver.java:93)

at com.adobe.idp.dsc.provider.impl.vm.VMMessageDispatcher.doSend(VMMessageDispatcher.java:225)

at com.adobe.idp.dsc.provider.impl.base.AbstractMessageDispatcher.send(AbstractMessageDispatcher.java:66)

at com.adobe.idp.dsc.clientsdk.ServiceClient.invoke(ServiceClient.java:208)

at com.adobe.workflow.engine.PEUtil.invokeAction(PEUtil.java:893)

at com.adobe.idp.workflow.dsc.invoker.WorkflowDSCInvoker.transientInvoke(WorkflowDSCInvoker.java:350)

at com.adobe.idp.workflow.dsc.invoker.WorkflowDSCInvoker.invoke(WorkflowDSCInvoker.java:158)

at com.adobe.idp.dsc.interceptor.impl.InvocationInterceptor.intercept(InvocationInterceptor.java:140)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.DocumentPassivationInterceptor.intercept(DocumentPassivationInterceptor.java:53)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.transaction.interceptor.TransactionInterceptor$1.doInTransaction(TransactionInterceptor.java:74)

at com.adobe.idp.dsc.transaction.impl.ejb.adapter.EjbTransactionCMTAdapterBean.execute(EjbTransactionCMTAdapterBean.java:357)

at com.adobe.idp.dsc.transaction.impl.ejb.adapter.EjbTransactionCMTAdapterBean.doRequiresNew(EjbTransactionCMTAdapterBean.java:299)

at sun.reflect.GeneratedMethodAccessor545.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.jboss.invocation.Invocation.performCall(Invocation.java:386)

at org.jboss.ejb.StatelessSessionContainer$ContainerInterceptor.invoke(StatelessSessionContainer.java:233)

at org.jboss.resource.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:156)

at org.jboss.ejb.plugins.StatelessSessionInstanceInterceptor.invoke(StatelessSessionInstanceInterceptor.java:173)

at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:63)

at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:121)

at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:404)

at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:181)

at org.jboss.ejb.plugins.SecurityInterceptor.process(SecurityInterceptor.java:228)

at org.jboss.ejb.plugins.SecurityInterceptor.invoke(SecurityInterceptor.java:211)

at org.jboss.ejb.plugins.security.PreSecurityInterceptor.process(PreSecurityInterceptor.java:97)

at org.jboss.ejb.plugins.security.PreSecurityInterceptor.invoke(PreSecurityInterceptor.java:81)

at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:205)

at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:138)

at org.jboss.ejb.SessionContainer.internalInvoke(SessionContainer.java:650)

at org.jboss.ejb.Container.invoke(Container.java:1092)

at org.jboss.ejb.plugins.local.BaseLocalProxyFactory.invoke(BaseLocalProxyFactory.java:436)

at org.jboss.ejb.plugins.local.StatelessSessionProxy.invoke(StatelessSessionProxy.java:103)

at $Proxy303.doRequiresNew(Unknown Source)

at com.adobe.idp.dsc.transaction.impl.ejb.EjbTransactionProvider.execute(EjbTransactionProvider.java:143)

at com.adobe.idp.dsc.transaction.interceptor.TransactionInterceptor.intercept(TransactionInterceptor.java:72)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.InvocationStrategyInterceptor.intercept(InvocationStrategyInterceptor.java:55)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.InvalidStateInterceptor.intercept(InvalidStateInterceptor.java:37)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.AuthorizationInterceptor.intercept(AuthorizationInterceptor.java:188)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.interceptor.impl.JMXInterceptor.intercept(JMXInterceptor.java:48)

at com.adobe.idp.dsc.interceptor.impl.RequestInterceptorChainImpl.proceed(RequestInterceptorChainImpl.java:60)

at com.adobe.idp.dsc.engine.impl.ServiceEngineImpl.invoke(ServiceEngineImpl.java:121)

at com.adobe.idp.dsc.routing.Router.routeRequest(Router.java:131)

at com.adobe.idp.dsc.provider.impl.base.AbstractMessageReceiver.invoke(AbstractMessageReceiver.java:329)

at com.adobe.idp.dsc.provider.impl.soap.axis.sdk.SoapSdkEndpoint.invokeCall(SoapSdkEndpoint.java:139)

at com.adobe.idp.dsc.provider.impl.soap.axis.sdk.SoapSdkEndpoint.invoke(SoapSdkEndpoint.java:81)

at sun.reflect.GeneratedMethodAccessor673.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java:397)

at org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.java:186)

at org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:323)

at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)

at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)

at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83)

at org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:454)

at org.apache.axis.server.AxisServer.invoke(AxisServer.java:281)

at org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:699)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)

at org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.java:327)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at com.adobe.idp.dsc.provider.impl.soap.axis.InvocationFilter.doFilter(InvocationFilter.java:43)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at com.adobe.idp.um.auth.filter.CSRFFilter.doFilter(CSRFFilter.java:86)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)

at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)

at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)

at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)

at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)

at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)

at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)

at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)

at java.lang.Thread.run(Thread.java:662)

Caused by: org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:281)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:510)

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:386)

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:271)

at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:342)

at com.adobe.idp.dsc.jdbc.helper.PreparedSqlHelper.executeQuery(PreparedSqlHelper.java:114)

at com.adobe.idp.dsc.jdbc.JDBCService.querySingle(JDBCService.java:254)

at sun.reflect.GeneratedMethodAccessor1022.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at com.adobe.idp.dsc.component.impl.DefaultPOJOInvokerImpl.invoke(DefaultPOJOInvokerImpl.java:118)

... 134 more

Caused by: javax.net.ssl.SSLException: bad record MAC

at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)

at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1649)

at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1607)

at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:859)

at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:755)

at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)

at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:217)

at org.postgresql.core.PGStream.Receive(PGStream.java:458)

at org.postgresql.core.PGStream.ReceiveTupleV3(PGStream.java:363)

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1813)

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)

... 144 more

[Darren]

Hi Jeff,

I have seen this before when running large number of concurrent short-lived processes that were accessing a database. I had to throttle the Watched Folder or calling process to only allow N number of concurrent processes to run because the ones that went over the connection pool limit allowed by the database would just hang or be refused a connection and fail.

Just something else to consider.

Thanks,

Darren

[DCS_JEFF]

Thanks again Darren,

We are running this in a test environment with very little activity.   We tried to run the process against a different Postgres Database, which is set up more like the production database... to see if that would be any different... but we had the same results.   It ran fine some and failed some.

We are stumped.

Is there any way to debug the process to see where it's actually coming from... something on the database side or is it LiveCycle?

On Wednesday, March 20, 2013 12:00:11 PM UTC-4, DCS_JEFF wrote:

[Darren]

Hi Jeff,

There should be a way to put the database into debug mode that should dump all activity out to a file. Then you could pick something up there. It is different for all databases and some databases like MySQL you edit the my.ini file to dump all SQL queries out. Don't forget to take it out of you will soon find yourself out of drive space :) (don't ask how i know this...)

I also created a small DSC that allows me to hook into log4j within JBoss and log to a file from within processes. This way you can log something just before the request and at least see how many requests were started and try to match them up with what was received by the database. Its time-consuming work but might show something. I should really put up a tutorial how to create this as its pretty simple and I use it in all of my projects.

You can edit the loglevel in postgres here too: http://jdbc.postgresql.org/documentation/80/connect.html

I would still be looking at your database read timeouts and connection pooling. You might just need to tweak them for your dev/test environment.

Cheers,

Darren

[DCS_JEFF]

Darren,

Thanks again for the information...   unfortunately, we do not administer the database, so that team is looking into the issue.