This discussion is archived
7 Replies Latest reply: Feb 8, 2013 8:55 AM by Joe Weinstein RSS

Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ

447464 Newbie
Currently Being Moderated
We have an intermittent bug with SQLJ and WebLogic 11g.

This code used to run FINE in Oracle Application Server 10g ASR2, but in that case EACH application had its own container (and JVM) and datasource for some APIs that are based on stored package code. SQLJ was used to interact with this package that returns either simple scalars or ref cursors. Now that we’re on WebLogic, multiple applications now share this code and share the same data source, and we’re running into this intermittent error/stacktrace:

When I look at the SQLJ generated Java source, it’s dying in the finally block. Here's that code:
    public String getUserName(int userId) throws SQLException {

        String __jPt_result;
        MyConnectionContext __sJT_cc = null;
        ExecutionContext ec = new ExecutionContext();

        try {
            // declare temps
            // was worried about concurrency so each connection gets its own Context
            __sJT_cc = getConnectionContext();
            if (__sJT_cc == null)
                sqlj.runtime.error.RuntimeRefErrors.raise_NULL_CONN_CTX();

            if (ec == null) {
                sqlj.runtime.ExecutionContext.raiseNullExecCtx();
            }
            sqlj.runtime.ExecutionContext.OracleContext __sJT_ec = ec.getOracleContext();

            oracle.jdbc.OracleCallableStatement __sJT_st = null;

            try {
                String theSqlTS = "BEGIN :1 := MY_APIS.GET_USER_NAME(\n       :2 )  \n; END;";
                __sJT_st = __sJT_ec.prepareOracleCall(__sJT_cc, "4MyPackage.MyAPIs2", theSqlTS);
                
                System.out.println("__sJT_cc=" + __sJT_cc);
                System.out.println("ec=" + ec );
                System.out.println("__sJT_ec=" + __sJT_ec);
                System.out.println("__sJT_st=" + __sJT_st);
                
                if (__sJT_ec.isNew()) {
                    System.out.println("registering out parameter for " + __sJT_st);
                    __sJT_st.registerOutParameter(1, oracle.jdbc.OracleTypes.VARCHAR);
                }
                // set IN parameters
                __sJT_st.setInt(2, portalUserIDIn);
                // execute statement
                __sJT_ec.oracleExecuteUpdate();
                // retrieve OUT parameters
                // __jPt_result = (String)__sJT_st.getString(1);
                __jPt_result = __sJT_st.getString(1);
            } catch(SQLException se) {
                se.printStackTrace(); // If I print this out, then __sJT_st is an OracleClosedStatement and it's failing registerOutParameter with closed statement
                throw se;
            }
            finally {
                __sJT_ec.oracleClose(); // normally dies here with SQLRecoverException: closed statement
            }
        } finally {
            // Since I created an ExecutionContext as well, I close it here.
            ec.close();
            if (__sJT_cc != null) {
                // Not closing this will use up all the pooled connections.
                __sJT_cc.close();
            }
        }

        return __jPt_result;

    } // getUserName
In that part, it’s trying to issue an executionContext.oracleClose(). If I add a catch (Exception ex) and output the stack trace, the actual error is on a registerOutParameter on the statement, but with the same exception. I thought the problem might be related to the fact that internally, SQLJ appears to have a FIVE statement cache.  When I ran 6 statements with the default cache size of 5, it failed. When I bumped the cache size to 10, it ran fine. HOWEVER, in Production, I set the cache size to 15 and we only have 10 statements, and it still winds up with the same error.

