Deletion Management Logs

  • 7019818
  • 30-Aug-2016
  • 07-Aug-2017

Environment

Retain 4.x

Situation

How do I tell if messages are being deleted in the logs?

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

Additional Information

This article was originally published in the GWAVA knowledgebase as article ID 2850.

Feedback service temporarily unavailable. For content questions or problems, please contact Support.