-->
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.

View unanswered posts | View active topics


Board index » Projects » Search, Validator, Shards

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 3 posts ] 
  Previous topic | Next topic 
Author Message
tindor
 Post subject: Transaction timeout when using MassIndexer
PostPosted: Thu Jun 21, 2012 5:14 am 
Newbie

Joined: Thu Jun 21, 2012 4:56 am
Posts: 2
Hi,
I'm quite new to Hibernate search, but I've read the reference and I've tried to create my first index. Everything went good on a small database with less than 500 items in the master table.
When I tried to create an index on the same table, but on a different DB server where there are around 1100 items I got transaction timeout problems.
I've tried to disable transactions but in vain. I've also tried to increase timeout, but it does not work.
I'll be very grateful if you can help me, here's the code :
Code:
   @TransactionAttribute(TransactionAttributeType.NEVER)
   @TransactionTimeout(value=2 , unit= TimeUnit.HOURS)
   public void reindex() throws InterruptedException {
      FullTextEntityManager fullTextEntityManager = Search
            .getFullTextEntityManager(em);
      MassIndexer indexer = fullTextEntityManager.createIndexer();
      indexer
         .batchSizeToLoadObjects( 30 )
         .threadsForSubsequentFetching( 2 )
         .threadsToLoadObjects( 2 )
         .cacheMode(CacheMode.IGNORE);
      //this starts synchronously
      indexer.startAndWait();
   }


This code is in a stateless bean and is invoked through a rest service. There's nothing special there except for the permission check.
I've tried to adjust the number of threads, because the DB server is running on a virtual machine with very little ram (512 mb), but it didn't help.
I've tried to change cacheMode to NORMAL, but then I get NullPointer somewhere when hibernate search tries to initialize a lazy collection.

