Derby
  1. Derby
  2. DERBY-5608

BaseTestCase.readProcessOutput should read getInputStream() and getErrorStream() in separate threads

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 10.9.1.0
    • Fix Version/s: 10.8.3.0, 10.9.1.0
    • Component/s: Test
    • Labels:
      None

      Description

      BaseTestCase.readProcessOutput() reads the streams from Process.getInputStream() and Process.getErrorStream() sequentially
      InputStream is = pr.getInputStream();
      InputStream es = pr.getErrorStream();
      ...
      output += "<STDOUT> " + inputStreamToString(is) + "<END STDOUT>\n";
      output += "<STDERR>" + inputStreamToString(es) + "<END STDERR>\n";

      I think that to be really correct the two streams need to be read in separate threads because if the error output is large it could block and cause a hang if they are read sequentially like this.

      I noticed during the DERBY-5601 discussion as Myrna referenced in that the addition of draining the error stream caused a different problem (an InterruptException). I don't understand how it could cause that problem but do think a hang blocking on reading the input would be possible if the error output was large enough both before and after the change to add the reading of the error stream sequentially.

        Issue Links

          Activity

          Hide
          Knut Anders Hatlen added a comment -

          [bulk update: close all resolved issues that haven't had any activity the last year]

          Show
          Knut Anders Hatlen added a comment - [bulk update: close all resolved issues that haven't had any activity the last year]
          Hide
          Kristian Waagan added a comment -

          Backported to 10.8, together with DERBY-5617, with revision 1327102.
          Resolving issue.

          Show
          Kristian Waagan added a comment - Backported to 10.8, together with DERBY-5617 , with revision 1327102. Resolving issue.
          Hide
          Kristian Waagan added a comment -

          Ok, I'll look into backporting it.

          Do you mean DERBY-5594?
          I don't think this will fix that issue, although I'm not sure. I'm also not sure if there is a bug with SpawnedProcess/StreamSaver To me it looks like the process is forcibly destroyed for some reason, and it would be good to understand why that's happening.

          Show
          Kristian Waagan added a comment - Ok, I'll look into backporting it. Do you mean DERBY-5594 ? I don't think this will fix that issue, although I'm not sure. I'm also not sure if there is a bug with SpawnedProcess/StreamSaver To me it looks like the process is forcibly destroyed for some reason, and it would be good to understand why that's happening.
          Hide
          Kathey Marsden added a comment -

          I think it would be good to backport to 10.8 . The cleaner we can get trunk and 10.8 the better and also if there are other fixes in this area, they will be easier to backport if this one goes. Do you think it will address DERBY-5494? I haven't had a chance to take a close look at that one yet.

          Show
          Kathey Marsden added a comment - I think it would be good to backport to 10.8 . The cleaner we can get trunk and 10.8 the better and also if there are other fixes in this area, they will be easier to backport if this one goes. Do you think it will address DERBY-5494 ? I haven't had a chance to take a close look at that one yet.
          Hide
          Kristian Waagan added a comment -

          Removed a space character prepended to the stdout output with revision 1291647.
          Does anyone see enough failures related to this issue to warrant backporting the fix, which should also include DERBY-5617?

          Show
          Kristian Waagan added a comment - Removed a space character prepended to the stdout output with revision 1291647. Does anyone see enough failures related to this issue to warrant backporting the fix, which should also include DERBY-5617 ?
          Hide
          Kristian Waagan added a comment -

          I'm ready to resolve this issue.
          We may want to consider a timeout when waiting for the process, but then again we are expecting the process to terminate normally.
          Keeping this open for a little longer to see if anything comes up.

          Patch 2a didn't help with Myrna's cascading errors issue.

          Show
          Kristian Waagan added a comment - I'm ready to resolve this issue. We may want to consider a timeout when waiting for the process, but then again we are expecting the process to terminate normally. Keeping this open for a little longer to see if anything comes up. Patch 2a didn't help with Myrna's cascading errors issue.
          Hide
          Kristian Waagan added a comment -

          I think patch 1a is an improvement, so I committed it to trunk with revision 1242681.

          Myrna's results suggest that the old readProcessOutput isn't the cause for the problems - it's another victim. This assumes of curse that the stream draining code in SpawnedProcess isn't buggy.

          I'm attaching another patch 2a, which resets the interrupt flag when waitFor is interrupted in SpawnedProcess.complete. If my theory is correct that should still leave you with some failed tests due to the interrupt, but the cascading errors caused by Derby shutdowns should go away.
          This fix is part of addressing the issues I mentioned for SpawnedProcess under DERBY-5601.

          The real issue here is finding out where the interrupt is coming from, but I don't know how to do that.

          Show
          Kristian Waagan added a comment - I think patch 1a is an improvement, so I committed it to trunk with revision 1242681. Myrna's results suggest that the old readProcessOutput isn't the cause for the problems - it's another victim. This assumes of curse that the stream draining code in SpawnedProcess isn't buggy. I'm attaching another patch 2a, which resets the interrupt flag when waitFor is interrupted in SpawnedProcess.complete. If my theory is correct that should still leave you with some failed tests due to the interrupt, but the cascading errors caused by Derby shutdowns should go away. This fix is part of addressing the issues I mentioned for SpawnedProcess under DERBY-5601 . The real issue here is finding out where the interrupt is coming from, but I don't know how to do that.
          Hide
          Myrna van Lunteren added a comment -

          I tried a run with a build with the patch applied on the system where the trouble is reproducible, and unfortunately, I see lots of cascading errors.

          It starts with this:
          1) test_01_WrongUsage(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)java.lang.InterruptedException
          at java.lang.ProcessImpl.waitFor(Native Method)
          at org.apache.derbyTesting.junit.SpawnedProcess.complete(SpawnedProcess.java:214)
          at org.apache.derbyTesting.junit.SpawnedProcess.complete(SpawnedProcess.java:176)
          at org.apache.derbyTesting.junit.BaseTestCase.readProcessOutput(BaseTestCase.java:774)
          at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:508)
          at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_01_WrongUsage(NetworkServerControlApiTest.java:81)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
          at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
          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)
          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 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 junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:25)

          The next failure is
          2) testBoundaries(org.apache.derbyTesting.functionTests.tests.jdbcapi.InternationalConnectTest)java.sql.SQLException: DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ001, SQLERRMC: java.security.AccessControlExceptionAccess denied (java.io.FilePermission [edited path to system dir]\system\AAAAAAAAAAAAAA[...repeat....]AAAA\tmp delete)XJ001.U

          The third failure is:
          3) shutdownDerby(org.apache.derbyTesting.functionTests.tests.store.BootAllTest)java.lang.NullPointerException
          at org.apache.derby.impl.services.monitor.TopService.getService(TopService.java:128)
          at org.apache.derby.impl.services.monitor.BaseMonitor.shutdown(BaseMonitor.java:199)
          at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
          at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:143)
          at java.sql.DriverManager.getConnection(DriverManager.java:317)
          at java.sql.DriverManager.getConnection(DriverManager.java:297)
          at org.apache.derbyTesting.junit.DriverManagerConnector.getConnectionByAttributes(DriverManagerConnector.java:144)
          at org.apache.derbyTesting.junit.DriverManagerConnector.shutEngine(DriverManagerConnector.java:121)
          at org.apache.derbyTesting.junit.TestConfiguration.shutdownEngine(TestConfiguration.java:1716)
          at org.apache.derbyTesting.functionTests.tests.store.BootAllTest.shutdownDerby(BootAllTest.java:116)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
          at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113)
          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:51)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:18)
          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:51)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:18)
          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:51)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
          at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
          at junit.extensions.TestSetup.run(TestSetup.java:18)

          Which then leaves Derby system shutdown, and causes many, many more failures.
          Tests run: 11591, Failures: 76, Errors: 817

          Show
          Myrna van Lunteren added a comment - I tried a run with a build with the patch applied on the system where the trouble is reproducible, and unfortunately, I see lots of cascading errors. It starts with this: 1) test_01_WrongUsage(org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest)java.lang.InterruptedException at java.lang.ProcessImpl.waitFor(Native Method) at org.apache.derbyTesting.junit.SpawnedProcess.complete(SpawnedProcess.java:214) at org.apache.derbyTesting.junit.SpawnedProcess.complete(SpawnedProcess.java:176) at org.apache.derbyTesting.junit.BaseTestCase.readProcessOutput(BaseTestCase.java:774) at org.apache.derbyTesting.junit.BaseTestCase.assertExecJavaCmdAsExpected(BaseTestCase.java:508) at org.apache.derbyTesting.functionTests.tests.derbynet.NetworkServerControlApiTest.test_01_WrongUsage(NetworkServerControlApiTest.java:81) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) 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) 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 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 junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:25) The next failure is 2) testBoundaries(org.apache.derbyTesting.functionTests.tests.jdbcapi.InternationalConnectTest)java.sql.SQLException: DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ001, SQLERRMC: java.security.AccessControlExceptionAccess denied (java.io.FilePermission [edited path to system dir] \system\AAAAAAAAAAAAAA [...repeat....] AAAA\tmp delete)XJ001.U The third failure is: 3) shutdownDerby(org.apache.derbyTesting.functionTests.tests.store.BootAllTest)java.lang.NullPointerException at org.apache.derby.impl.services.monitor.TopService.getService(TopService.java:128) at org.apache.derby.impl.services.monitor.BaseMonitor.shutdown(BaseMonitor.java:199) at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248) at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:143) at java.sql.DriverManager.getConnection(DriverManager.java:317) at java.sql.DriverManager.getConnection(DriverManager.java:297) at org.apache.derbyTesting.junit.DriverManagerConnector.getConnectionByAttributes(DriverManagerConnector.java:144) at org.apache.derbyTesting.junit.DriverManagerConnector.shutEngine(DriverManagerConnector.java:121) at org.apache.derbyTesting.junit.TestConfiguration.shutdownEngine(TestConfiguration.java:1716) at org.apache.derbyTesting.functionTests.tests.store.BootAllTest.shutdownDerby(BootAllTest.java:116) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:48) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:113) 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:51) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:18) 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:51) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:18) 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:51) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24) at junit.extensions.TestSetup$1.protect(TestSetup.java:21) at junit.extensions.TestSetup.run(TestSetup.java:18) Which then leaves Derby system shutdown, and causes many, many more failures. Tests run: 11591, Failures: 76, Errors: 817
          Hide
          Kristian Waagan added a comment -

          Attaching a patch that makes BaseTestCase.readProcessOutout use SpawnedProcess to handle the output from the subprocess.

          Only tested with derbynet._Suite so far.

          Patch ready for review.

          Show
          Kristian Waagan added a comment - Attaching a patch that makes BaseTestCase.readProcessOutout use SpawnedProcess to handle the output from the subprocess. Only tested with derbynet._Suite so far. Patch ready for review.
          Hide
          Kathey Marsden added a comment -

          +1 to dealing with this in SpawnedProcess. I will defer to you on what makes the most sense, a separate checkin for this part of your work under this issue or just resolve this as fixed by DERBY-5601 fix. Either sounds fine.

          Show
          Kathey Marsden added a comment - +1 to dealing with this in SpawnedProcess. I will defer to you on what makes the most sense, a separate checkin for this part of your work under this issue or just resolve this as fixed by DERBY-5601 fix. Either sounds fine.
          Hide
          Kristian Waagan added a comment -

          Don't know if it is an option, but could readProcessOutput be discarded ([1]) and SpawnedProcess be extended to deal with this?
          SpawnedProcess already does what readProcessOutput does (or should have done), except for constructing a string from the raw output data. After having read a bit about best practices for java.lang.Process, there seems to be several common pitfalls associated with its use. It would be good to deal with them in one place.
          SpawnedProcess also has some issues that needs to be fixed. I was planning to deal with that under DERBY-5601, but maybe this issue is a better fit?

          [1] Or keep the method and just use SpawnedProcess in the method implementation.

          Show
          Kristian Waagan added a comment - Don't know if it is an option, but could readProcessOutput be discarded ( [1] ) and SpawnedProcess be extended to deal with this? SpawnedProcess already does what readProcessOutput does (or should have done), except for constructing a string from the raw output data. After having read a bit about best practices for java.lang.Process, there seems to be several common pitfalls associated with its use. It would be good to deal with them in one place. SpawnedProcess also has some issues that needs to be fixed. I was planning to deal with that under DERBY-5601 , but maybe this issue is a better fit? [1] Or keep the method and just use SpawnedProcess in the method implementation.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development