Derby
  1. Derby
  2. DERBY-5559

AssertFailures (7, or 8) with ibm 1.6 and 1.5 on Windows XP in lang.NativeAuthProcs fixture testAll

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.9.1.0
    • Fix Version/s: 10.9.1.0
    • Component/s: Test
    • Labels:
      None
    • Environment:
      Windows XP, IBM 1.6 SR9 FP1, IBM 1.5. SR13
    • Bug behavior facts:
      Regression Test Failure

      Description

      Since revision 1221569, on windows XP I see some failures in the nightly test like this:

      1) testAll(org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs)junit.framework.AssertionFailedError
      at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.vetResetPassword(NativeAuthProcs.java:364)
      at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.resetPasswordTests(NativeAuthProcs.java:332)
      at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.testAll(NativeAuthProcs.java:189)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:116)
      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 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 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 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)

      See for instance: http://people.apache.org/~myrnavl/derby_test_results/main/windows/testlog/ibm15/1222901-suites.All_diff.txt
      There might be an intermittent issue here, one of the runs lists only 7 failures. But mostly there's 8.
      This does not occur on Linux with the same jvm versions.

      The changes between this run and the previous one when these failures did not occur:
      ================
      SUBVERSION LOG FROM 1221076 TO 1221569:
      ------------------------------------------------------------------------
      r1221456 | rhillegas | 2011-12-20 11:35:44 -0800 (Tue, 20 Dec 2011) | 1 line

      DERBY-866: Add regression tests for GRANT/REVOKE on new procedures supporting NATIVE authentication.
      ------------------------------------------------------------------------
      r1221434 | rhillegas | 2011-12-20 10:59:09 -0800 (Tue, 20 Dec 2011) | 1 line

      DERBY-866: Adjust RolesTest to account for new tuple in SYSROUTINEPERMS.
      ------------------------------------------------------------------------
      r1221423 | rhillegas | 2011-12-20 10:44:33 -0800 (Tue, 20 Dec 2011) | 1 line

      DERBY-866: Add syscs_reset_password() and syscs_modify_password() system procedures.
      ================

      derby.log in the failed directory only shows a start and shutdown.

      1. derby-5559.diff
        2 kB
        Mike Matrigali

        Activity

        Hide
        Knut Anders Hatlen added a comment -

        [bulk update] Close all resolved issues that haven't been updated for more than one year.

        Show
        Knut Anders Hatlen added a comment - [bulk update] Close all resolved issues that haven't been updated for more than one year.
        Hide
        Mike Matrigali added a comment -

        This fixed the problem which was reproduceable in my environment. And I have not seen any errors in this test in the nightly's since i checked it in. Closing it as resolved.

        Show
        Mike Matrigali added a comment - This fixed the problem which was reproduceable in my environment. And I have not seen any errors in this test in the nightly's since i checked it in. Closing it as resolved.
        Hide
        Dag H. Wanvik added a comment -

        I saw it at 1229481, so older than your fix. Thanks!

        Show
        Dag H. Wanvik added a comment - I saw it at 1229481, so older than your fix. Thanks!
        Hide
        Mike Matrigali added a comment -

        What build did you see it on dag? I checked in a change that fixed all the issues I was seeing at 1229835.

        Show
        Mike Matrigali added a comment - What build did you see it on dag? I checked in a change that fixed all the issues I was seeing at 1229835.
        Hide
        Dag H. Wanvik added a comment -

        I just saw this with Oracle JVM 7u4 prerelease on 64 bits Windows (VirtualBox), reproducable.

        Show
        Dag H. Wanvik added a comment - I just saw this with Oracle JVM 7u4 prerelease on 64 bits Windows (VirtualBox), reproducable.
        Hide
        Rick Hillegas added a comment -

        Thanks for running these experiments on these platforms, Mike, Myrna, and Kathey. I don't have these platforms so I can't reproduce the problem you are seeing. I think that increasing the timeout is the best solution. There are only 2 columns which we can check to verify whether these procedures ran: HASHINGSCHEME and LASTMODIFIED. The USERNAME column won't change and the PASSWORD column cannot be inspected via SQL.

        When I wrote these tests, the HASHINGSCHEME column was just filled with dummy content. Checking it would have been useless. Since then, I have wired up password hashing, so HASHINGSCHEME now contains real content. We can make the value of HASHINGSCHEME change (by changing the values of the Derby properties which control password hashing behavior). However, I think the test will give us more confidence that we're testing what we want to (viz, that the procedures ran) if we don't resort to turning other knobs in order to generate a visible result. I can look into making that change if the problem is not fixed by increasing the timeout. Sounds like increasing the timeout is working for you though.

        Thanks,
        -Rick

        Show
        Rick Hillegas added a comment - Thanks for running these experiments on these platforms, Mike, Myrna, and Kathey. I don't have these platforms so I can't reproduce the problem you are seeing. I think that increasing the timeout is the best solution. There are only 2 columns which we can check to verify whether these procedures ran: HASHINGSCHEME and LASTMODIFIED. The USERNAME column won't change and the PASSWORD column cannot be inspected via SQL. When I wrote these tests, the HASHINGSCHEME column was just filled with dummy content. Checking it would have been useless. Since then, I have wired up password hashing, so HASHINGSCHEME now contains real content. We can make the value of HASHINGSCHEME change (by changing the values of the Derby properties which control password hashing behavior). However, I think the test will give us more confidence that we're testing what we want to (viz, that the procedures ran) if we don't resort to turning other knobs in order to generate a visible result. I can look into making that change if the problem is not fixed by increasing the timeout. Sounds like increasing the timeout is working for you though. Thanks, -Rick
        Hide
        Kathey Marsden added a comment -

        Thanks Mike for the explanation. , That sounds reasonable to wait for 10ms then and should be portable except possibly on vmware where I recall we have seen time go backwards. It seems reasonable to just wait and see if the failure comes up elsewhere with the change.

        Show
        Kathey Marsden added a comment - Thanks Mike for the explanation. , That sounds reasonable to wait for 10ms then and should be portable except possibly on vmware where I recall we have seen time go backwards. It seems reasonable to just wait and see if the failure comes up elsewhere with the change.
        Hide
        Myrna van Lunteren added a comment -

        I moved the tests to a different, faster (2 CPU) machine, and now the test doesn't fail in the nightly run...

        Show
        Myrna van Lunteren added a comment - I moved the tests to a different, faster (2 CPU) machine, and now the test doesn't fail in the nightly run...
        Hide
        Mike Matrigali added a comment -

        there is not really anything to wait for other than the passing of time. At high level the test is doing something like:
        get timestamp of password file
        do an action expecting timestamp of password file to change
        get new timestamp of password file
        assert that new timestamp is bigger than old timestamp

        The waits are there to make sure that time between getting the first timestamp and doing the action time changes. On some JVM's it looks like
        1 ms is not long enough to wait.

        I agree the wait is arbitrary, hopefully at tleast if it still breaks the new errors will make it more obvious what is going on.

        Maybe Rick could comment if there is a better approach for the test, or if the above interpretation of intent of the test is right?

        Show
        Mike Matrigali added a comment - there is not really anything to wait for other than the passing of time. At high level the test is doing something like: get timestamp of password file do an action expecting timestamp of password file to change get new timestamp of password file assert that new timestamp is bigger than old timestamp The waits are there to make sure that time between getting the first timestamp and doing the action time changes. On some JVM's it looks like 1 ms is not long enough to wait. I agree the wait is arbitrary, hopefully at tleast if it still breaks the new errors will make it more obvious what is going on. Maybe Rick could comment if there is a better approach for the test, or if the above interpretation of intent of the test is right?
        Hide
        Kathey Marsden added a comment -

        Mike, I haven't looked closely, but I am wondering, is the test waiting for something specific that can be checked? I have noticed in the past that arbitrary waits tend to have problems in different configurations especially with slow jvm options like JIT turned off.

        Show
        Kathey Marsden added a comment - Mike, I haven't looked closely, but I am wondering, is the test waiting for something specific that can be checked? I have noticed in the past that arbitrary waits tend to have problems in different configurations especially with slow jvm options like JIT turned off.
        Hide
        Mike Matrigali added a comment -

        In this patch I upped the wait time in the test from 1ms to 10ms and added a few other waits at appropriate places. This set of changes seems to fix the problems on my laptop while just running the single test alone. I ran the test 60 times with the changes and it passed each time.
        The test still failed with just the waits increased, the added waits were necessary.

        Show
        Mike Matrigali added a comment - In this patch I upped the wait time in the test from 1ms to 10ms and added a few other waits at appropriate places. This set of changes seems to fix the problems on my laptop while just running the single test alone. I ran the test 60 times with the changes and it passed each time. The test still failed with just the waits increased, the added waits were necessary.
        Hide
        Mike Matrigali added a comment -

        I checked in a change to add printout of values when the asserts are hit. All the problems seem to be with timestamp comparisons where the
        tests seem to be waiting a minimal amount of time to make sure that the assert are correct. The current settings are not working for my laptop
        running XP and ibm 16 jvm.

        With the change I got 2 failures just running the single test in sane mode. In both cases the test is counting on the timestamp progressing but
        in both cases the timestamp before and after is the same.

        One option is to just go and bump the various waits in the test until it passes on my machine and then let others adjust as it fails on their
        machines, but would like some feedback to make sure there is not something better
        to be done for the tests.

        Here is the output:

        There were 2 failures:
        1) testAll(org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs$NoAuthorization)junit.framework.AssertionFailedError: expected newLastModified > oldLastModified, but instead: newLastModified = 1325899678421; oldLastModified = 1325899678421
        at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.vetResetPassword(NativeAuthProcs.java:391)
        at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.resetPasswordTests(NativeAuthProcs.java:353)
        at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.testAll(NativeAuthProcs.java:201)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:116)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        2) testAll(org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs$NoAuthorization)junit.framework.AssertionFailedError: expected newLastModified > lastModified, but instead: newLastModified = 1325899727468; lastModified = 1325899727468
        at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.resetPasswordTests(NativeAuthProcs.java:367)
        at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.testAll(NativeAuthProcs.java:201)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
        at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:116)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)
        at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
        at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
        at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
        at junit.extensions.TestSetup.run(TestSetup.java:23)

        FAILURES!!!
        Tests run: 8, Failures: 2, Errors: 0

        OK (10 tests)

        Show
        Mike Matrigali added a comment - I checked in a change to add printout of values when the asserts are hit. All the problems seem to be with timestamp comparisons where the tests seem to be waiting a minimal amount of time to make sure that the assert are correct. The current settings are not working for my laptop running XP and ibm 16 jvm. With the change I got 2 failures just running the single test in sane mode. In both cases the test is counting on the timestamp progressing but in both cases the timestamp before and after is the same. One option is to just go and bump the various waits in the test until it passes on my machine and then let others adjust as it fails on their machines, but would like some feedback to make sure there is not something better to be done for the tests. Here is the output: There were 2 failures: 1) testAll(org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs$NoAuthorization)junit.framework.AssertionFailedError: expected newLastModified > oldLastModified, but instead: newLastModified = 1325899678421; oldLastModified = 1325899678421 at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.vetResetPassword(NativeAuthProcs.java:391) at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.resetPasswordTests(NativeAuthProcs.java:353) at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.testAll(NativeAuthProcs.java:201) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:116) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) 2) testAll(org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs$NoAuthorization)junit.framework.AssertionFailedError: expected newLastModified > lastModified, but instead: newLastModified = 1325899727468; lastModified = 1325899727468 at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.resetPasswordTests(NativeAuthProcs.java:367) at org.apache.derbyTesting.functionTests.tests.lang.NativeAuthProcs.testAll(NativeAuthProcs.java:201) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:116) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.extensions.TestSetup.run(TestSetup.java:23) FAILURES!!! Tests run: 8, Failures: 2, Errors: 0 OK (10 tests)

          People

          • Assignee:
            Mike Matrigali
            Reporter:
            Myrna van Lunteren
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development