Difference between revisions of "Retain Logs"

From GWAVA Technologies Training
Jump to: navigation, search
(Logging Levels)
 
(29 intermediate revisions by one user not shown)
Line 14: Line 14:
 
*Reporting and Monitoring/Logging
 
*Reporting and Monitoring/Logging
  
Log files are closed and compress at midnight each day. By default, logs are kept for 10 days before being deleted, but that can be changed by the customer. There are some logs that are not included like the catalina.out which needs to be removed from time to time when it grows too large.
+
Log files are closed and compressed at midnight each day. By default, logs are kept for 10 days before being deleted, but that can be changed by the customer. There are some logs that are not included like the catalina.out which needs to be removed from time to time when it grows too large.
  
 
===Logging Levels===
 
===Logging Levels===
Line 24: Line 24:
  
 
We recommend Diagnostic because it contains all relevant data. That means the logs can be very large and somewhat cluttered but there are techniques for making reading the logs easier.
 
We recommend Diagnostic because it contains all relevant data. That means the logs can be very large and somewhat cluttered but there are techniques for making reading the logs easier.
 +
At Diagnostic level you can estimate the size of the logs by using 10kb/message or attachment as a rule of thumb.
  
 
==Monitoring and Reading Log Files==
 
==Monitoring and Reading Log Files==
Line 43: Line 44:
  
 
Generally, we install baretail to be able to watch a job run, but if we need to analyze a log we would use NotePad++ or TextPad for their strong search capabilities.
 
Generally, we install baretail to be able to watch a job run, but if we need to analyze a log we would use NotePad++ or TextPad for their strong search capabilities.
 +
 +
==Follow a Message==
 +
To show you how a message flows through the system I have focused on a single message as it appears in each of the logs.
 +
 +
For this example the message has the subject: '''UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171''' with 2 attachments: '''utf.txt''' and '''shuffled.csv''' and a recipient of '''test19@gwava.net '''
  
 
==RetainWorker log==
 
==RetainWorker log==
Line 81: Line 87:
  
 
There will be a section of getting the user list just after this.
 
There will be a section of getting the user list just after this.
 +
 +
Find the beginning of a job by searching "Job Starting" or "Starting scheduled Archive job".
  
 
===Logging in as a User===
 
===Logging in as a User===
Line 110: Line 118:
  
 
This is followed by a list of the user's folders.
 
This is followed by a list of the user's folders.
 +
 +
===User Folder List===
 +
In Exchange the user's folder list is retrieved, in Groupwise it would come later.
 +
 +
2016-07-19 12:14:38,450 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.archiveimpl.process.ExchangeUser: Discovered endpoint: https://sfex13srv.sf.gwava.net/EWS/Exchange.asmx
 +
2016-07-19 12:14:38,450 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078450
 +
2016-07-19 12:14:38,887 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078887
 +
2016-07-19 12:14:38,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078981
 +
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Appointment is Calendar: true
 +
2016-07-19 12:14:38,998 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Calendar - namePath :\test19\Calendar, \Root\Calendar,  id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEOAAA=
 +
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952078998
 +
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952078998
 +
2016-07-19 12:14:39,028 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079028
 +
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:39,043 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Deleted Items - namePath :\test19\Deleted Items, \Root\Trash, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAELAAA=
 +
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952079043
 +
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952079043
 +
2016-07-19 12:14:39,075 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079075
 +
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:39,224 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Drafts - namePath :\test19\Drafts, \Root\Drafts, id:  AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEQAAA=
 +
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952079224
 +
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952079224
 +
2016-07-19 12:14:39,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079278
 +
2016-07-19 12:14:40,653 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:40,653 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Inbox - namePath :\test19\Inbox, \Root\Mailbox, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA=
 +
2016-07-19 12:14:40,653 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952080653
 +
2016-07-19 12:14:40,700 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952080700
 +
2016-07-19 12:14:40,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952080918
 +
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Journal is Calendar: false
 +
2016-07-19 12:14:42,512 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Journal - namePath :\test19\Journal, \Root\Unknown, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAERAAA=
 +
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952082512
 +
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952082512
 +
2016-07-19 12:14:42,903 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952082903
 +
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.StickyNote is Calendar: false
 +
2016-07-19 12:14:42,934 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Notes - namePath :\test19\Notes, \Root\Notes, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAESAAA=
 +
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952082934
 +
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952082934
 +
2016-07-19 12:14:43,347 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083347
 +
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:43,481 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Outbox - namePath :\test19\Outbox, \Root\Outbox, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEMAAA=
 +
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083481
 +
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083481
 +
2016-07-19 12:14:43,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083512
 +
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:43,731 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Sent Items - namePath :\test19\Sent Items, \Root\SentItems, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEKAAA=
 +
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083731
 +
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083731
 +
2016-07-19 12:14:43,825 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083825
 +
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Task is Calendar: false
 +
2016-07-19 12:14:43,918 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Tasks - namePath :\test19\Tasks, \Root\Task, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAETAAA=
 +
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083918
 +
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083918
 +
2016-07-19 12:14:43,965 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083965
 +
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:44,871 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Top of Information Store - namePath :\test19, \Root, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEJAAA=
 +
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952084871
 +
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952084871
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Calendar - namePath :\test19\Calendar
 +
2016-07-19 12:14:44,981 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Conversation Action Settings
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Deleted Items - namePath :\test19\Deleted Items
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Drafts - namePath :\test19\Drafts
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Inbox - namePath :\test19\Inbox
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Journal - namePath :\test19\Journal
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: detected special folder: Junk Email
 +
2016-07-19 12:14:44,981 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Junk Email
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Notes - namePath :\test19\Notes
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Outbox - namePath :\test19\Outbox
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Sent Items - namePath :\test19\Sent Items
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Tasks - namePath :\test19\Tasks
 +
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952084981
 +
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Top of Information Store - namePath :\test19
 +
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085184
 +
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085184
 +
2016-07-19 12:14:45,331 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Calendar - namePath :\test19\Calendar
 +
2016-07-19 12:14:45,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Conversation Action Settings
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Deleted Items - namePath :\test19\Deleted Items
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Drafts - namePath :\test19\Drafts
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Inbox - namePath :\test19\Inbox
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Journal - namePath :\test19\Journal
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: detected special folder: Junk Email
 +
2016-07-19 12:14:45,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Junk Email
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Notes - namePath :\test19\Notes
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Outbox - namePath :\test19\Outbox
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Sent Items - namePath :\test19\Sent Items
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Tasks - namePath :\test19\Tasks
 +
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085387
 +
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
 +
2016-07-19 12:14:45,543 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Junk Email - namePath :\test19\Junk Email, \Root\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEaAAA=
 +
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085543
 +
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085543
 +
2016-07-19 12:14:45,778 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085778
 +
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:45,934 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Finder - namePath :\test19\Finder, \Root\Query, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEFAAA=
 +
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085934
 +
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085934
 +
2016-07-19 12:14:45,986 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085986
 +
2016-07-19 12:14:46,012 WARN  [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: type: voicemail is not supported by this Exchange version / or you do not have the privileges to access it.
 +
2016-07-19 12:14:46,012 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086012
 +
2016-07-19 12:14:46,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086043
 +
2016-07-19 12:14:46,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086043
 +
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,121 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Recoverable Items - namePath :\test19\Recoverable Items, \Root\RecoverItemsRoot, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUGAAA=
 +
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086121
 +
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952086121
 +
2016-07-19 12:14:46,137 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086137
 +
2016-07-19 12:14:46,137 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086137
 +
2016-07-19 12:14:46,153 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,278 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Calendar Logging - namePath :\test19\Recoverable Items\Calendar Logging, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUKAAA=
 +
2016-07-19 12:14:46,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086278
 +
2016-07-19 12:14:46,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086278
 +
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,325 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Deletions - namePath :\test19\Recoverable Items\Deletions, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUHAAA=
 +
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086325
 +
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086325
 +
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,340 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: DiscoveryHolds - namePath :\test19\Recoverable Items\DiscoveryHolds, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAA9JG7iAAA=
 +
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086340
 +
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086340
 +
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,372 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Purges - namePath :\test19\Recoverable Items\Purges, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUJAAA=
 +
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086372
 +
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086372
 +
2016-07-19 12:14:46,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
 +
2016-07-19 12:14:46,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Versions - namePath :\test19\Recoverable Items\Versions, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUIAAA=
 +
2016-07-19 12:14:46,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, method=getItemTime, abSystem=exchange, uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F}
 +
2016-07-19 12:14:46,450 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ProcessExchFilters: storageDateRange = begin=Mon Jul 18 11:17:06 MDT 2016,end=Tue Jul 19 12:00:01 MDT 2016, dateRange = begin=Wed Dec 31 17:00:00 MST 1969,end=Tue Jul 19 12:00:00 MDT 2016
 +
2016-07-19 12:14:46,496 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ExchangeDredger: cursor: Thread[Thread-137749,5,main]
 +
2016-07-19 12:14:46,590 TRACE [Thread-137749] com.gwava.ews.archiveimpl.process.CursorFetchThread: fetching from folder(test19@sf.gwava.net): Inbox
  
 
===Getting a message===
 
===Getting a message===
<code>
+
The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: =============================================================
+
 
  2016-07-05 16:32:20,256 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Processing ID: 6820dc7924bd77479af526bf5cb3282c00009dd6e626
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ExchangeDredger: subject: '''UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171''', boxtype: received
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Archive Message: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c00009dd6e626
+
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: =============================================================
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Location:\test19\Inbox
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Processing ID: 6820dc7924bd77479af526bf5cb3282c0000b051f4d3
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Subject:UTF8_HTML Go-Postal 06/16/2016 16:17:59 882533431
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Archive Message: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Date:2016-06-16 22:18:00
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Location:\test19\Inbox
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Sender:script@sf.gwava.net
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Subject:UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Recipient(s):test19@sf.gwava.net
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Date:2016-07-19 08:19:10
  2016-07-05 16:32:20,256 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Number of attachments: 2
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Sender:script@sf.gwava.net
  2016-07-05 16:32:20,256 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveMailboxBase: Reset LastArchivedItemRetentionDate to 1. New folder: \test19\Inbox, old:
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Recipient(s):test19@sf.gwava.net
2016-07-05 16:32:20,256 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: itemType: EXCH.MessageType
+
  2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Number of attachments: 2
  2016-07-05 16:32:20,397 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+06%2F16%2F2016+16%3A17%3A59+882533431&senderDisplay=script%40sf.gwava.net&delivered=1466115480&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHRyBzxhSAUfxouD06WRPHaOVMDcQ%3D%3D&exchange.m.dateReceived=2016-06-16T22%3A18%3A00Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&exchange.m.ct=UTF8_HTML+Go-Postal+06%2F16%2F2016+16%3A17%3A59+882533431&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1466115480&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c00009dd6e626&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-06-16T22%3A17%3A59Z&internet=false&status=
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: itemType: EXCH.MessageType
  2016-07-05 16:32:20,428 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+06%2F16%2F2016+16%3A17%3A59+882533431&senderDisplay=script%40sf.gwava.net&delivered=1466115480&filesize=594&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&finalpart=no&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHRyBzxhSAUfxouD06WRPHaOVMDcQ%3D%3D&exchange.m.dateReceived=2016-06-16T22%3A18%3A00Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&contentType=bodytext%2Fplain&exchange.m.ct=UTF8_HTML+Go-Postal+06%2F16%2F2016+16%3A17%3A59+882533431&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1466115480&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c00009dd6e626&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&compressedSize=408&filename=UTF8_HTML+Go-Postal+06%2F16%2F2016+16%3A17%3A59+882533431.txt&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-06-16T22%3A17%3A59Z&hash=5C18EC008BB67D988F3DDFC5868790AF6C963EF2CAD7DF0FF5A594949C93533F&internet=false&status=
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&senderDisplay=script%40sf.gwava.net&delivered=1468916350&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHR4ZY5l5sZFHaJsEW3wtM6F233Ew%3D%3D&exchange.m.dateReceived=2016-07-19T08%3A19%3A10Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&exchange.m.ct=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1468916350&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c0000b051f4d3&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-07-19T08%3A19%3A09Z&internet=false&status=
  2016-07-05 16:32:20,428 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&senderDisplay=script%40sf.gwava.net&delivered=1468916350&filesize=541&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&finalpart=no&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHR4ZY5l5sZFHaJsEW3wtM6F233Ew%3D%3D&exchange.m.dateReceived=2016-07-19T08%3A19%3A10Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&contentType=bodytext%2Fplain&exchange.m.ct=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1468916350&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c0000b051f4d3&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&compressedSize=374&filename=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171.txt&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-07-19T08%3A19%3A09Z&hash=46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D&internet=false&status=
  2016-07-05 16:32:20,428 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
  2016-07-05 16:32:20,428 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: headerstream.length: 1764 dataStream: 408
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
  2016-07-05 16:32:21,913 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1467757941913
+
  2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1764 dataStream: 374
2016-07-05 16:32:21,913 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getItem - 1467757941913
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: sent mail textbody with subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, server-response: Archive: OK: All is well. Result=AddedEMails: 1, emailID=4138831, parentID=13
2016-07-05 16:32:22,413 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@414631c)
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: +++msgCount: 1
2016-07-05 16:32:22,413 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@73a84e0f)
+
2016-07-19 12:19:05,737 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: '''shuffled.csv''', isItem: false, size: 592...
2016-07-05 16:32:22,413 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@137cfa5a)
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-05 16:32:22,413 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@1cb72b46)
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-05 16:32:22,413 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@3b9ca74f)
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@af54e05)
+
  2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1862 dataStream: 264
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@7e2fdb2b)
+
  2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@5b6732b3)
+
  2016-07-19 12:19:06,034 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: '''utf.txt''', isItem: false, size: 2050...
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@51f404f)
+
  2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@25bab38f)
+
  2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@25ccd290)
+
  2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@475c8e30)
+
  2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1858 dataStream: 778
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@383ea3ac)
+
  2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@486849ef)
+
  2016-07-19 12:19:07,056 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: headers.822, isItem: false, size: 884...
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@b734a20)
+
  2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@28fd6870)
+
  2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@65139d00)
+
  2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@6f3e877c)
+
  2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1808 dataStream: 347
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@7e8de2f1)
+
  2016-07-19 12:19:08,206 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@3d70abb8)
+
  2016-07-19 12:19:08,206 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: EmailID: 4138831, parentID: 13, stubbingStage: 0
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@4472da8b)
+
  2016-07-19 12:19:08,206 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Message archived succesfully!
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@5fecb01e)
+
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@4ee75b78)
+
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@76f21477)
+
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.archiveimpl.process.ExchangeArchiveFactory: createMailboxItem: com.microsoft.schemas.exchange.services._2006.types.MessageType@24863ea0)
+
2016-07-05 16:32:22,444 DEBUG [Thread-6944266] com.gwava.ews.archiveimpl.process.CursorFetchThread: Fetching attachments...:100(totalsize:310453), total to fetch: 50
+
2016-07-05 16:32:22,444 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1467757942444
+
2016-07-05 16:32:22,506 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getStreamedDirectory - 1467757942506
+
2016-07-05 16:32:22,506 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRawPort - 1467757942506
+
2016-07-05 16:32:23,523 TRACE [Thread-6944271] com.gwava.ews.HttpPostThreadThread: thread exits: 7434939
+
2016-07-05 16:32:24,335 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveEmail: sent mail textbody with subject: UTF8_HTML Go-Postal 06/16/2016 16:17:59 882533431, server-response: Archive: OK: All is well. Result=AddedEMails: 0, emailID=3294374, parentID=13
+
  2016-07-05 16:32:24,335 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 06/16/2016 16:17:59 882533431, att-name: shuffled.csv, isItem: false, size: 598...
+
  2016-07-05 16:32:24,335 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
+
  2016-07-05 16:32:24,335 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
+
  2016-07-05 16:32:24,335 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
+
  2016-07-05 16:32:24,335 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: headerstream.length: 1862 dataStream: 256
+
  2016-07-05 16:32:25,069 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=3294374, parentID=13
+
  2016-07-05 16:32:25,069 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 06/16/2016 16:17:59 882533431, att-name: utf.txt, isItem: false, size: 2050...
+
  2016-07-05 16:32:25,069 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
+
  2016-07-05 16:32:25,069 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
+
  2016-07-05 16:32:25,069 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
+
  2016-07-05 16:32:25,069 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: headerstream.length: 1858 dataStream: 922
+
  2016-07-05 16:32:25,288 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1467757945288
+
2016-07-05 16:32:25,288 TRACE [Thread-6944266] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findItem - 1467757945288
+
2016-07-05 16:32:25,867 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=3294374, parentID=13
+
  2016-07-05 16:32:25,867 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 06/16/2016 16:17:59 882533431, att-name: headers.822, isItem: false, size: 884...
+
  2016-07-05 16:32:25,867 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
+
  2016-07-05 16:32:25,867 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
+
  2016-07-05 16:32:25,867 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
+
  2016-07-05 16:32:25,897 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HTTPWrapper2: headerstream.length: 1808 dataStream: 349
+
  2016-07-05 16:32:26,238 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=3294374, parentID=13
+
  2016-07-05 16:32:26,238 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.ArchiveEmail: EmailID: 3294374, parentID: 13, stubbingStage: 0
+
  2016-07-05 16:32:26,238 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Message was previously archived so skipped!
+
2016-07-05 16:32:26,238 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: lastArchivedMailDeliveredDate vs. mail.deliveredDate (using delivered-date): Wed Dec 31 17:00:00 MST 1969 vs: Thu Jun 16 16:18:00 MDT 2016
+
2016-07-05 16:32:26,238 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.archiveimpl.process.CursorFetchThread: totalCount/totalItemsInCursor : 2/ 50
+
2016-07-05 16:32:26,238 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.jobs.ExchangeDredger: nextItem: ExchangeMessage [bodyHash=0, boxType=null, cachedOriginalSize=-1, compressedBodySize=-1, entrySourceKey=6820dc7924bd77479af526bf5cb3282c00009dd6e627, folderType=inbox, isSubmail=false, itemType=EXCH.MessageType, myItem=com.microsoft.schemas.exchange.services._2006.types.MessageType@5ba0ac5d, parentIDsAsString=null, parents=null, statusWordList=, submailLevel=0]
+
2016-07-05 16:32:26,238 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.jobs.ExchangeDredger: subject: UTF8_HTML Go-Postal 06/16/2016 16:18:01 439814630, boxtype: received
+
</code>
+
  
  
 
If the message already exists in the Retain archive you'll see a message like this:
 
