6 Replies Latest reply on Jan 4, 2007 3:55 AM by pat_m0le

    Incorrect binding of variables

      I am getting errors when running a EntityManager.merge() operation. Checking the log files reveals that hibernate is not reading the correct values from the database.

      I copied and pasted the query from the log files into the mysql query browser and ran it, and the correct results were shown.

      Fo for some reason, it ignores the correct results that were returned and overrides it with some random value (I can't figure out where it's coming from).

      Here's the log file chunk.


      2005-10-03 10:09:21,669 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] GETTING NEW EntityManager
      2005-10-03 10:09:21,669 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] logLivedSession.get() was NULL
      2005-10-03 10:09:21,669 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] LONG LIVED NOT FOUND
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4621715708596224
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [par.Blog#23]
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [par.Blog#23]
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [par.Blog#23]
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [par.Blog#23]
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.loader.Loader] loading entity: [par.Blog#23]
      2005-10-03 10:09:21,669 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2005-10-03 10:09:21,679 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
      2005-10-03 10:09:21,679 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=root, password=--hidden--}
      2005-10-03 10:09:21,729 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
      2005-10-03 10:09:21,729 DEBUG [org.hibernate.SQL] select blog0_.blogId as blogId0_5_, blog0_.message as message0_5_, blog0_.header as header0_5_, blog0_.userid as userid0_5_, blog0_.dateCreated as dateCrea4_0_5_, blog0_.numViews as numViews0_5_, user1_.userid as userid20_0_, user1_.displayName as displayN2_20_0_, user1_.emailAddress as emailAdd3_20_0_, user1_.dateOfBirth as dateOfBi4_20_0_, user1_.gender as gender20_0_, user1_.firstName as firstName20_0_, user1_.lastName as lastName20_0_, user1_.fips as fips20_0_, user1_.postalCode as postalCode20_0_, locationco2_.fips as fips8_1_, locationco2_.country as country8_1_, locationzi3_.zipcode as zipcode10_2_, locationzi3_.stateId as stateId10_2_, locationzi3_.fips as fips10_2_, locationzi3_.city as city10_2_, locationzi3_.latitude as latitude10_2_, locationzi3_.longitude as longitude10_2_, locationst4_.stateId as stateId9_3_, locationst4_.name as name9_3_, locationst4_.abbreviation as abbrevia3_9_3_, locationco5_.fips as fips8_4_, locationco5_.country as country8_4_ from blog blog0_ inner join user user1_ on blog0_.userid=user1_.userid left outer join location_country locationco2_ on user1_.fips=locationco2_.fips left outer join location_zipcode locationzi3_ on user1_.postalCode=locationzi3_.zipcode left outer join location_state locationst4_ on locationzi3_.stateId=locationst4_.stateId left outer join location_country locationco5_ on locationzi3_.fips=locationco5_.fips where blog0_.blogId=?
      2005-10-03 10:09:21,739 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.type.IntegerType] binding '23' to parameter: 1
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.loader.Loader] processing result set
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.loader.Loader] result set row: 0
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.type.IntegerType] returning '1' as column: userid20_0_
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.type.StringType] returning 'US' as column: fips8_1_
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.type.StringType] returning '90210' as column: zipcode10_2_
      2005-10-03 10:09:21,759 DEBUG [org.hibernate.type.IntegerType] returning '262' as column: stateId9_3_
      ... more values
      


      The last value shown above '262' is incorrect. I ran the query shown above it in the MySql Query Browser and got the correct value of '6'. So I do not know where this is coming from, or where to look to solve this.

        • 1. Re: Incorrect binding of variables

          I should point out that the error is that I get a 'no row found'
          http://www.hibernate.org/206.html

          Obviously it is because the row does not exist, because it generating an incorrect row number instead of using what was returned in the query.

          • 2. Re: Incorrect binding of variables

            Yeah, somethings definitely wrong in the hibernate classes.

            I did a System.out.println when the bean gets set, and the correct value seems to be put there. However a few lines later, it completely ignores it and sets some random value instead.

            2005-10-03 15:56:17,116 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2005-10-03 15:56:17,116 DEBUG [org.hibernate.SQL] select locationzi0_.zipcode as zipcode10_2_, locationzi0_.stateId as stateId10_2_, locationzi0_.fips as fips10_2_, locationzi0_.city as city10_2_, locationzi0_.latitude as latitude10_2_, locationzi0_.longitude as longitude10_2_, locationst1_.stateId_jd as stateId1_9_0_, locationst1_.name as name9_0_, locationst1_.abbreviation as abbrevia3_9_0_, locationco2_.fips as fips8_1_, locationco2_.country as country8_1_ from location_zipcode locationzi0_ left outer join location_state locationst1_ on locationzi0_.stateId=locationst1_.stateId_jd left outer join location_country locationco2_ on locationzi0_.fips=locationco2_.fips where locationzi0_.zipcode=?
            2005-10-03 15:56:17,116 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.type.StringType] binding '21236' to parameter: 1
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.loader.Loader] processing result set
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.loader.Loader] result set row: 0
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.type.IntegerType] returning '24' as column: stateId1_9_0_
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.type.StringType] returning 'US' as column: fips8_1_
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[par.LocationState#24], EntityKey[par.LocationCountry#US], EntityKey[par.LocationZipcode#21236]
            2005-10-03 15:56:17,126 INFO [STDOUT] Setting state id to: 24 from 0
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [par.LocationState#24]
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [par.LocationState#24]
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.type.StringType] returning 'Maryland' as column: name9_0_
            2005-10-03 15:56:17,126 DEBUG [org.hibernate.type.StringType] returning 'MD' as column: abbrevia3_9_0_
            2005-10-03 15:56:17,136 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [par.LocationZipcode#21236]
            2005-10-03 15:56:17,136 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [par.LocationZipcode#21236]
            2005-10-03 15:56:17,136 DEBUG [org.hibernate.type.IntegerType] returning '280' as column: stateId10_2_
            ...
            

            The last line '280' should be '24'. You can even see a few lines up when it correctly uses it 'par.LocationState#24'. However, after it gets set to '280' it bombs because the id is not correct.

            The error is shown below
            2005-10-03 15:56:17,136 INFO [org.hibernate.event.def.DefaultLoadEventListener] Error performing load command
            org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [par.LocationState#280]
             at org.hibernate.ObjectNotFoundException.throwIfNull(ObjectNotFoundException.java:27)
             at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:128)
             at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:177)
             at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:87)
             at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:781)
             at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:753)
             at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:266)
             at org.hibernate.type.EntityType.resolve(EntityType.java:303)
             at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:113)
             at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
             at org.hibernate.loader.Loader.doQuery(Loader.java:717)
             at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
             at org.hibernate.loader.Loader.loadEntity(Loader.java:1782)
             at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:47)
             at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:41)
             at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:2712)
             at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:365)
             at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:346)
             at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:123)
             at org.hibernate.event.def.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:177)
             at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:87)
             at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:781)
             at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:753)
             at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:266)
             at org.hibernate.type.EntityType.resolve(EntityType.java:303)
             at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:113)
             at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
             at org.hibernate.loader.Loader.doQuery(Loader.java:717)
             at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
             at org.hibernate.loader.Loader.doList(Loader.java:2147)
             at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2026)
             at org.hibernate.loader.Loader.list(Loader.java:2021)
             at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:369)
             at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:296)
             at org.hibernate.impl.SessionImpl.list(SessionImpl.java:992)
             at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
             at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:38)
            


            If it helps here's my setup
            MySql 5.0.13
            JBoss 4.0.3 RC2 & the EJB update released a week or so ago
            WinXP SP2

            Let me know if you need anything else.



            • 3. Re: Incorrect binding of variables

              Actually, the part of the log file I left out actually shows where it gets confused. I reposted the log show above, now with the middle part.

              You can see it getting confused starting between the
              org.hibernate.engine.TwoPhaseLoad
              and
              org.hibernate.event.def.DefaultLoadEventListener
              classes

              2005-10-03 16:08:12,045 DEBUG [org.hibernate.SQL] select locationzi0_.zipcode as zipcode74_2_, locationzi0_.stateId as stateId74_2_, locationzi0_.fips as fips74_2_, locationzi0_.city as city74_2_, locationzi0_.latitude as latitude74_2_, locationzi0_.longitude as longitude74_2_, locationst1_.stateId_jd as stateId1_73_0_, locationst1_.name as name73_0_, locationst1_.abbreviation as abbrevia3_73_0_, locationco2_.fips as fips72_1_, locationco2_.country as country72_1_ from location_zipcode locationzi0_ left outer join location_state locationst1_ on locationzi0_.stateId=locationst1_.stateId_jd left outer join location_country locationco2_ on locationzi0_.fips=locationco2_.fips where locationzi0_.zipcode=?
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.type.StringType] binding '21236' to parameter: 1
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.loader.Loader] processing result set
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.loader.Loader] result set row: 0
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.type.IntegerType] returning '24' as column: stateId1_73_0_
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.type.StringType] returning 'US' as column: fips72_1_
              2005-10-03 16:08:12,045 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[par.LocationState#24], EntityKey[par.LocationCountry#US], EntityKey[par.LocationZipcode#21236]
              2005-10-03 16:08:12,045 INFO [STDOUT] Setting state id to: 24 from 0
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [par.LocationState#24]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [par.LocationState#24]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.StringType] returning 'Maryland' as column: name73_0_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.StringType] returning 'MD' as column: abbrevia3_73_0_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] Initializing object from ResultSet: [par.LocationZipcode#21236]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Hydrating entity: [par.LocationZipcode#21236]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.IntegerType] returning '280' as column: stateId74_2_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.StringType] returning 'US' as column: fips74_2_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.StringType] returning 'NOTTINGHAM' as column: city74_2_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.FloatType] returning '39.3921' as column: latitude74_2_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.FloatType] returning '-76.4893' as column: longitude74_2_
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] done processing result set (1 rows)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] total objects hydrated: 2
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [par.LocationState#24]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [par.LocationState#24]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [par.LocationZipcode#21236]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] loading entity: [par.LocationState#280]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] attempting to resolve: [par.LocationState#280]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.event.def.DefaultLoadEventListener] object not resolved in any cache: [par.LocationState#280]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Fetching entity: [par.LocationState#280]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] loading entity: [par.LocationState#280]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.SQL] select locationst0_.stateId_jd as stateId1_73_0_, locationst0_.name as name73_0_, locationst0_.abbreviation as abbrevia3_73_0_ from location_state locationst0_ where locationst0_.stateId_jd=?
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.type.IntegerType] binding '280' to parameter: 1
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] processing result set
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] done processing result set (0 rows)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.jdbc.ConnectionManager] closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] total objects hydrated: 0
              2005-10-03 16:08:12,065 DEBUG [org.hibernate.loader.Loader] done entity load
              2005-10-03 16:08:12,065 INFO [org.hibernate.event.def.DefaultLoadEventListener] Error performing load command
              org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [par.LocationState#280]
               at org.hibernate.ObjectNotFoundException.throwIfNull(ObjectNotFoundException.java:27)
               at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:128)


              • 4. Re: Incorrect binding of variables

                OK, I figured out what caused it and a temporary workaround.

                I am using MySql 5.0.13.

                1. What caused it.
                I had 2 tables. The first one had a primary key that was a tinyint(3)
                The second table had a foreign key to the first table that was also a tinyint(3).

                Apparently, something in the hibernate code does not like tinyint(3). I don't know if it was because it was a primary key for a table, or a foreign key to a table or both.

                2. Temporary workaround. Change both tables to be integer instead of tinyint(3).

                Should I go ahead and file this as a bug, or will this be taken care of here?

                • 5. Re: Incorrect binding of variables

                  bump

                  • 6. Re: Incorrect binding of variables
                    pat_m0le

                    i've got the same problem with a varchar primary key, now with an integer primary key it works