-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 15 posts ] 
Author Message
 Post subject: Filter on set not applied
PostPosted: Tue Feb 08, 2005 5:55 pm 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
I am using filters to securize data access with Hibernate 3 b3. I am running into an issue with my proof of concept:

I have a Blog entity with a one-to-many relationship to a BlogEntry entity. The relationship is mapped as "inverse" on my blog.hmb.xml file. I have set up a security filter directly on the Blog entity and a second security filter within the <set> tag, to secure association to blogEntries.

When I enable both filters, only the one applying to the Blog entity is enabled. The filter on the SET is activated/working.

Here is the relationship mapping on Blog.hbm.xml

Code:

<hibernate-mapping package="my.package.domain">
    <class name="Blog" table="blog">
        <id name="id" column="id" type="java.lang.Long">
            <generator class="identity"/>
        </id>
        <property name="name" column="name" type="java.lang.String" />
        <property name="creationdatetime" column="creationDateTime" type="java.util.Date" />
       
        <set name="blogEntries" inverse="true" cascade="all" lazy="false">
            <key column="blogId"/>
            <one-to-many class="my.package.domain.BlogEntry"/>
            <filter name="blogEntryACLSecurityFilter" condition="id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :currentUserId))"/>
      </set>                           
      <filter name="hasValidRoles" condition="id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :securizedUser))"/>                                       
    </class>
   
    <filter-def name="hasValidRoles">
      <filter-param name="securizedUser" type="long"/>
      <filter-param name="accessLevel" type="byte"/>
   </filter-def>
    <filter-def name="blogEntryACLSecurityFilter">
      <filter-param name="currentUserId" type="long"/>
      <filter-param name="accessLevel" type="byte"/>
   </filter-def>

</hibernate-mapping>


I am querying using the following code:

Code:
session.enableFilter("blogEntryACLSecurityFilter").setParameter("currentUserId", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
session.enableFilter("hasValidRoles").setParameter("securizedUser", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
Query query = session.createQuery("SELECT blog FROM my.package.domain.Blog blog");
return query.list();


The database is set up so that 3 blog entries are available under the blog but that only 2 are available when the filters are up. I always see 3!
    ->I have run my queries manually and they work fine
    ->I have tried it with lazy = true and false, no change)
    ->I did try setting the filter on the BlogEntry.hbm.xml file, no change


I am running out of ideas! any help would be appreciated :)

Thanks in advance,

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject: Re: Filter on set not applied
PostPosted: Tue Feb 08, 2005 5:56 pm 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
vgiguere wrote:
I am using filters to securize data access with Hibernate 3 b3. I am running into an issue with my proof of concept:

I have a Blog entity with a one-to-many relationship to a BlogEntry entity. The relationship is mapped as "inverse" on my blog.hmb.xml file. I have set up a security filter directly on the Blog entity and a second security filter within the <set> tag, to secure association to blogEntries.

When I enable both filters, only the one applying to the Blog entity is enabled. The filter on the SET is NOT activated/working.

Here is the relationship mapping on Blog.hbm.xml

Code:

<hibernate-mapping package="my.package.domain">
    <class name="Blog" table="blog">
        <id name="id" column="id" type="java.lang.Long">
            <generator class="identity"/>
        </id>
        <property name="name" column="name" type="java.lang.String" />
        <property name="creationdatetime" column="creationDateTime" type="java.util.Date" />
       
        <set name="blogEntries" inverse="true" cascade="all" lazy="false">
            <key column="blogId"/>
            <one-to-many class="my.package.domain.BlogEntry"/>
            <filter name="blogEntryACLSecurityFilter" condition="id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :currentUserId))"/>
      </set>                           
      <filter name="hasValidRoles" condition="id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :securizedUser))"/>                                       
    </class>
   
    <filter-def name="hasValidRoles">
      <filter-param name="securizedUser" type="long"/>
      <filter-param name="accessLevel" type="byte"/>
   </filter-def>
    <filter-def name="blogEntryACLSecurityFilter">
      <filter-param name="currentUserId" type="long"/>
      <filter-param name="accessLevel" type="byte"/>
   </filter-def>

</hibernate-mapping>


I am querying using the following code:

Code:
session.enableFilter("blogEntryACLSecurityFilter").setParameter("currentUserId", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
session.enableFilter("hasValidRoles").setParameter("securizedUser", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
Query query = session.createQuery("SELECT blog FROM my.package.domain.Blog blog");
return query.list();


The database is set up so that 3 blog entries are available under the blog but that only 2 are available when the filters are up. I always see 3!
    ->I have run my queries manually and they work fine
    ->I have tried it with lazy = true and false, no change)
    ->I did try setting the filter on the BlogEntry.hbm.xml file, no change

I am running out of ideas! any help would be appreciated :)

Thanks in advance,

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Tue Feb 08, 2005 7:10 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Can you enable sql logging from within hibernate and the resulting sql for both the eager and lazy fecthed scenarios?

I just added a unit test to explicitly test for this scenario: see org.hibernate.test.filter.DynamicFilterTest.testCombinedClassAndCollectionFiltersEnabled(). That passes without any issues. The sql generated contains both of the defined filter criteria.

Also:
1) What db are you using?
2) Which of the query parser are you using?


Top
 Profile  
 
 Post subject:
PostPosted: Tue Feb 08, 2005 7:24 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Quote:
Can you enable sql logging from within hibernate and the resulting sql for both the eager and lazy fecthed scenarios?


