Environment
Situation
Resolution
When items are deleted from Retain it is recorded in the RetainServer log. This does not show the subject of the message just the hash.
Deleting an individual item through search messages:
10:04:26, 378[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: DeletionTaskExecutor begins
10:04:26, 378[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: Running deletion job.
10:04:26, 378[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: Normal deletion mode
10:04:26, 378[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: autoApprove:true
10:04:26, 378[DeletionJobTask-1-thread-3] [TRACE] AbstractDeletionTaskExecutor: deleteMatchingEmails: calling initializeSearch()
10:04:26, 393[DeletionJobTask-1-thread-3] [INFO ] LiveUserDeletion: Result page TotalHits: 1 1 in result set
10:04:26, 393[DeletionJobTask-1-thread-3] [TRACE] HibernateStringUtil: inSet: 183
10:04:26, 393[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: List: 183
10:04:26, 393[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: fromIndex=0,toIndex=1
10:04:26, 409[DeletionJobTask-1-thread-3] [INFO ] GooGooStatementCache: Multiply prepared statement! select folder0_.folder_id as folder_i1_12_0_, folder0_.parent_id as parent_i2_12_0_, folder0_.uuid_mapping_id as uuid_map3_12_0_, folder0_.f_naturalFolderId as f_natura4_12_0_, folder0_.f_name as f_name5_12_0_, folder0_.f_subtype as f_subtyp6_12_0_ from t_folder folder0_ where folder0_.folder_id=?
10:04:26, 550[DeletionJobTask-1-thread-3] [TRACE] AbstractDeletionTaskExecutor: deletePage: deleting items from index
10:04:26, 550[DeletionJobTask-1-thread-3] [TRACE] AbstractDeletionTaskExecutor: sleep for 10 seconds then continue...
10:04:26, 550[IndexDeletionDropLet] [DEBUG] AbstractDeletionTaskExecutor: deleteIndexDocs
10:04:26, 565[IndexDeletionDropLet] [DEBUG] AbstractDeletionTaskExecutor: deleteIndexDocs, SearchResults.size: 1
10:04:36, 550[DeletionJobTask-1-thread-3] [TRACE] AbstractDeletionTaskExecutor: deleteMatchingEmails: calling deleteFullMailboxes()
10:04:36, 565[DeletionJobTask-1-thread-3] [WARN ] DJDeletionOperation: DeletionJob scheduled but no settings found... stopping job.
10:04:36, 565[DeletionJobTask-1-thread-3] [INFO ] AbstractDeletionTaskExecutor: DeletionTaskExecutor ends
10:04:36, 565[DumpsterThread] [DEBUG] DeletionJobFactory: Dumpster Thread beginning
10:04:36, 565[DumpsterThread] [INFO ] DumpsterDiver: Dumpster dive begins
10:04:36, 565[DumpsterThread] [INFO ] DumpsterDiver: Got these many children of dumpster1
10:04:36, 565[DumpsterThread] [TRACE] DumpsterDiver: Delete 183
10:04:36, 597[DumpsterThread] [INFO ] DumpsterDiver: Deleting node 183
10:04:36, 753[DumpsterThread] [INFO ] DumpsterDiver: Delete orphaned documents
10:04:36, 753[DumpsterThread] [INFO ] DeleteDocuments: Removing orphaned documents page
10:04:36, 768[DumpsterThread] [TRACE] DeleteDao: Deleting com.gwava.dao.social.Document id=196, hash=23956AE46D70C9850934BBCDCC2AD37AA8899E59E1A2F03715985941CA276C0F
10:04:36, 768[DumpsterThread] [TRACE] DeleteDao: Deleting com.gwava.dao.social.Document id=197, hash=AB9D03C2DE048CF7EAEC36AB5878D68C19FDA1BBF4BD77451636855013AB27E2
10:04:36, 768[DumpsterThread] [INFO ] DeleteDocuments: Executed query in 15
10:04:36, 768[DumpsterThread] [INFO ] DeleteDocuments: deleteDocumentList:23956AE46D70C9850934BBCDCC2AD37AA8899E59E1A2F03715985941CA276C0F 0 196
10:04:36, 800[DumpsterThread] [INFO ] DeleteDocuments: deleteDocumentList:AB9D03C2DE048CF7EAEC36AB5878D68C19FDA1BBF4BD77451636855013AB27E2 0 197
10:04:36, 800[DumpsterThread] [INFO ] DeleteDocuments: Removing orphaned documents page
10:04:36, 800[DumpsterThread] [INFO ] DeleteDocuments: Executed query in 0
10:04:36, 800[DumpsterThread] [INFO ] DeleteDocuments: deleteOrphanedDocuments: Nothing left
10:04:36, 800[DumpsterThread] [INFO ] DumpsterDiver: Dumpster dive completed
10:04:36, 800[DumpsterThread] [DEBUG] DeletionJobFactory: Dumpster Thread ending
Deletion Managment:
If you schedule a deletion job it will run during the maintainance cycle at 1am (by default):
2015-08-12 01:03:22,584 [Maintain] INFO com.gwava.jobs.MaintenanceJob - Execute deletion jobs
But if jobs are set to manual then you will see this message:
2015-08-12 01:03:22,593 [DeletionJobTask-1-thread-3] DEBUG com.gwava.deletion.DeletionTaskHelper - Skipping deletion job. Only manual trigger selected.
You can trigger a job manually by clicking on the "Run Job Now" button under the Schedule tab and you will see this in the logs:
2015-08-12 09:06:03,072 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.DeletionTaskHelper - Manual trigger of deletion job requested. Not checking schedule
And the job begins:
2015-08-12 09:06:03,072 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - Running deletion job.
2015-08-12 09:06:03,072 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - Normal deletion mode
2015-08-12 09:06:03,072 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - autoApprove:true
2015-08-12 09:06:03,074 [DeletionJobTask-1-thread-1] DEBUG com.gwava.deletion.DJDeletionOperation - Deletion report stored at /var/opt/beginfinite/retain/archive/Deletion8464290409683004469EYSZTWSUTFUWYFMRMHWHU.html
If you are running the job against individual users you'll see them listed:
2015-08-12 09:06:03,094 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.DJDeletionOperation - Include user scope: [4632DB80-0EA9-0000-9A73-667864633738]
Then it begins to build batches of 500 eligible items from the indexes:
2015-08-12 09:06:05,301 [DeletionJobTask-1-thread-1] TRACE com.gwava.hibernate.HibernateStringUtil - inSet: 823104,823105,...,824095,824096
2015-08-12 09:06:05,301 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - List<EMail>: 823104,823105,...,824095,824096
2015-08-12 09:06:05,373 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - fromIndex=0,toIndex=100
2015-08-12 09:06:07,100 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - fromIndex=100,toIndex=200
2015-08-12 09:06:07,583 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - fromIndex=200,toIndex=300
2015-08-12 09:06:08,393 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - fromIndex=300,toIndex=400
2015-08-12 09:06:09,427 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - fromIndex=400,toIndex=500
2015-08-12 09:06:10,913 [DeletionJobTask-1-thread-1] DEBUG com.gwava.deletion.AbstractDeletionTaskExecutor - deleteIndexDocs
2015-08-12 09:06:10,913 [DeletionJobTask-1-thread-1] DEBUG com.gwava.deletion.AbstractDeletionTaskExecutor - deleteIndexDocs, tl.size: 500
Once it has build batches of items to be deleted it sends the email (yes, we know. This is going to be changed to when the deletion job actually ends) and begins to remove items from the database:
2015-08-12 09:06:58,459 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.DeletionTaskHelper - Sending mail after deletion job...
2015-08-12 09:06:58,501 [DeletionJobTask-1-thread-1] INFO com.gwava.deletion.AbstractDeletionTaskExecutor - DeletionTaskExecutor ends
2015-08-12 09:06:58,508 [DumpsterThread] DEBUG com.gwava.deletion.DeletionJobFactory - Dumpster Thread beginning
2015-08-12 09:06:58,512 [DumpsterThread] INFO com.gwava.deletion.DumpsterDiver - Dumpster dive begins
2015-08-12 09:06:58,573 [DumpsterThread] INFO com.gwava.deletion.DumpsterDiver - Got these many children of dumpster500
2015-08-12 09:06:58,573 [DumpsterThread] TRACE com.gwava.deletion.DumpsterDiver - Delete 823039
2015-08-12 09:06:58,582 [DumpsterThread] INFO com.gwava.deletion.DumpsterDiver - Deleting node 823039
and continues until that is finished:
2015-08-12 09:09:26,605 [DumpsterThread] INFO com.gwava.deletion.DumpsterDiver - Delete orphaned documents
2015-08-12 09:09:26,605 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - Removing orphaned documents page
Then the job moves on to delete items from disk, which are also done in batches:
2015-08-12 09:09:26,692 [DumpsterThread] TRACE com.gwava.message.dao.DeleteDao - Deleting com.gwava.dao.social.Document id=841321, hash=560170B00B4B4C4FABA777D76D93BA98527C12E77AE77A6C2F7DB4580AF0FE8D
2015-08-12 09:09:40,482 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - Executed query in 13877
2015-08-12 09:09:40,489 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - deleteDocumentList:560170B00B4B4C4FABA777D76D93BA98527C12E77AE77A6C2F7DB4580AF0FE8D 0 841321
until it is done and the deletion job ends:
2015-08-12 09:12:30,777 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - Removing orphaned documents page
2015-08-12 09:12:30,777 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - Executed query in 0
2015-08-12 09:12:30,777 [DumpsterThread] INFO com.gwava.deletion.ng.DeleteDocuments - deleteOrphanedDocuments: Nothing left
2015-08-12 09:12:30,778 [DumpsterThread] INFO com.gwava.deletion.DumpsterDiver - Dumpster dive completed
2015-08-12 09:12:30,778 [DumpsterThread] DEBUG com.gwava.deletion.DeletionJobFactory - Dumpster Thread ending