mq
  1. mq
  2. MQ-140

persist store internal API test 'persist/api/file' logs many ERROR [3007] when trying to load destinations or messages

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Works as designed
    • Affects Version/s: 4.5
    • Fix Version/s: None
    • Component/s: test
    • Labels:
      None
    • Environment:

      MQ broker running on Windows with JDK1.6 and 1.7

      Description

      MQ Broker running on Windows with either JDK1.6 or JDK1.7 some times appear to go on a spin printing the following messages. Some tests fail when this happens.

      This behavior is not consistently reproducible. I have seen it most times when running the test tonga/jmsserver/persist/api/file

      snippet of the broker log. Attaching the complete test log.

      [10/Jan/2012:16:47:21 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:21 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:21 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242839703 on destination T:798511184 could not be found in the store
      [10/Jan/2012:16:47:21 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242839734 on destination Q:1997718144 could not be found in the store
      [10/Jan/2012:16:47:21 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242839750 on destination Q:1997718144 could not be found in the store
      [10/Jan/2012:16:47:23 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:23 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:23 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841437 on destination Q:1997718144 could not be found in the store
      [10/Jan/2012:16:47:23 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841438 on destination T:798511184 could not be found in the store
      [10/Jan/2012:16:47:23 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841439 on destination T:798511184 could not be found in the store
      [10/Jan/2012:16:47:24 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:24 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:24 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841437 on destination Q:1997718144 could not be found in the store
      [10/Jan/2012:16:47:24 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841438 on destination T:798511184 could not be found in the store
      [10/Jan/2012:16:47:24 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841439 on destination T:798511184 could not be found in the store
      [10/Jan/2012:16:47:24 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242841437 on destination Q:1997718144 could not be found in the store
      [10/Jan/2012:16:47:24 PST] ERROR [B3013]: Destination Q:270042449 could not be found in the store
      [10/Jan/2012:16:47:26 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:26 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:26 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242846547 on destination Q:1722087962 could not be found in the store
      com.sun.messaging.jmq.jmsserver.util.BrokerException: Message 0-10.133.161.100-9090-1326242846547 on destination Q:1722087962 could not be found in the store
      at com.sun.messaging.jmq.jmsserver.persist.file.MsgStore.moveMessage(MsgStore.java:401)
      at com.sun.messaging.jmq.jmsserver.persist.file.FileStore.moveMessage(FileStore.java:896)
      at test.jmsserver.persist.MessageTest.moveMessage_test3(MessageTest.java:1383)
      at test.jmsserver.persist.MessageTest.runtest(MessageTest.java:102)
      at test.jmsserver.persist.StoreTest.runTest(StoreTest.java:121)
      at test.jmsserver.persist.StoreTest.main(StoreTest.java:487)
      [10/Jan/2012:16:47:28 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:28 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:29 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:29 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:31 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:31 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:31 PST] ERROR [B3008]: Message 0-10.133.161.100-9090-1326242849984 on destination Q:748022277 exists in the store already
      [10/Jan/2012:16:47:31 PST] ERROR [B3013]: Destination Q:1944390472 could not be found in the store
      [10/Jan/2012:16:47:33 PST] [B1059]: Resetting persistent store...
      [10/Jan/2012:16:47:33 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:33 PST] WARNING Existing file: incompleteTxnStorehas older cookie version than current version. Current version = 1. Original file version = 0
      [10/Jan/2012:16:47:35 PST] [B1060]: Loading persistent data...
      [10/Jan/2012:16:47:35 PST] Using built-in file-based persistent store: C:\temp\MQ5.0\binary\win32\opt\var\instances\persistapi.file\
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855000 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855015 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855016 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855017 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855031 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855032 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855033 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855034 on destination Q:1388340007 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855062 on destination Q:1856554643 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855078 on destination Q:1856554643 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855079 on destination Q:1856554643 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855000 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855015 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855016 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855017 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855031 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855032 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855033 on destination T:633513490 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855187 on destination Q:1388340007 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855188 on destination Q:1856554643 could not be found in the store
      [10/Jan/2012:16:47:35 PST] ERROR [B3007]: Message 0-10.133.161.100-9090-1326242855189 on destination Q:1856554643 could not be found in the store

        Activity

        Hide
        amyk added a comment - - edited

        Mathi had reported that he saw the problem while running MQ test list and reported that

        "This condition does not occur when run with the newTxnLog disabled."
        "The problem happens with 4.5 and 4.5.2 as well"

        talked to Mathi afterward, the broker was not "spinning" rather appeared that the newTxnLog was processing a lot of records which caused the broker startup slow but eventually the broker did startup and subsequent test appeared to fail due to timeout

        Show
        amyk added a comment - - edited Mathi had reported that he saw the problem while running MQ test list and reported that "This condition does not occur when run with the newTxnLog disabled." "The problem happens with 4.5 and 4.5.2 as well" talked to Mathi afterward, the broker was not "spinning" rather appeared that the newTxnLog was processing a lot of records which caused the broker startup slow but eventually the broker did startup and subsequent test appeared to fail due to timeout
        Hide
        mathim added a comment -

        this bug causes problems when running tonga tests on windows. tests run very very slow. Increasing the priority of the bug.

        Show
        mathim added a comment - this bug causes problems when running tonga tests on windows. tests run very very slow. Increasing the priority of the bug.
        Hide
        amyk added a comment - - edited

        Mathi, did you notice the problem when you run the putback.list ? Is it possible that you could provide a minimum test list by reducing the number of tests in the list that reproduces the problem ?

        Show
        amyk added a comment - - edited Mathi, did you notice the problem when you run the putback.list ? Is it possible that you could provide a minimum test list by reducing the number of tests in the list that reproduces the problem ?
        Hide
        mathim added a comment -

        i think putback.list will definitely reproduce this problem. when ever any test restarts the broker, the broker goes in loops

        Show
        mathim added a comment - i think putback.list will definitely reproduce this problem. when ever any test restarts the broker, the broker goes in loops
        Hide
        amyk added a comment - - edited

        The test persist/api/file creates its own broker instance with name "persistapi.file". So 1) if any other tests restart a broker it would not be the instance "persistapi.file"; 2) the test persist/api/file does not affect the default broker (the one running on port 7676) that other tests can restart; 3) The broker logging output shown in Description can only come from test persist/api/file

        The persist/api/file is a persist store internal API ('white box') test. The test

        1. Takes ~7.5min to run (on a Solaris 8x3325 MHz system)
        2. The ERROR [B3007] are expected by the test. For example, some sub-tests of the test remove messages from a destination, then verify attempting to retrieve or remove the same message again will get exception as expected - e.g. test outputs like following can be found in .eout file

        == Store.getInterestState:test 5:got BrokerException; test passed
        == exception: com.sun.messaging.jmq.jmsserver.util.BrokerException: [B3007]: Message 0-10.133.184.56-9090-1362561524324 on destination T:483311002 could not be found in the store
        ----------------

        According to Mathi, some of Mathi's comments above came from his early stage of testing MQ 5.0 Grizzly connection service which was caused by a different issue that has been fixed (see internal jira JMS-216).

        Change this issue to test and close. The putback.list (part of nightly.list) has been running on Windows for each nightly/milestone build. Mathi, please file a separate issue if you see problem other than test persist/api/file when running putback.list on your Windows system

        Show
        amyk added a comment - - edited The test persist/api/file creates its own broker instance with name "persistapi.file". So 1) if any other tests restart a broker it would not be the instance "persistapi.file"; 2) the test persist/api/file does not affect the default broker (the one running on port 7676) that other tests can restart; 3) The broker logging output shown in Description can only come from test persist/api/file The persist/api/file is a persist store internal API ('white box') test. The test 1. Takes ~7.5min to run (on a Solaris 8x3325 MHz system) 2. The ERROR [B3007] are expected by the test. For example, some sub-tests of the test remove messages from a destination, then verify attempting to retrieve or remove the same message again will get exception as expected - e.g. test outputs like following can be found in .eout file == Store.getInterestState:test 5:got BrokerException; test passed == exception: com.sun.messaging.jmq.jmsserver.util.BrokerException: [B3007] : Message 0-10.133.184.56-9090-1362561524324 on destination T:483311002 could not be found in the store ---------------- According to Mathi, some of Mathi's comments above came from his early stage of testing MQ 5.0 Grizzly connection service which was caused by a different issue that has been fixed (see internal jira JMS-216). Change this issue to test and close. The putback.list (part of nightly.list) has been running on Windows for each nightly/milestone build. Mathi, please file a separate issue if you see problem other than test persist/api/file when running putback.list on your Windows system

          People

          • Assignee:
            amyk
            Reporter:
            mathim
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: