Derby
  1. Derby
  2. DERBY-1191

Some SQLExceptions, for example those generated from BrokeredStatements, do not print to derby.log even when derby.stream.error.logSeverityLevel=0

    Details

    • Urgency:
      Low
    • Issue & fix info:
      Repro attached

      Description

      I found this when working on DERBY-1047. Exceptions thrown using
      org.apache.derby.impl.jdbc.Util.generateCsSQLException()
      do not print to derby.log even when derby.stream.error.logSeverityLevel=0

      For example the attached repro generates an expected exception but does not print the error to the log.

      java -Dderby.stream.error.logSeverityLevel=0 Derby1047

      This causes an expected exception to be thrown but it does not print to the derby.log

      10.2.0.0 alpha
      Apache Derby
      Apache Derby Embedded JDBC Driver
      done creating table
      COL1
      -----------
      1
      2
      PASS: Expected Exception can'tholdable cusror in global xact:Cannot set holdability ResultSet.HOLD_CURSORS_OVER_COMMIT for a global transaction.
      COL1
      -----------
      1
      2
      3

      The code generating the exception is in org.apache.derby.iapi.jdbc.BrokeredStatement

      final void checkHoldability() throws SQLException

      { int holdability = controlCheck().checkHoldCursors(resultSetHoldability); if (holdability != resultSetHoldability) throw Util.generateCsSQLException(SQLState.CANNOT_HOLD_CURSOR_XA); }
      1. derby-1191_checkForTransactionInProgress_diff.txt
        4 kB
        Kathey Marsden
      2. derby-1191_factory_hack_no_commit_diff.txt
        3 kB
        Kathey Marsden
      3. ReproDerby1191.java
        0.7 kB
        Kathey Marsden

        Issue Links

          Activity

          Hide
          Kathey Marsden added a comment -

          I wanted to clarify that I don't think this issue is not limited to XA.
          There are errors are thrown using this mechanism, for example:

          EmbeddedConnection.close()
          EmbeddedConnection.createBoot()
          Savepoint code in EmbeddedConnection30

          Places where Util.javaException(Throwable) is used, for example network server and
          EmbeddedConnection.bootDatabase()

          Show
          Kathey Marsden added a comment - I wanted to clarify that I don't think this issue is not limited to XA. There are errors are thrown using this mechanism, for example: EmbeddedConnection.close() EmbeddedConnection.createBoot() Savepoint code in EmbeddedConnection30 Places where Util.javaException(Throwable) is used, for example network server and EmbeddedConnection.bootDatabase()
          Hide
          Kathey Marsden added a comment -

          Fixing priority. There will be a bit of a delay to post repro because I need to change the case as it doesn't actually throw the exception anymore with the fix for DERBY-1158.

          Show
          Kathey Marsden added a comment - Fixing priority. There will be a bit of a delay to post repro because I need to change the case as it doesn't actually throw the exception anymore with the fix for DERBY-1158 .
          Hide
          Daniel John Debrunner added a comment -

          It's not clear to me that such exceptions belong in derby.log. Most exceptions that are a result of an application error (incorrect use of the JDBC api) do not end up in derby.log. E.g. calling ResultSet.getXXX when not on a row, calling a method on a closed JDBC object, calling ResultSet.getXXX with an out of range column identifier.

          I think derby.log should be reserved for errors that occur within the engine, not those at the JDBC api level.

          Show
          Daniel John Debrunner added a comment - It's not clear to me that such exceptions belong in derby.log. Most exceptions that are a result of an application error (incorrect use of the JDBC api) do not end up in derby.log. E.g. calling ResultSet.getXXX when not on a row, calling a method on a closed JDBC object, calling ResultSet.getXXX with an out of range column identifier. I think derby.log should be reserved for errors that occur within the engine, not those at the JDBC api level.
          Hide
          Kathey Marsden added a comment -

          I disagree.

          The description of derby.stream.error.logSeverityLevel the property says:
          Specifies which errors are logged to the Derby error log (typically the derby.log file). In test environments, use the setting derby.stream.error.logSeverityLevel=0 so that all problems are reported.

          http://db.apache.org/derby/docs/dev/tuning/rtunproper26985.html

          Only printing some of the exceptions causes support issues. When users get unexpected exceptions, we usually ask them to set derby.stream.error.logSeverityLevel=0 and send the derby.log. It is very useful to have the exception there, complete with the full exception chain, regardless of where it came from and not have to worry about getting traces output from the application.

          Here is one current support case example:

          Issue: Create database fails with "Database not found" exception after creating the database.

          There have been multiple round trips so far:

          1) Initial issue:
          "We are seeing this error creating the database but the database actually gets created ok"
          ij> connect 'jdbc:derby:databases/TopDown1;create=true';
          ERROR XJ004: Database 'databases/TopDown1' not found.
          SQL Exception: Database 'databases/TopDown1' not found.

          2) Asked for derby.log with derby.stream.error.logSeverityLevel=0
          "Here is the log file <derby.log>
          However, it does not contain any useful info "

          3) Asked for ij stack trace with ij.exceptionTrace=true
          [java] ij> connect 'jdbc:derby:databases/TopDown1;create=true';
          [java] ERROR XJ004: Database 'databases/TopDown1' not found.
          [java] SQL Exception: Database 'databases/TopDown1' not found.
          [java] at java.lang.Throwable.<init>(Throwable.java:196)
          [java] at java.lang.Exception.<init>(Exception.java:41)
          [java] at java.sql.SQLException.<init>(SQLException.java:40)
          [java] at org.apache.derby.impl.jdbc.EmbedSQLException.<init>(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.EmbedConnection.newSQLException(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.EmbedConnection.<init>(Unknown Source)
          [java] at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(Unknown Source)
          [java] at org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Unknown Source)
          [java] at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source)
          [java] at java.sql.DriverManager.getConnection(DriverManager.java:525)
          [java] at java.sql.DriverManager.getConnection(DriverManager.java:140)
          [java] at org.apache.derby.impl.tools.ij.ij.dynamicConnection(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.ij.ConnectStatement(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.ij.ijStatement(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.utilMain.go(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.Main.go(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.Main.mainCore(Unknown Source)
          [java] at org.apache.derby.impl.tools.ij.Main14.main(Unknown Source)
          [java] at org.apache.derby.tools.ij.main(Unknown Source)

          Many other cases regarding errors thrown from the JDBC API occur because we have a bug or user expectations are different (ala DERBY-1158). Regardless of whether this issue is a bug or not, when communicating with users it is really good for the derby.log to be a one stop shop for exceptions.

          Show
          Kathey Marsden added a comment - I disagree. The description of derby.stream.error.logSeverityLevel the property says: Specifies which errors are logged to the Derby error log (typically the derby.log file). In test environments, use the setting derby.stream.error.logSeverityLevel=0 so that all problems are reported. http://db.apache.org/derby/docs/dev/tuning/rtunproper26985.html Only printing some of the exceptions causes support issues. When users get unexpected exceptions, we usually ask them to set derby.stream.error.logSeverityLevel=0 and send the derby.log. It is very useful to have the exception there, complete with the full exception chain, regardless of where it came from and not have to worry about getting traces output from the application. Here is one current support case example: Issue: Create database fails with "Database not found" exception after creating the database. There have been multiple round trips so far: 1) Initial issue: "We are seeing this error creating the database but the database actually gets created ok" ij> connect 'jdbc:derby:databases/TopDown1;create=true'; ERROR XJ004: Database 'databases/TopDown1' not found. SQL Exception: Database 'databases/TopDown1' not found. 2) Asked for derby.log with derby.stream.error.logSeverityLevel=0 "Here is the log file <derby.log> However, it does not contain any useful info " 3) Asked for ij stack trace with ij.exceptionTrace=true [java] ij> connect 'jdbc:derby:databases/TopDown1;create=true'; [java] ERROR XJ004: Database 'databases/TopDown1' not found. [java] SQL Exception: Database 'databases/TopDown1' not found. [java] at java.lang.Throwable.<init>(Throwable.java:196) [java] at java.lang.Exception.<init>(Exception.java:41) [java] at java.sql.SQLException.<init>(SQLException.java:40) [java] at org.apache.derby.impl.jdbc.EmbedSQLException.<init>(Unknown Source) [java] at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source) [java] at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source) [java] at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) [java] at org.apache.derby.impl.jdbc.EmbedConnection.newSQLException(Unknown Source) [java] at org.apache.derby.impl.jdbc.EmbedConnection.<init>(Unknown Source) [java] at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(Unknown Source) [java] at org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Unknown Source) [java] at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source) [java] at java.sql.DriverManager.getConnection(DriverManager.java:525) [java] at java.sql.DriverManager.getConnection(DriverManager.java:140) [java] at org.apache.derby.impl.tools.ij.ij.dynamicConnection(Unknown Source) [java] at org.apache.derby.impl.tools.ij.ij.ConnectStatement(Unknown Source) [java] at org.apache.derby.impl.tools.ij.ij.ijStatement(Unknown Source) [java] at org.apache.derby.impl.tools.ij.utilMain.go(Unknown Source) [java] at org.apache.derby.impl.tools.ij.Main.go(Unknown Source) [java] at org.apache.derby.impl.tools.ij.Main.mainCore(Unknown Source) [java] at org.apache.derby.impl.tools.ij.Main14.main(Unknown Source) [java] at org.apache.derby.tools.ij.main(Unknown Source) Many other cases regarding errors thrown from the JDBC API occur because we have a bug or user expectations are different (ala DERBY-1158 ). Regardless of whether this issue is a bug or not, when communicating with users it is really good for the derby.log to be a one stop shop for exceptions.
          Hide
          Daniel John Debrunner added a comment -

          The example you give is a problem with the engine, thus the error should be in the log. I just don't think application errors should make it to the derby.log, they are not a "problem" with Derby.

          Show
          Daniel John Debrunner added a comment - The example you give is a problem with the engine, thus the error should be in the log. I just don't think application errors should make it to the derby.log, they are not a "problem" with Derby.
          Hide
          David Van Couvering added a comment -

          I was thinking of working on this, but reading the comments, it is not clear to me what ultimately needs to be fixed here. It sounds like we want engine-level exceptions, not application errors, to be logged. How does one distinguish between the two in a programmatic way? I'm not clear what approach I would follow to fix this. Should they just be fixed on a case-by-case basis or is there a determinant available in the code?

          Show
          David Van Couvering added a comment - I was thinking of working on this, but reading the comments, it is not clear to me what ultimately needs to be fixed here. It sounds like we want engine-level exceptions, not application errors, to be logged. How does one distinguish between the two in a programmatic way? I'm not clear what approach I would follow to fix this. Should they just be fixed on a case-by-case basis or is there a determinant available in the code?
          Hide
          Kathey Marsden added a comment -

          Changing this to major. I think it is very important for users trying to diagnose issues particularly for the new exceptions now thrown on connection close if the transaction has not been rolled back with DERBY-3319.

          Show
          Kathey Marsden added a comment - Changing this to major. I think it is very important for users trying to diagnose issues particularly for the new exceptions now thrown on connection close if the transaction has not been rolled back with DERBY-3319 .
          Hide
          Kathey Marsden added a comment -

          Linking DERBY-3319
          This issue will be very important users trying to determine what application changes are required after that fix.

          Show
          Kathey Marsden added a comment - Linking DERBY-3319 This issue will be very important users trying to determine what application changes are required after that fix.
          Hide
          Kathey Marsden added a comment -

          Looking back at the comments in this issue, I see that Dan had some objection to logging exceptions at the JDBC API level especially usage errors. I still think logging all exceptions is useful. The one I especially am interested in logging at the moment is:

          SQLState 25001
          java.sql.SQLException: Cannot close a connection while a transaction is still active.

          which is new after the DERBY-3319 fix for pooled connections and has proved hard to track down in the cases of DERBY-4053, DERBY-4225 and I think perhaps a current user case I am trying to diagnose.

          I think this exception would fall into the category of usage error and JDBC API level, but it sure would be helpful to see it especially for something that used to work.

          Do others have opinions on this?

          Show
          Kathey Marsden added a comment - Looking back at the comments in this issue, I see that Dan had some objection to logging exceptions at the JDBC API level especially usage errors. I still think logging all exceptions is useful. The one I especially am interested in logging at the moment is: SQLState 25001 java.sql.SQLException: Cannot close a connection while a transaction is still active. which is new after the DERBY-3319 fix for pooled connections and has proved hard to track down in the cases of DERBY-4053 , DERBY-4225 and I think perhaps a current user case I am trying to diagnose. I think this exception would fall into the category of usage error and JDBC API level, but it sure would be helpful to see it especially for something that used to work. Do others have opinions on this?
          Hide
          Mamta A. Satoor added a comment -

          I can see Dan's point but I do believe that it will be good to have one central place to look at all the exceptions irrespective of what code caused it.

          Show
          Mamta A. Satoor added a comment - I can see Dan's point but I do believe that it will be good to have one central place to look at all the exceptions irrespective of what code caused it.
          Hide
          Kathey Marsden added a comment -

          Attaching a reproduction for this issue. ReproDerby1191. It includes just the one exception that we really need logged after the fix for DERBY-3319. I am sure fixing this one will fix others as well, but there may be additional code paths that need attention.

          Show
          Kathey Marsden added a comment - Attaching a reproduction for this issue. ReproDerby1191. It includes just the one exception that we really need logged after the fix for DERBY-3319 . I am sure fixing this one will fix others as well, but there may be additional code paths that need attention.
          Hide
          Kathey Marsden added a comment -

          Note a fix for this issue might be helpful in diagnosing a recent user report:
          http://www.nabble.com/Derby-10.5.1.1-regression-tt24733315.html#a24733315

          Here an XCL30/XJ001 error shows up only in the protocol tracing and is not otherwise reported.

          Show
          Kathey Marsden added a comment - Note a fix for this issue might be helpful in diagnosing a recent user report: http://www.nabble.com/Derby-10.5.1.1-regression-tt24733315.html#a24733315 Here an XCL30/XJ001 error shows up only in the protocol tracing and is not otherwise reported.
          Hide
          Kathey Marsden added a comment -

          Lily helped me explore possible options for this issue (Thanks Lily!) . Basically there seem to be two.
          1) log the exception when the exception is created in SQLExceptionFactory and SQLExceptionFactory40 getSQLException(). Adding a method logException(SQLException se) to SQLExceptionFactory and calling it just before returning the exception. The advantage to this approach is that it requires a small amount of centralized code. The disadvantages are that it requires access to the Monitor which seems a little out of place here. Also at least in one case we create an exception that we normally never throw. In EmbeddedConnection we have:
          public static final SQLException NO_MEM =
          Util.generateCsSQLException(SQLState.LOGIN_FAILED, "java.lang.OutOfMemoryError");

          and then only throw that if we run out of memory. There would have to be special casing to handle this.

          The side effect of logging from a Factory class seems a little odd.

          2) Add a method to the Util class throwAndLogSQLException(SQLException se) which logs the exception and then throws it. Then change the individual code calls to instead of doing:
          throw Util.generateCsSQLException(...);

          to call
          throwAndLog(Util.generateCsSQLException(...));

          This seems clearer and the exception does not get logged until it is thrown. The downside is that it changes a lot of code and it is possible some exceptions might get missed. Developers need to be aware that for new exceptions they need to call the method instead of just throwing the exception.

          It might be tricky to backport to release branches since it would change so much code.

          I am really about split on the two options and welcome opinions or better ideas.

          Show
          Kathey Marsden added a comment - Lily helped me explore possible options for this issue (Thanks Lily!) . Basically there seem to be two. 1) log the exception when the exception is created in SQLExceptionFactory and SQLExceptionFactory40 getSQLException(). Adding a method logException(SQLException se) to SQLExceptionFactory and calling it just before returning the exception. The advantage to this approach is that it requires a small amount of centralized code. The disadvantages are that it requires access to the Monitor which seems a little out of place here. Also at least in one case we create an exception that we normally never throw. In EmbeddedConnection we have: public static final SQLException NO_MEM = Util.generateCsSQLException(SQLState.LOGIN_FAILED, "java.lang.OutOfMemoryError"); and then only throw that if we run out of memory. There would have to be special casing to handle this. The side effect of logging from a Factory class seems a little odd. 2) Add a method to the Util class throwAndLogSQLException(SQLException se) which logs the exception and then throws it. Then change the individual code calls to instead of doing: throw Util.generateCsSQLException(...); to call throwAndLog(Util.generateCsSQLException(...)); This seems clearer and the exception does not get logged until it is thrown. The downside is that it changes a lot of code and it is possible some exceptions might get missed. Developers need to be aware that for new exceptions they need to call the method instead of just throwing the exception. It might be tricky to backport to release branches since it would change so much code. I am really about split on the two options and welcome opinions or better ideas.
          Hide
          Myrna van Lunteren added a comment -

          I would worry about making a large code change in older branches. But it does seem - without actually looking at the code - that the second suggestion is clearer in the way the process flows.
          It seems to me, could you do both - do approach 1 for older releases (10.4 and earlier) and approach 2 for trunk (and 10.5?) or would that be too much work and cause too much pain backporting fixes?

          Show
          Myrna van Lunteren added a comment - I would worry about making a large code change in older branches. But it does seem - without actually looking at the code - that the second suggestion is clearer in the way the process flows. It seems to me, could you do both - do approach 1 for older releases (10.4 and earlier) and approach 2 for trunk (and 10.5?) or would that be too much work and cause too much pain backporting fixes?
          Hide
          Kathey Marsden added a comment -

          We certainly could take a different approach on the branches, If we choose option 2 on trunk and do not backport it may indeed interfere with merging unrelated fixes since so many methods will be impacted.

          Show
          Kathey Marsden added a comment - We certainly could take a different approach on the branches, If we choose option 2 on trunk and do not backport it may indeed interfere with merging unrelated fixes since so many methods will be impacted.
          Hide
          Kathey Marsden added a comment -

          derby-1191_factory_hack_no_commit_diff.txt contains the SQLExceptionFactory solution. On implementing it, it really looks like it is in the wrong place, but I will give it to someone having a problem with 10.5 to help debug their problem. I am posting it here in case someone else needs to log the JDBC and network server errors for debugging. The patch is against 10.5.

          Show
          Kathey Marsden added a comment - derby-1191_factory_hack_no_commit_diff.txt contains the SQLExceptionFactory solution. On implementing it, it really looks like it is in the wrong place, but I will give it to someone having a problem with 10.5 to help debug their problem. I am posting it here in case someone else needs to log the JDBC and network server errors for debugging. The patch is against 10.5.
          Hide
          Kathey Marsden added a comment -

          Here is a patch that takes the approach of adding a public static void logAndThrowSQLException(SQLException se) method and then calling that instead of just throwing the exception.

          The initial patch only uses the method for EmbedConnection.checkForTransactionInProgress() which is the most important exception to log after the fix for DERBY-3319.

          If everyone agrees on the approach, I would like to commit this patch and backport it to 10.5 and then follow up with larger patches that use the method for other SQLExceptions thrown by Derby embedded JDBC and network server.

          I am running regression tests now. I manually tested that the exception gets logged always with a sane build and with the appropriate derby.stream.error.logSeverityLevel with an insane build. I didn't add a regression test because we don't really have a good way I think to test error log contents.

          Show
          Kathey Marsden added a comment - Here is a patch that takes the approach of adding a public static void logAndThrowSQLException(SQLException se) method and then calling that instead of just throwing the exception. The initial patch only uses the method for EmbedConnection.checkForTransactionInProgress() which is the most important exception to log after the fix for DERBY-3319 . If everyone agrees on the approach, I would like to commit this patch and backport it to 10.5 and then follow up with larger patches that use the method for other SQLExceptions thrown by Derby embedded JDBC and network server. I am running regression tests now. I manually tested that the exception gets logged always with a sane build and with the appropriate derby.stream.error.logSeverityLevel with an insane build. I didn't add a regression test because we don't really have a good way I think to test error log contents.
          Hide
          Kathey Marsden added a comment -

          tests all passed for derby1191_checkForTransactionInProgress_diff.txt. I will check in in an about an hour unless someone asks for more time for review.

          Show
          Kathey Marsden added a comment - tests all passed for derby1191_checkForTransactionInProgress_diff.txt. I will check in in an about an hour unless someone asks for more time for review.
          Hide
          Dag H. Wanvik added a comment -

          Is the intention here (with the new Util.logAndThrowSQLException method), that this be
          used everywhere we now just do "throw newSQLException", so we should use new method in all new
          engine code?

          Show
          Dag H. Wanvik added a comment - Is the intention here (with the new Util.logAndThrowSQLException method), that this be used everywhere we now just do "throw newSQLException", so we should use new method in all new engine code?
          Hide
          Kathey Marsden added a comment -

          Yes. If everyone agrees this is the right approach, I will start in September submitting patches to make all the changes and then put some documentation on the Wiki. I thought I would start with this one exception that I really needed now and then let it sit a few weeks to make sure there are not better implementation ideas out there.

          Show
          Kathey Marsden added a comment - Yes. If everyone agrees this is the right approach, I will start in September submitting patches to make all the changes and then put some documentation on the Wiki. I thought I would start with this one exception that I really needed now and then let it sit a few weeks to make sure there are not better implementation ideas out there.
          Hide
          Knut Anders Hatlen added a comment -

          I agree that option 2 sounds better, but I have some comments to the patch that was committed:

          1) Many of the lines mix tabs and spaces (that is, they are mixed on the same line), and some lines exceed 80 characters

          2) The error stream is automatically redirected to System.err if derby.log cannot be opened, so the special case for printing to the console is probably not necessary

          3) Checking the exact contents of the error message is likely to break in some locales, or if the message text is changed without updating the magic string. Better to follow the getCause() chain to look for OutOfMemoryError? Or perhaps just change the condition to se == EmbedConnection.NO_MEM?

          Show
          Knut Anders Hatlen added a comment - I agree that option 2 sounds better, but I have some comments to the patch that was committed: 1) Many of the lines mix tabs and spaces (that is, they are mixed on the same line), and some lines exceed 80 characters 2) The error stream is automatically redirected to System.err if derby.log cannot be opened, so the special case for printing to the console is probably not necessary 3) Checking the exact contents of the error message is likely to break in some locales, or if the message text is changed without updating the magic string. Better to follow the getCause() chain to look for OutOfMemoryError? Or perhaps just change the condition to se == EmbedConnection.NO_MEM?
          Hide
          Kathey Marsden added a comment -

          Thank you Knut for reviewing the change. I had tried initially to put the check se == Embedconnection.NO_MEM but for some reason it wasn't working. I will research further and will make the other changes.

          Show
          Kathey Marsden added a comment - Thank you Knut for reviewing the change. I had tried initially to put the check se == Embedconnection.NO_MEM but for some reason it wasn't working. I will research further and will make the other changes.
          Hide
          Kristian Waagan added a comment -

          Clearing patch available flag, there are comments to address.

          Show
          Kristian Waagan added a comment - Clearing patch available flag, there are comments to address.
          Hide
          Kathey Marsden added a comment -

          Unmarking HVF as they really critical ones like the connection not closing due to an open transaction have been fixed.

          Show
          Kathey Marsden added a comment - Unmarking HVF as they really critical ones like the connection not closing due to an open transaction have been fixed.

            People

            • Assignee:
              Unassigned
              Reporter:
              Kathey Marsden
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:

                Development