Topic
  • 8 replies
  • Latest Post - ‏2012-10-29T16:45:41Z by SystemAdmin
SystemAdmin
SystemAdmin
590 Posts

Pinned topic Liberty Profile and JPA

‏2012-10-24T19:36:35Z |
Hi,

I am using OpenJPA with Liberty profile and DB2 and I see a lot of ffdc logs created with the following error, even though the application is running fine:
------Start of DE processing------ = 10/24/12 12:06:08:861 MST
Exception = com.ibm.db2.jcc.am.SqlException
Source = com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet.findColumn
probeid = 384
Stack Dump = com.ibm.db2.jcc.am.SqlException: jcc1015010300http://4.14.113 Invalid parameter: Unknown column name TIME_ZONE. ERRORCODE=-4460, SQLSTATE=null
at com.ibm.db2.jcc.am.ed.a(ed.java:661)
at com.ibm.db2.jcc.am.ed.a(ed.java:60)
at com.ibm.db2.jcc.am.ed.a(ed.java:103)
at com.ibm.db2.jcc.am.fb.a(fb.java:2121)
at com.ibm.db2.jcc.am.ResultSet.findColumnX(ResultSet.java:1932)
at com.ibm.db2.jcc.am.ResultSet.findColumn(ResultSet.java:1921)
at com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet.findColumn(WSJdbcResultSet.java:421)
at org.apache.openjpa.lib.jdbc.DelegatingResultSet.findColumn(DelegatingResultSet.java:277)
at org.apache.openjpa.jdbc.sql.ResultSetResult.findObject(ResultSetResult.java:509)
at org.apache.openjpa.jdbc.sql.ResultSetResult.translate(ResultSetResult.java:497)
at org.apache.openjpa.jdbc.sql.ResultSetResult.containsInternal(ResultSetResult.java:240)
at org.apache.openjpa.jdbc.sql.AbstractResult.contains(AbstractResult.java:199)
at org.apache.openjpa.jdbc.meta.strats.StringFieldStrategy.load(StringFieldStrategy.java:159)
at org.apache.openjpa.jdbc.meta.FieldMapping.load(FieldMapping.java:928)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:1114)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:1062)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.initializeState(JDBCStoreManager.java:409)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.initialize(JDBCStoreManager.java:304)
at org.apache.openjpa.kernel.DelegatingStoreManager.initialize(DelegatingStoreManager.java:112)
at org.apache.openjpa.kernel.ROPStoreManager.initialize(ROPStoreManager.java:57)
at org.apache.openjpa.kernel.BrokerImpl.initialize(BrokerImpl.java:1038)
at org.apache.openjpa.kernel.BrokerImpl.find(BrokerImpl.java:996)
at org.apache.openjpa.kernel.BrokerImpl.find(BrokerImpl.java:918)
at org.apache.openjpa.jdbc.kernel.JDBCStoreManager.load(JDBCStoreManager.java:1036)
at org.apache.openjpa.jdbc.kernel.GenericResultObjectProvider.getResultObject(GenericResultObjectProvider.java:93)
at org.apache.openjpa.lib.rop.EagerResultList.<init>(EagerResultList.java:36)
at org.apache.openjpa.kernel.QueryImpl.toResult(QueryImpl.java:1251)
at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:1007)
at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:863)
at org.apache.openjpa.kernel.QueryImpl.execute(QueryImpl.java:794)
at org.apache.openjpa.kernel.DelegatingQuery.execute(DelegatingQuery.java:542)
at org.apache.openjpa.persistence.QueryImpl.execute(QueryImpl.java:286)
at org.apache.openjpa.persistence.QueryImpl.getResultList(QueryImpl.java:302)
Couple of things I would like to mention:

1. The TIME_ZONE is a valid column in the table being accessed.
2. These ffdc logs are created only once for the specific code being run.