Of course I meant: Can you enable sql logging from within hibernate and post the resulting sql for both the eager and lazy fecthed scenarios? :)


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 9:58 am 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
Hi Steve, thanks for your reply

1) What db are you using? ->Sybase 12.5.3
2) Which of the query parser are you using? -> I have not specified the hibernate.query.factory_class property, so I guess I am using: org.hibernate.hql.classic.ClassicQueryTranslatorFactory (I will try the other one, just in case)

Meanwhile: If I turn the sql on, I only see the request that selects the parent (Blog) object:

Code:
Hibernate: select blog0_.id as id, blog0_.name as name0_, blog0_.creationDateTime as creation3_0_ from blog blog0_ where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))


The output is identical with or without lazy instanciation:
Code:
Hibernate: select blog0_.id as id, blog0_.name as name0_, blog0_.creationDateTime as creation3_0_ from blog blog0_ where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))


It really looks like the filter is never setup and, even thought child objects (BlogEntry) are loaded, there is no hint as to how/when this is done (no sql query displayed). I believe we used to see it in hibernate 2.

I must be doing something wrong.

Thanks for the help

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 11:11 am 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
I have looked at the test you have set up org.hibernate.test.filter.DynamicFilterTest.testCombinedClassAndCollectionFiltersEnabled()

I validate that this it corresponds to what I am trying to do.

I have changed the query parser for the ASTQueryTranslatorFactory and I a little bit more output:

Code:
2005-02-09 09:53:38,608 DEBUG SessionImpl.list - find: SELECT blog FROM my.package.domain.Blog blog
2005-02-09 09:53:38,618 DEBUG QueryParameters.traceParameters - named parameters: {}
2005-02-09 09:53:38,909 DEBUG QueryTranslatorImpl.parse - parse() - HQL: SELECT blog FROM my.package.domain.Blog blog
2005-02-09 09:53:39,019 DEBUG AST.logAst - --- HQL AST ---
\-'query' [QUERY]
    \-'SELECT_FROM' [SELECT_FROM]
       +-'FROM' [FROM]
       |  +-'.' [DOT]
       |  |  +-'.' [DOT]
       |  |  |  +-'.' [DOT]
       |  |  |  |  +-'.' [DOT]
       |  |  |  |  |  +-'com' [IDENT]
       |  |  |  |  |  \-'db' [IDENT]
       |  |  |  |  \-'persistence' [IDENT]
       |  |  |  \-'domain' [IDENT]
       |  |  \-'Blog' [IDENT]
       |  \-'blog' [ALIAS]
       \-'SELECT' [SELECT]
          \-'blog' [IDENT]

2005-02-09 09:53:39,099 DEBUG HqlSqlBaseWalker.beforeQuery - query() << begin, level = 1
2005-02-09 09:53:39,139 DEBUG FromElement.doInitialize - my.package.domain.Blog (blog) -> blog0_
2005-02-09 09:53:39,149 DEBUG HqlSqlBaseWalker.afterQuery - query() : finishing up...
2005-02-09 09:53:39,179 DEBUG JoinProcessor.addJoinNodes - Using FROM fragment [blog blog0_]
2005-02-09 09:53:39,189 DEBUG SyntheticAndFactory.addWhereFragment - addWhereFragment() : {and blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))}
2005-02-09 09:53:39,189 DEBUG QueryNode.getWhereClause - getWhereClause() : Creating a new WHERE clause...
2005-02-09 09:53:39,199 DEBUG HqlSqlBaseWalker.afterQuery - query() >> end, level = 1
2005-02-09 09:53:39,209 DEBUG AST.logAst - --- SQL AST ---
\-'SELECT' [SELECT]   querySpaces (blog)
    +-'{select clause}' [SELECT_CLAUSE]
    |  +-'blog0_.id as id' [ALIAS_REF]  {alias=blog, className=my.package.domain.Blog, tableAlias=blog0_}
    |  \-'blog0_.name as name0_, blog0_.creationDateTime as creation3_0_' [SQL_TOKEN]
    +-'FROM' [FROM]  FromClause{FROM}
    |  \-'blog blog0_' [FROM_FRAGMENT]  FromElement{className=my.package.domain.Blog,explicit,not a collection join,classAlias=blog,tableName=blog,tableAlias=blog0_,colums={}}
    \-'WHERE' [WHERE]
       \-'blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))' [SQL_TOKEN]

