More fun with Map properties

[Eric Sword]

This is probably one of the strangest bugs I have ever seen.  I have a domain object that has two properties which are maps - options and params.  It also has several other normal props that are strings and then a few transient props whose values are derived from some of the possible values in the options map.  (This is to handle doing some type resolution on the options since all options are stored as strings but I want a quick way to access some as booleans.  I know, it's complicated...)

Interacting with the domain object has worked fine since grails 1.1.  Since upgrading to 2.0.3,  every once in a while when we run the app (either as a war in tomcat or standalone from the interactive shell), the values of the data in the options and params map get completely messed up when an object is load from a GORM call (either get or list).  One of two things happens:

1) The data isn't there at all, or
2) The keys of the maps are fine, but the values all become the id of the domain object itself

I know this is hard to believe, but we've seen it on multiple systems.  The data in the DB is fine.  Nothing has been written to it.  If we stop the app and restart, the data is loaded correctly.  It's just that about one in every 20 launches, instead of this (the object as JSON):

    {
        "id":273,
        "name":"bluemarble",
        "description":"",
        "resolvedUrl":"http://192.168.56.90:8080/geoserver/wms",
        "resolvedLayerId":"topp:bluemarble",
        "isBaseLayer":true,
        "type":{
            "enumType":"com.xxx.LayerType",
            "name":"WMS"
        },
        "params":{
            "srs":"EPSG:5346"
        },
        "options":{
            "isBaseLayer":"true"
        },
        "dateCreated":"2012-05-02T19:41:04Z",
        "lastUpdated":"2012-05-07T19:07:43Z",
        "mapServer":{
            "id":5
        }
    },

we get this:

    {
        "id":273,
        "name":"bluemarble",
        "description":"",
        "resolvedUrl":"http://192.168.56.90:8080/geoserver/wms",
        "resolvedLayerId":"topp:bluemarble",
        "isBaseLayer":true,
        "type":{
            "enumType":"com.saic.hub.LayerType",
            "name":"WMS"
        },
        "params":{
            "srs":"273"
        },
        "options":{
            "isBaseLayer":"273"
        },
        "dateCreated":"2012-05-02T19:41:04Z",
        "lastUpdated":"2012-05-07T19:07:43Z",
        "mapServer":{
            "id":5
        }
    },

In this case, the data is listed as the id of the object.  We have seen other cases where the values aren't there at all.

I know this is a long shot, but does anyone have any clue about why this could be happening?  It's driving me nuts, especially since it's impossible to reproduce on command.

tx,

e

[Eric Sword]

I've traced the error to the hibernate-generated sql statement.  The domain object looks something like this:

class MapLayer {
    String name
    ...other props...
    Map params = [:]
    Map options = [:]
}

Normally, the statements to retrieve the values of the params and options properties look like this:

DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select params0_.params as params22_0_, params0_.params_elt as params3_0_, params0_.params_idx as params2_0_ from map_layer_params params0_ where params0_.params=?
DEBUG [main] org.hibernate.SQL.logStatement[ 111]:logStatement[ 111]: select options0_.options as options22_0_, options0_.options_elt as options3_0_, options0_.options_idx as options2_0_ from map_layer_options options0_ where options0_.options=?

However, sometimes when I run the app, the generated statements look like this:

DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select params0_.params as params3_0_, params0_.params_idx as params2_0_ from map_layer_params params0_ where params0_.params=?
DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select options0_.options as options3_0_, options0_.options_idx as options2_0_ from map_layer_options options0_ where options0_.options=?

The clauses for the params_elt and options_elt columns (which correspond to the actual value for an entry in the maps) are missing.  I have also seen it where the _idx clauses are missing instead though I haven't captured the logs for that.

This behavior seems to happen about one out of every four or five launches of the app on average, though it can go as many as 20 launches.  If it is going to fail (i.e. generate the wrong sql), it does it the first time a MapLayer object is retrieved and will fail on all subsequent queries.  

Any ideas for why the SQL could be getting generated incorrectly?

e

[ideasculptor]

Can you reproduce the problem if you explicitly name each of the columns In a mapping section of the domain object? I'm on my phone in a restaurant or I'd give you the syntax, as it took me a while to guess it since it isn't documented anywhere. I ask because I haven't seen this issue in my one domain object with map properties, so it seems likely that your problem is related to having multiple map properties or my lack of a problem is because I specify table name, index, key, and value columns explicitly.

Sent from my iPhone

On May 8, 2012, at 4:42 PM, Eric Sword <[hidden email]> wrote:

> I've traced the error to the hibernate-generated sql statement.  The domain
> object looks something like this:
>
> class MapLayer {
>    String name
>    ...other props...
>    Map params = [:]
>    Map options = [:]
> }
>
> Normally, the statements to retrieve the values of the params and options
> properties look like this:
>
> DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select params0_.params as
> params22_0_, params0_.params_elt as params3_0_, params0_.params_idx as
> params2_0_ from map_layer_params params0_ where params0_.params=?
> DEBUG [main] org.hibernate.SQL.logStatement[ 111]:logStatement[ 111]: select
> options0_.options as options22_0_, options0_.options_elt as options3_0_,
> options0_.options_idx as options2_0_ from map_layer_options options0_ where
> options0_.options=?
>
> However, sometimes when I run the app, the generated statements look like
> this:
>
> DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select params0_.params as
> params3_0_, params0_.params_idx as params2_0_ from map_layer_params params0_
> where params0_.params=?
> DEBUG [main] org.hibernate.SQL.logStatement[ 111]: select options0_.options
> as options3_0_, options0_.options_idx as options2_0_ from map_layer_options
> options0_ where options0_.options=?
>
> The clauses for the params_elt and options_elt columns (which correspond to
> the actual value for an entry in the maps) are missing.  I have also seen it
> where the _idx clauses are missing instead though I haven't captured the
> logs for that.
>
> This behavior seems to happen about one out of every four or five launches
> of the app on average, though it can go as many as 20 launches.  If it is
> going to fail (i.e. generate the wrong sql), it does it the first time a
> MapLayer object is retrieved and will fail on all subsequent queries.  
>
> Any ideas for why the SQL could be getting generated incorrectly?
>
> e
>
>
>
> --
> View this message in context: http://grails.1312388.n4.nabble.com/More-fun-with-Map-properties-tp4617698p4619041.html
> Sent from the Grails - user mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> To unsubscribe from this list, please visit:
>
>    http://xircles.codehaus.org/manage_email
>
>

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

[Eric Sword]

I added to the mapping  closure:

    static mapping = {
        sort "name": "asc"   //this was already there
        params column: 'params'
        options column: 'options'
    }

No change in behavior, unfortunately.  I then wondered if it had something to do with having multiple map properties, so I removed one.  Same problem occurred - ran the app (actually a single integration test) a few times and the bad behavior occurred on the 3 try.  

Finally, I added a test for another object type that has a single map property.  We hadn't seen any problems with this one yet, but it is accessed much less frequently and the map property for it is used rarely.  Sure enough, we also see the problem there.

So I am beginning to think there must be some sort of weird class loading conflict with one of the plugins we use.  I don't know what else could cause such indeterminate behavior.  My next step is to try to remove plugins to see if I can identify one with a conflict.

My other idea is to dive into the GrailsDomainBinder class, and specifically the bindMapSecondPass method to see if there is any way for it to get messed up.  

Anyone have other ideas or better places for me to look?

[ideasculptor]

On Wed, May 9, 2012 at 8:52 AM, Eric Sword <[hidden email]> wrote:

I added to the mapping  closure:

   static mapping = {
       sort "name": "asc"   //this was already there
       params column: 'params'
       options column: 'options'
   }

No change in behavior, unfortunately.  I then wondered if it had something
to do with having multiple map properties, so I removed one.  Same problem
occurred - ran the app (actually a single integration test) a few times and
the bad behavior occurred on the 3 try.

I have a custom table name and all 3 columns in that table have custom names, via this mapping.

Map etlConfig

static mapping = {

etlConfig indexColumn: [name: "property"], joinTable: [name: "building_etl_config", column: "value", key: "building_id"]

}

And no, none of those options were documented for mapping a Map. I figured it out via guesswork and the source code.

--sam

[ideasculptor]

On Wed, May 9, 2012 at 11:12 AM, Samuel Gendler <[hidden email]> wrote:

On Wed, May 9, 2012 at 8:52 AM, Eric Sword <[hidden email]> wrote:

I added to the mapping  closure:

   static mapping = {
       sort "name": "asc"   //this was already there
       params column: 'params'
       options column: 'options'
   }

No change in behavior, unfortunately.  I then wondered if it had something
to do with having multiple map properties, so I removed one.  Same problem
occurred - ran the app (actually a single integration test) a few times and
the bad behavior occurred on the 3 try.

I have a custom table name and all 3 columns in that table have custom names, via this mapping.

Map etlConfig

