Operation Full Scan failed

[velvet]

Hello,

we wanted to backup a fresh system but get this error message:

----
This is an automated notification from ZxBackup about Full Scan.

Operation Full Scan failed.

Operation Id: 064c11ca-9195-4eaf-b6db-ecacbb7e2ec5

ZeXtras Version: 1.8.11
ZeXtras commit: a7c892d274217bc312945152e49013aadc8c2b35
Zimbra version: 8.0.4_GA_5737 20130524120036 20130524-1207 FOSS

- exception -
com.zimbra.cs.mailbox.MailboxLock$LockFailedExcept ion: timeout
at com.zimbra.cs.mailbox.MailboxLock.lock ( MailboxLock.java:58 )
at com.zextras.zal.ZEMailbox.getItemList ( ZEMailbox.java:585 )
at com.zextras.op.backup.ZEScanOperation.doItemsScan ( ZEScanOperation.java:488 )
at com.zextras.op.backup.ZEScanOperation.doAllItemsSc an ( ZEScanOperation.java:463 )
at com.zextras.op.backup.ZEScanOperation.doAccountSca n ( ZEScanOperation.java:415 )
at com.zextras.op.backup.ZEScanOperation.doDomainScan ( ZEScanOperation.java:105 )
at com.zextras.op.backup.ZEFullScanOperation.doOperat ion ( ZEFullScanOperation.java:385 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )

Last progress info:
--
Operation log path: none
Purge Account Checked: 35/35
Account scanned: 11/41
Account skipped(disabled by COS): 0
Account updated/new: 0/5
Item scanned: 39424
Item updated/new/unique: 3/23514/14336
------------

ZeXtras Version: 1.8.11
Zimbra version: 8.0.4_GA_5737 20130524120036 20130524-1207 FOSS
OS: Ubuntu 12.04 LTS

someone an idea?

thanks,
velvet

[Cine]

Hello Velvet!

The error you report means that ZeXtras Backup has been unable to access a mailbox due to a lock set by another Zimbra process. Could you please retry running the FullScan?
Should it fail again, could you please provide us with the output of the following command?

(run as the 'zimbra' user)

zmlocalconfig | grep -i mailboxd_java

Also, please let me know the amount of Ram memory on your server.

Have a nice day,
Cine
the ZeXtras Team

[velvet]

Hi Cine,

fail again!

MemTotal: 8150608 kB
MemFree: 133752 kB


mailboxd_java_heap_new_size_percent = 25
mailboxd_java_heap_size = 1996
mailboxd_java_options = -server -Djava.awt.headless=true -Dsun.net.inetaddr.ttl=${networkaddress_cache_ttl} -Dorg.apache.jasper.compiler.disablejsr199=true -XX:+UseConcMarkSweepGC -XX:PermSize=128m -XX:MaxPermSize=350m -XX:SoftRefLRUPolicyMSPerMB=1 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:-OmitStackTraceInFastThrow -Djava.net.preferIPv4Stack=true


ps: increased the XX:PermSize=128m to XX:PermSize=192m

same error:

- exception -
com.zimbra.cs.mailbox.MailboxLock$LockFailedExcept ion: timeout
at com.zimbra.cs.mailbox.MailboxLock.lock ( MailboxLock.java:58 )
at com.zextras.zal.ZEMailbox.getItemList ( ZEMailbox.java:585 )
at com.zextras.op.backup.ZEScanOperation.doItemsScan ( ZEScanOperation.java:488 )
at com.zextras.op.backup.ZEScanOperation.doAllItemsSc an ( ZEScanOperation.java:469 )
at com.zextras.op.backup.ZEScanOperation.doAccountSca n ( ZEScanOperation.java:415 )
at com.zextras.op.backup.ZEScanOperation.doDomainScan ( ZEScanOperation.java:105 )
at com.zextras.op.backup.ZEFullScanOperation.doOperat ion ( ZEFullScanOperation.java:385 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )

Thanks for your quick reply!
Velvet

[Cine]

Hello Velvet!

Did the operation stop when accessing the same mailbox as before? If so, the cause might be a thread that froze/got stuck after locking the mailbox and before unlocking it, and in this case restarting the mailboxd should kill the thread and allow you to perform the FullScan.

Have a nice day,
Cine
the ZeXtras Team

p.s.: Albeit this is not the cause of the issue you are experiencing, I'd suggest you to rise the PermSize value from 128m to 196m, which is the default for Zimbra 8.x.

[velvet]

Hello Cine,

mailboxd restarted but same error

- exception -
com.zimbra.cs.mailbox.MailboxLock$LockFailedExcept ion: timeout
at com.zimbra.cs.mailbox.MailboxLock.lock ( MailboxLock.java:58 )
at com.zimbra.cs.mailbox.Mailbox.beginTrackingSync ( Mailbox.java:3170 )
at com.zextras.zal.ZEMailbox.beginTrackingSync ( ZEMailbox.java:546 )
at com.zextras.op.backup.ZEScanOperation.doAccountSca n ( ZEScanOperation.java:385 )
at com.zextras.op.backup.ZEScanOperation.doDomainScan ( ZEScanOperation.java:105 )
at com.zextras.op.backup.ZEFullScanOperation.doOperat ion ( ZEFullScanOperation.java:385 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )

Thanks Velvet

[Cine]

Hello Cine,

mailboxd restarted but same error

- exception -
com.zimbra.cs.mailbox.MailboxLock$LockFailedExcept ion: timeout
at com.zimbra.cs.mailbox.MailboxLock.lock ( MailboxLock.java:58 )
at com.zimbra.cs.mailbox.Mailbox.beginTrackingSync ( Mailbox.java:3170 )
at com.zextras.zal.ZEMailbox.beginTrackingSync ( ZEMailbox.java:546 )
at com.zextras.op.backup.ZEScanOperation.doAccountSca n ( ZEScanOperation.java:385 )
at com.zextras.op.backup.ZEScanOperation.doDomainScan ( ZEScanOperation.java:105 )
at com.zextras.op.backup.ZEFullScanOperation.doOperat ion ( ZEFullScanOperation.java:385 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )

Thanks Velvet

Hello Velvet!