2005-02-09 09:53:39,239 DEBUG QueryTranslatorImpl.generate - HQL: SELECT blog FROM my.package.domain.Blog blog
2005-02-09 09:53:39,239 DEBUG QueryTranslatorImpl.generate - SQL: select blog0_.id as id, blog0_.name as name0_, blog0_.creationDateTime as creation3_0_ from blog blog0_ where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))
2005-02-09 09:53:39,259 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - flushing session
2005-02-09 09:53:39,269 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 09:53:39,269 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 09:53:39,269 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,279 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,279 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,299 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000705
2005-02-09 09:53:39,299 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 09:53:39,309 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 09:53:39,309 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 09:53:39,309 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,319 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,319 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,319 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000705
2005-02-09 09:53:39,329 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,339 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,339 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,339 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000706
2005-02-09 09:53:39,349 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 09:53:39,349 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 09:53:39,359 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 09:53:39,359 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,359 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,369 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,379 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000705
2005-02-09 09:53:39,379 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,379 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,389 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,399 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000706
2005-02-09 09:53:39,399 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,409 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 09:53:39,419 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,419 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000707
2005-02-09 09:53:39,419 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 09:53:39,429 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,429 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 09:53:39,439 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,439 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,439 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,449 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002265
2005-02-09 09:53:39,459 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,469 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,469 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,479 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002266
2005-02-09 09:53:39,479 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,489 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,489 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,499 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002267
2005-02-09 09:53:39,499 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,499 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,509 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 09:53:39,509 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,519 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,519 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,539 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002268
2005-02-09 09:53:39,539 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,549 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,549 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,549 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002269
2005-02-09 09:53:39,560 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,560 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,570 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,570 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002270
2005-02-09 09:53:39,580 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,580 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,580 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 09:53:39,590 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,590 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,590 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,600 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002271
2005-02-09 09:53:39,610 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,610 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,610 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,620 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002272
2005-02-09 09:53:39,620 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 09:53:39,620 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 09:53:39,630 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 09:53:39,630 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002273
2005-02-09 09:53:39,650 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 09:53:39,650 DEBUG AbstractFlushingEventListener.flushEntities - Flushing entities and processing referenced collections
2005-02-09 09:53:39,660 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000746], was: [my.package.domain.User.roles#10000746] (initialized)
2005-02-09 09:53:39,660 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000747], was: [my.package.domain.User.roles#10000747] (initialized)
2005-02-09 09:53:39,660 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000748], was: [my.package.domain.User.roles#10000748] (initialized)
2005-02-09 09:53:39,670 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001006], was: [my.package.domain.Blog.blogEntries#10001006] (initialized)
2005-02-09 09:53:39,680 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001007], was: [my.package.domain.Blog.blogEntries#10001007] (initialized)
2005-02-09 09:53:39,680 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001008], was: [my.package.domain.Blog.blogEntries#10001008] (initialized)
2005-02-09 09:53:39,690 DEBUG AbstractFlushingEventListener.flushCollections - Processing unreferenced collections
2005-02-09 09:53:39,700 DEBUG AbstractFlushingEventListener.flushCollections - Scheduling collection removes/(re)creates/updates
2005-02-09 09:53:39,700 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - Flushed: 0 insertions, 0 updates, 0 deletions to 26 objects
2005-02-09 09:53:39,700 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - Flushed: 0 (re)creations, 0 updates, 0 removals to 6 collections
2005-02-09 09:53:39,710 DEBUG Printer.toString - listing entities:
2005-02-09 09:53:39,710 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 09:53:21, name=allAccessBlog, id=10001006, blogEntries=[my.package.domain.BlogEntry#10002265, my.package.domain.BlogEntry#10002266, my.package.domain.BlogEntry#10002267]}
2005-02-09 09:53:39,710 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Company contact information, blog=my.package.domain.Blog#10001006, id=10002265}
2005-02-09 09:53:39,720 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Sensitive information about employees' salaries, blog=my.package.domain.Blog#10001007, id=10002268}
2005-02-09 09:53:39,720 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000706, entityType=my.package.domain.Blog, id=3136633892082026323, entityId=10001007}
2005-02-09 09:53:39,730 DEBUG Printer.toString - my.package.domain.User{userName=Mike, userid=10000747, userLastName=Director, roles=[my.package.domain.Role#10000705, my.package.domain.Role#10000706], birthDate=1968-01-02 00:09:00}
2005-02-09 09:53:39,740 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=2, roleId=10000706, entityType=my.package.domain.Blog, id=3136633892082026326, entityId=10001006}
2005-02-09 09:53:39,740 DEBUG Printer.toString - my.package.domain.Role{rolename=readSensitiveLevelInformation, roleid=10000706}
2005-02-09 09:53:39,740 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret about future IPO, blog=my.package.domain.Blog#10001008, id=10002272}
2005-02-09 09:53:39,760 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Useless information about company values, blog=my.package.domain.Blog#10001006, id=10002267}
2005-02-09 09:53:39,760 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret information about accounting frauds, blog=my.package.domain.Blog#10001008, id=10002273}
2005-02-09 09:53:39,770 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000707, entityType=my.package.domain.Blog, id=3136633892082026325, entityId=10001008}
2005-02-09 09:53:39,770 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Released Gartner report showing that we are in quadrant 3, blog=my.package.domain.Blog#10001006, id=10002266}
2005-02-09 09:53:39,780 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Sensitive information about marketing plans , blog=my.package.domain.Blog#10001007, id=10002269}
2005-02-09 09:53:39,780 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000705, entityType=my.package.domain.BlogEntry, id=3136633892082026330, entityId=10002266}
2005-02-09 09:53:39,780 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000707, entityType=my.package.domain.Blog, id=3136633892082026324, entityId=10001007}
2005-02-09 09:53:39,790 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=2, roleId=10000707, entityType=my.package.domain.Blog, id=3136633892082026327, entityId=10001006}
2005-02-09 09:53:39,790 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 09:53:21, name=sensitiveBlog, id=10001007, blogEntries=[my.package.domain.BlogEntry#10002268, my.package.domain.BlogEntry#10002269, my.package.domain.BlogEntry#10002270]}
2005-02-09 09:53:39,800 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret information about planned merger, blog=my.package.domain.Blog#10001008, id=10002271}
2005-02-09 09:53:39,800 DEBUG Printer.toString - my.package.domain.User{userName=Donald, userid=10000748, userLastName=Trump, roles=[my.package.domain.Role#10000705, my.package.domain.Role#10000706, my.package.domain.Role#10000707], birthDate=1953-01-05 00:01:00}
2005-02-09 09:53:39,810 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 09:53:21, name=topSecretBlog, id=10001008, blogEntries=[my.package.domain.BlogEntry#10002271, my.package.domain.BlogEntry#10002272, my.package.domain.BlogEntry#10002273]}
2005-02-09 09:53:39,810 DEBUG Printer.toString - my.package.domain.Role{rolename=readAllAccessLevelInformation, roleid=10000705}
2005-02-09 09:53:39,810 DEBUG Printer.toString - more......
2005-02-09 09:53:39,820 DEBUG DefaultAutoFlushEventListener.onAutoFlush - Dont need to execute flush
2005-02-09 09:53:39,820 DEBUG AbstractBatcher.logOpenPreparedStatement - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-02-09 09:53:39,830 DEBUG SQL.log - select blog0_.id as id, blog0_.name as name0_, blog0_.creationDateTime as creation3_0_ from blog blog0_ where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))
Hibernate: select blog0_.id as id, blog0_.name as name0_, blog0_.creationDateTime as creation3_0_ from blog blog0_ where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))
2005-02-09 09:53:39,840 DEBUG AbstractBatcher.getPreparedStatement - preparing statement
2005-02-09 09:53:39,850 DEBUG ByteType.nullSafeSet - binding '1' to parameter: 1
2005-02-09 09:53:39,850 DEBUG LongType.nullSafeSet - binding '10000746' to parameter: 2
2005-02-09 09:53:40,010 DEBUG AbstractBatcher.logOpenResults - about to open ResultSet (open ResultSets: 0, globally: 0)
2005-02-09 09:53:40,020 DEBUG Loader.wrapResultSetIfEnabled - Using naked result set
2005-02-09 09:53:40,020 DEBUG Loader.doQuery - processing result set
2005-02-09 09:53:40,020 DEBUG Loader.doQuery - result set row: 0
2005-02-09 09:53:40,050 DEBUG LongType.nullSafeGet - returning '10001006' as column: id
2005-02-09 09:53:40,060 DEBUG Loader.getRow - result row: EntityKey[my.package.domain.Blog#10001006]
2005-02-09 09:53:40,060 DEBUG Loader.doQuery - done processing result set (1 rows)
2005-02-09 09:53:40,070 DEBUG AbstractBatcher.logCloseResults - about to close ResultSet (open ResultSets: 1, globally: 1)
2005-02-09 09:53:40,070 DEBUG AbstractBatcher.logClosePreparedStatement - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-02-09 09:53:40,080 DEBUG AbstractBatcher.closePreparedStatement - closing statement
2005-02-09 09:53:40,080 DEBUG Loader.initializeEntitiesAndCollections - total objects hydrated: 0
2005-02-09 09:53:40,080 DEBUG PersistenceContext.initializeNonLazyCollections - initializing non-lazy collections
2005-02-09 09:53:40,090 DEBUG SessionImpl.close - closing session
2005-02-09 09:53:40,090 DEBUG SessionImpl.disconnect - disconnecting session
2005-02-09 09:53:40,090 DEBUG AbstractBatcher.closeConnection - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
2005-02-09 09:53:40,110 DEBUG DriverManagerConnectionProvider.closeConnection - returning connection to pool, pool size: 1
2005-02-09 09:53:40,110 DEBUG SessionImpl.afterTransactionCompletion - after transaction completion


Thanks in advance

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 11:13 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Well the fact that you never see the other query displayed to stdout is a clear indication that it is never happening ;) Are you certain these are not being cached from some prior action (in either the session or second-level cache)?

