Derby
  1. Derby
  2. DERBY-5194

AutoloadTest timed out waiting for network server to start

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Duplicate
    • Affects Version/s: 10.8.1.2, 10.8.2.2
    • Fix Version/s: None
    • Component/s: Test
    • Labels:
      None
    • Bug behavior facts:
      Regression Test Failure

      Description

      Seen when testing the 10.8.1.1 release candidate on Windows Vista:

      http://dbtg.foundry.sun.com/derby/test/10.8.1.1_RC/logs/jvm1.6/vista/JDBCDriversEmbedded/report.txt

      1) AutoloadTest: clientjunit.framework.AssertionFailedError: Timed out waiting for network server to start
      at org.apache.derbyTesting.junit.NetworkServerTestSetup.setUp(NetworkServerTestSetup.java:205)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:20)
      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)

      The following exception was printed to the console while the test was running:

      java.lang.Exception: DRDA_InvalidReplyTooShort.S:Invalid reply from network server: Insufficient data.
      at org.apache.derby.impl.drda.NetworkServerControlImpl.consolePropertyMessageWork(Unknown Source)
      at org.apache.derby.impl.drda.NetworkServerControlImpl.consolePropertyMessage(Unknown Source)
      at org.apache.derby.impl.drda.NetworkServerControlImpl.fillReplyBuffer(Unknown Source)
      at org.apache.derby.impl.drda.NetworkServerControlImpl.readResult(Unknown Source)
      at org.apache.derby.impl.drda.NetworkServerControlImpl.pingWithNoOpen(Unknown Source)
      at org.apache.derby.impl.drda.NetworkServerControlImpl.ping(Unknown Source)
      at org.apache.derby.drda.NetworkServerControl.ping(Unknown Source)
      at org.apache.derbyTesting.junit.NetworkServerTestSetup.pingForServerUp(NetworkServerTestSetup.java:567)
      at org.apache.derbyTesting.junit.NetworkServerTestSetup.pingForServerStart(NetworkServerTestSetup.java:636)
      at org.apache.derbyTesting.junit.NetworkServerTestSetup.setUp(NetworkServerTestSetup.java:196)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:20)
      at junit.framework.TestResult.runProtected(TestResult.java:124)
      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.framework.TestResult.runProtected(TestResult.java:124)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at junit.framework.TestSuite.runTest(TestSuite.java:230)
      at junit.framework.TestSuite.run(TestSuite.java:225)
      at junit.framework.TestSuite.runTest(TestSuite.java:230)
      at junit.framework.TestSuite.run(TestSuite.java:225)
      at junit.textui.TestRunner.doRun(TestRunner.java:121)
      at junit.textui.TestRunner.start(TestRunner.java:185)
      at junit.textui.TestRunner.main(TestRunner.java:143)

      1. sleep-repro.diff
        0.8 kB
        Knut Anders Hatlen

        Issue Links

          Activity

          Hide
          Lily Wei added a comment -

          I run AutoloadTest with 10.8.1.1 on Windows 7. I can not reproduce this issue. I also run Suites.All for db-derby-10.8.1.1-bin release and can not reproduce this problem. Does this only happen on 10.8.1.1? Do we see it on 10.8.1.0? Thanks!

          Show
          Lily Wei added a comment - I run AutoloadTest with 10.8.1.1 on Windows 7. I can not reproduce this issue. I also run Suites.All for db-derby-10.8.1.1-bin release and can not reproduce this problem. Does this only happen on 10.8.1.1? Do we see it on 10.8.1.0? Thanks!
          Hide
          Knut Anders Hatlen added a comment -

          Hi Lily,

          I've only seen this failure with 10.8.1.1, and only once. I suspect that this is a problem in the NetworkServerTestSetup decorator or the network server shutdown code, and that it's just a coincident that it happened in AutoloadTest. We've seen many other tests fail with similar timeouts, that's why I suspect it's a more general problem. My current hypothesis is that the decorator tries to set up a new server before the previous server instance has been shut down properly. I'll do some digging and see if I can confirm the hypothesis.

          Show
          Knut Anders Hatlen added a comment - Hi Lily, I've only seen this failure with 10.8.1.1, and only once. I suspect that this is a problem in the NetworkServerTestSetup decorator or the network server shutdown code, and that it's just a coincident that it happened in AutoloadTest. We've seen many other tests fail with similar timeouts, that's why I suspect it's a more general problem. My current hypothesis is that the decorator tries to set up a new server before the previous server instance has been shut down properly. I'll do some digging and see if I can confirm the hypothesis.
          Hide
          Knut Anders Hatlen added a comment -

          Also note that AutoloadTest doesn't get run as part of suites.All, as far as I can see. To run it as part of a suite, I think you'd need to run one of the following suites:

          • jdbcapi.JDBCDriversEmbeddedTest
          • jdbcapi.JDBCDriversClientTest
          • jdbcapi.JDBCDriversAllTest
          • the "junit-core" ant target

          The failure reported here was seen when running JDBCDriversEmbeddedTest.

          Show
          Knut Anders Hatlen added a comment - Also note that AutoloadTest doesn't get run as part of suites.All, as far as I can see. To run it as part of a suite, I think you'd need to run one of the following suites: jdbcapi.JDBCDriversEmbeddedTest jdbcapi.JDBCDriversClientTest jdbcapi.JDBCDriversAllTest the "junit-core" ant target The failure reported here was seen when running JDBCDriversEmbeddedTest.
          Hide
          Knut Anders Hatlen added a comment -

          Sleeping for half a second before closing the server socket during network server shutdown (see the attached sleep-repro.diff) makes the test fail consistently in my environment when run via JDBCDriversEmbeddedTest.

          logs/serverConsoleOutput.log shows that the server fails to start with the following error: java.net.BindException: Address already in use

          I think the problem is that the network server shutdown only waits until ping starts failing, and that since DERBY-3869 ping can start failing before the server socket has been closed. The shutdown command therefore returns while the server socket is still up, and the test continues and attempts to create a new server while the port is still in use.

          Show
          Knut Anders Hatlen added a comment - Sleeping for half a second before closing the server socket during network server shutdown (see the attached sleep-repro.diff) makes the test fail consistently in my environment when run via JDBCDriversEmbeddedTest. logs/serverConsoleOutput.log shows that the server fails to start with the following error: java.net.BindException: Address already in use I think the problem is that the network server shutdown only waits until ping starts failing, and that since DERBY-3869 ping can start failing before the server socket has been closed. The shutdown command therefore returns while the server socket is still up, and the test continues and attempts to create a new server while the port is still in use.
          Hide
          Knut Anders Hatlen added a comment -

          On a closer look, DERBY-3869 only changed the behaviour of ping commands that set up a new connection to the server. shutdown() uses a lightweight variant of ping that reuses an existing connection, and therefore doesn't go through the code path changed in DERBY-3869. But I think the root cause of the failure is as suggested, that shutdown() returns before the socket has been closed and associated resources released, and starting the next network server instance fails.

          Show
          Knut Anders Hatlen added a comment - On a closer look, DERBY-3869 only changed the behaviour of ping commands that set up a new connection to the server. shutdown() uses a lightweight variant of ping that reuses an existing connection, and therefore doesn't go through the code path changed in DERBY-3869 . But I think the root cause of the failure is as suggested, that shutdown() returns before the socket has been closed and associated resources released, and starting the next network server instance fails.
          Hide
          Knut Anders Hatlen added a comment -

          Happened again on Windows Vista with the 10.8.2.1 release candidate: http://dbtg.foundry.sun.com/derby/test/10.8.2.1_RC/logs/jvm1.6/vista/JDBCDriversEmbedded/report.txt

          Show
          Knut Anders Hatlen added a comment - Happened again on Windows Vista with the 10.8.2.1 release candidate: http://dbtg.foundry.sun.com/derby/test/10.8.2.1_RC/logs/jvm1.6/vista/JDBCDriversEmbedded/report.txt
          Hide
          Knut Anders Hatlen added a comment -

          Resolving as a duplicate of DERBY-4201. Please reopen or file a new bug report if it happens again.

          Show
          Knut Anders Hatlen added a comment - Resolving as a duplicate of DERBY-4201 . Please reopen or file a new bug report if it happens again.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development