For one Office365 mailbox processed using javamail, folder.close(true) is not purging deleted emails

2
votes

Multiple mailboxes are getting processed hosted on Office365 using JavaMail. IMAP protocol is used to access these mailboxes.

After processing a mail from mailbox, message is deleted by using following 2 methods

  1. message.setFlag(Flags.Flag.Deleted, true ); - set's the delete flag.
  2. folder.close(true) - this commands expunges the messages where delete flag is set to true.

Above 2 commands were working fine for all mailboxes for more then 3 months, but few day's back - folder.close(true) stopped working for one of the mailboxes.

Messages marked for deleted are not getting expunged for mailbox and showing up in web outlook for Office365. Manual deletion from web outlook is working fine.

But now, processed email's are getting accumulated in the INBOX because they are not getting expunged (purged).

Other mailboxes are working fine with the above approach. This mailbox also worked fine for 3+ month, but giving this issue since last few days. 

2019-02-14 12:42:20.028 [INFO ] System.out                               - DEBUG: setDebug: JavaMail version 1.6.2
2019-02-14 12:42:20.032 [INFO ] System.out                               - DEBUG: getProvider() returning javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Oracle]
2019-02-14 12:42:20.041 [INFO ] System.out                               - DEBUG IMAPS: mail.imap.partialfetch: false
2019-02-14 12:42:20.042 [INFO ] System.out                               - DEBUG IMAPS: mail.imap.ignorebodystructuresize: false
2019-02-14 12:42:20.043 [INFO ] System.out                               - DEBUG IMAPS: mail.imap.statuscachetimeout: 1000
2019-02-14 12:42:20.043 [INFO ] System.out                               - DEBUG IMAPS: mail.imap.appendbuffersize: -1
2019-02-14 12:42:20.043 [INFO ] System.out                               - DEBUG IMAPS: mail.imap.minidletime: 10
2019-02-14 12:42:20.043 [INFO ] System.out                               - DEBUG IMAPS: closeFoldersOnStoreFailure
2019-02-14 12:42:20.045 [INFO ] System.out                               - DEBUG IMAPS: trying to connect to host "52.96.17.2", port 993, isSSL true
2019-02-14 12:42:20.285 [INFO ] System.out                               - * OK The Microsoft Exchange IMAP4 service is ready. [XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX]
2019-02-14 12:42:20.286 [INFO ] System.out                               - A0 CAPABILITY
2019-02-14 12:42:20.313 [INFO ] System.out                               - * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+
2019-02-14 12:42:20.313 [INFO ] System.out                               - A0 OK CAPABILITY completed.
2019-02-14 12:42:20.314 [INFO ] System.out                               - DEBUG IMAPS: AUTH: PLAIN
2019-02-14 12:42:20.314 [INFO ] System.out                               - DEBUG IMAPS: AUTH: XOAUTH2
2019-02-14 12:42:20.322 [INFO ] System.out                               - DEBUG IMAPS: protocolConnect login, host=52.96.17.2, user=RXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX, password=
2019-02-14 12:42:20.322 [INFO ] System.out                               - DEBUG IMAPS: AUTHENTICATE PLAIN command trace suppressed
2019-02-14 12:42:20.659 [INFO ] System.out                               - DEBUG IMAPS: AUTHENTICATE PLAIN command result: A1 OK AUTHENTICATE completed.
2019-02-14 12:42:20.661 [INFO ] System.out                               - A2 CAPABILITY
2019-02-14 12:42:20.710 [INFO ] System.out                               - * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTACCESSRULES CLIENTNETWORKPRESENCELOCATION BACKENDAUTHENTICATE CHILDREN IDLE NAMESPACE LITERAL+
2019-02-14 12:42:20.711 [INFO ] System.out                               - A2 OK CAPABILITY completed.
2019-02-14 12:42:20.712 [INFO ] System.out                               - DEBUG IMAPS: AUTH: PLAIN
2019-02-14 12:42:20.712 [INFO ] System.out                               - DEBUG IMAPS: AUTH: XOAUTH2
2019-02-14 12:42:20.723 [INFO ] System.out                               - DEBUG IMAPS: connection available -- size: 1
2019-02-14 12:42:20.725 [INFO ] System.out                               - A3 SELECT INBOX
2019-02-14 12:42:21.240 [INFO ] System.out                               - * 18612 EXISTS
2019-02-14 12:42:21.240 [INFO ] System.out                               - * 9 RECENT
2019-02-14 12:42:21.240 [INFO ] System.out                               - * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
2019-02-14 12:42:21.240 [INFO ] System.out                               - * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
2019-02-14 12:42:21.240 [INFO ] System.out                               - * OK [UNSEEN 525] Is the first unseen message
2019-02-14 12:42:21.240 [INFO ] System.out                               - * OK [UIDVALIDITY 14] UIDVALIDITY value
2019-02-14 12:42:21.240 [INFO ] System.out                               - * OK [UIDNEXT 229182] The next unique identifier value
2019-02-14 12:42:21.241 [INFO ] System.out                               - A3 OK [READ-WRITE] SELECT completed.
2019-02-14 12:42:21.250 [INFO ] System.out                               - A4 STORE 1 +FLAGS (\Deleted)
2019-02-14 12:42:21.305 [INFO ] System.out                               - * 1 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:21.305 [INFO ] System.out                               - A4 OK STORE completed.
2019-02-14 12:42:21.306 [INFO ] System.out                               - A5 FETCH 1 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:21.365 [INFO ] System.out                               - * 1 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:44:13 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:45:33 -0500" RFC822.SIZE 3380282)
2019-02-14 12:42:21.433 [INFO ] System.out                               - A5 OK FETCH completed.
2019-02-14 12:42:21.436 [INFO ] System.out                               - A6 STORE 2 +FLAGS (\Deleted)
2019-02-14 12:42:21.488 [INFO ] System.out                               - * 2 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:21.489 [INFO ] System.out                               - A6 OK STORE completed.
2019-02-14 12:42:21.489 [INFO ] System.out                               - A7 FETCH 2 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:21.545 [INFO ] System.out                               - * 2 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:44:03 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:45:45 -0500" RFC822.SIZE 142562)
2019-02-14 12:42:21.611 [INFO ] System.out                               - A7 OK FETCH completed.
2019-02-14 12:42:21.611 [INFO ] System.out                               - A8 STORE 3 +FLAGS (\Deleted)
2019-02-14 12:42:21.664 [INFO ] System.out                               - * 3 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:21.664 [INFO ] System.out                               - A8 OK STORE completed.
2019-02-14 12:42:21.664 [INFO ] System.out                               - A9 FETCH 3 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:21.723 [INFO ] System.out                               - * 3 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:44:02 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:45:47 -0500" RFC822.SIZE 142336)
2019-02-14 12:42:21.789 [INFO ] System.out                               - A9 OK FETCH completed.
2019-02-14 12:42:21.790 [INFO ] System.out                               - A10 STORE 4 +FLAGS (\Deleted)
2019-02-14 12:42:21.846 [INFO ] System.out                               - * 4 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:21.846 [INFO ] System.out                               - A10 OK STORE completed.
2019-02-14 12:42:21.846 [INFO ] System.out                               - A11 FETCH 4 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:21.904 [INFO ] System.out                               - * 4 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:45:53 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" (("Mail Delivery System" NIL "MAILER-DAEMON" "xxx.com")) NIL NIL ((NIL NIL "UQOYQZC9WLTITDTU.yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:45:58 -0500" RFC822.SIZE 112177)
2019-02-14 12:42:21.969 [INFO ] System.out                               - A11 OK FETCH completed.
2019-02-14 12:42:21.969 [INFO ] System.out                               - A12 STORE 5 +FLAGS (\Deleted)
2019-02-14 12:42:22.022 [INFO ] System.out                               - * 5 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:22.023 [INFO ] System.out                               - A12 OK STORE completed.
2019-02-14 12:42:22.023 [INFO ] System.out                               - A13 FETCH 5 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:22.080 [INFO ] System.out                               - * 5 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:44:41 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:46:34 -0500" RFC822.SIZE 123255)
2019-02-14 12:42:22.144 [INFO ] System.out                               - A13 OK FETCH completed.
2019-02-14 12:42:22.145 [INFO ] System.out                               - A14 STORE 6 +FLAGS (\Deleted)
2019-02-14 12:42:22.198 [INFO ] System.out                               - * 6 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:22.198 [INFO ] System.out                               - A14 OK STORE completed.
2019-02-14 12:42:22.198 [INFO ] System.out                               - A15 FETCH 6 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:22.263 [INFO ] System.out                               - * 6 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:46:38 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" (("Mail Delivery System" NIL "MAILER-DAEMON" "xxx.com")) NIL NIL ((NIL NIL "UQOYQZC9WLTITDTU.yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:46:41 -0500" RFC822.SIZE 112337)
2019-02-14 12:42:22.345 [INFO ] System.out                               - A15 OK FETCH completed.
2019-02-14 12:42:22.346 [INFO ] System.out                               - A16 STORE 7 +FLAGS (\Deleted)
2019-02-14 12:42:22.398 [INFO ] System.out                               - * 7 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:22.399 [INFO ] System.out                               - A16 OK STORE completed.
2019-02-14 12:42:22.399 [INFO ] System.out                               - A17 FETCH 7 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:22.454 [INFO ] System.out                               - * 7 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:45:36 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:46:53 -0500" RFC822.SIZE 2056890)
2019-02-14 12:42:22.520 [INFO ] System.out                               - A17 OK FETCH completed.
2019-02-14 12:42:22.522 [INFO ] System.out                               - A18 STORE 8 +FLAGS (\Deleted)
2019-02-14 12:42:22.575 [INFO ] System.out                               - * 8 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:22.575 [INFO ] System.out                               - A18 OK STORE completed.
2019-02-14 12:42:22.575 [INFO ] System.out                               - A19 FETCH 8 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:22.636 [INFO ] System.out                               - * 8 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:46:10 +0000" "XXXXXXXXXXXXXXXXXXXXXX" (("XXXXXXXXXXX" NIL "xxxx" "xxx.com")) NIL NIL (("XXXXXXXXXXXX" NIL "XXXXXXX" "xxx.com")) (("fas" NIL "fas" "xxx.com") ("New Accounts" NIL "UQOYQZC9WLTITDTU.yyyy" "xxx.com")) NIL NIL "") INTERNALDATE "08-Feb-2019 08:47:10 -0500" RFC822.SIZE 513338)
2019-02-14 12:42:22.701 [INFO ] System.out                               - A19 OK FETCH completed.
2019-02-14 12:42:22.701 [INFO ] System.out                               - A20 STORE 9 +FLAGS (\Deleted)
2019-02-14 12:42:22.754 [INFO ] System.out                               - * 9 FETCH (FLAGS (\Seen \Deleted))
2019-02-14 12:42:22.755 [INFO ] System.out                               - A20 OK STORE completed.
2019-02-14 12:42:22.755 [INFO ] System.out                               - A21 FETCH 9 (ENVELOPE INTERNALDATE RFC822.SIZE)
2019-02-14 12:42:22.810 [INFO ] System.out                               - * 9 FETCH (ENVELOPE ("Fri, 8 Feb 2019 13:45:27 +0000" "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" ((NIL NIL "yyyy" "xxx.com")) NIL NIL ((NIL NIL "yyyy" "xxx.com")) NIL NIL NIL "") INTERNALDATE "08-Feb-2019 08:48:26 -0500" RFC822.SIZE 906337)
2019-02-14 12:42:22.876 [INFO ] System.out                               - A21 OK FETCH completed.
2019-02-14 12:42:22.877 [INFO ] i.i.zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz  - Closing the folder ##############################
2019-02-14 12:42:22.877 [INFO ] System.out                               - A22 CLOSE
2019-02-14 12:42:25.321 [INFO ] System.out                               - A22 OK CLOSE completed.
2019-02-14 12:42:25.322 [INFO ] System.out                               - DEBUG IMAPS: added an Authenticated connection -- size: 1
2019-02-14 12:42:25.323 [INFO ] i.i.xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx  - End Closing the folder #################################
2019-02-14 12:42:25.323 [INFO ] System.out                               - DEBUG IMAPS: IMAPStore cleanup, force false
2019-02-14 12:42:25.323 [INFO ] System.out                               - A23 LOGOUT
2019-02-14 12:42:25.372 [INFO ] System.out                               - * BYE Microsoft Exchange Server IMAP4 server signing off.
2019-02-14 12:42:25.372 [INFO ] System.out                               - A23 OK LOGOUT completed.
2019-02-14 12:42:25.373 [INFO ] System.out                               - DEBUG IMAPS: IMAPStore cleanup done
1
office365jakarta-mailimap
Try calling expunge manually? – Max
Sounds like a server bug. Expunge should never fail. Might need to get the account checked for consistency. – Max
The question isn't whether Microsoft supports JavaMail access, the question is whether they support IMAP access. Show them the IMAP protocol log from the JavaMail debug output and ask them why those IMAP operations are not deleting and expunging the messages. – Bill Shannon
Issue was with archival process for the mailbox. With help from Microsoft it is fixed and now deletion is working fine. Thanks a lot @Bill Shanon and @Max! – programmer joe
If someone else runs into the same problem, how should they fix it? Feel free to "answer" your own question below. – Bill Shannon

1 Answers

2
votes

Issue was specific to Office 365 mailbox configuration. Which was combination of 2 things:

  1. Retention policy of the mailbox was indefinite.
  2. Archival was not enabled for the mailbox.

Once the emails are deleted from mailbox, they go to Recoverable Items folder. Once the mailbox quota exceeded the maximum allowed size, as retention policy of the mailbox was indefinite, they were not getting deleted from this folder. So any deletes from the INBOX was not going to Recoverable items folder as it was full, and these mails were put again in the mailbox.

Solution was to start the archival of the mailbox keeping recoverable items only for last 7 days.