Try eagerly fetching the assocation:
Code:
session.createQuery("FROM Blog blog left join fetch blog.blogEntries").list();


What happens there?


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 11:18 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Looking at that log you posted, it is definitely seeing the collection in cache.

Is this a simplified main() or unit-test you can post?


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 11:53 am 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
Hi Steve,
Thanks again for your help.

This is all happening in a unit test that validates that I can secure a child relationship using the filters.

The data gets loaded by the setUp() method. I open a transaction at the beginning of setUp() and commit it at the end (prior to querying the data).

These are some of my configuration properties:

Code:
        <property name="hibernate.query.factory_class">org.hibernate.hql.ast.ASTQueryTranslatorFactory</property>
      <property name="hibernate.transaction.factory_class">org.hibernate.transaction.JDBCTransactionFactory</property>
      <property name="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
      <property name="show_sql">true</property>
      <property name="use_outer_join">true</property>
      <property name="hibernate.jdbc.batch_size">10</property>   


I have tried the left join fetch but it did not help.

Code:
2005-02-09 10:32:58,111 DEBUG SessionImpl.list - find: SELECT blog FROM my.package.domain.Blog blog left join fetch blog.blogEntries
2005-02-09 10:32:58,111 DEBUG QueryParameters.traceParameters - named parameters: {}
2005-02-09 10:32:58,161 DEBUG QueryTranslatorImpl.parse - parse() - HQL: SELECT blog FROM my.package.domain.Blog blog left join fetch blog.blogEntries
2005-02-09 10:32:58,171 DEBUG AST.logAst - --- HQL AST ---
\-'query' [QUERY]
    \-'SELECT_FROM' [SELECT_FROM]
       +-'FROM' [FROM]
       |  +-'.' [DOT]
       |  |  +-'.' [DOT]
       |  |  |  +-'.' [DOT]
       |  |  |  |  +-'.' [DOT]
       |  |  |  |  |  +-'com' [IDENT]
       |  |  |  |  |  \-'db' [IDENT]
       |  |  |  |  \-'persistence' [IDENT]
       |  |  |  \-'domain' [IDENT]
       |  |  \-'Blog' [IDENT]
       |  +-'blog' [ALIAS]
       |  \-'join' [JOIN]
       |     +-'left' [LEFT]
       |     +-'fetch' [FETCH]
       |     \-'.' [DOT]
       |        +-'blog' [IDENT]
       |        \-'blogEntries' [IDENT]
       \-'SELECT' [SELECT]
          \-'blog' [IDENT]