If the message already exists in the Retain archive you'll see a message like this:
 
  2016-07-05 16:31:49,803 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Message was previously archived so skipped!
 
  2016-07-05 16:31:49,803 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Message was previously archived so skipped!
 +
 +
Messages are separated by "============================================================="
 +
 +
You can search for messages by "Subject:" or "&hash=" which is unique for every message.
  
 
===Leaving a Mailbox===
 
===Leaving a Mailbox===
Line 233: Line 336:
  
 
===Error Messages===
 
===Error Messages===
There are many error codes, so this is just a single sample.  
+
There are many error codes, most of which are recorded in the knowledgebase [http://support.gwava.com] so this is just a single sample.  
 
<code>
 
<code>
 
  2016-07-05 23:55:15,491 ERROR [RTWQuartzScheduler_Archive_Worker-1] com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy: reportError: Process Archive Job :: com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy.returnCaller:55 :: com.gwava.archive.exceptions.RetainWorkerFatalException: com.gwava.archive.exceptions.RetainWorkerException: com.gwava.archive.exceptions.RetainWorkerFatalException:  
 
  2016-07-05 23:55:15,491 ERROR [RTWQuartzScheduler_Archive_Worker-1] com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy: reportError: Process Archive Job :: com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy.returnCaller:55 :: com.gwava.archive.exceptions.RetainWorkerFatalException: com.gwava.archive.exceptions.RetainWorkerException: com.gwava.archive.exceptions.RetainWorkerFatalException:  
Line 273: Line 376:
 
Most errors have been documented now. Often you just have to find the first error after the beginning of the job and you have the issue that needs to be fixed. Error stacks can be quite long and you'll need to find the top, there may be warnings above it that have some details as well.
 
Most errors have been documented now. Often you just have to find the first error after the beginning of the job and you have the issue that needs to be fixed. Error stacks can be quite long and you'll need to find the top, there may be warnings above it that have some details as well.
  
===How to get meaning from the logs===
+
===Worker Log Reading Techniques===
  
 
When troubleshooting a particular error is not fixing things you may have to change how you see what is happening in the logs.
 
When troubleshooting a particular error is not fixing things you may have to change how you see what is happening in the logs.
Line 307: Line 410:
 
  12:00:00, 123[http-bio-48080-exec-7] [INFO ] AppController: Logs space left : 32639156224
 
  12:00:00, 123[http-bio-48080-exec-7] [INFO ] AppController: Logs space left : 32639156224
  
===Receive Item===
+
===Receive a Message===
An item received by the server will be logged like this:
+
The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv
 +
 
 +
12:19:03, 471[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
 +
12:19:03, 471[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: receiving document...
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
 +
12:19:03, 471[Store_1468952343471_28125] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
 +
12:19:03, 471[Store_1468952343471_28125] [INFO ] StoreEmail: userID: '''test19@gwava.net'''
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: file received: '''"UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt"''' (541 bytes)
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: file received, ContentLength: 2143 bytes
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 374
 +
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: asDoc.compressedSize = 374
 +
12:19:03, 471[Store_1468952343471_28125] [DEBUG] SingleProcessStorageEngine: receiving document UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt done. hash:46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
 +
12:19:04, 002[Store_1468952343471_28125] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952344;et=0
 +
12:19:04, 815[Store_1468952343471_28125] [INFO ] RetainDBStorageEngine: About to commmit transaction null
 +
12:19:04, 846[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149617, hash=46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
 +
12:19:04, 846[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
 +
12:19:05, 737[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt" has parent: \test19\Inbox isSubmail: false has changed: true
 +
12:19:05, 737[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: check if indexing needed...
 +
12:19:05, 737[Store_1468952343471_28125] [DEBUG] StoreEmail: archiving document...done
 +
12:19:05, 737[Store_1468952343471_28125] [TRACE] StoreEmail: All dummy bytes read (5)
 +
12:19:05, 737[Store_1468952343471_28125] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
 +
12:19:05, 737[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
 +
12:19:05, 752[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
 +
12:19:05, 752[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: receiving document...
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
 +
12:19:05, 752[Store_1468952345752_28126] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
 +
12:19:05, 752[Store_1468952345752_28126] [INFO ] StoreEmail: userID: test19@gwava.net
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: file received: '''"shuffled.csv"''' (592 bytes)
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: file received, ContentLength: 2131 bytes
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 264
 +
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: asDoc.compressedSize = 264
 +
12:19:05, 752[Store_1468952345752_28126] [DEBUG] SingleProcessStorageEngine: receiving document shuffled.csv done. hash:AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
 +
12:19:05, 768[Store_1468952345752_28126] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952345;et=0
 +
12:19:05, 924[Store_1468952345752_28126] [INFO ] RetainDBStorageEngine: About to commmit transaction null
 +
12:19:05, 924[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: handling non-bodytext...
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID:  6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149618, hash=AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: Message was present: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, doc: com.gwava.dao.social.Document id=12149618, hash=AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: "shuffled.csv" has parent: \test19\Inbox isSubmail: false has changed: false
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: check if indexing needed...
 +
12:19:06, 034[Store_1468952345752_28126] [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=?
 +
12:19:06, 034[Store_1468952345752_28126] [DEBUG] StoreEmail: archiving document...done
 +
12:19:06, 034[Store_1468952345752_28126] [TRACE] StoreEmail: All dummy bytes read (5)
 +
12:19:06, 034[Store_1468952345752_28126] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
 +
12:19:06, 034[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
 +
12:19:06, 049[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
 +
12:19:06, 049[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: receiving document...
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
 +
12:19:06, 049[Store_1468952346049_28127] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
 +
12:19:06, 049[Store_1468952346049_28127] [INFO ] StoreEmail: userID: test19@gwava.net
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: file received: '''"utf.txt"''' (2050 bytes)
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: file received, ContentLength: 2641 bytes
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 778
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: asDoc.compressedSize = 778
 +
12:19:06, 049[Store_1468952346049_28127] [DEBUG] SingleProcessStorageEngine: receiving document utf.txt done. hash:4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
 +
12:19:06, 049[Store_1468952346049_28127] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
 +
12:19:06, 862[Store_1468952346049_28127] [INFO ] RetainDBStorageEngine: About to commmit transaction null
 +
12:19:06, 877[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: handling non-bodytext...
 +
12:19:06, 956[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
 +
12:19:06, 987[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
 +
12:19:06, 987[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
 +
12:19:07, 002[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149619, hash=4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
 +
12:19:07, 018[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: Message was present: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, doc: com.gwava.dao.social.Document id=12149619, hash=4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
 +
12:19:07, 043[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
 +
12:19:07, 056[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: "utf.txt" has parent: \test19\Inbox isSubmail: false has changed: false
 +
12:19:07, 056[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: check if indexing needed...
 +
12:19:07, 056[Store_1468952346049_28127] [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=?
 +
12:19:07, 056[Store_1468952346049_28127] [DEBUG] StoreEmail: archiving document...done
 +
12:19:07, 056[Store_1468952346049_28127] [TRACE] StoreEmail: All dummy bytes read (5)
 +
12:19:07, 056[Store_1468952346049_28127] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
 +
12:19:07, 056[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
 +
 
 +
===Job Ending===
 +
The end of the job will look like this:
 +
 
 +
13:00:25, 398[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 398[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:25, 413[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 413[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:25, 429[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 429[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F
 +
13:00:25, 507[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 507[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F
 +
13:00:25, 523[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 523[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:25, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: mb ca727e52-c039-4e2e-bb2e-be57851e2ae8 found, archived: 0, intUuid: ca727e52-c039-4e2e-bb2e-be57851e2ae8
 +
13:00:25, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: lastmailbox, enterMailbox: ca727e52-c039-4e2e-bb2e-be57851e2ae8 archived: 0
 +
13:00:25, 804[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 804[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F
 +
13:00:25, 819[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:25, 819[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 694[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 694[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 773[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 773[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 788[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 788[http-bio-48080-exec-6] [INFO ] LegacyStatController: Worker job has concluded
 +
13:00:26, 804[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 804[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F
 +
13:00:26, 819[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 819[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 835[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 835[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 851[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 851[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 882[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 882[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:26, 913[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
 +
13:00:26, 913[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
 +
13:00:27, 070[http-bio-48080-exec-3] [INFO ] JobStatusController: HeartBeat message received for JobRun: HeartBeat {ID=789, endTime=1468954826, status=1}
 +
13:00:27, 091[HeartBeat] [TRACE] CheckHeartBeatThread: Entered CheckHeartBeatThread and will be sleeping for 10 minutes
 +
13:00:27, 148[Thread-165589] [TRACE] JobStatusController: server endJobRun Email response.getBody() = null
 +
 
 +
===Server Log Reading Techniques===
 +
 
 +
Tracing a message coming into the server can be challenging because the server can be receiving data from multiple sources at the same time. You can use the threadID to do it.
 +
A threadID is something like <code>[http-bio-48080-exec-6]</code>
 +
 
 +
==Indexer==
 +
You would go into the Indexer logs when trying to determine why the indexer is not starting, seeing many failed items in the Server Configuration/Index tab, or if items are not being found in search.
 +
 
 +
===Indexing a Message===
 +
There is nothing special about when a job begins. The indexer indexes items as it is fed new data:
 +
 
 +
The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv
  
  12:00:31, 357[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
+
  12:19:13, 143 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: indexing: '''UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt''', filesize: 541, handlerclass: com.gwava.extractor.TextExtractor hash: 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
  12:00:31, 357[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
+
  12:19:13, 143 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
  12:00:31, 357[Store_1468951231357_26437] [TRACE] StoreEmail: receiving document...
+
  12:19:13, 143 [TRACE] [solrcloudQueueThread1] Extractor: Textextractor rejected binary file
  12:00:31, 435[Store_1468951231357_26437] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
+
  12:19:13, 143 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
  12:00:31, 435[Store_1468951231357_26437] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F  ff1c23d79912e145a9c9032f014fe08e00000000010d#ff1c23d79912e145a9c9032f014fe08e0000787c0ae1 9C753C220E56D2C41C1B4EE4EFC3FA38C27F374A15A00CB81F28491F33B9C0C5
+
  12:19:13, 159 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing
  12:00:31, 435[Store_1468951231357_26437] [INFO ] StoreEmail: userID: HealthMailboxaecf446a130c44fca64e1c8322275a9a@sf.gwava.net
+
  12:19:13, 159 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: addToSolrCloud() - addingDoc to index...
  12:00:31, 435[Store_1468951231357_26437] [TRACE] StoreEmail: file received: "Delivery probe - Mbx DB - testUsers Time 7/18/2016 5:58:33 PM.txt" (32 bytes)
+
  12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudIndexingAddition: Add doc response:{responseHeader={status=0,QTime=73}}
  12:00:31, 435[Store_1468951231357_26437] [TRACE] StoreEmail: file received, ContentLength: 1992 bytes
+
  12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: addToSolrCloud() - addingDoc to index done.
  12:00:31, 435[Store_1468951231357_26437] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 50
+
  12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - successFullyAddedDoc: true, indexedValue: 64
  12:00:31, 435[Store_1468951231357_26437] [TRACE] StoreEmail: asDoc.compressedSize = 50
+
  12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: [BGINDEXER] Adding email id 4138831 to index.
  12:00:31, 435[Store_1468951231357_26437] [DEBUG] SingleProcessStorageEngine: receiving document Delivery probe - Mbx DB - testUsers Time 7/18/2016 5:58:33 PM.txt done. hash:9C753C220E56D2C41C1B4EE4EFC3FA38C27F374A15A00CB81F28491F33B9C0C5
+
  12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: consume() - committing changes to DB ...
  12:00:31, 483[Store_1468951231357_26437] [INFO ] RetainDBStorageEngine: About to commmit transaction null
+
  12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: creating docUtil...
  12:00:31, 544[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]: , msgID: ff1c23d79912e145a9c9032f014fe08e00000000010d#ff1c23d79912e145a9c9032f014fe08e0000787c0ae1, uuid: 2ad90122-91f8-4ff8-af70-26b55fd55dff, doc: com.gwava.dao.social.Document id=1, hash=9C753C220E56D2C41C1B4EE4EFC3FA38C27F374A15A00CB81F28491F33B9C0C5
+
  12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: Indexer: Adding email to index...4138834
  12:00:31, 888[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: Message was present: Delivery probe - Mbx DB - testUsers Time 7/18/2016 5:58:33 PM, doc: com.gwava.dao.social.Document id=1, hash=9C753C220E56D2C41C1B4EE4EFC3FA38C27F374A15A00CB81F28491F33B9C0C5
+
  12:19:13, 659 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
  12:00:31, 951[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: TRANSACTION: skipping double attachment
+
12:19:13, 659 [TRACE] [solrcloudQueueThread1] Extractor: Textextractor rejected binary file
  12:00:31, 951[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: Delivery probe - Mbx DB - testUsers Time 7/18/2016 5:58:33 PM - attachments hasChanged: false
+
  12:19:13, 659 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
  12:00:31, 951[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: "Delivery probe - Mbx DB - testUsers Time 7/18/2016 5:58:33 PM.txt" has parent: \HealthMailboxdb61d28848744a06ad5fed608d2f037a\Inbox isSubmail: false has changed: false
+
  12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 0
  12:00:31, 951[Store_1468951231357_26437] [DEBUG] RetainDBStorageEngine: check if indexing needed...
+
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Entering attachment processing
  12:00:31, 966[Store_1468951231357_26437] [DEBUG] StoreEmail: archiving document...done
+
  12:19:13, 674 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: indexing: '''utf.txt''', filesize: 1948, handlerclass: com.gwava.extractor.TextExtractor hash: 1DF136232E51E46642C545EFA40F0BA8CAE0D4C20BFAFCA30FF517DE8FBC9331
  12:00:31, 966[Store_1468951231357_26437] [TRACE] StoreEmail: All dummy bytes read (5)
+
  12:19:13, 674 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
  12:00:31, 966[Store_1468951231357_26437] [INFO ] StoreEmail: #done archiving: ff1c23d79912e145a9c9032f014fe08e00000000010d#ff1c23d79912e145a9c9032f014fe08e0000787c0ae1 9C753C220E56D2C41C1B4EE4EFC3FA38C27F374A15A00CB81F28491F33B9C0C5
+
  12:19:13, 674 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
  12:00:31, 966[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
+
  12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing
  12:00:32, 013[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
+
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 1
 +
  12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Entering attachment processing
 +
  12:19:13, 690 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: INDEXING_NOT_ON_WHITELIST: '''shuffled.csv''', filesize: 592, handlerclass: null hash: EEB758423B031AECEDC077AA6DA93A7F3339D7B9815EF4515EDD84D86994B0AF
 +
  12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing
 +
12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 2
  
  

Latest revision as of 19:33, 25 July 2016

When attempting to troubleshoot Retain the logs will be the greatest help to you.

Contents

[edit] Logging Overview

There are a few different logs that you will encounter. They are found in the logs directory [1] This page will talk about the main ones:

  • RetainWorker which contains the job log. This will be on the server that hosts the worker agent.
  • RetainServer which contains the server log, what messages it received, indexed, and deleted. This will be on the server that hosts the Retain server.
  • RetainStatServer which contains the Reporting and Monitoring log. This will be on the server that hosts the Reporting and Monitoring server.
  • Indexer which contains what messages were indexed. This will be on the server that hosts the Indexer.

Logging is enabled and configured in a few places:

  • Server Configuration/Logging
  • Workers/<workername>/Logging
  • Reporting and Monitoring/Logging

Log files are closed and compressed at midnight each day. By default, logs are kept for 10 days before being deleted, but that can be changed by the customer. There are some logs that are not included like the catalina.out which needs to be removed from time to time when it grows too large.

[edit] Logging Levels

There are four logging levels:

  • Error Only
  • Normal (Info)
  • Verbose (Debug)
  • Diagnostic (Trace)

We recommend Diagnostic because it contains all relevant data. That means the logs can be very large and somewhat cluttered but there are techniques for making reading the logs easier. At Diagnostic level you can estimate the size of the logs by using 10kb/message or attachment as a rule of thumb.

[edit] Monitoring and Reading Log Files

We prefer having logs set to Diagnostic so we can just capture the error the first time and not have the customer have to attempt to repeat it as an archive job can take a long time to run.

[edit] Utilities for Reading Logs

Log files can be large text files, sometimes very large. You will need a text editor to view the log.

[edit] Linux

Linux has some built-in commands that are very handy

  • less is a built-in text editor in linux. It is very powerful with search capabililties using / and ?, it can also tail a running log with Shift-F.
  • tail to tail or watch a running log file.

[edit] Windows

While Windows does come with NotePad, it cannot handle very large text files. You will need a third-party Windows Utilities

  • NotePad++ which can also tail files can open typical log Retain log files, but will refuse to open very large log files.
  • TextPad can open larger log files and has very powerful search capabilities, but cannot tail a log.
  • baretail can tail a running log file, it can highlight text but doesn't have search capabilities.
  • glogg is able to open the rare very large log file.

Generally, we install baretail to be able to watch a job run, but if we need to analyze a log we would use NotePad++ or TextPad for their strong search capabilities.

[edit] Follow a Message

To show you how a message flows through the system I have focused on a single message as it appears in each of the logs.

For this example the message has the subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 with 2 attachments: utf.txt and shuffled.csv and a recipient of test19@gwava.net

[edit] RetainWorker log

This log is against an Exchange 2013 system, but the principles apply to each email system even if the details may differ. The Worker log contains what happens as the worker connects to the email system and gets messages. You want to have the logs run in Diagnostic mode which is set in the Logging tab of the Worker web object in the Retain admin console.

[edit] Job Start

When a job begins there will be a header that looks something like this:

2016-07-05 16:30:00,022 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.quartz.QuartzTriggerListener: FIRED: This trigger is a recurring friendly job name =  Daily EX Trigger 'ECD7EFFD600E95C66902048EE9A47EB5_triggerGroup.ECD7EFFD600E95C66902048EE9A47EB5_triggerName':  triggerClass: 'org.quartz.CronTrigger isVolatile: false calendar: 'null' misfireInstruction: 0 nextFireTime: Wed Jul 06 16:30:00 MDT 2016
2016-07-05 16:30:00,054 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.RetainArchiveJob: Add Daily EX (ECD7EFFD600E95C66902048EE9A47EB5) to queue []
2016-07-05 16:30:00,054 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.RetainArchiveJob: Job Daily EX (ECD7EFFD600E95C66902048EE9A47EB5) is in a RUNNING state
2016-07-05 16:30:00,054 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.RetainArchiveJob: Job memory: (free/max/total): (2996635/7459840/7459840)
2016-07-05 16:30:00,054 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.RetainArchiveJob: Starting scheduled Archive job ECD7EFFD600E95C66902048EE9A47EB5 @ Tue Jul 05 16:30:00 MDT 2016
2016-07-05 16:30:00,084 TRACE [Stubber-1467757800054] com.gwava.jobs.stubbing.BGStubber: Background Stubbing thread coming to life ...
2016-07-05 16:30:00,537 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.job.stats.RQStatsUpdater: Creating new stat tracker for thread: RTWQuartzScheduler_Archive_Worker-9
2016-07-05 16:30:00,537 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Job starting Daily EX
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:     Mail System : exchange
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:     Profile Settings applied to this job : 
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Profile Name : Item Store Flag
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Mailbox Type : Users
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Item Type : Mail, Appointment, Note, Task
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Item Source : All
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Message Status : Opened Doesn't Matter|Read Doesn't Matter|Private Doesn't Matter|Personal Doesn't Matter|Confidential Doesn't Matter
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:     Scope
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Date Range to Scan : All Messages (ignore date)
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Duplicate Check : Ignore all messages older than item store flag
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Set Storage Flags : Don't set Purge flag, Don't set Retention flag, Set Item Store flag
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:     Miscellaneous
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Store Attachments : Store all attachments
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Store/index Internet Headers : true
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Include Routing Properties : true
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Include Shared Folders : all
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:     Advanced
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Advanced Criteria : 0
2016-07-05 16:30:00,537 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:         Folder Scope : all

There will be a section of getting the user list just after this.

Find the beginning of a job by searching "Job Starting" or "Starting scheduled Archive job".

[edit] Logging in as a User

Then Retain begins the data dredge by entering user mailboxes:

2016-07-05 16:31:51,522 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: =============================================================================================
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Logging in as : test19@gwava.net to dredge their mailbox.
2016-07-05 16:31:51,522 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.jobs.ProcessExchFilters: profile.getDateType(): 1
2016-07-05 16:31:51,522 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.jobs.ProcessExchFilters: profile.getDateType(): All Messages (ignore date)
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:    - Query Range Used:
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:       - GTE:1970-01-01 00:00:00
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger:       - LTE:2016-07-05 22:31:51
2016-07-05 16:31:51,522 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.RetainUser: Begin login of test19@gwava.net
2016-07-05 16:31:51,522 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, mailbox=test19@gwava.net, method=checkIfUserExists, abSystem=exchange, domain=sf.gwava.net, display=test19, uuid=779d94ef38f5164f97cc4b38ed03299e, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F, email=test19@sf.gwava.net, po=SFEX13SRV}
2016-07-05 16:31:51,538 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.HttpUIDResolver: checkIfUserExists response: OK: USER EXISTS ::: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb
2016-07-05 16:31:51,538 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.RetainUser: End login of test19@gwava.net
2016-07-05 16:31:51,538 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.stats.StatsUpdater: updating job status information name: lastmailboxnumber
2016-07-05 16:31:51,538 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, jobid=ECD7EFFD600E95C66902048EE9A47EB5, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, method=svStatus, proc_id=null, f_order=1, lastmailboxnumber=2, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F}
2016-07-05 16:31:51,803 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.stats.StatsUpdater: updating job status information name: lastmailbox
2016-07-05 16:31:51,803 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, jobid=ECD7EFFD600E95C66902048EE9A47EB5, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, lastmailbox=test19@gwava.net, method=svStatus, proc_id=null, f_order=1, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F}
2016-07-05 16:31:52,102 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.stats.StatsUpdater: updating job status information name: lastpo
2016-07-05 16:31:52,102 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, jobid=ECD7EFFD600E95C66902048EE9A47EB5, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, method=svStatus, proc_id=null, f_order=1, lastpo=SFEX13SRV, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F}
2016-07-05 16:31:52,116 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.retain.worker.rest.client.JobStatusTracker: Starting the stat mailbox run update for user: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb
2016-07-05 16:31:52,288 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.MailboxArchivingStats: enterMailbox: test19@gwava.net

Search for "Logging in as :" to find the next user.

This is followed by a list of the user's folders.

[edit] User Folder List

In Exchange the user's folder list is retrieved, in Groupwise it would come later.

2016-07-19 12:14:38,450 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.archiveimpl.process.ExchangeUser: Discovered endpoint: https://sfex13srv.sf.gwava.net/EWS/Exchange.asmx
2016-07-19 12:14:38,450 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078450
2016-07-19 12:14:38,887 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078887
2016-07-19 12:14:38,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952078981
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Appointment is Calendar: true
2016-07-19 12:14:38,998 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Calendar - namePath :\test19\Calendar, \Root\Calendar,  id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEOAAA=
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952078998
2016-07-19 12:14:38,998 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952078998
2016-07-19 12:14:39,028 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079028
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:39,043 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Deleted Items - namePath :\test19\Deleted Items, \Root\Trash, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAELAAA=
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952079043
2016-07-19 12:14:39,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952079043
2016-07-19 12:14:39,075 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079075
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:39,224 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Drafts - namePath :\test19\Drafts, \Root\Drafts, id:  AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEQAAA=
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952079224
2016-07-19 12:14:39,224 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952079224
2016-07-19 12:14:39,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952079278
2016-07-19 12:14:40,653 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:40,653 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Inbox - namePath :\test19\Inbox, \Root\Mailbox, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA=
2016-07-19 12:14:40,653 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952080653
2016-07-19 12:14:40,700 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952080700
2016-07-19 12:14:40,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952080918
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Journal is Calendar: false
2016-07-19 12:14:42,512 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Journal - namePath :\test19\Journal, \Root\Unknown, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAERAAA=
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952082512
2016-07-19 12:14:42,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952082512
2016-07-19 12:14:42,903 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952082903
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.StickyNote is Calendar: false
2016-07-19 12:14:42,934 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Notes - namePath :\test19\Notes, \Root\Notes, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAESAAA=
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952082934
2016-07-19 12:14:42,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952082934
2016-07-19 12:14:43,347 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083347
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:43,481 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Outbox - namePath :\test19\Outbox, \Root\Outbox, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEMAAA=
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083481
2016-07-19 12:14:43,481 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083481
2016-07-19 12:14:43,512 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083512
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:43,731 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Sent Items - namePath :\test19\Sent Items, \Root\SentItems, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEKAAA=
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083731
2016-07-19 12:14:43,731 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083731
2016-07-19 12:14:43,825 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083825
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Task is Calendar: false
2016-07-19 12:14:43,918 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Tasks - namePath :\test19\Tasks, \Root\Task, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAETAAA=
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952083918
2016-07-19 12:14:43,918 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952083918
2016-07-19 12:14:43,965 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952083965
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:44,871 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Top of Information Store - namePath :\test19, \Root, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEJAAA=
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952084871
2016-07-19 12:14:44,871 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952084871
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Calendar - namePath :\test19\Calendar
2016-07-19 12:14:44,981 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Conversation Action Settings
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Deleted Items - namePath :\test19\Deleted Items
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Drafts - namePath :\test19\Drafts
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Inbox - namePath :\test19\Inbox
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Journal - namePath :\test19\Journal
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: detected special folder: Junk Email
2016-07-19 12:14:44,981 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Junk Email
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Notes - namePath :\test19\Notes
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Outbox - namePath :\test19\Outbox
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Sent Items - namePath :\test19\Sent Items
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Tasks - namePath :\test19\Tasks
2016-07-19 12:14:44,981 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952084981
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Top of Information Store - namePath :\test19
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085184
2016-07-19 12:14:45,184 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085184
2016-07-19 12:14:45,331 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Calendar - namePath :\test19\Calendar
2016-07-19 12:14:45,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Conversation Action Settings
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Deleted Items - namePath :\test19\Deleted Items
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Drafts - namePath :\test19\Drafts
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Inbox - namePath :\test19\Inbox
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Journal - namePath :\test19\Journal
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: detected special folder: Junk Email
2016-07-19 12:14:45,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.folders.ExchangeWorkerFolderCache: exclude folder: Junk Email
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Notes - namePath :\test19\Notes
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Outbox - namePath :\test19\Outbox
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Sent Items - namePath :\test19\Sent Items
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: folder already cached: Tasks - namePath :\test19\Tasks
2016-07-19 12:14:45,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085387
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: IPF.Note is Calendar: false
2016-07-19 12:14:45,543 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Junk Email - namePath :\test19\Junk Email, \Root\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEaAAA=
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085543
2016-07-19 12:14:45,543 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085543
2016-07-19 12:14:45,778 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085778
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:45,934 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Finder - namePath :\test19\Finder, \Root\Query, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAEFAAA=
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952085934
2016-07-19 12:14:45,934 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952085934
2016-07-19 12:14:45,986 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952085986
2016-07-19 12:14:46,012 WARN  [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: type: voicemail is not supported by this Exchange version / or you do not have the privileges to access it.
2016-07-19 12:14:46,012 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086012
2016-07-19 12:14:46,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086043
2016-07-19 12:14:46,043 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086043
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,121 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Recoverable Items - namePath :\test19\Recoverable Items, \Root\RecoverItemsRoot, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUGAAA=
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086121
2016-07-19 12:14:46,121 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: findFolder - 1468952086121
2016-07-19 12:14:46,137 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086137
2016-07-19 12:14:46,137 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086137
2016-07-19 12:14:46,153 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,278 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Calendar Logging - namePath :\test19\Recoverable Items\Calendar Logging, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUKAAA=
2016-07-19 12:14:46,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086278
2016-07-19 12:14:46,278 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086278
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,325 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Deletions - namePath :\test19\Recoverable Items\Deletions, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUHAAA=
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086325
2016-07-19 12:14:46,325 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086325
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,340 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: DiscoveryHolds - namePath :\test19\Recoverable Items\DiscoveryHolds, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAA9JG7iAAA=
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086340
2016-07-19 12:14:46,340 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086340
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,372 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Purges - namePath :\test19\Recoverable Items\Purges, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUJAAA=
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getRequestServerVersion - 1468952086372
2016-07-19 12:14:46,372 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: getFolder - 1468952086372
2016-07-19 12:14:46,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderInfo: folderClass: null is Calendar: false
2016-07-19 12:14:46,387 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.folders.ExchangeFolderCache: adding folder to the chache: Versions - namePath :\test19\Recoverable Items\Versions, \Root\RecoverItemsRoot\PersonalFolder, id: AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAUIAAA=
2016-07-19 12:14:46,387 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, method=getItemTime, abSystem=exchange, uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F}
2016-07-19 12:14:46,450 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ProcessExchFilters: storageDateRange = begin=Mon Jul 18 11:17:06 MDT 2016,end=Tue Jul 19 12:00:01 MDT 2016, dateRange = begin=Wed Dec 31 17:00:00 MST 1969,end=Tue Jul 19 12:00:00 MDT 2016
2016-07-19 12:14:46,496 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ExchangeDredger: cursor: Thread[Thread-137749,5,main]
2016-07-19 12:14:46,590 TRACE [Thread-137749] com.gwava.ews.archiveimpl.process.CursorFetchThread: fetching from folder(test19@sf.gwava.net): Inbox

[edit] Getting a message

The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv

2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.ews.jobs.ExchangeDredger: subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, boxtype: received
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: =============================================================
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Processing ID: 6820dc7924bd77479af526bf5cb3282c0000b051f4d3
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Archive Message: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Location:\test19\Inbox
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Subject:UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Date:2016-07-19 08:19:10
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Sender:script@sf.gwava.net
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Recipient(s):test19@sf.gwava.net
2016-07-19 12:19:03,440 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Number of attachments: 2
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: itemType: EXCH.MessageType
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&senderDisplay=script%40sf.gwava.net&delivered=1468916350&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHR4ZY5l5sZFHaJsEW3wtM6F233Ew%3D%3D&exchange.m.dateReceived=2016-07-19T08%3A19%3A10Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&exchange.m.ct=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1468916350&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c0000b051f4d3&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-07-19T08%3A19%3A09Z&internet=false&status=
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveMetaData: hashMapToQueryString: emailSystem=exchange&archiver=Worker1+%28Exchange%29&senderUUID=script%40sf.gwava.net&exchange.m.Sender-Name=script%40sf.gwava.net&subject=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&senderDisplay=script%40sf.gwava.net&delivered=1468916350&filesize=541&uuid=66cd42a7-1e0c-4c76-a461-e4c81726dbfb&userid=test19%40gwava.net&dirPathIDStr=%5CRoot%5CMailbox&folderID=AAMkAGI3OGE2Mjk5LWMxZWMtNDRlNy1iOWFhLWJhNjdhZjEyYjkzYgAuAAAAAADpCgDO8OTCS66scINjm1RaAQBoINx5JL13R5r1Jr9csygsAAAAAAENAAA%3D&archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F&itemTypeString=EXCH.MessageType&finalpart=no&jobid=ECD7EFFD600E95C66902048EE9A47EB5&exchange.m.ci=AQHR4ZY5l5sZFHaJsEW3wtM6F233Ew%3D%3D&exchange.m.dateReceived=2016-07-19T08%3A19%3A10Z&password=WVVTSUJURE5OQU9ORFVaTVRHVA%3D%3D&dirPath=%5Ctest19%5CInbox&from=script%40sf.gwava.net&categories=&contentType=bodytext%2Fplain&exchange.m.ct=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171&exchange.m.foldertype=inbox&exchange.m.Sender-Routing-Type=SMTP&personalSubject=&friendlyname=Daily+EX&expireDays=0&exchange.m.Sender-Email=script%40sf.gwava.net&parentFolderID=6820dc7924bd77479af526bf5cb3282c00000000010d&created=1468916350&msgid=6820dc7924bd77479af526bf5cb3282c00000000010d%236820dc7924bd77479af526bf5cb3282c0000b051f4d3&priority=Standard&exchange.m.sensitivity=Normal&isSubmail=false&boxTypeString=received&compressedSize=374&filename=UTF8_HTML+Go-Postal+07%2F19%2F2016+02%3A19%3A09+762595171.txt&recipients=0%3Atest19%3Atest19%40sf.gwava.net%3A%3B&exchange.m.itemClass=IPM.Note&item.class=com.microsoft.schemas.exchange.services._2006.types.MessageType&attachmentCount=2&exchange.m.dateSent=2016-07-19T08%3A19%3A09Z&hash=46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D&internet=false&status=
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-19 12:19:03,440 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1764 dataStream: 374
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: sent mail textbody with subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, server-response: Archive: OK: All is well. Result=AddedEMails: 1, emailID=4138831, parentID=13
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: +++msgCount: 1
2016-07-19 12:19:05,737 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: shuffled.csv, isItem: false, size: 592...
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-19 12:19:05,737 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1862 dataStream: 264
2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-19 12:19:06,034 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: utf.txt, isItem: false, size: 2050...
2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-19 12:19:06,034 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1858 dataStream: 778
2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-19 12:19:07,056 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: archiveEmail: processing binary attachment, subject: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, att-name: headers.822, isItem: false, size: 884...
2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Skipping check for whether the instance exists
2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.RetainServerCommunication: Sending data and waiting for response.
2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: using ApacheClient with TimedHttpMethodRetryHandler...
2016-07-19 12:19:07,056 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.http.HTTPWrapper2: headerstream.length: 1808 dataStream: 347
2016-07-19 12:19:08,206 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveAttachment: Send a nice healthy blob:Archive: OK: All is well. Result=AddedEMails: 0, emailID=4138831, parentID=13
2016-07-19 12:19:08,206 TRACE [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.process.ArchiveEmail: EmailID: 4138831, parentID: 13, stubbingStage: 0
2016-07-19 12:19:08,206 DEBUG [RTWQuartzScheduler_Archive_Worker-4] com.gwava.caapi.Archiver: Message archived succesfully!


If the message already exists in the Retain archive you'll see a message like this:

2016-07-05 16:31:49,803 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.Archiver: Message was previously archived so skipped!

Messages are separated by "============================================================="

You can search for messages by "Subject:" or "&hash=" which is unique for every message.

[edit] Leaving a Mailbox

2016-07-05 16:31:51,303 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.DateFlagManager: Using MaxItemRetention-Date
2016-07-05 16:31:51,303 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.DateFlagManager: 
Last archived mail Retention date=Thu Oct 22 10:49:58 MDT 2015 
Last mail before first error mail Retention date=Wed Dec 31 17:00:00 MST 1969
Max mail Retention date=Thu Oct 22 10:49:58 MDT 2015
Mailbox login time=Tue Jul 05 16:30:13 MDT 2016 
Date Chosen:Thu Oct 22 10:48:58 MDT 2015
2016-07-05 16:31:51,303 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.MailboxArchivingStats: Calculated date-flag TimeStamp: (Thu Oct 22 10:48:58 MDT 2015)
2016-07-05 16:31:51,303 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, 4112started=1467757897334, method=svStatus, 4112earlyexited=false, proc_id=null, 4112mailboxerrortotal=0, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F, jobid=ECD7EFFD600E95C66902048EE9A47EB5, 4112mailboxprocessed=1, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, 4112mailboxwarntotal=0, 4112useraborted=false, 4112ended=1467757911303, 4112mailboxmessagetotal=0, 4112dateflags=, 4112mailboxintuuid=533e8805-1c3f-49eb-b597-350d3ab1b7b9}
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative mails processed for this job: 0
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative mails archived for this job: 0
2016-07-05 16:31:51,522 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative errors for this job: 0
2016-07-05 16:31:51,522 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Logging out...
2016-07-05 16:31:51,522 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: deleteStreamedDirectory - 1467757911522

[edit] End of the Job

2016-07-05 23:55:08,494 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.DateFlagManager: Using MaxItemRetention-Date
2016-07-05 23:55:08,494 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.archive.process.DateFlagManager: 
Last archived mail Retention date=Fri May 27 14:18:52 MDT 2016
Last mail before first error mail Retention date=Wed Dec 31 17:00:00 MST 1969
Max mail Retention date=Fri May 27 14:18:52 MDT 2016
Mailbox login time=Tue Jul 05 16:30:13 MDT 2016 
Date Chosen:Fri May 27 14:17:52 MDT 2016
2016-07-05 23:55:08,494 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.MailboxArchivingStats: Calculated date-flag TimeStamp: (Fri May 27 14:17:52 MDT 2016)
2016-07-05 23:55:08,494 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.http.RetainServerCommunication: RetainServerCommunication.obtainHTTPResponseCodeAndData() - About to post to : http://10.1.4.52:48080/RetainServer/Server/ServerController2.jsp Params:{emailSystem=exchange, 4112started=1467784457771, method=svStatus, 4112earlyexited=false, proc_id=null, 4112mailboxerrortotal=0, archiverID=DDB2E4039E3B4C6AFF18ECD1FD30A29F, jobid=ECD7EFFD600E95C66902048EE9A47EB5, 4112mailboxprocessed=1, password=WVVTSUJURE5OQU9ORFVaTVRHVA==, 4112mailboxwarntotal=0, 4112useraborted=false, 4112ended=1467784508494, 4112mailboxmessagetotal=0, 4112dateflags=, 4112mailboxintuuid=ca727e52-c039-4e2e-bb2e-be57851e2ae8}
2016-07-05 23:55:08,593 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative mails processed for this job: 0
2016-07-05 23:55:08,593 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative mails archived for this job: 0
2016-07-05 23:55:08,593 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Cumulative errors for this job: 0
2016-07-05 23:55:08,593 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Logging out...
2016-07-05 23:55:08,593 TRACE [RTWQuartzScheduler_Archive_Worker-9] com.gwava.ews.RetainExchangeWebserviceFactory: invoking retainews method: deleteStreamedDirectory - 1467784508593 
2016-07-05 23:55:08,618 INFO  [RTWQuartzScheduler_Archive_Worker-9] com.gwava.caapi.process.RetainDredger: Job ending : Daily EX
2016-07-05 23:55:08,618 DEBUG [RTWQuartzScheduler_Archive_Worker-9] com.gwava.jobs.stats.StatsUpdater: archived 10031 msgs for this job. Job total Errors: 0

[edit] Error Messages

There are many error codes, most of which are recorded in the knowledgebase [2] so this is just a single sample.

2016-07-05 23:55:15,491 ERROR [RTWQuartzScheduler_Archive_Worker-1] com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy: reportError: Process Archive Job :: com.gwava.workerutils.DefaultCAAPIErrorHandleStrategy.returnCaller:55 :: com.gwava.archive.exceptions.RetainWorkerFatalException: com.gwava.archive.exceptions.RetainWorkerException: com.gwava.archive.exceptions.RetainWorkerFatalException: 
	at com.gwava.caapi.process.RetainDredger.processNormalJob(RetainDredger.java:272)
	at com.gwava.ews.jobs.ExchangeDredger.executeWork(ExchangeDredger.java:509)
	at com.gwava.jobs.RetainArchiveJob.performDredge(RetainArchiveJob.java:567)
	at com.gwava.jobs.RetainArchiveJob.execute(RetainArchiveJob.java:235)
	at com.gwava.jobs.RetainArchiveJob.execute(RetainArchiveJob.java:448)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
Caused by: com.gwava.archive.exceptions.RetainWorkerFatalException: 
	at com.gwava.ews.jobs.selection.LiveEWSUserSelection.resolveArchiveSource(LiveEWSUserSelection.java:91)
	at com.gwava.ews.jobs.selection.EWSUserSelection.getListOfUsers(EWSUserSelection.java:112)
	at com.gwava.ews.jobs.ExchangeDredger.getListOfUsers(ExchangeDredger.java:142)
	at com.gwava.ews.jobs.ExchangeDredger.getListOfUsers(ExchangeDredger.java:48)
	at com.gwava.caapi.process.RetainDredger.processNormalJob(RetainDredger.java:270)
	... 6 more
Caused by: javax.naming.NameNotFoundException: [LDAP: error code 32 - 0000208D: NameErr: DSID-03100213, problem 2001 (NO_OBJECT), data 0, best match of:
	
]; remaining name '<GUID=e3d02cb7937f7f4e957efe9218b19193>'
	at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3160)
	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3081)
	at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2888)
	at com.sun.jndi.ldap.LdapCtx.c_getAttributes(LdapCtx.java:1329)
	at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_getAttributes(ComponentDirContext.java:235)
	at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:141)
	at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:129)
	at javax.naming.directory.InitialDirContext.getAttributes(InitialDirContext.java:142)
	at com.gwava.address.exchange.impl.UserViaGUIDLDAP.getUserForDN(UserViaGUIDLDAP.java:60)
	at com.gwava.address.exchange.impl.UserViaGUIDLDAP.getUser(UserViaGUIDLDAP.java:47)
	at com.gwava.address.exchange.impl.UserViaGUIDLDAP.performOperation(UserViaGUIDLDAP.java:99)
	at com.gwava.ews.jobs.selection.LiveEWSUserSelection.processIncludeUserSource(LiveEWSUserSelection.java:151)
	at com.gwava.ews.jobs.selection.LiveEWSUserSelection.resolveArchiveSource(LiveEWSUserSelection.java:80)
	... 10 more

An LDAP 32 is one that is in the knowledgebase [3].

Most errors have been documented now. Often you just have to find the first error after the beginning of the job and you have the issue that needs to be fixed. Error stacks can be quite long and you'll need to find the top, there may be warnings above it that have some details as well.

[edit] Worker Log Reading Techniques

When troubleshooting a particular error is not fixing things you may have to change how you see what is happening in the logs.

There is a lot more information in the logs then is useful sometimes. So you have to find a way to pull signal from all the noise. One way of doing that is to extract lines that are more useful than others.

Using an advanced text editor like TextPad is handy.

  • Search for "Job starting" to find the beginning of the job and mark all instances.
  • Search for "Logging in as :" to find each user and mark all.
  • Search for "ERROR" and mark all. Since errors come in multi-line stacks this will only show you where they are in relation to everything else.
  • Search for "Job ending :" and mark all.
  • Search for "&hash=" this marks the line with all the header data being sent to the server, this line is unique for each message.

Copy all bookmarked lines and paste into a new document. Now you can see the essential information of the job with much less noise and you can see patterns better.

If there are lots of errors with a particular mailbox then it is likely that the mailbox needs to be repaired by the email system.

If you note the time it takes for each message to be archived you can see if there are any gaps that show places where a job is being slowed down. For example, if there are hundreds of recipients it will take a long time for the database to store them all and you can limit the number stored with the rest being placed in an XML file.

[edit] RetainServer log

[edit] Job Start

When a job starts it will be noted in the RetainServer log and look like this:

12:00:00, 013[RTSQuartzScheduler_QuartzSchedulerThread] [DEBUG] SimpleJobFactory: Producing instance of Job 'MODULEFORWARDGroup.MODULEFORWARDER', class=com.gwava.smtp.ModuleForwarder
12:00:00, 013[Maintain] [DEBUG] JobRunShell: Calling execute on job MODULEFORWARDGroup.MODULEFORWARDER
12:00:00, 013[Maintain] [INFO ] ModuleForwarder: Starting module forwarding job.
12:00:00, 013[Maintain] [DEBUG] ModuleForwarder: Checking for SMTP forwarding.
12:00:00, 029[Maintain] [DEBUG] ModuleForwarder: Checking for FTP/FTPS forwarding.
12:00:00, 029[Maintain] [INFO ] FTPPostArchiveListener: No messages to forward.
12:00:00, 029[Maintain] [DEBUG] FTPPostArchiveListener: Notifying queue thread.
12:00:00, 123[http-bio-48080-exec-7] [INFO ] AppController: Location of Catalina.base: E:\Program Files\Beginfinite\Retain\Tomcat 7.0\logs
12:00:00, 123[http-bio-48080-exec-7] [INFO ] AppController: Logs space left : 32639156224

[edit] Receive a Message

The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv

12:19:03, 471[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
12:19:03, 471[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: receiving document...
12:19:03, 471[Store_1468952343471_28125] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
12:19:03, 471[Store_1468952343471_28125] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
12:19:03, 471[Store_1468952343471_28125] [INFO ] StoreEmail: userID: test19@gwava.net
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: file received: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt" (541 bytes)
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: file received, ContentLength: 2143 bytes
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 374
12:19:03, 471[Store_1468952343471_28125] [TRACE] StoreEmail: asDoc.compressedSize = 374
12:19:03, 471[Store_1468952343471_28125] [DEBUG] SingleProcessStorageEngine: receiving document UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt done. hash:46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
12:19:04, 002[Store_1468952343471_28125] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952344;et=0
12:19:04, 815[Store_1468952343471_28125] [INFO ] RetainDBStorageEngine: About to commmit transaction null
12:19:04, 846[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149617, hash=46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
12:19:04, 846[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
12:19:05, 737[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt" has parent: \test19\Inbox isSubmail: false has changed: true
12:19:05, 737[Store_1468952343471_28125] [DEBUG] RetainDBStorageEngine: check if indexing needed...
12:19:05, 737[Store_1468952343471_28125] [DEBUG] StoreEmail: archiving document...done
12:19:05, 737[Store_1468952343471_28125] [TRACE] StoreEmail: All dummy bytes read (5)
12:19:05, 737[Store_1468952343471_28125] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
12:19:05, 737[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
12:19:05, 752[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
12:19:05, 752[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: receiving document...
12:19:05, 752[Store_1468952345752_28126] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
12:19:05, 752[Store_1468952345752_28126] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
12:19:05, 752[Store_1468952345752_28126] [INFO ] StoreEmail: userID: test19@gwava.net
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: file received: "shuffled.csv" (592 bytes)
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: file received, ContentLength: 2131 bytes
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 264
12:19:05, 752[Store_1468952345752_28126] [TRACE] StoreEmail: asDoc.compressedSize = 264
12:19:05, 752[Store_1468952345752_28126] [DEBUG] SingleProcessStorageEngine: receiving document shuffled.csv done. hash:AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
12:19:05, 768[Store_1468952345752_28126] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952345;et=0
12:19:05, 924[Store_1468952345752_28126] [INFO ] RetainDBStorageEngine: About to commmit transaction null
12:19:05, 924[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: handling non-bodytext...
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID:  6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149618, hash=AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: Message was present: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, doc: com.gwava.dao.social.Document id=12149618, hash=AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: "shuffled.csv" has parent: \test19\Inbox isSubmail: false has changed: false
12:19:06, 034[Store_1468952345752_28126] [DEBUG] RetainDBStorageEngine: check if indexing needed...
12:19:06, 034[Store_1468952345752_28126] [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=?
12:19:06, 034[Store_1468952345752_28126] [DEBUG] StoreEmail: archiving document...done
12:19:06, 034[Store_1468952345752_28126] [TRACE] StoreEmail: All dummy bytes read (5)
12:19:06, 034[Store_1468952345752_28126] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 AB7815E40BBDC8ADD8829950A76FD929731FEE90D30BEDB8331736E6ADAC93C9
12:19:06, 034[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully
12:19:06, 049[http-bio-48080-exec-5] [INFO ] index: ==========================================================================================
12:19:06, 049[http-bio-48080-exec-5] [TRACE] index: index.jsp: began
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: receiving document...
12:19:06, 049[Store_1468952346049_28127] [TRACE] IndexingOperationsImpl: IndexAdmin().isInitialized(): true
12:19:06, 049[Store_1468952346049_28127] [INFO ] StoreEmail: #begin archiving: DDB2E4039E3B4C6AFF18ECD1FD30A29F 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
12:19:06, 049[Store_1468952346049_28127] [INFO ] StoreEmail: userID: test19@gwava.net
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: file received: "utf.txt" (2050 bytes)
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: file received, ContentLength: 2641 bytes
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: request.getContentLength() - (metaDataLength+2) = 778
12:19:06, 049[Store_1468952346049_28127] [TRACE] StoreEmail: asDoc.compressedSize = 778
12:19:06, 049[Store_1468952346049_28127] [DEBUG] SingleProcessStorageEngine: receiving document utf.txt done. hash:4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
12:19:06, 049[Store_1468952346049_28127] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
12:19:06, 862[Store_1468952346049_28127] [INFO ] RetainDBStorageEngine: About to commmit transaction null
12:19:06, 877[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: handling non-bodytext...
12:19:06, 956[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
12:19:06, 987[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
12:19:06, 987[solrcloudQueueThread0] [TRACE] PartitionCache: Def Partition Path: PARTITION:id=0;name=default;path=E:\Retain\archive;bt=1468952346;et=0
12:19:07, 002[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: [HibernateUtil.insertMessage]:  , msgID: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3, uuid: 66cd42a7-1e0c-4c76-a461-e4c81726dbfb, doc: com.gwava.dao.social.Document id=12149619, hash=4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
12:19:07, 018[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: Message was present: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171, doc: com.gwava.dao.social.Document id=12149619, hash=4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
12:19:07, 043[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171 - attachments hasChanged: true
12:19:07, 056[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: "utf.txt" has parent: \test19\Inbox isSubmail: false has changed: false
12:19:07, 056[Store_1468952346049_28127] [DEBUG] RetainDBStorageEngine: check if indexing needed...
12:19:07, 056[Store_1468952346049_28127] [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=?
12:19:07, 056[Store_1468952346049_28127] [DEBUG] StoreEmail: archiving document...done
12:19:07, 056[Store_1468952346049_28127] [TRACE] StoreEmail: All dummy bytes read (5)
12:19:07, 056[Store_1468952346049_28127] [INFO ] StoreEmail: #done archiving: 6820dc7924bd77479af526bf5cb3282c00000000010d#6820dc7924bd77479af526bf5cb3282c0000b051f4d3 4A3FBDE01EADC2955640FCC4BC1479198DD6BCCBD4E5A40E19C88F58C414AAD5
12:19:07, 056[http-bio-48080-exec-5] [TRACE] index: index.jsp: ended gracefully

[edit] Job Ending

The end of the job will look like this:

13:00:25, 398[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 398[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:25, 413[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 413[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:25, 429[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 429[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F 
13:00:25, 507[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 507[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F 
13:00:25, 523[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 523[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:25, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: mb ca727e52-c039-4e2e-bb2e-be57851e2ae8 found, archived: 0, intUuid: ca727e52-c039-4e2e-bb2e-be57851e2ae8
13:00:25, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: lastmailbox, enterMailbox: ca727e52-c039-4e2e-bb2e-be57851e2ae8 archived: 0
13:00:25, 804[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 804[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F 
13:00:25, 819[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:25, 819[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 694[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 694[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 773[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 773[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 788[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 788[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 788[http-bio-48080-exec-6] [INFO ] LegacyStatController: Worker job has concluded
13:00:26, 804[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 804[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F 
13:00:26, 819[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 819[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 835[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 835[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 851[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 851[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 882[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 882[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:26, 913[http-bio-48080-exec-6] [DEBUG] ServerController: ServerController.jsp: Method called: svStatus
13:00:26, 913[http-bio-48080-exec-6] [TRACE] LegacyStatController: processSvStatus, worker: DDB2E4039E3B4C6AFF18ECD1FD30A29F ECD7EFFD600E95C66902048EE9A47EB5
13:00:27, 070[http-bio-48080-exec-3] [INFO ] JobStatusController: HeartBeat message received for JobRun: HeartBeat {ID=789, endTime=1468954826, status=1}
13:00:27, 091[HeartBeat] [TRACE] CheckHeartBeatThread: Entered CheckHeartBeatThread and will be sleeping for 10 minutes
13:00:27, 148[Thread-165589] [TRACE] JobStatusController: server endJobRun Email response.getBody() = null

[edit] Server Log Reading Techniques

Tracing a message coming into the server can be challenging because the server can be receiving data from multiple sources at the same time. You can use the threadID to do it. A threadID is something like [http-bio-48080-exec-6]

[edit] Indexer

You would go into the Indexer logs when trying to determine why the indexer is not starting, seeing many failed items in the Server Configuration/Index tab, or if items are not being found in search.

[edit] Indexing a Message

There is nothing special about when a job begins. The indexer indexes items as it is fed new data:

The following message has the subject: "UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171" with 2 attachments: utf.txt and shuffled.csv

12:19:13, 143 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: indexing: UTF8_HTML Go-Postal 07/19/2016 02:19:09 762595171.txt, filesize: 541, handlerclass: com.gwava.extractor.TextExtractor hash: 46B808CC98C3ED7B988353761D0A116B9B97115EE5E8524BD5DF2A8B8DFBCE7D
12:19:13, 143 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
12:19:13, 143 [TRACE] [solrcloudQueueThread1] Extractor: Textextractor rejected binary file
12:19:13, 143 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
12:19:13, 159 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing
12:19:13, 159 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: addToSolrCloud() - addingDoc to index...
12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudIndexingAddition: Add doc response:{responseHeader={status=0,QTime=73}}
12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: addToSolrCloud() - addingDoc to index done.
12:19:13, 643 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - successFullyAddedDoc: true, indexedValue: 64
12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: [BGINDEXER] Adding email id 4138831 to index.
12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: consume() - committing changes to DB ...
12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: creating docUtil...
12:19:13, 643 [INFO ] [solrcloudQueueThread1] SolrCloudIndexingQueueThread: Indexer: Adding email to index...4138834
12:19:13, 659 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
12:19:13, 659 [TRACE] [solrcloudQueueThread1] Extractor: Textextractor rejected binary file
12:19:13, 659 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 0
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Entering attachment processing
12:19:13, 674 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: indexing: utf.txt, filesize: 1948, handlerclass: com.gwava.extractor.TextExtractor hash: 1DF136232E51E46642C545EFA40F0BA8CAE0D4C20BFAFCA30FF517DE8FBC9331
12:19:13, 674 [TRACE] [solrcloudQueueThread1] TextExtractionService: Began extraction process
12:19:13, 674 [TRACE] [solrcloudQueueThread1] TextExtractionService: Returned from Extraction process
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing
12:19:13, 674 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 1
12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Entering attachment processing
12:19:13, 690 [DEBUG] [solrcloudQueueThread1] SolrCloudDocumentUtil: INDEXING_NOT_ON_WHITELIST: shuffled.csv, filesize: 592, handlerclass: null hash: EEB758423B031AECEDC077AA6DA93A7F3339D7B9815EF4515EDD84D86994B0AF
12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachmentStreams() - Exiting attachment processing 
12:19:13, 690 [TRACE] [solrcloudQueueThread1] SolrCloudDocumentUtil: processAttachedDocumentToIndex() - Looping through att 2



Return to Retain Training

Personal tools
Namespaces

Variants
Actions
Home
Exchange
GroupWise
JAVA
Linux
MTK
Retain
GW Monitoring and Reporting (Redline)
GW Disaster Recovery (Reload)
GW Forensics (Reveal)
GWAVA
Secure Messaging Gateway
GW Mailbox Management (Vertigo)
Windows
Other
User Experience
Toolbox
Languages
Toolbox