This is strange indeed...
Do you confirm that the process gets stuck every time on the same account?
An analysis on the account will be needed to find the cause of the issue (I'll send you a PM), meanwhile please do the following:
- Create a copy of the Class of Service to which the account belongs to
- Exclude the CoS from the backup (as described at ZxBackup COS-level Backup Management - ZeXtras Suite Wiki)
- Move the account to this new CoS
- Start the FullScan again

This will force ZxBackup to skip the account, so that if the operation is completed this way we'll be sure that the cause is to be searched within the account.

Have a nice day,
Cine

[velvet]

Hi Cine,

yes the process gets stuck! I figured out the account - this was already making problems when import.
the good news is the backup is working now! the bad news import problems with this account:

here the error msg:

- exception -
[ExternalRestore] Unknown Exception
at com.zextras.op.backup.ZEExternalRestoreOperation.r estoreItemsFromExternal ( ZEExternalRestoreOperation.java:1010 )
at com.zextras.op.backup.ZEExternalRestoreOperation.d oOperation ( ZEExternalRestoreOperation.java:748 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )
Caused by: java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf ( Arrays.java:2271 )
at java.io.ByteArrayOutputStream.grow ( ByteArrayOutputStream.java:113 )
at java.io.ByteArrayOutputStream.ensureCapacity ( ByteArrayOutputStream.java:93 )
at java.io.ByteArrayOutputStream.write ( ByteArrayOutputStream.java:140 )
at com.sun.mail.util.ASCIIUtility.getBytes ( ASCIIUtility.java:270 )
at javax.mail.internet.MimeMessage.parse ( MimeMessage.java:339 )
at javax.mail.internet.MimeMessage.<init> ( MimeMessage.java:209 )
at com.sun.mail.handlers.message_rfc822.getContent ( message_rfc822.java:103 )
at javax.activation.DataSourceDataContentHandler.getC ontent ( DataHandler.java:790 )
at javax.activation.DataHandler.getContent ( DataHandler.java:537 )
at javax.mail.internet.MimeBodyPart.getContent ( MimeBodyPart.java:637 )
at com.zimbra.cs.mime.Mime.getMessageContent ( Mime.java:532 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:231 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:213 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:176 )
at com.zimbra.cs.mime.ExpandMimeMessage.expand ( ExpandMimeMessage.java:86 )
at com.zimbra.cs.mime.ParsedMessage.init ( ParsedMessage.java:280 )
at com.zimbra.cs.mime.ParsedMessage.initialize ( ParsedMessage.java:229 )
at com.zimbra.cs.mime.ParsedMessage.initialize ( ParsedMessage.java:197 )
at com.zimbra.cs.mime.ParsedMessage.<init> ( ParsedMessage.java:151 )
at com.zimbra.cs.mime.ParsedMessage.<init> ( ParsedMessage.java:147 )
at com.zimbra.cs.mailbox.CalendarItem.storeUpdatedBlo b ( CalendarItem.java:2331 )
at com.zimbra.cs.mailbox.CalendarItem.modifyBlob ( CalendarItem.java:2590 )
at com.zimbra.cs.mailbox.CalendarItem.processNewInvit eRequestOrCancel ( CalendarItem.java:2100 )
at com.zimbra.cs.mailbox.CalendarItem.processNewInvit e ( CalendarItem.java:1400 )
at com.zimbra.cs.mailbox.Mailbox.addInvite ( Mailbox.java:4908 )
at com.zextras.zal.ZEMailbox.addInvite ( ZEMailbox.java:816 )
at com.zextras.backup.ZEBItem.createZimbraItem ( ZEBItem.java:1855 )
at com.zextras.backup.ZEBItem.restore ( ZEBItem.java:652 )
at com.zextras.op.backup.ZEExternalRestoreOperation.r estoreItemsFromExternal ( ZEExternalRestoreOperation.java:933 )
at com.zextras.op.backup.ZEExternalRestoreOperation.d oOperation ( ZEExternalRestoreOperation.java:748 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )

thanks,
velvet

[Cine]

Hi Cine,

the good news is the backup is working now!

Hello Velvet!
This is great news

yes the process gets stuck! I figured out the account - this was already making problems when import.
the bad news import problems with this account:

Hmmm... I thought we were talking about a FullScan, could you please give us a bit of context on this?

here the error msg:

- exception -
[ExternalRestore] Unknown Exception
at com.zextras.op.backup.ZEExternalRestoreOperation.r estoreItemsFromExternal ( ZEExternalRestoreOperation.java:1010 )
at com.zextras.op.backup.ZEExternalRestoreOperation.d oOperation ( ZEExternalRestoreOperation.java:748 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )
at com.zextras.backup.ZEBackupThread.execOperation ( ZEBackupThread.java:225 )
at com.zextras.backup.ZEBackupThread.run ( ZEBackupThread.java:114 )
Caused by: java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf ( Arrays.java:2271 )
at java.io.ByteArrayOutputStream.grow ( ByteArrayOutputStream.java:113 )
at java.io.ByteArrayOutputStream.ensureCapacity ( ByteArrayOutputStream.java:93 )
at java.io.ByteArrayOutputStream.write ( ByteArrayOutputStream.java:140 )
at com.sun.mail.util.ASCIIUtility.getBytes ( ASCIIUtility.java:270 )
at javax.mail.internet.MimeMessage.parse ( MimeMessage.java:339 )
at javax.mail.internet.MimeMessage.<init> ( MimeMessage.java:209 )
at com.sun.mail.handlers.message_rfc822.getContent ( message_rfc822.java:103 )
at javax.activation.DataSourceDataContentHandler.getC ontent ( DataHandler.java:790 )
at javax.activation.DataHandler.getContent ( DataHandler.java:537 )
at javax.mail.internet.MimeBodyPart.getContent ( MimeBodyPart.java:637 )
at com.zimbra.cs.mime.Mime.getMessageContent ( Mime.java:532 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:231 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:213 )
at com.zimbra.cs.mime.MimeVisitor.accept ( MimeVisitor.java:176 )
at com.zimbra.cs.mime.ExpandMimeMessage.expand ( ExpandMimeMessage.java:86 )
at com.zimbra.cs.mime.ParsedMessage.init ( ParsedMessage.java:280 )
at com.zimbra.cs.mime.ParsedMessage.initialize ( ParsedMessage.java:229 )
at com.zimbra.cs.mime.ParsedMessage.initialize ( ParsedMessage.java:197 )
at com.zimbra.cs.mime.ParsedMessage.<init> ( ParsedMessage.java:151 )
at com.zimbra.cs.mime.ParsedMessage.<init> ( ParsedMessage.java:147 )
at com.zimbra.cs.mailbox.CalendarItem.storeUpdatedBlo b ( CalendarItem.java:2331 )
at com.zimbra.cs.mailbox.CalendarItem.modifyBlob ( CalendarItem.java:2590 )
at com.zimbra.cs.mailbox.CalendarItem.processNewInvit eRequestOrCancel ( CalendarItem.java:2100 )
at com.zimbra.cs.mailbox.CalendarItem.processNewInvit e ( CalendarItem.java:1400 )
at com.zimbra.cs.mailbox.Mailbox.addInvite ( Mailbox.java:4908 )
at com.zextras.zal.ZEMailbox.addInvite ( ZEMailbox.java:816 )
at com.zextras.backup.ZEBItem.createZimbraItem ( ZEBItem.java:1855 )
at com.zextras.backup.ZEBItem.restore ( ZEBItem.java:652 )
at com.zextras.op.backup.ZEExternalRestoreOperation.r estoreItemsFromExternal ( ZEExternalRestoreOperation.java:933 )
at com.zextras.op.backup.ZEExternalRestoreOperation.d oOperation ( ZEExternalRestoreOperation.java:748 )
at com.zextras.op.ZEOperation.exec ( ZEOperation.java:652 )

thanks,
velvet

Looks there is a bad item inside the account, which causes an Out of Memory error (see the "java.lang.OutOfMemoryError: Java heap space" line in the error) upon decoding... I'll be able to give you some additional help on this once provide a bit of context on this import

Have a nice day,
Cine
the ZeXtras Team

[velvet]

Hi Cine,

sorry for the confusion! after a total system crash I have restored all accounts whitchout check the log files!

Everything looked good until I make a backup (fullscan) - I found the account which makes trouble and exclude it from backup as you told me!
Now, I wanted to restore the account again and get the message above!

How can I figure out the bad item?

Thanks,
Velvet

[Cine]

Hi Cine,

sorry for the confusion! after a total system crash I have restored all accounts whitchout check the log files!

Everything looked good until I make a backup (fullscan) - I found the account which makes trouble and exclude it from backup as you told me!
Now, I wanted to restore the account again and get the message above!

No problem

Let's see if I got the picture now:

- Your original Zimbra server, running ZeXtras Backup, crashed.
- You restored your data on a new server (?using the old server's backup path as the source?)
- The restore was completed (?you got an "Operation Completed" notification?)
- The first FullScan crashed.
- You noticed an exception in the import log.

How can I figure out the bad item?

I see from the error you posted that the item causing the issue is a Calendar appointment/invitation, to be more specific I'd need to see the restore log... Could you please compress it and email it to community@zextras.com? Also, if you still have the "Operation Completed" notification from the first import, could you please send that as well?

Thanks,
Velvet

You're welcome!

Have a nice day,
Cine
the ZeXtras Team