2005-02-09 10:32:58,271 DEBUG HqlSqlBaseWalker.beforeQuery - query() << begin, level = 1
2005-02-09 10:32:58,281 DEBUG FromElement.doInitialize - my.package.domain.Blog (blog) -> blog0_
2005-02-09 10:32:58,281 DEBUG FromReferenceNode.setResolved - Resolved :  blog -> blog0_.id
2005-02-09 10:32:58,291 DEBUG DotNode.getDataType - getDataType() : blogEntries -> org.hibernate.type.SetType@d55986(my.package.domain.Blog.blogEntries)
2005-02-09 10:32:58,291 DEBUG FromElementFactory.createEntityAssociation - createEntityAssociation() : One to many - path = blog.blogEntries role = my.package.domain.Blog.blogEntries associatedEntityName = my.package.domain.BlogEntry
2005-02-09 10:32:58,311 DEBUG FromElement.doInitialize - my.package.domain.BlogEntry (no alias) -> blogentrie1_
2005-02-09 10:32:58,311 DEBUG DotNode.dereferenceCollection - dereferenceCollection() : Created new FROM element for blog.blogEntries : FromElement{<1> tableAlias='blogentrie1_', className='my.package.domain.BlogEntry', classAlias='null', role='my.package.domain.Blog.blogEntries', includeSubclasses=true, collectionJoin=false, fetch=true, origin=FromElement{<0> tableAlias='blog0_', className='my.package.domain.Blog', classAlias='blog', role='null', includeSubclasses=true, collectionJoin=false, fetch=false, origin=null, persister=SingleTableEntityPersister(my.package.domain.Blog), queryableCollection=null, joinSequence=null, columns=null}, persister=SingleTableEntityPersister(my.package.domain.BlogEntry), queryableCollection=OneToManyPersister(my.package.domain.Blog.blogEntries), joinSequence=JoinSequence{->OneToManyPersister(my.package.domain.Blog.blogEntries)[blogentrie1_]}, columns=[blog0_.id]}
2005-02-09 10:32:58,311 DEBUG FromReferenceNode.setResolved - Resolved :  blog.blogEntries -> .
2005-02-09 10:32:58,311 DEBUG HqlSqlBaseWalker.afterQuery - query() : finishing up...
2005-02-09 10:32:58,321 DEBUG JoinProcessor.addJoinNodes - Using FROM fragment [blog blog0_]
2005-02-09 10:32:58,321 DEBUG SyntheticAndFactory.addWhereFragment - addWhereFragment() : {and blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))}
2005-02-09 10:32:58,321 DEBUG QueryNode.getWhereClause - getWhereClause() : Creating a new WHERE clause...
2005-02-09 10:32:58,321 DEBUG JoinProcessor.addJoinNodes - Using FROM fragment [left outer join blog_entry blogentrie1_ on blog0_.id=blogentrie1_.blogId and blogentrie1_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :blogEntryACLSecurityFilter.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :blogEntryACLSecurityFilter.currentUserId))]
2005-02-09 10:32:58,321 DEBUG HqlSqlBaseWalker.afterQuery - query() >> end, level = 1
2005-02-09 10:32:58,321 DEBUG AST.logAst - --- SQL AST ---
\-'SELECT' [SELECT]   querySpaces (blog_entry,blog)
    +-'{select clause}' [SELECT_CLAUSE]
    |  +-'blog0_.id as id0_' [ALIAS_REF]  {alias=blog, className=my.package.domain.Blog, tableAlias=blog0_}
    |  +-'blogentrie1_.id as id1_' [SELECT_EXPR]  {FromElement{className=my.package.domain.BlogEntry,explicit,not a collection join,classAlias=my.package.domain.BlogEntry,tableName=blog_entry,tableAlias=blogentrie1_,colums={blog0_.id }}}
    |  +-'blog0_.name as name0_0_, blog0_.creationDateTime as creation3_0_0_' [SQL_TOKEN]
    |  +-'blogentrie1_.content as content1_1_, blogentrie1_.blogId as blogId1_1_' [SQL_TOKEN]
    |  \-'blogentrie1_.blogId as blogId__, blogentrie1_.id as id__' [SQL_TOKEN]
    +-'FROM' [FROM]  FromClause{FROM}
    |  \-'blog blog0_' [FROM_FRAGMENT]  FromElement{className=my.package.domain.Blog,explicit,not a collection join,classAlias=blog,tableName=blog,tableAlias=blog0_,colums={}}
    |     \-'left outer join blog_entry blogentrie1_ on blog0_.id=blogentrie1_.blogId and blogentrie1_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :blogEntryACLSecurityFilter.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :blogEntryACLSecurityFilter.currentUserId))' [JOIN_FRAGMENT]  FromElement{className=my.package.domain.BlogEntry,explicit,not a collection join,classAlias=my.package.domain.BlogEntry,tableName=blog_entry,tableAlias=blogentrie1_,colums={blog0_.id }}
    \-'WHERE' [WHERE]
       \-'blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))' [SQL_TOKEN]