Also, when I stepped the code after decompiling a number of Oracle JDBC and SQLJ RUNTIME classes (as much as would easily decompile since DJDE did not decompile a number of them very well and I could not recompile the javaoutput code), I noticed that when you close a SQLJ statement, eventually it gets to a statement that’s called closeWithKey(). After reading the JDBC documentation, and looking at the code, it looks like it determines if the driver can cache statements via a static initializer in the ExecutionContext, and if it can, then when you issue a close, it does this closeWithKey. If I look at what appears to be a Hashmap of statements that are a cache for the connection, they appear to be CLOSED statements. The behavior is also dependent on how I create the datasource (it behaves worse if I use the USER-jdbc.xml descriptor rather than defining the datasource for the server. It still fails at the server level though INTERMITTENTLY.

So, this call is from SQLJ generated java code. It’s a simple wrapper against a stored procedure call that gives back a username based on his ID#. The user has additional attributes that are stored in Oracle Internet Directory and this API provides access to those as well.

Here's an example of the stacktrace
java.sql.SQLRecoverableException: Closed Statement    
    at oracle.jdbc.driver.OracleClosedStatement.closeWithKey(OracleClosedStatement.java:4026)
    at oracle.jdbc.driver.OracleCallableStatementWrapper.closeWithKey(OracleCallableStatementWrapper.java:1440)
    at weblogic.jdbc.wrapper.CallableStatement_oracle_jdbc_driver_OracleCallableStatementWrapper.closeWithKey(Unknown Source)
    at sqlj.runtime.ExecutionContext$OracleContext.oracleClose(ExecutionContext.java:1634)
    at eGovUtils.eGovAPIs.getPortalUserName(eGovAPIs.java:288)
    at com.ciber.depformu.security.SecurityProxy.getFullNameByUserID(SecurityProxy.java:516)
    at com.ciber.depformu.util.XMLBuilder.buildSubmitInfo(XMLBuilder.java:1552)
    at com.ciber.depformu.util.XMLBuilder.buildDocument(XMLBuilder.java:216)
    at com.ciber.depformu.servlets.ConsViewRCServlet.doGet(ConsViewRCServlet.java:143)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
    at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
    at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:26)
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:56)
    at com.ciber.depformu.listener.Log4jMDCFilter.doFilter(Log4jMDCFilter.java:72)
    at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:56)
    at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.wrapRun(WebAppServletContext.java:3715)
    at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3681)
    at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
    at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120)
    at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2277)
    at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2183)
    at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1454)
    at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
    at weblogic.work.ExecuteThread.run(ExecuteThread.java:178)
If you can help in any way, it would be greatly appreciated.

