OpenJPA
  1. OpenJPA
  2. OPENJPA-2204

NPE in JDBCStoreManager with Trace turned on

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.2.1, 2.3.0
    • Fix Version/s: 2.3.0
    • Component/s: jdbc, logging
    • Labels:
      None

      Description

      Reporting JIRA on behalf of a user without access to JIRAs...

      OK - nearly there! Presumably because we're no longer hooked in to the container, OpenJPA was pumping out its log messages to system out. I set openjpa.Log to "commons" and, as desired, it now sends trace to java.util.logging. The only problem is that, when I set trace to "openjpa.*=all" I get a NullPointerException (that isn't there when trace is turned off):

      [31/05/12 11:31:05:576 BST] 00000020 id= com.ibm.amc.AmcRuntimeException 3 printStackTrace java.lang.NullPointerException
      at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.find(JDBCStoreManager.java:979)
      at org.apache.openjpa.jdbc.meta.strats.UntypedPCValueHandler.toObjectValue(UntypedPCValueHandler.java:127)
      at org.apache.openjpa.jdbc.meta.strats.HandlerStrategies.loadObject(HandlerStrategies.java:207)
      at org.apache.openjpa.jdbc.meta.strats.HandlerCollectionTableFieldStrategy.loadElement(HandlerCollectionTableFieldStrategy.java:78)
      at org.apache.openjpa.jdbc.meta.strats.StoreCollectionFieldStrategy.load(StoreCollectionFieldStrategy.java:558)
      at org.apache.openjpa.jdbc.meta.FieldMapping.load(FieldMapping.java:934)
      at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:673)
      at com.ibm.ws.persistence.jdbc.kernel.WsJpaJDBCStoreManager.load(WsJpaJDBCStoreManager.java:130)
      at org.apache.openjpa.kernel.DelegatingStoreManager.load(DelegatingStoreManager.java:117)
      at org.apache.openjpa.kernel.ROPStoreManager.load(ROPStoreManager.java:78)
      at org.apache.openjpa.kernel.StateManagerImpl.loadFields(StateManagerImpl.java:3071)
      at org.apache.openjpa.kernel.StateManagerImpl.loadField(StateManagerImpl.java:3148)
      at org.apache.openjpa.kernel.StateManagerImpl.beforeAccessField(StateManagerImpl.java:1612)
      at org.apache.openjpa.kernel.StateManagerImpl.accessingField(StateManagerImpl.java:1597)
      at com.ibm.amc.server.action.impl.ActionStatusImpl.pcGetupdates(ActionStatusImpl.java)
      at com.ibm.amc.server.action.impl.ActionStatusImpl.getUpdates(ActionStatusImpl.java:206)

      This NPE looks to be due to dumping the parameters for the JDBCStoreManager.find():

      if (_log.isTraceEnabled())

      { _log.trace("find: oid="+oid+" "+vm.getDeclaredTypeMapping().getDescribedType()); }

      And, either vm or vm.getDeclaredTypeMapping() is null...

        Activity

        Kevin Sutter created issue -
        Hide
        Kevin Sutter added a comment -

        A quick review of the code shows that the vm parameter must not be null. This JDBCStoreManager.find() is called from three locations and all three locations have accessed the "vm" parameter prior to this find() operation. So, it's looking like it's the getDeclaredTypeMapping() that is returning null. I'll look at that next...

        Show
        Kevin Sutter added a comment - A quick review of the code shows that the vm parameter must not be null. This JDBCStoreManager.find() is called from three locations and all three locations have accessed the "vm" parameter prior to this find() operation. So, it's looking like it's the getDeclaredTypeMapping() that is returning null. I'll look at that next...
        Hide
        Kevin Sutter added a comment -

        Now that I look closer at the original exception and call stack, it looks like the NPE might actually be coming from attempting to dump the oid... We check if the oid is null at the beginning of the method, but maybe the toString() method on one of our oid types is causing the NPE...

        Show
        Kevin Sutter added a comment - Now that I look closer at the original exception and call stack, it looks like the NPE might actually be coming from attempting to dump the oid... We check if the oid is null at the beginning of the method, but maybe the toString() method on one of our oid types is causing the NPE...
        Kevin Sutter made changes -
        Field Original Value New Value
        Description Reporting JIRA on behalf of a user without access to JIRAs...

        OK - nearly there! Presumably because we're no longer hooked in to the container, OpenJPA was pumping out its log messages to system out. I set openjpa.Log to "commons" and, as desired, it now sends trace to java.util.logging. The only problem is that, when I set trace to "openjpa.*=all" I get a NullPointerException (that isn't there when trace isn't turned off):

        [31/05/12 11:31:05:576 BST] 00000020 id= com.ibm.amc.AmcRuntimeException 3 printStackTrace java.lang.NullPointerException
        at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.find(JDBCStoreManager.java:979)
        at org.apache.openjpa.jdbc.meta.strats.UntypedPCValueHandler.toObjectValue(UntypedPCValueHandler.java:127)
        at org.apache.openjpa.jdbc.meta.strats.HandlerStrategies.loadObject(HandlerStrategies.java:207)
        at org.apache.openjpa.jdbc.meta.strats.HandlerCollectionTableFieldStrategy.loadElement(HandlerCollectionTableFieldStrategy.java:78)
        at org.apache.openjpa.jdbc.meta.strats.StoreCollectionFieldStrategy.load(StoreCollectionFieldStrategy.java:558)
        at org.apache.openjpa.jdbc.meta.FieldMapping.load(FieldMapping.java:934)
        at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:673)
        at com.ibm.ws.persistence.jdbc.kernel.WsJpaJDBCStoreManager.load(WsJpaJDBCStoreManager.java:130)
        at org.apache.openjpa.kernel.DelegatingStoreManager.load(DelegatingStoreManager.java:117)
        at org.apache.openjpa.kernel.ROPStoreManager.load(ROPStoreManager.java:78)
        at org.apache.openjpa.kernel.StateManagerImpl.loadFields(StateManagerImpl.java:3071)
        at org.apache.openjpa.kernel.StateManagerImpl.loadField(StateManagerImpl.java:3148)
        at org.apache.openjpa.kernel.StateManagerImpl.beforeAccessField(StateManagerImpl.java:1612)
        at org.apache.openjpa.kernel.StateManagerImpl.accessingField(StateManagerImpl.java:1597)
        at com.ibm.amc.server.action.impl.ActionStatusImpl.pcGetupdates(ActionStatusImpl.java)
        at com.ibm.amc.server.action.impl.ActionStatusImpl.getUpdates(ActionStatusImpl.java:206)

        This NPE looks to be due to dumping the parameters for the JDBCStoreManager.find():

                if (_log.isTraceEnabled()) {
                    _log.trace("find: oid="+oid+" "+vm.getDeclaredTypeMapping().getDescribedType());
                }

        And, either vm or vm.getDeclaredTypeMapping() is null...
        Reporting JIRA on behalf of a user without access to JIRAs...

        OK - nearly there! Presumably because we're no longer hooked in to the container, OpenJPA was pumping out its log messages to system out. I set openjpa.Log to "commons" and, as desired, it now sends trace to java.util.logging. The only problem is that, when I set trace to "openjpa.*=all" I get a NullPointerException (that isn't there when trace is turned off):

        [31/05/12 11:31:05:576 BST] 00000020 id= com.ibm.amc.AmcRuntimeException 3 printStackTrace java.lang.NullPointerException
        at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.find(JDBCStoreManager.java:979)
        at org.apache.openjpa.jdbc.meta.strats.UntypedPCValueHandler.toObjectValue(UntypedPCValueHandler.java:127)
        at org.apache.openjpa.jdbc.meta.strats.HandlerStrategies.loadObject(HandlerStrategies.java:207)
        at org.apache.openjpa.jdbc.meta.strats.HandlerCollectionTableFieldStrategy.loadElement(HandlerCollectionTableFieldStrategy.java:78)
        at org.apache.openjpa.jdbc.meta.strats.StoreCollectionFieldStrategy.load(StoreCollectionFieldStrategy.java:558)
        at org.apache.openjpa.jdbc.meta.FieldMapping.load(FieldMapping.java:934)
        at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:673)
        at com.ibm.ws.persistence.jdbc.kernel.WsJpaJDBCStoreManager.load(WsJpaJDBCStoreManager.java:130)
        at org.apache.openjpa.kernel.DelegatingStoreManager.load(DelegatingStoreManager.java:117)
        at org.apache.openjpa.kernel.ROPStoreManager.load(ROPStoreManager.java:78)
        at org.apache.openjpa.kernel.StateManagerImpl.loadFields(StateManagerImpl.java:3071)
        at org.apache.openjpa.kernel.StateManagerImpl.loadField(StateManagerImpl.java:3148)
        at org.apache.openjpa.kernel.StateManagerImpl.beforeAccessField(StateManagerImpl.java:1612)
        at org.apache.openjpa.kernel.StateManagerImpl.accessingField(StateManagerImpl.java:1597)
        at com.ibm.amc.server.action.impl.ActionStatusImpl.pcGetupdates(ActionStatusImpl.java)
        at com.ibm.amc.server.action.impl.ActionStatusImpl.getUpdates(ActionStatusImpl.java:206)

        This NPE looks to be due to dumping the parameters for the JDBCStoreManager.find():

                if (_log.isTraceEnabled()) {
                    _log.trace("find: oid="+oid+" "+vm.getDeclaredTypeMapping().getDescribedType());
                }

        And, either vm or vm.getDeclaredTypeMapping() is null...
        Hide
        Kevin Sutter added a comment -

        Reproduced the problem by turning on Trace for the org.apache.openjpa.persistence.graph.TestPersistentGraph junit testcase. My first guess was correct – the getDeclaredTypeMapping() was returning null and causing the NPE for the trace string. I modified the prep for this trace string and all works now. I'll correct in Trunk and let other service stream owners pull it back, if desired.

        Show
        Kevin Sutter added a comment - Reproduced the problem by turning on Trace for the org.apache.openjpa.persistence.graph.TestPersistentGraph junit testcase. My first guess was correct – the getDeclaredTypeMapping() was returning null and causing the NPE for the trace string. I modified the prep for this trace string and all works now. I'll correct in Trunk and let other service stream owners pull it back, if desired.
        Kevin Sutter made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Kevin Sutter [ kwsutter ]
        Fix Version/s 2.3.0 [ 12319463 ]
        Resolution Fixed [ 1 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        4d 12h 36m 1 Kevin Sutter 05/Jun/12 03:23

          People

          • Assignee:
            Kevin Sutter
            Reporter:
            Kevin Sutter
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development