I've also tried to get Hibernate session from the EntityManager, but I always get roughly the same exceptions and it happens about 5 minutes after the index writer is stared (the default transaction timeout is 300 seconds) :
Code:
11:37:09,327 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,327 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getTransactionKey
11:37:09,327 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getTransactionKey
11:37:09,327 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getResource
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getResource
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) BaseTransaction.getStatus
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,328 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,329 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,329 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,329 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,329 INFO  [stdout] (Hibernate Search: collectionsloader-1) Hibernate:
11:37:09,329 INFO  [stdout] (Hibernate Search: collectionsloader-1)     select
11:37:09,329 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.ID as ID19_6_,
11:37:09,330 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.CREATION_DATE as CREATION2_19_6_,
11:37:09,330 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.CREATOR_ID as CREATOR8_19_6_,
11:37:09,330 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.HEADLINE as HEADLINE19_6_,
11:37:09,330 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_DATA as IMAGE4_19_6_,
11:37:09,330 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_NAME as IMAGE5_19_6_,
11:37:09,331 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_TYPE_ID as IMAGE9_19_6_,
11:37:09,331 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IS_ACTIVE as IS6_19_6_,
11:37:09,331 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.LAST_UPDATE_DATE as LAST7_19_6_,
11:37:09,331 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.ID as ID18_0_,
11:37:09,331 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.CREATOR_ID as CREATOR14_18_0_,
11:37:09,332 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.DEACTIVATION_DATE as DEACTIVA2_18_0_,
11:37:09,332 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.E_MAIL as E3_18_0_,
11:37:09,332 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.FEEDBACKS_CREATED as FEEDBACKS4_18_0_,
11:37:09,333 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.IS_ACTIVE as IS5_18_0_,
11:37:09,333 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.LAST_LOGIN_DATE as LAST6_18_0_,
11:37:09,333 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.LAST_UPDATE_DATE as LAST7_18_0_,
11:37:09,334 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.OPINIONS_CREATED as OPINIONS8_18_0_,
11:37:09,334 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.PASSWORD as PASSWORD18_0_,
11:37:09,334 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.PRODUCTS_CREATED as PRODUCTS10_18_0_,
11:37:09,334 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.REGISTRATION_DATE as REGISTR11_18_0_,
11:37:09,335 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.USER_PROFILE_ID as USER12_18_0_,
11:37:09,335 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.VISIBLE_NAME as VISIBLE13_18_0_,
11:37:09,335 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.ID as ID18_1_,
11:37:09,336 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.CREATOR_ID as CREATOR14_18_1_,
11:37:09,336 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.DEACTIVATION_DATE as DEACTIVA2_18_1_,
11:37:09,336 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.E_MAIL as E3_18_1_,
11:37:09,337 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.FEEDBACKS_CREATED as FEEDBACKS4_18_1_,
11:37:09,337 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.IS_ACTIVE as IS5_18_1_,
11:37:09,337 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.LAST_LOGIN_DATE as LAST6_18_1_,
11:37:09,337 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.LAST_UPDATE_DATE as LAST7_18_1_,
11:37:09,338 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.OPINIONS_CREATED as OPINIONS8_18_1_,
11:37:09,338 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.PASSWORD as PASSWORD18_1_,
11:37:09,338 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.PRODUCTS_CREATED as PRODUCTS10_18_1_,
11:37:09,339 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.REGISTRATION_DATE as REGISTR11_18_1_,
11:37:09,339 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.USER_PROFILE_ID as USER12_18_1_,
11:37:09,339 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.VISIBLE_NAME as VISIBLE13_18_1_,
11:37:09,340 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.USER_ID as USER4_18_8_,
11:37:09,340 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ID as ID8_,
11:37:09,340 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ID as ID15_2_,
11:37:09,341 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.CATEGORY_ID as CATEGORY2_15_2_,
11:37:09,341 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ROLE_ID as ROLE3_15_2_,
11:37:09,341 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.USER_ID as USER4_15_2_,
11:37:09,342 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.ID as ID9_3_,
11:37:09,342 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.IS_ACTIVE as IS2_9_3_,
11:37:09,342 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.SYSTEM_CODE as SYSTEM3_9_3_,
11:37:09,342 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.ID as ID4_4_,
11:37:09,343 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.IS_ACTIVE as IS2_4_4_,
11:37:09,343 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.SYSTEM_CODE as SYSTEM3_4_4_,
11:37:09,343 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.ID as ID2_5_,
11:37:09,343 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.NAME as NAME2_5_,
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.SYSTEM_CODE as SYSTEM3_2_5_
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)     from
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)         IMAGES image0_
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USERS user1_
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on image0_.CREATOR_ID=user1_.ID
11:37:09,344 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USERS user2_
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on user1_.CREATOR_ID=user2_.ID
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USER_ROLES userrolesl3_
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on user2_.ID=userrolesl3_.USER_ID
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,345 INFO  [stdout] (Hibernate Search: collectionsloader-1)         CATEGORIES category4_
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on userrolesl3_.CATEGORY_ID=category4_.ID
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)         ROLES role5_
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on userrolesl3_.ROLE_ID=role5_.ID
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)         IMAGE_TYPES imagetype6_
11:37:09,346 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on image0_.IMAGE_TYPE_ID=imagetype6_.ID
11:37:09,347 INFO  [stdout] (Hibernate Search: collectionsloader-1)     where
11:37:09,347 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.ID=?
11:37:09,408 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()
11:37:09,408 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()
11:37:09,408 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1340267829407
11:37:09,409 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:-d5afc69:4fe2dbdd:14 in state  RUN
11:37:09,409 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Reaper scheduling TX for cancellation 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,410 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1340267829417
11:37:09,410 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Thread Thread[Transaction Reaper Worker 0,5,main] performing cancellations
11:37:09,410 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 7
11:37:09,411 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Reaper Worker Thread[Transaction Reaper Worker 0,5,main] attempting to cancel 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,412 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::Abort() for action-id 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,413 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:-d5afc69:4fe2dbdd:14 invoked while multiple threads active within it.
11:37:09,413 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 aborting with 1 threads active!
11:37:09,414 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeAllChildThreads () action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 removing Thread[Hibernate Search: collectionsloader-2,5,main]
11:37:09,414 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 removing TSThread:9
11:37:09,415 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 removing TSThread:9 result = true
11:37:09,416 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) InputObjectState::InputObjectState()
11:37:09,416 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) FileSystemStore.allObjUids(EISNAME, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
11:37:09,416 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) OutputObjectState::OutputObjectState()
11:37:09,418 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()
11:37:09,418 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()
11:37:09,418 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1340267829417
11:37:09,419 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:-d5afc69:4fe2dbdd:15 in state  RUN
11:37:09,419 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Reaper scheduling TX for cancellation 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,419 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1340267829909
11:37:09,420 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 490
11:37:09,432 TRACE [org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate] (Hibernate Search: collectionsloader-2) add to Lucene index: class com.example.project.model.Product#1546:Document<stored,indexed,omitNorms<_hibernate_class:com.example.project.model.Product> stored,indexed,omitNorms<id:1546> stored,indexed<creationDate:20120608081611163> stored,indexed<isActive:true> stored,indexed<attributesVersion:2> stored,indexed<category.id:1> stored,indexed<category.isActive:true> stored,indexed<category.systemCode:DATING_AGENCY> stored,indexed<category.categoryAttributesList.id:9> stored,indexed<category.categoryAttributesList.isActive:true> stored,indexed<category.categoryAttributesList.isAttribute1Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute2Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute3Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute4Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute5Searchable:true> stored,indexed<category.categoryAttributesList.creator.id:1> stored,indexed<category.categoryAttributesList.attribute1TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute3TypeId.id:100009> stored,indexed<category.categoryAttributesList.attribute2TypeId.id:100010> stored,indexed<category.categoryAttributesList.attribute4TypeId.id:100009> stored,indexed<category.categoryAttributesList.attribute5TypeId.id:100009> stored,indexed<category.categoryAttributesList.translations.id:4> stored,indexed<category.categoryAttributesList.id:1> stored,indexed<category.categoryAttributesList.isActive:false> stored,indexed<category.categoryAttributesList.isAttribute1Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute2Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute3Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute4Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute5Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute6Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute7Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute8Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute9Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute10Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute11Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute12Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute13Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute14Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute15Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute16Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute17Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute18Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute19Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute20Searchable:false> stored,indexed<category.categoryAttributesList.creator.id:1> stored,indexed<category.categoryAttributesList.attribute9TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute8TypeId.id:102003> stored,indexed<category.categoryAttributesList.attribute7TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute6TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute21TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute20TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute1TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute19TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute18TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute17TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute16TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute15TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute14TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute13TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute12TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute11TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute10TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute3TypeId.id:100010> stored,indexed<category.categoryAttributesList.attribute2TypeId.id:102001> stored,indexed<category.categoryAttributesList.attribute4TypeId.id:100011> stored,indexed<category.categoryAttributesList.attribute5TypeId.id:102002> stored,indexed<category.categoryAttributesList.translations.id:1>>
11:37:09,438 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::doAbort (LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@6f696c6[connectionListener=765f6ac6 connectionManager=2724a4bc warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-d5afc69:4fe2dbdd:14, node_name=1, branch_uid=0:ffff7f000101:-d5afc69:4fe2dbdd:27, subordinatenodename=null, eis_name=unknown eis name >])))
11:37:09,441 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-2) TransactionImple.getStatus
11:37:09,442 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) LastResourceRecord::topLevelAbort() for 0:0:0:0:1
11:37:09,529 TRACE [org.hibernate.search.backend.impl.lucene.works.AddWorkDelegate] (Hibernate Search: collectionsloader-1) add to Lucene index: class com.example.project.model.Product#1528:Document<stored,indexed,omitNorms<_hibernate_class:com.example.project.model.Product> stored,indexed,omitNorms<id:1528> stored,indexed<creationDate:20120608081603181> stored,indexed<isActive:true> stored,indexed<attributesVersion:2> stored,indexed<category.id:1> stored,indexed<category.isActive:true> stored,indexed<category.systemCode:DATING_AGENCY> stored,indexed<category.categoryAttributesList.id:9> stored,indexed<category.categoryAttributesList.isActive:true> stored,indexed<category.categoryAttributesList.isAttribute1Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute2Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute3Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute4Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute5Searchable:true> stored,indexed<category.categoryAttributesList.creator.id:1> stored,indexed<category.categoryAttributesList.attribute1TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute3TypeId.id:100009> stored,indexed<category.categoryAttributesList.attribute2TypeId.id:100010> stored,indexed<category.categoryAttributesList.attribute4TypeId.id:100009> stored,indexed<category.categoryAttributesList.attribute5TypeId.id:100009> stored,indexed<category.categoryAttributesList.translations.id:4> stored,indexed<category.categoryAttributesList.id:1> stored,indexed<category.categoryAttributesList.isActive:false> stored,indexed<category.categoryAttributesList.isAttribute1Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute2Searchable:true> stored,indexed<category.categoryAttributesList.isAttribute3Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute4Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute5Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute6Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute7Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute8Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute9Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute10Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute11Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute12Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute13Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute14Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute15Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute16Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute17Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute18Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute19Searchable:false> stored,indexed<category.categoryAttributesList.isAttribute20Searchable:false> stored,indexed<category.categoryAttributesList.creator.id:1> stored,indexed<category.categoryAttributesList.attribute9TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute8TypeId.id:102003> stored,indexed<category.categoryAttributesList.attribute7TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute6TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute21TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute20TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute1TypeId.id:101004> stored,indexed<category.categoryAttributesList.attribute19TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute18TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute17TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute16TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute15TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute14TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute13TypeId.id:100007> stored,indexed<category.categoryAttributesList.attribute12TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute11TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute10TypeId.id:100003> stored,indexed<category.categoryAttributesList.attribute3TypeId.id:100010> stored,indexed<category.categoryAttributesList.attribute2TypeId.id:102001> stored,indexed<category.categoryAttributesList.attribute4TypeId.id:100011> stored,indexed<category.categoryAttributesList.attribute5TypeId.id:102002> stored,indexed<category.categoryAttributesList.translations.id:1>>
11:37:09,536 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,536 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getTransactionKey
11:37:09,536 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getTransactionKey
11:37:09,536 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getResource
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionSynchronizationRegistryImple.getResource
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) BaseTransaction.getStatus
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,537 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,538 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,538 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,538 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.equals
11:37:09,538 INFO  [stdout] (Hibernate Search: collectionsloader-1) Hibernate:
11:37:09,538 INFO  [stdout] (Hibernate Search: collectionsloader-1)     select
11:37:09,538 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.ID as ID19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.CREATION_DATE as CREATION2_19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.CREATOR_ID as CREATOR8_19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.HEADLINE as HEADLINE19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_DATA as IMAGE4_19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_NAME as IMAGE5_19_6_,
11:37:09,539 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IMAGE_TYPE_ID as IMAGE9_19_6_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.IS_ACTIVE as IS6_19_6_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.LAST_UPDATE_DATE as LAST7_19_6_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.ID as ID18_0_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.CREATOR_ID as CREATOR14_18_0_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.DEACTIVATION_DATE as DEACTIVA2_18_0_,
11:37:09,540 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.E_MAIL as E3_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.FEEDBACKS_CREATED as FEEDBACKS4_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.IS_ACTIVE as IS5_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.LAST_LOGIN_DATE as LAST6_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.LAST_UPDATE_DATE as LAST7_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.OPINIONS_CREATED as OPINIONS8_18_0_,
11:37:09,541 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.PASSWORD as PASSWORD18_0_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.PRODUCTS_CREATED as PRODUCTS10_18_0_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.REGISTRATION_DATE as REGISTR11_18_0_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.USER_PROFILE_ID as USER12_18_0_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user1_.VISIBLE_NAME as VISIBLE13_18_0_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.ID as ID18_1_,
11:37:09,542 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.CREATOR_ID as CREATOR14_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.DEACTIVATION_DATE as DEACTIVA2_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.E_MAIL as E3_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.FEEDBACKS_CREATED as FEEDBACKS4_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.IS_ACTIVE as IS5_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.LAST_LOGIN_DATE as LAST6_18_1_,
11:37:09,543 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.LAST_UPDATE_DATE as LAST7_18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.OPINIONS_CREATED as OPINIONS8_18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.PASSWORD as PASSWORD18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.PRODUCTS_CREATED as PRODUCTS10_18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.REGISTRATION_DATE as REGISTR11_18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.USER_PROFILE_ID as USER12_18_1_,
11:37:09,544 INFO  [stdout] (Hibernate Search: collectionsloader-1)         user2_.VISIBLE_NAME as VISIBLE13_18_1_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.USER_ID as USER4_18_8_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ID as ID8_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ID as ID15_2_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.CATEGORY_ID as CATEGORY2_15_2_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.ROLE_ID as ROLE3_15_2_,
11:37:09,545 INFO  [stdout] (Hibernate Search: collectionsloader-1)         userrolesl3_.USER_ID as USER4_15_2_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.ID as ID9_3_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.IS_ACTIVE as IS2_9_3_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         category4_.SYSTEM_CODE as SYSTEM3_9_3_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.ID as ID4_4_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.IS_ACTIVE as IS2_4_4_,
11:37:09,546 INFO  [stdout] (Hibernate Search: collectionsloader-1)         role5_.SYSTEM_CODE as SYSTEM3_4_4_,
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.ID as ID2_5_,
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.NAME as NAME2_5_,
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)         imagetype6_.SYSTEM_CODE as SYSTEM3_2_5_
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)     from
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)         IMAGES image0_
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,547 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USERS user1_
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on image0_.CREATOR_ID=user1_.ID
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USERS user2_
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on user1_.CREATOR_ID=user2_.ID
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)         USER_ROLES userrolesl3_
11:37:09,548 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on user2_.ID=userrolesl3_.USER_ID
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)         CATEGORIES category4_
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on userrolesl3_.CATEGORY_ID=category4_.ID
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)         ROLES role5_
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on userrolesl3_.ROLE_ID=role5_.ID
11:37:09,549 INFO  [stdout] (Hibernate Search: collectionsloader-1)     left outer join
11:37:09,550 INFO  [stdout] (Hibernate Search: collectionsloader-1)         IMAGE_TYPES imagetype6_
11:37:09,550 INFO  [stdout] (Hibernate Search: collectionsloader-1)             on image0_.IMAGE_TYPE_ID=imagetype6_.ID
11:37:09,550 INFO  [stdout] (Hibernate Search: collectionsloader-1)     where
11:37:09,550 INFO  [stdout] (Hibernate Search: collectionsloader-1)         image0_.ID=?
11:37:09,556 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-2) SQL Error: 0, SQLState: null
11:37:09,556 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-2) javax.resource.ResourceException: IJ000460: Error checking for a transaction
11:37:09,616 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (Hibernate Search: collectionsloader-2) HHH000327: Error performing load command : org.hibernate.exception.GenericJDBCException: Could not open connection
11:37:09,617 INFO  [stdout] (Hibernate Search: collectionsloader-2) org.hibernate.exception.GenericJDBCException: Could not open connection
11:37:09,617 DEBUG [org.hibernate.search.batchindexing.impl.EntityConsumerLuceneWorkProducer] (Hibernate Search: collectionsloader-2) finished
11:37:09,617 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-2) BaseTransaction.commit
11:37:09,618 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-2) TransactionImple.commitAndDisassociate
11:37:09,618 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) BasicAction::Abort() for action-id 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,618 WARN  [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,635 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,635 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,636 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,636 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,636 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,636 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,637 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) BaseTransaction.getStatus
11:37:09,638 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-d5afc69:4fe2dbdd:14 status: ActionStatus.ABORTED )
11:37:09,638 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 removing TSThread:4
11:37:09,638 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:-d5afc69:4fe2dbdd:14
11:37:09,638 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:14 removing TSThread:4 result = true
11:37:09,639 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Reaper Worker Thread[Transaction Reaper Worker 0,5,main] attempting to cancel 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,639 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-d5afc69:4fe2dbdd:14 status: ActionStatus.ABORTED )
11:37:09,640 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::Abort() for action-id 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,640 INFO  [stdout] (Hibernate Search: collectionsloader-2) javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
11:37:09,640 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:-d5afc69:4fe2dbdd:15 invoked while multiple threads active within it.
11:37:09,641 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-2) BaseTransaction.rollback
11:37:09,641 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 aborting with 1 threads active!
11:37:09,641 INFO  [stdout] (Hibernate Search: collectionsloader-2) java.lang.IllegalStateException: BaseTransaction.rollback - ARJUNA016074: no transaction!
11:37:09,641 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeAllChildThreads () action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 removing Thread[Hibernate Search: collectionsloader-1,5,main]
11:37:09,642 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 removing TSThread:9
11:37:09,643 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 removing TSThread:9 result = true
11:37:09,643 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) BasicAction::doAbort (LastResourceRecord(XAOnePhaseResource(LocalXAResourceImpl@46e5dce1[connectionListener=3c536f11 connectionManager=2724a4bc warned=false currentXid=< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000101:-d5afc69:4fe2dbdd:15, node_name=1, branch_uid=0:ffff7f000101:-d5afc69:4fe2dbdd:29, subordinatenodename=null, eis_name=unknown eis name >])))
11:37:09,644 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) LastResourceRecord::topLevelAbort() for 0:0:0:0:1
11:37:09,702 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,703 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.getStatus
11:37:09,703 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,703 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-1) SQL Error: 0, SQLState: null
11:37:09,703 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,704 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-1) javax.resource.ResourceException: IJ000460: Error checking for a transaction
11:37:09,704 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,705 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (Hibernate Search: collectionsloader-1) HHH000327: Error performing load command : org.hibernate.exception.GenericJDBCException: Could not open connection
11:37:09,705 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) TransactionImple.equals
11:37:09,706 INFO  [stdout] (Hibernate Search: collectionsloader-1) org.hibernate.exception.GenericJDBCException: Could not open connection
11:37:09,706 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) SynchronizationImple.afterCompletion
11:37:09,707 DEBUG [org.hibernate.search.batchindexing.impl.BatchIndexingWorkspace] (Hibernate Search: BatchIndexingWorkspace-1) All work for type com.example.project.model.Product has been produced
11:37:09,706 DEBUG [org.hibernate.search.batchindexing.impl.EntityConsumerLuceneWorkProducer] (Hibernate Search: collectionsloader-1) finished
11:37:09,707 TRACE [org.hibernate.search.spi.internals.PolymorphicIndexHierarchy] (http--0.0.0.0-8080-1) Targeted indexed classes for [class com.example.project.model.Product]: [class com.example.project.model.Product]
11:37:09,707 TRACE [com.arjuna.ats.jta] (Transaction Reaper Worker 0) BaseTransaction.getStatus
11:37:09,708 TRACE [org.hibernate.search.backend.impl.lucene.works.OptimizeWorkDelegate] (http--0.0.0.0-8080-1) optimize Lucene index: null
11:37:09,708 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) BaseTransaction.commit
11:37:09,709 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) TransactionImple.commitAndDisassociate
11:37:09,709 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-d5afc69:4fe2dbdd:15 status: ActionStatus.ABORTED )
11:37:09,721 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) BasicAction::Abort() for action-id 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,721 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,722 WARN  [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:-d5afc69:4fe2dbdd:15
11:37:09,722 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) Thread Thread[Transaction Reaper Worker 0,5,main] waiting for cancelled TXs
11:37:09,723 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 removing TSThread:5
11:37:09,724 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) BasicAction::removeChildThread () action 0:ffff7f000101:-d5afc69:4fe2dbdd:15 removing TSThread:5 result = true
11:37:09,724 TRACE [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) TransactionReaper::remove ( BasicAction: 0:ffff7f000101:-d5afc69:4fe2dbdd:15 status: ActionStatus.ABORTED )
11:37:09,725 INFO  [stdout] (Hibernate Search: collectionsloader-1) javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
11:37:09,725 TRACE [com.arjuna.ats.jta] (Hibernate Search: collectionsloader-1) BaseTransaction.rollback
11:37:09,725 INFO  [stdout] (Hibernate Search: collectionsloader-1) java.lang.IllegalStateException: BaseTransaction.rollback - ARJUNA016074: no transaction!
11:37:09,910 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()
11:37:09,910 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()
11:37:09,910 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 9223372036854775807
11:37:09,911 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 9223370696586945896
11:37:10,094 DEBUG [org.hibernate.search.backend.impl.lucene.works.FlushWorkDelegate] (http--0.0.0.0-8080-1) performing FlushWorkDelegate
11:37:10,649 TRACE [org.hibernate.search.backend.impl.lucene.IndexWriterHolder] (http--0.0.0.0-8080-1) Index changes commited.
11:37:10,649 INFO  [org.hibernate.search.jmx.IndexingProgressMonitor] (http--0.0.0.0-8080-1) HSEARCH000029: Indexing completed. Reindexed 1548 entities. Unregistering MBean from server
11:37:10,650 TRACE [com.arjuna.ats.jta] (http--0.0.0.0-8080-1) BaseTransaction.getStatus
11:37:10,760 DEBUG [com.example.project.rest.filters.LocaleFilter] (http--0.0.0.0-8080-1) Removing locale from LocaleThreadLocal
11:37:10,834 TRACE [org.jboss.security.SecurityRolesAssociation] (http--0.0.0.0-8080-1) Setting threadlocal:null
11:37:10,835 TRACE [com.arjuna.ats.jta] (http--0.0.0.0-8080-1) BaseTransaction.getStatus
11:37:55,980 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
11:37:55,980 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
11:37:55,980 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Thu, 21 Jun 2012 11:37:55
11:37:55,981 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:37:55,981 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
11:37:55,981 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
11:37:55,982 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:37:55,982 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
11:37:55,983 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:37:55,983 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
11:37:55,983 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:37:55,983 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
11:37:55,984 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:37:55,984 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000101:-d5afc69:4fe2dbdd:38
OutputObjectState Type  : null
OutputObjectState Size  : 24
OutputObjectState Buffer: , Recovery)
11:37:56,001 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000101:-d5afc69:4fe2dbdd:38
OutputObjectState Type  : null
OutputObjectState Size  : 64
OutputObjectState Buffer: , Recovery/TransactionStatusManager)
11:37:56,003 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:37:56,004 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
11:37:56,004 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:37:56,004 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:37:56,004 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
11:37:56,005 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:37:56,005 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, StateType.OS_SHADOW)
11:37:56,005 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, 10)
11:37:56,006 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, StateType.OS_ORIGINAL)
11:37:56,006 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, 11)
11:37:56,006 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager) - returning StateStatus.OS_COMMITTED
11:37:56,007 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:37:56,007 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass
11:37:56,007 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:37:56,007 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
11:37:56,007 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:37:56,008 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:38:06,008 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Thu, 21 Jun 2012 11:38:06
11:38:06,008 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
11:38:06,008 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:38:06,009 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
11:38:06,009 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:38:06,009 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass
11:38:06,009 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed
11:38:06,010 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed
11:38:06,010 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:38:06,010 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
11:38:06,011 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off
11:40:06,011 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
11:40:06,011 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
11:40:06,012 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Thu, 21 Jun 2012 11:40:06
11:40:06,012 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:40:06,012 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
11:40:06,012 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
11:40:06,013 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:40:06,013 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
11:40:06,014 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:06,014 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
11:40:06,014 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:40:06,014 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
11:40:06,015 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:40:06,015 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000101:-d5afc69:4fe2dbdd:3d
OutputObjectState Type  : null
OutputObjectState Size  : 24
OutputObjectState Buffer: , Recovery)
11:40:06,063 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(OutputObjectState Uid   : 0:ffff7f000101:-d5afc69:4fe2dbdd:3d
OutputObjectState Type  : null
OutputObjectState Size  : 64
OutputObjectState Buffer: , Recovery/TransactionStatusManager)
11:40:06,066 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:40:06,066 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
11:40:06,066 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:40:06,067 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:40:06,067 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 2)
11:40:06,068 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:40:06,068 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, StateType.OS_SHADOW)
11:40:06,068 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, 10)
11:40:06,068 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, StateType.OS_ORIGINAL)
11:40:06,069 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.genPathName(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager, 11)
11:40:06,069 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) ShadowingStore.currentState(0:ffff7f000101:-d5afc69:4fe2dbdd:a, Recovery/TransactionStatusManager) - returning StateStatus.OS_COMMITTED
11:40:06,069 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:06,069 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass
11:40:06,070 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
11:40:06,070 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
11:40:06,070 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
11:40:06,070 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:16,070 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Thu, 21 Jun 2012 11:40:16
11:40:16,071 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
11:40:16,071 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:16,071 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
11:40:16,072 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:16,072 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass
11:40:16,072 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed
11:40:16,073 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed
11:40:16,073 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) 
11:40:16,073 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
11:40:16,073 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off