static mapping = {

etlConfig indexColumn: [name: "property"], joinTable: [name: "building_etl_config", column: "value", key: "building_id"]

}

I guess I can add that 'indexColumn' is the map key, and joinTable.column is the map value, joinTable.key is the column name for the foreign key in the join table, and joinTable.name is the join table's name.  Which is a pretty bizarre way to have to go about dealing with key and value from the same map.  I'd have been inclined to make indexColumn the name of the foreign key column back to the parent table, and then have joinTable.key be the map key and joinTable.column be the map value - if I had to re-use the joinTable mapping instead of implementing something specific to mapping Maps.

 

And no, none of those options were documented for mapping a Map. I figured it out via guesswork and the source code.

--sam

[Eric Sword]

I've been deep in Hibernate for a couple of hours now.  The behavior that is causing the problem is that when hibernate is building the various query strings,  the SelectFragment.toFragmentString method will drop out columns with duplicate aliases.  The generated aliases for the columns in the mapping table are sometimes not unique.  Each Column object that is added to a Table object has a uniqueInteger property which is used to derive the alias for the column.  That uniqueInteger property is set when the Column is added to the Table in Table.addColumn.  The value is set to be the new size of the table (which makes sense since the column was just added, the table just grew).  

All of the columns are added in GrailsDomainBinder.bindMapSecondPass.  Normally, the primary mapping column is added first and so its uniqueInteger = 1.  Then the _idx column is added with uniqueInteger=2.  Finally, the _elt column is added with uniqueInteger = 3.  Somehow, every once in a while, the uniqueInteger of the primary mapping column is getting reset to either 2 or 3.  Thus, it's alias will match that for either the _idx or the _elt column, and the select fragment for the respective column will be dropped from the sql statement.  

I have yet to figure out why this happens, and my brain is too much mush right now to continue.  Hopefully I'll get to the conclusion of this saga tomorrow.  Anyone else who has a clue about it will have my undying thanks.

[Eric Sword]

I realized after my last post that I had enough information to implement a workaround, even though I don't know the exact source of the bug yet.  As I said above, the problem comes from Hibernate generating column aliases that are not unique.  The org.hibernate.mapping.Column.getAlias method builds the alias from two pieces- the first part of the column name (everything up until the first non-letter character) and the uniqueInteger property.  The problem is that when you have columns named options, options_elt, and options_idx, the string part comes out the same for all of them.  So if the  uniqueInteger really isn't unique, you get duplicates.

The workaround is to use an explicit mapping as Samuel demonstrates to make sure the column names are different enough.  As far as I can tell, you really only need to change the first column (which is the id of the containing object) to avoid the bug -

    static mapping = {
        options joinTable: [key: "owner_id"]
    }

Which makes the SQL look like this:

Static select for collection MapLayer.options: select options0_.owner_id as owner1_3_0_, options0_.options_elt as options3_0_, options0_.options_idx as options2_0_ from map_layer_options options0_ where options0_.owner_id=?

Crisis averted.

I think I actually know what causes the bug now as well, but need a little more digging before I can log it.

[Eric Sword]

Bug submitted with sample project - http://jira.grails.org/browse/GRAILS-9105 

I hope this little novel I've written will help someone else keep his/her sanity.

[ideasculptor]

On Fri, May 11, 2012 at 9:50 AM, Eric Sword <[hidden email]> wrote:

I think I actually know what causes the bug now as well, but need a little
more digging before I can log it.

Nice diagnosis. And I'm so glad that it isn't something that is going to turn around and bite me just when I least expect it.  I knew I hadn't seen the problem, but without knowing why, it made me a little nervous.  I wind up renaming lots of columns.  I write enough ad-hoc queries in command line query interfaces that I try to keep column names easy to remember and type, so any property that generates particularly long or hard-to-type column names always get mapped to other column names in my projects.  Looks like that saved my ass this time.

Hopefully, the grails team will be able to at least patch a future release to use more distinct column names if they don't implement an actual fix for the underlying bug.

[redcoat]

Hi Eric,

Wish I'd found this before spending hours in Hibernate code!  We should create a list of "if you see something really strange, check here first"!

I updated the Jira with what I found when trying to figure out exactly what was causing the issue - it appears to be based on the way Hibernate creates Aliases for key vs non-key columns (using the parent Table's uniqueInteger), coupled with the naming of the columns.  I'd expect it to have manifested in the Hibernate-only world before now, though I guess most people don't name things the way Grails defaults it.

cheers,

David

[redcoat]

Turns out this is a known Hibernate bug:  https://hibernate.onjira.com/browse/HHH-7243