Eric
  • 1. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    447464 Newbie
    Currently Being Moderated
    Can someone move this thread to the WebLogic JDBC Forum?
    WebLogic Server - JDBC
  • 2. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    Joe Weinstein Expert
    Currently Being Moderated
    At first blush it sounds like the code is not thread-safe, and the WebLogic environment is
    offering much more concurrency to provoke it. Multiple threads may be occasionally using
    the same (or same-keyed!) statement(s), such that they both close it, and the second
    one loses.
  • 3. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    447464 Newbie
    Currently Being Moderated
    When we first went to WebLogic from Oracle Application Server 10g R2, we were experiencing a lot of problems with the code:
    1. It was trying to iterate resultsets where the ExecutionContext.OracleContext was already closed.
    2. It was returning nulls or the value 1 instead of the actual a data.

    I figured the problem was due to concurrency since all the applications that were migrated were now sharing the SAME data source, and sharing this code as a library. In that version, the sqlj code looked like this:
      public String getPortalUserName (
        int UserIDIn)
      throws SQLException
      {
        String __jPt_result;
        #sql [getDBConnection.getConnectionContext()] __jPt_result = { VALUES(MYAPIS.GET_USER_NAME(:UserIDIn)) };
        return __jPt_result;
      }
    Internally, the getDBConnection class had a static variable, DefaultContext and the getConnectionContext() returned it. Therefore EVERY session would then have the same ExecutionContext. When I read some notes on SQLJ, it said there could be unpredictable results or NullPointers if the same ExecutionContext was shared across multiple threads. This code is called in a web/servlet environment.

    I switched the code to what I posted earlier (there are actually about a dozen methods in it). Originally in the SQLJ source, I had declared a ConnectionContext based on a datasource. That became the inner MyConnectionContext. Each generated SQLJ method would then call a method inside of the main class called getConnectionContext() which would create an instance of this class, passing the dataSource name read from a properties file. From what I undertood, by creating my own ConnectionContext, it would be threadsafe because it would have it's own ExecutionContext (created when the connection context was instantiated). Even so, I created an ExecutionContext, and closed it explicitly in the finally {} blocks. The initial errors went away.

    However, like I said, recently we've been experiencing these intermitten stack traces, when we migrated yet another application into this environment. Based on some tests I was doing, I thought that it was resulting from the statement cache size. By setting it to ZERO, and using a [ConnectionName]-jdbc.xml WebLogic deployment descriptor, the error happens immediately. If I bump up the statement cache size to 15 (that's more than what this class would ever run for statements) the errors go away locally. However, the errors did not go away in the Production environment. This application makes more API calls than the first few that were deployed.

    I've since added a SECOND datasource for my application that is experiencing the issue hoping that the new/migrated application won't interfere with that (it has its own pool). It's been "ok" for now, but this doesn't seem like the correct fix as we'd be adding a data source PER application that used these APIs, rather than them sharing the same datasource/connection pool.


    Anyway, what would I do to fix this?


    The .java code was generated by sqlj translator (by running Make inside Jdeveloper). It had to be brought into the IDE and changed anyway since any refcursor code was not working (see beginning statement). The code still makes use of SQLJ calls, but looks like it's mainly JDBC. Like I said, when debugging it with a cacheSize of 0, it appears that it can't run two calls to the same method (even if I'm only user running it in JDEV) as the second one fails because the statement that is retrieved from the connection's prepareCall, is an OracleClosedStatement. An OracleStatementWrapper sets the statement to an instance of OracleClosedStatement when close() is called, and this seems to be what comes back from the cache on the second call.

    Any help will be greatly appreciated!

    Eric
  • 5. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    Joe Weinstein Expert
    Currently Being Moderated
    It sounds like the code is making some other oracle-specific call that actually closes the statement, then
    calling the normal close(), then if the statement goes back in the cache it is re-used to get you the
    already-closed problem. Is there any oracle-specific casting in the code?
  • 6. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    447464 Newbie
    Currently Being Moderated
    All of the closes are done using the code that was in the original post. Under the hood, it's doing a number of different things (this is all SQLJ and Oracle JDBC classes decompiled BTW). I was surprised when the SQLJ translated code was created that the prepared statement wasn't a simple close call, i.e.
                oracle.jdbc.OracleCallableStatement __sJT_st = null;
    
                try {
                    String theSqlTS = "BEGIN :1 := EGOV_APIS.GET_PORTAL_USER_NAME(\n       :2 )  \n; END;";
                    __sJT_st = __sJT_ec.prepareOracleCall(__sJT_cc, "4eGovUtils.eGovAPIs2", theSqlTS);
                    [... other code ...]
                } finally {
                       __sJT_st.close();
                }
    So to explain in detail, every function ends like this:
                finally {
                    __sJT_ec.oracleClose(); // normally dies here with SQLRecoverException: closed statement
                }
            } finally {
                // Since I created an ExecutionContext as well, I close it here.
                ec.close();
                if (__sJT_cc != null) {
                    // Not closing this will use up all the pooled connections.
                    __sJT_cc.close();
                }
            }
    __sJT_ec, is an instance of sqlj.runtime.ExecutionContext.OracleContext.
    ec is declared locally and is an instance of sqlj.runtime.ExecutionContext
    __sJT_cc is also declared locally and is an instance of sqlj.runtime.ref.ConnectionContextImpl which implements sqlj.runtime.ConnectionContext. This code was generated when I used the statement: #sql public static context MyConnectionContext with (dataSource="jdbc/eGovUserDS");


    When __sJT_ec.oracleClose(); is called, it hits this block of code (again, this is decompiled):
                    public void oracleClose()
                        throws SQLException
                    {
    /*1630*/            if(m_ops != null)
    /*1632*/                if(m_new_cache || m_caching)
    /*1634*/                    m_ops.closeWithKey(m_key);
    /*1638*/                else
    /*1638*/                    m_ops.close();
    /*1641*/            m_ops = null;
    /*1642*/            m_ocs = null;
    /*1643*/            m_key = null;
                    }
    So, it gets to the line m_ops.closeWithKey(m_key);

    That results in a call to this:
                 public void closeWithKey(String s)
                     throws SQLException
                 {
    /* 3540*/        synchronized(connection)
                     {
    /* 3545*/            closeOrCache(s);
                     }
                 }
    
    
    ***** this is from the base class oracle.jdbc.driver.OracleStatement:
    
                protected void closeOrCache(String s)
                    throws SQLException
                {
    /*1557*/        if(closed)
    /*1558*/            return;
    /*1567*/        if(statementType != 0 && cacheState != 0 && cacheState != 3 && connection.isStatementCacheInitialized())
                    {
    /*1578*/            if(s == null)
                        {
    /*1580*/                if(connection.getImplicitCachingEnabled())
                            {
    /*1582*/                    connection.cacheImplicitStatement((OraclePreparedStatement)this, sqlObject.getOriginalSql(), statementType, userRsetType);
                            } else
                            {
    /*1591*/                    cacheState = 0;
    /*1593*/                    hardClose();
                            }
                        } else
    /*1599*/            if(connection.getExplicitCachingEnabled())
                        {
    /*1601*/                connection.cacheExplicitStatement((OraclePreparedStatement)this, s);
                        } else
                        {
    /*1609*/                cacheState = 0;
    /*1611*/                hardClose();
                        }
                    } else
                    {
    /*1620*/            hardClose();
                    }
                }
    The ExecutionContext determines that the driver supports this caching in a static initializer and there's no way to override that from the code. I can set the statement cache size to zero, but if it sees this other flag set from initializer it uses caching checks when it issues the prepareCall. I'm assuming that it must cache the statement.

    Anyway, an ec.close() performs:
                public void close()
                    throws SQLException
                {
    /*1751*/        if(m_oc != null)
                    {
    /*1753*/            m_oc.cleanup();
    /*1754*/            m_oc = null;
                    }
                }
    
                    private void cleanup()
                    {
    /*1659*/            try
                        {
    /*1659*/                oracleClose();
                        }
    /*1659*/            catch(SQLException _ex) { }
                    }
    
                    public void oracleClose()
                        throws SQLException
                    {
    /*1630*/            if(m_ops != null)
    /*1632*/                if(m_new_cache || m_caching)
    /*1634*/                    m_ops.closeWithKey(m_key);
    /*1638*/                else
    /*1638*/                    m_ops.close();
    /*1641*/            m_ops = null;
    /*1642*/            m_ocs = null;
    /*1643*/            m_key = null;
                    }
    Essentially, I'd say that is redundant call since it's hitting the same thing, but in the second call, it doesn't have any work to do since mops is now null._


    The very last call is: __sJT_cc.close(); which is coming from ConnectionContextImpl, as stated before. I didn't decompile this one, but I'd have to assume that it cleans up the ExecutionContext that's inside of it (possibly) and then the connection itself. Since I am declaring a new ConnectionContext PER METHOD, I probably don't need that ExecutionContext as it does have a new instance of that inside of it.

    There's only one place in any code that I could find where OracleClosedStatement was even referenced, and that's in oracle.jdbc.driver.OracleStatementWrapper. It looks like this:
    static final OracleCallableStatement closedStatement = new OracleClosedStatement();

    So, when close is called on this class, it calls this:
    ***** Any time the close method is called, we are going to end up pointing to this 
    OracleClosedStatement, i.e.
    
                public void close()
                    throws SQLException
                {
    /*  80*/        statement.close();
    /*  81*/        statement = closedStatement;
                }
    
                public void closeWithKey(String s)
                    throws SQLException
                {
    /*  88*/        statement.closeWithKey(s);
    /*  89*/        statement = closedStatement;
                }
    So, internally, it appears there must be some sort of statement cache (in weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection) and the keyed statement that it pulls back from this is an OracleClosedStatement. When it tries to then register the out parameter on it, it fails with a closed statement: java.sql.SQLRecoverableException: Closed Connection


    That was a lot of rambling.  In short:
    1. I let SQLJ Generate the code. It generated the closing of the OracleContext.
    2. Since I created my own ExecutionContext() and have a ConnectionContext that I used (due to errors before), I close them.
    3. I don't directly call anything on the statement that SQLJ prepared. (I don't close it).
    4. It all appears to be Oracle-specific classes that are used in this generated code. I mean, it's using: sqlj.runtime.ExecutionContext.OracleContext, and creating an oracle.jdbc.OracleCallableStatement via a call to that class's prepareOracleCall


    I tried to use JPUBLISHER (JDeveloper has an option to Generate source from a package) inside of it, and it creates code that I can't image would work properly.

    Ironically, I actually rewrote all of this code about a year ago, using Spring JDBC and it's used in other applications, but all of our legacy applications use this old SQLJ code (there's probably 20 or more apps). So, it really does need to work reliably. It worked FINE under Oracle 10g ASR2, but WLS just hasn't liked it, and again, I hate to keep tinkering with GENERATED code. It might be a situation where we have to bite the bullet and as apps are brought into WLS, they HAVE TO use the rewritten code, but people always complain when they have to change things.

    Should I open a TAR and send a JDEV workspace based on a package with EMP/DEPT to Oracle that exhibits the behavior? It would probably take some time to pull that off, but it is doable. Of course, I'm assuming I can reproduce the error

    Eric
  • 7. Re: Intermittent SQLRecoverableException: Closed Statement on WLS 11g with SQLJ
    Joe Weinstein Expert
    Currently Being Moderated
    Good luck on the help request. Try turning off the WebLogic cache, by configuring the
    statement cache size as zero, if that is involved, but re-using a closed statement is
    a sorry thing....

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points