I'm also using Jboss AS 7.1 , Hibernate search 4.1.1 , JPA with Hibernate and maven.
Top
 Profile  
 
hardy.ferentschik
 Post subject: Re: Transaction timeout when using MassIndexer
PostPosted: Mon Jun 25, 2012 5:02 am 
Hibernate Team
Hibernate Team

Joined: Thu Apr 05, 2007 5:52 am
Posts: 1689
Location: Sweden
Hi,

have you tried to remove all transaction annotations. You don't really need it. 5 minutes for 1100 items sounds also very high. It seems to me that something else is going on there. How does your actual domain model look like and what is the exact exception? Do you have some self referencing data? Maybe you need to set the max depth attribute for some indexed embedded associations? Are you executing other transactional code while indexing occurs?

--Hardy
Top
 Profile  
 
tindor
 Post subject: Re: Transaction timeout when using MassIndexer
PostPosted: Mon Jun 25, 2012 3:09 pm 
Newbie

Joined: Thu Jun 21, 2012 4:56 am
Posts: 2
Hi,
Thanks for the fast response!
Here's the last exception I get when I run the indexer :
Code:
20:44:38,366 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:7ac6b937:4fe857a3:1757
20:44:38,366 WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-1) SQL Error: 0, SQLState: null
20:44:38,367 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:7ac6b937:4fe857a3:1758 invoked while multiple threads active within it.
20:44:38,367 ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (Hibernate Search: collectionsloader-1) javax.resource.ResourceException: IJ000460: Error checking for a transaction
20:44:38,367 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:7ac6b937:4fe857a3:1758 aborting with 1 threads active!
20:44:38,426 INFO  [org.hibernate.engine.jdbc.internal.LogicalConnectionImpl] (Transaction Reaper Worker 0) HHH000106: Forcing container resource cleanup on transaction completion
20:44:38,427 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:7ac6b937:4fe857a3:1758
20:44:38,472 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (Hibernate Search: collectionsloader-2) HHH000327: Error performing load command : org.hibernate.HibernateException: proxy handle is no longer valid
20:44:38,473 INFO  [stdout] (Hibernate Search: collectionsloader-2) org.hibernate.HibernateException: proxy handle is no longer valid
20:44:38,473 DEBUG [org.hibernate.search.batchindexing.impl.EntityConsumerLuceneWorkProducer] (Hibernate Search: collectionsloader-2) finished
20:44:38,495 WARN  [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-2) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:7ac6b937:4fe857a3:1758
20:44:38,496 INFO  [stdout] (Hibernate Search: collectionsloader-2) javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
20:44:38,496 INFO  [stdout] (Hibernate Search: collectionsloader-2) java.lang.IllegalStateException: BaseTransaction.rollback - ARJUNA016074: no transaction!
20:44:38,545 INFO  [org.hibernate.event.internal.DefaultLoadEventListener] (Hibernate Search: collectionsloader-1) HHH000327: Error performing load command : org.hibernate.exception.GenericJDBCException: Could not open connection
20:44:38,556 INFO  [stdout] (Hibernate Search: collectionsloader-1) org.hibernate.exception.GenericJDBCException: Could not open connection
20:44:38,557 DEBUG [org.hibernate.search.batchindexing.impl.EntityConsumerLuceneWorkProducer] (Hibernate Search: collectionsloader-1) finished
20:44:38,584 WARN  [com.arjuna.ats.arjuna] (Hibernate Search: collectionsloader-1) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:7ac6b937:4fe857a3:1757
20:44:38,584 DEBUG [org.hibernate.search.batchindexing.impl.BatchIndexingWorkspace] (Hibernate Search: BatchIndexingWorkspace-1) All work for type com.example.model.Product has been produced
20:44:38,585 INFO  [stdout] (Hibernate Search: collectionsloader-1) javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
20:44:38,585 TRACE [org.hibernate.search.spi.internals.PolymorphicIndexHierarchy] (http--0.0.0.0-8080-2) Targeted indexed classes for [class com.example.model.Product]: [class com.example.model.Product]
20:44:38,585 INFO  [stdout] (Hibernate Search: collectionsloader-1) java.lang.IllegalStateException: BaseTransaction.rollback - ARJUNA016074: no transaction!
20:44:38,586 TRACE [org.hibernate.search.backend.impl.lucene.works.OptimizeWorkDelegate] (http--0.0.0.0-8080-2) optimize Lucene index: null
20:44:50,970 DEBUG [org.hibernate.search.backend.impl.lucene.works.FlushWorkDelegate] (http--0.0.0.0-8080-2) performing FlushWorkDelegate
20:45:00,099 TRACE [org.hibernate.search.backend.impl.lucene.IndexWriterHolder] (http--0.0.0.0-8080-2) Index changes commited.
20:45:00,099 INFO  [org.hibernate.search.jmx.IndexingProgressMonitor] (http--0.0.0.0-8080-2) HSEARCH000029: Indexing completed. Reindexed 1551 entities. Unregistering MBean from server