I initially thought that this might be due to JBBC 4.0 specific ResultSetMetaData.getColumnName and ResultSetMetaData.getColumnLabel changes, however, I did set the useJDBC4ColumnNameAndLabelSemantics=2 on datasource properties, but it has no effect. I also tried with a previous JDBC 3.0 driver, but these ffdc exceptions won't stop.

I do not have this same problem in WAS 8.0, with same db2 driver.

Any idea what's going on? Thanks in advance.
  • sutter
    sutter
    6 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-24T19:57:37Z  
    Hi rakesh_in,
    We have not seen this particular issue in any of our testing. From a functional viewpoint, I can tell you that as part of JPA's processing of the executed query, JPA is attempting to validate the data against the columns in the database. For whatever reason, JPA's attempt to find out column TIME_ZONE is not successful. The WebSphere JDBC adapter receives this exception and logs an ffdc record. (I have verified that this is not new behavior for 8.5 or Liberty.)

    This exception must not be affecting the rest of the JPA processing if no other messages are being logged and your application seems to work okay.

    Just to verify, have you looked at your SystemOut and SystemErr logs to see if any messages are getting logged related to this ffdc activity?

    Since it sounds like you are interested in getting to the bottom of this, I would suggest opening a PMR so that the proper resolution can be discovered.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
  • SystemAdmin
    SystemAdmin
    590 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-24T20:10:35Z  
    • sutter
    • ‏2012-10-24T19:57:37Z
    Hi rakesh_in,
    We have not seen this particular issue in any of our testing. From a functional viewpoint, I can tell you that as part of JPA's processing of the executed query, JPA is attempting to validate the data against the columns in the database. For whatever reason, JPA's attempt to find out column TIME_ZONE is not successful. The WebSphere JDBC adapter receives this exception and logs an ffdc record. (I have verified that this is not new behavior for 8.5 or Liberty.)

    This exception must not be affecting the rest of the JPA processing if no other messages are being logged and your application seems to work okay.

    Just to verify, have you looked at your SystemOut and SystemErr logs to see if any messages are getting logged related to this ffdc activity?

    Since it sounds like you are interested in getting to the bottom of this, I would suggest opening a PMR so that the proper resolution can be discovered.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
    Thanks Kevin for quick response.
    As far as I can see, there is no impact on the application. It is just that these logs are annoying and we would prefer to run exception free.
    There is nothing in console.log but the messages.log has statements like this:

    10/24/12 12:06:07:767 MST 00000068 com.ibm.ws.logging.internal.impl.Incident I FFDC1015I: An FFDC Incident has been created: "com.ibm.db2.jcc.am.SqlException: jcc1015010300http://4.14.113 Invalid parameter: Unknown column name TIME_ZONE. ERRORCODE=-4460, SQLSTATE=null com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet.findColumn 384" at ffdc_12.10.24_12.06.07.0.log

    Should I open a DB2 PMR on this or a Liberty Profile one?
  • sutter
    sutter
    6 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-24T20:22:43Z  
    Thanks Kevin for quick response.
    As far as I can see, there is no impact on the application. It is just that these logs are annoying and we would prefer to run exception free.
    There is nothing in console.log but the messages.log has statements like this:

    10/24/12 12:06:07:767 MST 00000068 com.ibm.ws.logging.internal.impl.Incident I FFDC1015I: An FFDC Incident has been created: "com.ibm.db2.jcc.am.SqlException: jcc1015010300http://4.14.113 Invalid parameter: Unknown column name TIME_ZONE. ERRORCODE=-4460, SQLSTATE=null com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet.findColumn 384" at ffdc_12.10.24_12.06.07.0.log

    Should I open a DB2 PMR on this or a Liberty Profile one?
    The PMR would be against WebSphere. Since I would guess the same issue would apply outside of the Liberty profile, you could request it to go against the JPA queue.

    Before we go that route though, could you also post your persistence.xml? Also, if you could post the specific JPQL query that is being executed? Not sure if I can get anything out of them, but it's worth a shot.

    Since you ran with previous releases without an issue, there must be some additional error checking being performed. But, nobody seems to know what or why just yet...

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
  • SystemAdmin
    SystemAdmin
    590 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-26T06:01:02Z  
    • sutter
    • ‏2012-10-24T20:22:43Z
    The PMR would be against WebSphere. Since I would guess the same issue would apply outside of the Liberty profile, you could request it to go against the JPA queue.

    Before we go that route though, could you also post your persistence.xml? Also, if you could post the specific JPQL query that is being executed? Not sure if I can get anything out of them, but it's worth a shot.

    Since you ran with previous releases without an issue, there must be some additional error checking being performed. But, nobody seems to know what or why just yet...

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
    I think I have narrowed down the problem. Here's the situation: When we have defined NamedNativeQuery and the query contains let's say 4 columns. Now if we have a resultClass associated to that query which is simply a POJO having let's say five fields, four of which are mapped to the 4 columns of the NamedNativeQuery, but the fifth one is not (after all it is POJO), the JPA tries to retrieve column index for that fifth field, and that throws this exception. The JPA code though ignores this exception, returning zero for column index, but ffdc captures it nonetheless.

    Here's the code fragment from org.apache.openjpa.jdbc.sql.ResultSetResult.java
    /**
    * Return the 1-based result set index for the given column or id, or a
    * non-positive number if the column is not contained in this result.
    */
    protected int findObject(Object obj, Joins joins)
    throws SQLException {
    try {
    String s1 = obj.toString();
    DBIdentifier sName = DBIdentifier.newColumn(obj.toString());
    return getResultSet().findColumn(_dict.convertSchemaCase(sName));
    } catch (SQLException se) {
    _dict.log.trace(se.getMessage());
    return 0;
    }
    }

    Is there anything that can be done here to tell ffdc to not worry about it, or any better solution (besides mapping the fifth field which I may not want to) ?
  • sutter
    sutter
    6 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-26T13:30:56Z  
    I think I have narrowed down the problem. Here's the situation: When we have defined NamedNativeQuery and the query contains let's say 4 columns. Now if we have a resultClass associated to that query which is simply a POJO having let's say five fields, four of which are mapped to the 4 columns of the NamedNativeQuery, but the fifth one is not (after all it is POJO), the JPA tries to retrieve column index for that fifth field, and that throws this exception. The JPA code though ignores this exception, returning zero for column index, but ffdc captures it nonetheless.

    Here's the code fragment from org.apache.openjpa.jdbc.sql.ResultSetResult.java
    /**
    * Return the 1-based result set index for the given column or id, or a
    * non-positive number if the column is not contained in this result.
    */
    protected int findObject(Object obj, Joins joins)
    throws SQLException {
    try {
    String s1 = obj.toString();
    DBIdentifier sName = DBIdentifier.newColumn(obj.toString());
    return getResultSet().findColumn(_dict.convertSchemaCase(sName));
    } catch (SQLException se) {
    _dict.log.trace(se.getMessage());
    return 0;
    }
    }

    Is there anything that can be done here to tell ffdc to not worry about it, or any better solution (besides mapping the fifth field which I may not want to) ?
    Excellent debugging effort, rakesh_in! Thanks.

    Areyou using the @SqlResultSetMapping annotation to describe the expected results and mappings from your NamedNativeQuery? Is your "resultClass" an entity pojo, or a non-entity pojo? The results from a query are normally entities, but they are not limited to this.

    The code snippet you provided is what JPA is doing to process the ResultSet, but the ffdc entry is coming from further up the stack in the JDBC layer. The JDBC code is interacting with the database asking about the column and automatically logs the error when the invocation fails -- even though JPA doesn't care if the call fails or not.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
  • SystemAdmin
    SystemAdmin
    590 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-26T19:03:24Z  
    • sutter
    • ‏2012-10-26T13:30:56Z
    Excellent debugging effort, rakesh_in! Thanks.

    Areyou using the @SqlResultSetMapping annotation to describe the expected results and mappings from your NamedNativeQuery? Is your "resultClass" an entity pojo, or a non-entity pojo? The results from a query are normally entities, but they are not limited to this.

    The code snippet you provided is what JPA is doing to process the ResultSet, but the ffdc entry is coming from further up the stack in the JDBC layer. The JDBC code is interacting with the database asking about the column and automatically logs the error when the invocation fails -- even though JPA doesn't care if the call fails or not.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
    I am not using @SqlResultSetMapping annotation. Just the resultClass which is defined in persistent.xml.

    However, given your question, I tried to use the @SqlResultSetMapping, like the following:
    @SqlResultSetMapping(name="testnamed1", entities={
    @EntityResult(entityClass=my.pkg.NQTest.class, fields = {
    @FieldResult(name="col1", column="column_1"),
    @FieldResult(name="col2", column="column_2"),
    @FieldResult(name="col3", column="column_3"),
    @FieldResult(name="col4", column="column_4")

    })
    })
    @NamedNativeQuery
    (
    name="testnamed1",
    query="select column_1, column_2, column_3, column_4 from .....
    resultSetMapping="testnamed1"
    )

    NQTest is the class containing five fields. Please note that col5 is not mapped to anything and is not retrieved in the query. However, when I run this using usual em.createNamedQuery("testnamed1"), I still get the same db2 error in ffdc: Unknown column name 'column_5'.
  • sutter
    sutter
    6 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-29T14:28:44Z  
    I am not using @SqlResultSetMapping annotation. Just the resultClass which is defined in persistent.xml.

    However, given your question, I tried to use the @SqlResultSetMapping, like the following:
    @SqlResultSetMapping(name="testnamed1", entities={
    @EntityResult(entityClass=my.pkg.NQTest.class, fields = {
    @FieldResult(name="col1", column="column_1"),
    @FieldResult(name="col2", column="column_2"),
    @FieldResult(name="col3", column="column_3"),
    @FieldResult(name="col4", column="column_4")

    })
    })
    @NamedNativeQuery
    (
    name="testnamed1",
    query="select column_1, column_2, column_3, column_4 from .....
    resultSetMapping="testnamed1"
    )

    NQTest is the class containing five fields. Please note that col5 is not mapped to anything and is not retrieved in the query. However, when I run this using usual em.createNamedQuery("testnamed1"), I still get the same db2 error in ffdc: Unknown column name 'column_5'.
    Hi rakesh_in,
    When using a SqlResultSetMapping annotation (or xml element), I would have expected that that fields not referenced would have been ignored and, thus, avoid the ffdc entry that you have identified. Maybe there's something else unique with your scenario, but I thought this was going to get around your issue.

    If you want to pursue removing this ffdc entry, I would now suggest opening a PMR to address the problem. Suggest routing the PMR to the JPA L3 queue. Also, reference this forum discussion in the PMR so that the background doesn't have to be repeated. My support team should be able to help with a more complete diagnosis. Either I missed something simple during the debug discussions we've had, or there's a bug and JPA doesn't have to reference the columns that were not referenced by your query.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
  • SystemAdmin
    SystemAdmin
    590 Posts

    Re: Liberty Profile and JPA

    ‏2012-10-29T16:45:41Z  
    • sutter
    • ‏2012-10-29T14:28:44Z
    Hi rakesh_in,
    When using a SqlResultSetMapping annotation (or xml element), I would have expected that that fields not referenced would have been ignored and, thus, avoid the ffdc entry that you have identified. Maybe there's something else unique with your scenario, but I thought this was going to get around your issue.

    If you want to pursue removing this ffdc entry, I would now suggest opening a PMR to address the problem. Suggest routing the PMR to the JPA L3 queue. Also, reference this forum discussion in the PMR so that the background doesn't have to be repeated. My support team should be able to help with a more complete diagnosis. Either I missed something simple during the debug discussions we've had, or there's a bug and JPA doesn't have to reference the columns that were not referenced by your query.

    Thanks,
    Kevin Sutter, JPA Architect, IBM WebSphere
    Thanks Kevin for your help on this. I will open the PMR and request routing as you mentioned.