Derby
  1. Derby
  2. DERBY-5113

Intermittent failure in BlobSetMethodsTest on Java 7: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.3.1.4, 10.3.2.1, 10.3.3.0, 10.4.1.3, 10.4.2.0, 10.5.1.1, 10.5.2.0, 10.5.3.0, 10.6.1.0, 10.6.2.1, 10.7.1.1
    • Fix Version/s: 10.8.1.2
    • Component/s: JDBC, Test
    • Labels:
      None
    • Environment:
      Solaris 10 and Windows
      Java(TM) SE Runtime Environment (build 1.7.0-ea-b131)
    • Bug behavior facts:
      Regression Test Failure, Wrong query result

      Description

      Not sure if this is a test issue, a product issue or a JVM issue. It started happening when JDK 7 was upgraded from b116 to b131 in the nightly tests. I haven't been able to reproduce the failure in my environment, but it happens frequently in the nightly testing. For example here:

      http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.7/testing/testlog/sol/1078053-suitesAll_diff.txt

      19) testSetBytesLargeBlob(org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest)java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.setStreamFailure(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedBlob.truncate(Unknown Source)
      at org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest.testSetBytesLargeBlob(BlobSetMethodsTest.java:102)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:112)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
      Caused by: java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)

      The problem does not appear to be the reordering of the test cases that we've seen in many other tests when running on Java 7 b131. According to the traces printed to the test log (for example in the above mentioned URL), this failure is also seen in the cases where the test cases run in the same order as on most other platforms.

      1. derby-5113-1a-test.diff
        2 kB
        Knut Anders Hatlen
      2. derby-5113-2a-truncate.diff
        3 kB
        Knut Anders Hatlen
      3. reporting.diff
        0.7 kB
        Knut Anders Hatlen

        Activity

        Hide
        Knut Anders Hatlen added a comment -

        The stack trace of the underlying IOException is lost because Util.setStreamFailure() only preserves the message text when it converts it to an SQLException. The attached patch makes setStreamFailure() preserve the stack trace too, so that we'll get more information the next time it happens.

        Running regression tests now.

        Show
        Knut Anders Hatlen added a comment - The stack trace of the underlying IOException is lost because Util.setStreamFailure() only preserves the message text when it converts it to an SQLException. The attached patch makes setStreamFailure() preserve the stack trace too, so that we'll get more information the next time it happens. Running regression tests now.
        Hide
        Knut Anders Hatlen added a comment -

        Committed reporting.diff with revision 1079761. This should give us more info the next time the test fails.

        Show
        Knut Anders Hatlen added a comment - Committed reporting.diff with revision 1079761. This should give us more info the next time the test fails.
        Hide
        Knut Anders Hatlen added a comment -

        Got a failure with the improved error reporting.

        http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.7/testing/testlog/sol32/1079883-suitesAll_diff.txt

        3) testSetBytesLargeBlob(org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest)java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'.
        at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.Util.setStreamFailure(Unknown Source)
        at org.apache.derby.impl.jdbc.EmbedBlob.truncate(Unknown Source)
        at org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest.testSetBytesLargeBlob(BlobSetMethodsTest.java:102)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:112)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
        at junit.extensions.TestSetup.run(TestSetup.java:25)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        Caused by: java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'.
        at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
        at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
        ... 36 more
        Caused by: java.io.EOFException: Reached EOF prematurely; expected 1,024, got 0.
        at org.apache.derby.impl.jdbc.LOBStreamControl.copyData(Unknown Source)
        ... 31 more

        Show
        Knut Anders Hatlen added a comment - Got a failure with the improved error reporting. http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.7/testing/testlog/sol32/1079883-suitesAll_diff.txt 3) testSetBytesLargeBlob(org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest)java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source) at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source) at org.apache.derby.impl.jdbc.Util.setStreamFailure(Unknown Source) at org.apache.derby.impl.jdbc.EmbedBlob.truncate(Unknown Source) at org.apache.derbyTesting.functionTests.tests.jdbc4.BlobSetMethodsTest.testSetBytesLargeBlob(BlobSetMethodsTest.java:102) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:112) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) Caused by: java.sql.SQLException: Unable to set stream: 'Reached EOF prematurely; expected 1,024, got 0.'. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source) ... 36 more Caused by: java.io.EOFException: Reached EOF prematurely; expected 1,024, got 0. at org.apache.derby.impl.jdbc.LOBStreamControl.copyData(Unknown Source) ... 31 more
        Hide
        Knut Anders Hatlen added a comment -

        We have two bugs here. One test bug and one product bug.

        The product bug is that EmbedBlob.truncate() doesn't reset the position of the underlying stream before copying the first N bytes to a new location. If the stream position has been altered by a call to another method (like EmbedBlob.getBytes() here), the copying happens on the wrong position, and we may see this exception being raised. This bug is only seen if the Blob is in stream format, which typically means that the Blob must have been fetched from store and its size must be > 32K.

        The product bug doesn't explain why it fails intermittently on Java 7, though, and it isn't reproducible when running the test standalone. The length of the Blob used in the failing test is only about 5K, so the Blob should be materialized and not be represented as a stream, and the buggy code path shouldn't be taken. The only reason I can think of that the buggy code path should be taken here, is if the page size is smaller than 5K, which would make store return the Blob as a stream rather than a fully materialized byte array. And if the test is run with the derby.storage.pageSize property set to 4096, it does indeed fail consistently.

        Looking at tests that set the derby.storage.pageSize property, I found that store.AccessTest sets the property, but doesn't always reset it. If its test cases runs in the order in which they appear in the source file, the property will be reset. But the order of the test cases is not guaranteed, and the latest builds of Java 7 tend to run the test cases in a different order than other JVMs. If one of the test cases that don't reset the property runs last, a smaller page size value may survive in the database until BlobSetMethodsTest runs, and we'll see this failure.

        Show
        Knut Anders Hatlen added a comment - We have two bugs here. One test bug and one product bug. The product bug is that EmbedBlob.truncate() doesn't reset the position of the underlying stream before copying the first N bytes to a new location. If the stream position has been altered by a call to another method (like EmbedBlob.getBytes() here), the copying happens on the wrong position, and we may see this exception being raised. This bug is only seen if the Blob is in stream format, which typically means that the Blob must have been fetched from store and its size must be > 32K. The product bug doesn't explain why it fails intermittently on Java 7, though, and it isn't reproducible when running the test standalone. The length of the Blob used in the failing test is only about 5K, so the Blob should be materialized and not be represented as a stream, and the buggy code path shouldn't be taken. The only reason I can think of that the buggy code path should be taken here, is if the page size is smaller than 5K, which would make store return the Blob as a stream rather than a fully materialized byte array. And if the test is run with the derby.storage.pageSize property set to 4096, it does indeed fail consistently. Looking at tests that set the derby.storage.pageSize property, I found that store.AccessTest sets the property, but doesn't always reset it. If its test cases runs in the order in which they appear in the source file, the property will be reset. But the order of the test cases is not guaranteed, and the latest builds of Java 7 tend to run the test cases in a different order than other JVMs. If one of the test cases that don't reset the property runs last, a smaller page size value may survive in the database until BlobSetMethodsTest runs, and we'll see this failure.
        Hide
        Knut Anders Hatlen added a comment -

        The attached patch adds a tearDown() method to AccessTest. The database properties modified by the test are now cleared after each test case. DatabasePropertyTestSetup couldn't be used for this since the properties are set to different values in each test case, and not globally for the whole test which is how that decorator is normally used.

        Committed revision 1081059.

        Show
        Knut Anders Hatlen added a comment - The attached patch adds a tearDown() method to AccessTest. The database properties modified by the test are now cleared after each test case. DatabasePropertyTestSetup couldn't be used for this since the properties are set to different values in each test case, and not globally for the whole test which is how that decorator is normally used. Committed revision 1081059.
        Hide
        Knut Anders Hatlen added a comment -

        This patch adds a new test case to BlobClob4BlobTest which consistently shows the truncate bug. The patch also fixes the bug by resetting the position in the BLOB before copying the bytes.

        Show
        Knut Anders Hatlen added a comment - This patch adds a new test case to BlobClob4BlobTest which consistently shows the truncate bug. The patch also fixes the bug by resetting the position in the BLOB before copying the bytes.
        Hide
        Knut Anders Hatlen added a comment -

        Committed revision 1081293.

        Show
        Knut Anders Hatlen added a comment - Committed revision 1081293.
        Hide
        Knut Anders Hatlen added a comment -

        The bug in EmbedBlob.truncate() is seen all the way back to 10.3 when truncate() was implemented. Before that, the method threw a not implemented exception.

        Marking the bug as a wrong result bug, since if the length argument isn't so big that the call fails with premature EOF, the truncated Blob object will contain the wrong value (correct length, but not the right bytes).

        Show
        Knut Anders Hatlen added a comment - The bug in EmbedBlob.truncate() is seen all the way back to 10.3 when truncate() was implemented. Before that, the method threw a not implemented exception. Marking the bug as a wrong result bug, since if the length argument isn't so big that the call fails with premature EOF, the truncated Blob object will contain the wrong value (correct length, but not the right bytes).

          People

          • Assignee:
            Knut Anders Hatlen
            Reporter:
            Knut Anders Hatlen
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development