The message
Code:
20:45:00,099 INFO  [org.hibernate.search.jmx.IndexingProgressMonitor] (http--0.0.0.0-8080-2) HSEARCH000029: Indexing completed. Reindexed 1551 entities. Unregistering MBean from
is misleading, because the index does not contain 1551 entities, but just around 280.

As for the speed - the DB is running on a virtual machine with very little ram (I think 512 mb), on which I've installed Jboss 7.1 and Postgresql. On a real machine the DB is about 10 times faster, but still, the problem will still be there, just it'll timeout at a later moment.
I also ran the indexer again without any transactional annoations(besides @Stateless) and I got this:

Code:
1:18:15,288 ERROR [com.example.rest.services.LuceneIndexRestService] (http--0.0.0.0-8080-1) Exception reindexing products: javax.ejb.EJBTransactionRolledbackException: Transaction rolled back
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleEndTransactionException(CMTTxInterceptor.java:115) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:95) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:232) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:32) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final]
   at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final]
   at com.example.service.impl.HibernateIndexLoaderService$$$view10.reindex(Unknown Source) [example-ejb-1.0-SNAPSHOT.jar:]
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_26]
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [rt.jar:1.6.0_26]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_26]
   at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_26]
   at org.jboss.weld.util.reflection.SecureReflections$13.work(SecureReflections.java:264) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.util.reflection.SecureReflectionAccess.run(SecureReflectionAccess.java:52) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.util.reflection.SecureReflectionAccess.runAsInvocation(SecureReflectionAccess.java:137) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.util.reflection.SecureReflections.invoke(SecureReflections.java:260) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.bean.proxy.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:111) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:105) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at com.example.service.impl.HibernateIndexLoaderService$Proxy$_$$_Weld$Proxy$.reindex(HibernateIndexLoaderService$Proxy$_$$_Weld$Proxy$.java) [example-ejb-1.0-SNAPSHOT.jar:]
   at com.example.rest.services.LuceneIndexRestService.reindex(LuceneIndexRestService.java:39) [classes:]
   at com.example.rest.services.LuceneIndexRestService$Proxy$_$$_WeldClientProxy.reindex(LuceneIndexRestService$Proxy$_$$_WeldClientProxy.java) [classes:]
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_26]
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [rt.jar:1.6.0_26]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_26]
   at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_26]
   at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:155) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs-2.3.2.Final.jar:]
   at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs-2.3.2.Final.jar:]
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.0.Final.jar:1.0.0.Final]
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
   at org.jboss.weld.servlet.ConversationPropagationFilter.doFilter(ConversationPropagationFilter.java:62) [weld-core-1.1.5.AS71.Final.jar:2012-02-10 15:31]
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
   at com.example.rest.filters.LocaleFilter.doFilter(LocaleFilter.java:69) [classes:]
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489) [jbossweb-7.0.13.Final.jar:]
   at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.1.1.Final.jar:7.1.1.Final]
   at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) [jboss-as-web-7.1.1.Final.jar:7.1.1.Final]
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [jbossweb-7.0.13.Final.jar:]
   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) [jbossweb-7.0.13.Final.jar:]
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877) [jbossweb-7.0.13.Final.jar:]
   at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671) [jbossweb-7.0.13.Final.jar:]
   at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) [jbossweb-7.0.13.Final.jar:]
   at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_26]
Caused by: javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
   at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1155) [jbossjts-4.16.2.Final.jar:]
   at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) [jbossjts-4.16.2.Final.jar:]
   at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75) [jbossjts-integration-4.16.2.Final.jar:]
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
   ... 71 more



As for my model hierarchy - I have a Product(which is indexed). It has regular fields, translations, creator and a Category, to which it belongs. The category has translations and attributes. The attributes are embedded - they are a list, but at most one attribute set is active. Each set has 60 fields describing what a product might have and whether it's searchable and how visible it is.
All mentioned above are fields of the index. There's no circular reference. Also, each product has 4 images (with their bytes from the DB), but they are lazy loaded.
The problem here is not with the time BTW - I can wait, because I hope that this index should be done just once. After that, all the data in the DB will be manipulated through the application and there's no problem with the Hibernate Search event listeners.

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

Board index » Projects » Search, Validator, Shards

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.