2005-02-09 10:32:58,331 DEBUG QueryTranslatorImpl.generate - HQL: SELECT blog FROM my.package.domain.Blog blog left join fetch blog.blogEntries
2005-02-09 10:32:58,331 DEBUG QueryTranslatorImpl.generate - SQL: select blog0_.id as id0_, blogentrie1_.id as id1_, blog0_.name as name0_0_, blog0_.creationDateTime as creation3_0_0_, blogentrie1_.content as content1_1_, blogentrie1_.blogId as blogId1_1_, blogentrie1_.blogId as blogId__, blogentrie1_.id as id__ from blog blog0_ left outer join blog_entry blogentrie1_ on blog0_.id=blogentrie1_.blogId and blogentrie1_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :blogEntryACLSecurityFilter.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :blogEntryACLSecurityFilter.currentUserId)) where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= :hasValidRoles.accessLevel and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = :hasValidRoles.securizedUser))
2005-02-09 10:32:58,341 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - flushing session
2005-02-09 10:32:58,341 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 10:32:58,341 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 10:32:58,341 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,341 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,341 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,341 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000717
2005-02-09 10:32:58,341 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 10:32:58,341 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 10:32:58,341 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 10:32:58,341 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,341 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000717
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,351 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000718
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - processing cascades for: my.package.domain.User
2005-02-09 10:32:58,351 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.User.roles
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,351 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000719
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,351 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000717
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,351 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.Role
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,351 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10000718
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.User
2005-02-09 10:32:58,351 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,361 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,361 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002301
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,361 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002302
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,361 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002303
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,361 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,361 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,361 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002304
2005-02-09 10:32:58,361 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,361 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002305
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,371 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002306
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,371 DEBUG Cascades.cascadeCollection - cascading to collection: my.package.domain.Blog.blogEntries
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,371 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002307
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,371 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002308
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - cascading to saveOrUpdate()
2005-02-09 10:32:58,371 DEBUG AbstractSaveEventListener.getEntityState - persistent instance of: my.package.domain.BlogEntry
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - ignoring persistent instance
2005-02-09 10:32:58,371 DEBUG DefaultSaveOrUpdateEventListener.entityIsPersistent - object already associated with session with id: 10002309
2005-02-09 10:32:58,371 DEBUG Cascades.cascade - done processing cascades for: my.package.domain.Blog
2005-02-09 10:32:58,381 DEBUG AbstractFlushingEventListener.flushEntities - Flushing entities and processing referenced collections
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000758], was: [my.package.domain.User.roles#10000758] (initialized)
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000759], was: [my.package.domain.User.roles#10000759] (initialized)
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.User.roles#10000760], was: [my.package.domain.User.roles#10000760] (initialized)
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001018], was: [my.package.domain.Blog.blogEntries#10001018] (initialized)
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001019], was: [my.package.domain.Blog.blogEntries#10001019] (initialized)
2005-02-09 10:32:58,381 DEBUG Collections.updateReachableCollection - Collection found: [my.package.domain.Blog.blogEntries#10001020], was: [my.package.domain.Blog.blogEntries#10001020] (initialized)
2005-02-09 10:32:58,381 DEBUG AbstractFlushingEventListener.flushCollections - Processing unreferenced collections
2005-02-09 10:32:58,381 DEBUG AbstractFlushingEventListener.flushCollections - Scheduling collection removes/(re)creates/updates
2005-02-09 10:32:58,381 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - Flushed: 0 insertions, 0 updates, 0 deletions to 26 objects
2005-02-09 10:32:58,381 DEBUG AbstractFlushingEventListener.flushEverythingToExecutions - Flushed: 0 (re)creations, 0 updates, 0 removals to 6 collections
2005-02-09 10:32:58,381 DEBUG Printer.toString - listing entities:
2005-02-09 10:32:58,381 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 10:32:57, name=allAccessBlog, id=10001018, blogEntries=[my.package.domain.BlogEntry#10002301, my.package.domain.BlogEntry#10002302, my.package.domain.BlogEntry#10002303]}
2005-02-09 10:32:58,381 DEBUG Printer.toString - my.package.domain.User{userName=Mike, userid=10000759, userLastName=Director, roles=[my.package.domain.Role#10000717, my.package.domain.Role#10000718], birthDate=1968-01-02 00:09:00}
2005-02-09 10:32:58,381 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000717, entityType=my.package.domain.BlogEntry, id=3136633892082026361, entityId=10002303}
2005-02-09 10:32:58,381 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Sensitive information about Q4 earnings, blog=my.package.domain.Blog#10001019, id=10002306}
2005-02-09 10:32:58,381 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=2, roleId=10000719, entityType=my.package.domain.Blog, id=3136633892082026359, entityId=10001018}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret information about planned merger, blog=my.package.domain.Blog#10001020, id=10002307}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.Role{rolename=readTopSecretLevelInformation, roleid=10000719}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Sensitive information about employees' salaries, blog=my.package.domain.Blog#10001019, id=10002304}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Useless information about company values, blog=my.package.domain.Blog#10001018, id=10002303}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 10:32:57, name=topSecretBlog, id=10001020, blogEntries=[my.package.domain.BlogEntry#10002307, my.package.domain.BlogEntry#10002308, my.package.domain.BlogEntry#10002309]}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000719, entityType=my.package.domain.Blog, id=3136633892082026357, entityId=10001020}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret information about accounting frauds, blog=my.package.domain.Blog#10001020, id=10002309}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.Blog{creationdatetime=2005-02-09 10:32:57, name=sensitiveBlog, id=10001019, blogEntries=[my.package.domain.BlogEntry#10002304, my.package.domain.BlogEntry#10002305, my.package.domain.BlogEntry#10002306]}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.User{userName=Joe, userid=10000758, userLastName=Apprentice, roles=[my.package.domain.Role#10000717], birthDate=1980-01-09 00:04:00}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000717, entityType=my.package.domain.Blog, id=3136633892082026360, entityId=10001018}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000717, entityType=my.package.domain.BlogEntry, id=3136633892082026362, entityId=10002302}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000719, entityType=my.package.domain.Blog, id=3136633892082026356, entityId=10001019}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Company contact information, blog=my.package.domain.Blog#10001018, id=10002301}
2005-02-09 10:32:58,391 DEBUG Printer.toString - my.package.domain.User{userName=Donald, userid=10000760, userLastName=Trump, roles=[my.package.domain.Role#10000719, my.package.domain.Role#10000717, my.package.domain.Role#10000718], birthDate=1953-01-05 00:01:00}
2005-02-09 10:32:58,421 DEBUG Printer.toString - my.package.entitlement.EntityAcl{accessLevel=1, roleId=10000718, entityType=my.package.domain.Blog, id=3136633892082026355, entityId=10001019}
2005-02-09 10:32:58,421 DEBUG Printer.toString - my.package.domain.BlogEntry{text=Top Secret about future IPO, blog=my.package.domain.Blog#10001020, id=10002308}
2005-02-09 10:32:58,441 DEBUG Printer.toString - more......
2005-02-09 10:32:58,441 DEBUG DefaultAutoFlushEventListener.onAutoFlush - Dont need to execute flush
2005-02-09 10:32:58,441 DEBUG AbstractBatcher.logOpenPreparedStatement - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-02-09 10:32:58,441 DEBUG SQL.log - select blog0_.id as id0_, blogentrie1_.id as id1_, blog0_.name as name0_0_, blog0_.creationDateTime as creation3_0_0_, blogentrie1_.content as content1_1_, blogentrie1_.blogId as blogId1_1_, blogentrie1_.blogId as blogId__, blogentrie1_.id as id__ from blog blog0_ left outer join blog_entry blogentrie1_ on blog0_.id=blogentrie1_.blogId and blogentrie1_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?)) where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))
Hibernate: select blog0_.id as id0_, blogentrie1_.id as id1_, blog0_.name as name0_0_, blog0_.creationDateTime as creation3_0_0_, blogentrie1_.content as content1_1_, blogentrie1_.blogId as blogId1_1_, blogentrie1_.blogId as blogId__, blogentrie1_.id as id__ from blog blog0_ left outer join blog_entry blogentrie1_ on blog0_.id=blogentrie1_.blogId and blogentrie1_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?)) where blog0_.id in (select acl.entityId from entity_acl acl where acl.accessLevel >= ? and acl.roleId in (select userRole.roleid from user_roles userRole where userRole.userid = ?))
2005-02-09 10:32:58,441 DEBUG AbstractBatcher.getPreparedStatement - preparing statement
2005-02-09 10:32:58,441 DEBUG ByteType.nullSafeSet - binding '1' to parameter: 1
2005-02-09 10:32:58,441 DEBUG LongType.nullSafeSet - binding '10000758' to parameter: 2
2005-02-09 10:32:58,441 DEBUG ByteType.nullSafeSet - binding '1' to parameter: 3
2005-02-09 10:32:58,441 DEBUG LongType.nullSafeSet - binding '10000758' to parameter: 4
2005-02-09 10:32:58,782 DEBUG AbstractBatcher.logOpenResults - about to open ResultSet (open ResultSets: 0, globally: 0)
2005-02-09 10:32:58,782 DEBUG Loader.wrapResultSetIfEnabled - Using naked result set
2005-02-09 10:32:58,782 DEBUG Loader.doQuery - processing result set
2005-02-09 10:32:58,782 DEBUG Loader.doQuery - result set row: 0
2005-02-09 10:32:58,782 DEBUG LongType.nullSafeGet - returning '10001018' as column: id0_
2005-02-09 10:32:58,782 DEBUG LongType.nullSafeGet - returning '10002302' as column: id1_
2005-02-09 10:32:58,782 DEBUG Loader.getRow - result row: EntityKey[my.package.domain.Blog#10001018], EntityKey[my.package.domain.BlogEntry#10002302]
2005-02-09 10:32:58,792 DEBUG Loader.doQuery - result set row: 1
2005-02-09 10:32:58,792 DEBUG LongType.nullSafeGet - returning '10001018' as column: id0_
2005-02-09 10:32:58,792 DEBUG LongType.nullSafeGet - returning '10002303' as column: id1_
2005-02-09 10:32:58,792 DEBUG Loader.getRow - result row: EntityKey[my.package.domain.Blog#10001018], EntityKey[my.package.domain.BlogEntry#10002303]
2005-02-09 10:32:58,792 DEBUG Loader.doQuery - done processing result set (2 rows)
2005-02-09 10:32:58,792 DEBUG AbstractBatcher.logCloseResults - about to close ResultSet (open ResultSets: 1, globally: 1)
2005-02-09 10:32:58,792 DEBUG AbstractBatcher.logClosePreparedStatement - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-02-09 10:32:58,792 DEBUG AbstractBatcher.closePreparedStatement - closing statement
2005-02-09 10:32:58,792 DEBUG Loader.initializeEntitiesAndCollections - total objects hydrated: 0
2005-02-09 10:32:58,792 DEBUG PersistenceContext.initializeNonLazyCollections - initializing non-lazy collections
2005-02-09 10:32:58,792 DEBUG SessionImpl.close - closing session
2005-02-09 10:32:58,792 DEBUG SessionImpl.disconnect - disconnecting session
2005-02-09 10:32:58,792 DEBUG AbstractBatcher.closeConnection - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
2005-02-09 10:32:58,802 DEBUG DriverManagerConnectionProvider.closeConnection - returning connection to pool, pool size: 1
2005-02-09 10:32:58,802 DEBUG SessionImpl.afterTransactionCompletion - after transaction completion


If your require it, I can try to set up another test (because this one is meant to test my infrastructure and posting it would be quite complex).

Thanks again,

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 2:24 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Quote:
2005-02-09 10:32:58,782 DEBUG Loader.doQuery - processing result set
2005-02-09 10:32:58,782 DEBUG Loader.doQuery - result set row: 0
2005-02-09 10:32:58,782 DEBUG LongType.nullSafeGet - returning '10001018' as column: id0_
2005-02-09 10:32:58,782 DEBUG LongType.nullSafeGet - returning '10002302' as column: id1_
2005-02-09 10:32:58,782 DEBUG Loader.getRow - result row: EntityKey[my.package.domain.Blog#10001018], EntityKey[my.package.domain.BlogEntry#10002302]
2005-02-09 10:32:58,792 DEBUG Loader.doQuery - result set row: 1
2005-02-09 10:32:58,792 DEBUG LongType.nullSafeGet - returning '10001018' as column: id0_
2005-02-09 10:32:58,792 DEBUG LongType.nullSafeGet - returning '10002303' as column: id1_
2005-02-09 10:32:58,792 DEBUG Loader.getRow - result row: EntityKey[my.package.domain.Blog#10001018], EntityKey[my.package.domain.BlogEntry#10002303]
2005-02-09 10:32:58,792 DEBUG Loader.doQuery - done processing result set (2 rows)


That all looks exactly as it should. You said there should be one Blog with 2 BlogEntries returned, correct?


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 3:53 pm 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
Hi Steve,

I agree with you. Since I added left join fetch blog.blogEntries , The SQL for loading the blogEntry is showing in the logs and, to my surprise, I do see too that the query returns 2 blogEntries.

The Blog that is created though still has 3 blogEntry.

I took the SQL query with the outer join that I see in the log and hit the database directly with it, it returned 2 results, as expected.

But I am still not able to load my objects properly.

my Junit test is:
Code:
public void testAccessIsRestrictedThroughObjectHierarchyFromTopLevelObject()
    {
       Collection col = blogDAO.retrieveBlogsForUser(averageJoeUser, AccessLevel.Permission.READ, true);       
       Blog blog = (Blog)col.iterator().next();
        assertEquals("When BlogEntry ACL is on, user should not have access to restricted blog entries by navigating the association", 2, blog.getBlogEntries().size());
    }


The DAO code is:

Code:
session.enableFilter("blogEntryACLSecurityFilter").setParameter("currentUserId", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
session.enableFilter("hasValidRoles").setParameter("securizedUser", user.getUserid()).setParameter("accessLevel", accessLevel);
Query query = session.createQuery("FROM my.package.domain.Blog blog left join fetch blog.blogEntries");
return query.list();


This is the exact code that also outputs what I have posted on my last post. I am sorry for taking your time like that. I am beginning to believe that I am doing something really stupid but not seing it.

Is there a way to disable caching in order to see if the problem is coming from there?

Any other ideas? (I have tried with Hibernate beta 1, 2, and 3 : same problem)

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 4:09 pm 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
Steve,

I have found something: If I do a session.clear() before applying the filters, it works.

Code:
session.clear();
session.enableFilter("blogEntryACLSecurityFilter").setParameter("currentUserId", user.getUserid()).setParameter("accessLevel", AccessLevel.Permission.READ);
session.enableFilter("hasValidRoles").setParameter("securizedUser", user.getUserid()).setParameter("accessLevel", accessLevel);
Query query = session.createQuery("FROM my.package.domain.Blog blog");
return query.list();


Maybe this might give you an idea about what I am doing wrong!

Thanks in advance

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 4:27 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Yes, as I said before it means that that session you are using had prior knowledge of that collection (i.e., it was associated with the session prior to enabling the filters). Clearing the session disassociated the collection from the session.


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 4:41 pm 
Senior
Senior

Joined: Tue Feb 08, 2005 5:26 pm
Posts: 157
Location: Montréal, Québec - Canada
Hi Steve,
One last question:

I am obviously not familiar with objects lifecycle within the session. Just to make sure that I get this straight:

In the following scenario:
    I begin a transaction
    I create objects and saved them
    I commit my transaction
    I set up filters
    I query on the data that I had previously loaded
    --> I will retrieve cached data and filters might not applied

The above scenario is expected behaviour and session data will not be invalidated and filters might not be applied unless I clear the session before querying.

Is that correct?

Thank you very much for your help.
I appreciate it.

_________________
Vincent Giguère
J2EE Developer


Top
 Profile  
 
 Post subject:
PostPosted: Wed Feb 09, 2005 5:55 pm 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 3:00 pm
Posts: 1816
Location: Austin, TX
Yes, filters are only applied when Hibernate needs to hit the database. In your case, where the collection was already cached in the session, the filter would not be "applied" because Hibernate does not need to hit the database.

That is expected behaviour.


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 15 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.