search

daust / JasperReportsIntegration

JasperReportsIntegration provides an interface to use the JasperReports reporting engine in an Oracle database application, specifically with Oracle Application Express (Oracle APEX).
BSD 3-Clause "New" or "Revised" License
55 stars 23 forks source link

Invalid Connection / killed in connection pool: Error on first reports of the day, probably due to Idle time #96

Closed snipercat closed 2 years ago

snipercat commented 2 years ago

Hello, this is my infrastructure

DataBase: Oracle 11G R2 Tomcat 9.0.56 Java jdk-17.0.1 Reports: the reports were created originally using iReport 4.6.0 but the were opened with JaspersoftStudio 6.18.1 and compiled there.

I have a problem with the three first reports each day, I get the following log messages:

This is an old log and I edited the Query, but I get the same Query of the report with a ? on the parameters

26-Jan-2022 06:05:47.119 SEVERE [https-jsse-nio-8443-exec-8] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() para servlet [ReportWrapper] lanzó excepción
    java.lang.RuntimeException: Error executing SQL statement for: CDP_pgn.
        at de.oc.utils.Utils.throwRuntimeException(Utils.java:18)
        at de.oc.integration.jasper.webapp.ReportWrapper.service(ReportWrapper.java:265)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:833)
26-Jan-2022 06:06:26.754 SEVERE [https-jsse-nio-8443-exec-3] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() para servlet [ReportWrapper] lanzó excepción
    java.lang.RuntimeException: Error executing SQL statement for: CDP_pgn.
        at de.oc.utils.Utils.throwRuntimeException(Utils.java:18)
        at de.oc.integration.jasper.webapp.ReportWrapper.service(ReportWrapper.java:265)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:833)
26-Jan-2022 08:15:51.998 SEVERE [https-jsse-nio-8443-exec-9] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() para servlet [ReportWrapper] lanzó excepción
    java.lang.RuntimeException: Error preparing statement for executing the report query:

select COLUMNS
from VIEW
where COLUMN = ?

        at de.oc.utils.Utils.throwRuntimeException(Utils.java:18)
        at de.oc.integration.jasper.webapp.ReportWrapper.service(ReportWrapper.java:265)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:833)

After trying to download the report three times, getting those errors, the reports download without problem until the next day.

Trying to find out the problem I acceded to the test Page _/jri/test?_dataSource=DATASOURCENAME before download any report and I got these errors

30-Jan-2022 05:00:01.884 SEVERE [http-nio-8080-exec-8] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [Test] in context with path [/jri] threw exception
    java.lang.RuntimeException: Error while selecting user objects: ORA-02396: exceeded maximum idle time, please connect again

        at de.oc.utils.Utils.throwRuntimeException(Utils.java:18)
        at de.oc.integration.jasper.webapp.Test.doGet(Test.java:130)
        at javax.servlet.http.HttpServlet.doHead(HttpServlet.java:241)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:678)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:833)
30-Jan-2022 05:00:02.903 SEVERE [http-nio-8080-exec-9] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [Test] in context with path [/jri] threw exception
    java.lang.RuntimeException: Error while selecting user objects: ORA-01012: not logged on

        at de.oc.utils.Utils.throwRuntimeException(Utils.java:18)
        at de.oc.integration.jasper.webapp.Test.doGet(Test.java:130)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:833)

I asked to the DBA about the idle time, he told me that the produciton DataBase has an Idle time of 6 hours, so I created a schedule task on the server to acces to the test page every 5 hours and I haven't had the problem again.

This is the script if someone needs it and call it with crontab.

wget --spider "localhost:8080/jri/test?_dataSource=DATASOURCE_NAME"

I report this as an Issue because I think the applications should check if the connection is still alive and create one if not, before trying to create the report. or does the Aplication do it but I have to configure something?

P.S: Thank you so much for this applications, this has been so useful for many APEX Developers.

daust commented 2 years ago

Which version of the JasperReportsIntegration do you use, 2.7.1?

2.7.1 supports .jasper files up until jasperreports version 6.16, you are using 6.18.1, this is too high but can work.

And BTW, you can just deploy the .jrxml file ... newer versions of the integration will compile them on-the-fly with the right version that is embedded.

daust commented 2 years ago

Do you use a JNDI connection or the built-in connection pool? If so, please post the xml config file (without ip addresses and passwords).

Do you use some sort of tnsnames magic or all standard?

daust commented 2 years ago

One workaround would be to use a different idle time for the reporting user: https://dbaclass.com/article/ora-02396-exceeded-maximum-idle-time-please-connect/

snipercat commented 2 years ago

Which version of the JasperReportsIntegration do you use, 2.7.1?

Oh sorry, I forgot to say the the JasperReports Integration Version, I am using 2.7.1

And BTW, you can just deploy the .jrxml file ... newer versions of the integration will compile them on-the-fly with the right version that is embedded.

I'll deploy the .jrxml as you say and stop the schedule task, Tomorrow I'll check if it solves the problem.

Do you use a JNDI connection or the built-in connection pool?

I use the built-in connection pool, modifying the application.properties and using jdbc

One workaround would be to use a different idle time for the reporting user: https://dbaclass.com/article/ora-02396-exceeded-maximum-idle-time-please-connect/

This could work, but I'll ask to the DBA if we can set an unlimited idle connection time for that user

daust commented 2 years ago

Thank you for the feedback. Will try to reproduce it tomorrow. Stay tuned.

daust commented 2 years ago

I'll deploy the .jrxml as you say and stop the schedule task, Tomorrow I'll check if it solves the problem. I don't expect that it will fix it. But it is a good approach to work around some problems with report version differences betwenn JasperSoftStudio and the integration.

nlwilson02 commented 2 years ago

I had the same problem with reports using database links, the first execution of the day failed. The databases for which the database links are defined are refreshed every night, which involves a shutdown. The work around for me was an automated job that generates a sample report using the database links early each morning. This first scheduled report will fail but it opens the connection pool for the report user for the current day, so the next report is successful. I don't experience this problem for any other report that uses the local Oracle databases without database links. I am using JRI 2.7.1 with Oracle 19C.

daust commented 2 years ago

Thank you for the additional information.

Seems more like database related issues than a JasperReport / connection pool issue.

For the database links, perhaps you can modify the code so that after refreshing ... each db link will be used with a simple select sysdate from dual@db_link? Is the shutdown on the source or target db with regard to the db_link? Do you have a specific ORA- error message?

And what is the "business" reason behind the idle time? Perhaps the DBA can create a profile just for connection pool users. Often, we also set the password expiration higher for those accounts.

But I will check tomorrow for the idle time issue.

nlwilson02 commented 2 years ago

I don't remember the exact ORA error message just a 404 page error when executing the report the first time. A reload of the page and the report ran fine. The remote/target databases that we have database links for are managed by another institution so we do not not the exact time of when the databases will be back online. My script check's the status of the remote database and once it is back online in the morning, a very simple Jasper report with the database links is executed using utl_http. We didn't have this issue with older version of JasperIntegration but once we upgraded to 2.7 we started to see the problem.

daust commented 2 years ago

Hhhhm, in 2.7.0 I did upgrade the jdbc drivers and made cloud connections work. ATP cloud needed more security libraries than on premise. Not sure whether this has caused it.

daust commented 2 years ago

After testing multiple approaches with timeouts, I could finally find the right and proper solution: https://docs.oracle.com/en/database/oracle/oracle-database/21/jjucp/validating-ucp-connections.html#GUID-A7C850D6-4026-4629-BCFA-9181C29EFBF9

The connection can be validated automatically by the connection pool BEFORE it is given to the application, i.e. "borrowed":

poolDataSource.setValidateConnectionOnBorrow(true);

Seems to work very well :). The solution is utterly simple ... yet so hard to find. Should be the default from my point of view, at least mentioned in the samples.

Thank you for raising this. Will increase the user experience a lot.