Zimbra

JoshuaPrismon · #1 (**permalink**) 10-16-2007, 07:54 PM

Got annoyed at the size of my inbox. Decided it was time to update everything and filter the mail to make it more organized. Since the Zimbra rules don't allow me to run a filter over existing email messages, I decided to use thunderbird. Grabbed the leading edge thunderbird.

Manually searched for files, copied them into different folders in Zimbra. Everything looked fine in thunderbird, so I cleaned my inbox out. Then I went to the web client. Bad news, instead of copying 50 messages into one folder, I have 50 duplicate email messages in each folder (different messages each folder). Not sure if it was a Thunderbird screw up or a Zimbra one.

The mailstore looks intact. I snapshotted the file system before I started, but apparently caused more then 1GB of changes on the disk, which invalidated the snapshot. I have a offsite backup from last week.

I think I will probably end up just using grep to get at old file system based messages, but has anyone seen this before? I suppose I could use lmtp inject to rebuild the message store, but it's a unholy mess.

Anyone have any bright ideas? I already tried to re-index the user account to see if that would make a difference.

jholder · #2 (**permalink**) 10-16-2007, 08:04 PM

Quote:

Originally Posted by JoshuaPrismon

Got annoyed at the size of my inbox. Decided it was time to update everything and filter the mail to make it more organized. Since the Zimbra rules don't allow me to run a filter over existing email messages, I decided to use thunderbird. Grabbed the leading edge thunderbird.

Manually searched for files, copied them into different folders in Zimbra. Everything looked fine in thunderbird, so I cleaned my inbox out. Then I went to the web client. Bad news, instead of copying 50 messages into one folder, I have 50 duplicate email messages in each folder (different messages each folder). Not sure if it was a Thunderbird screw up or a Zimbra one.

The mailstore looks intact. I snapshotted the file system before I started, but apparently caused more then 1GB of changes on the disk, which invalidated the snapshot. I have a offsite backup from last week.

I think I will probably end up just using grep to get at old file system based messages, but has anyone seen this before? I suppose I could use lmtp inject to rebuild the message store, but it's a unholy mess.

Anyone have any bright ideas? I already tried to re-index the user account to see if that would make a difference.

Weird-
What does your mailbox.log indicate during that time? If it's on the Zimbra end, it should indicate it. If it's on the Tunderbird site, you should see somesort of upload. Also check zmmailboxd.out

JoshuaPrismon · #3 (**permalink**) 10-16-2007, 10:03 PM

Code:

I get a lot of errors that look like this:

2007-10-16 01:02:05,078 ERROR [btpool0-8] [name=josh@prismon.net;mid=3;ip=168.230.130.248;ua=ZimbraWebClient - IE7 (Win)/5.0.0_RC1_1538.RHEL5;] log - Nested 
in javax.servlet.ServletException: java.lang.IllegalStateException: Committed:
java.lang.IllegalStateException: Committed
        at org.mortbay.jetty.Response.resetBuffer(Response.java:990)
        at javax.servlet.ServletResponseWrapper.resetBuffer(ServletResponseWrapper.java:202)
        at org.mortbay.servlet.GzipFilter$GZIPResponseWrapper.resetBuffer(GzipFilter.java:268)
        at org.mortbay.servlet.GzipFilter$GZIPResponseWrapper.sendError(GzipFilter.java:283)
        at javax.servlet.http.HttpServletResponseWrapper.sendError(HttpServletResponseWrapper.java:128)
        at org.mortbay.jetty.servlet.DefaultServlet.doGet(DefaultServlet.java:400)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:362)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
        at org.mortbay.jetty.servlet.Dispatcher.include(Dispatcher.java:192)
        at org.apache.taglibs.standard.tag.common.core.ImportSupport.acquireString(Unknown Source)
        at org.apache.taglibs.standard.tag.common.core.ImportSupport.doEndTag(Unknown Source)
        at org.apache.jsp.tag.web.head_tag._jspx_meth_c_import_0(org.apache.jsp.tag.web.head_tag:407)
        at org.apache.jsp.tag.web.head_tag.doTag(org.apache.jsp.tag.web.head_tag:154)
        at org.apache.jsp.tag.web.infra.view_tag._jspx_meth_app_head_0(org.apache.jsp.tag.web.infra.view_tag:367)
        at org.apache.jsp.tag.web.infra.view_tag.doTag(org.apache.jsp.tag.web.infra.view_tag:324)
        at org.apache.jsp.h.search._jspx_meth_app_view_0(org.apache.jsp.h.search:1487)
        at org.apache.jsp.h.search._jspx_meth_c_otherwise_0(org.apache.jsp.h.search:1432)
        at org.apache.jsp.h.search._jspx_meth_c_choose_1(org.apache.jsp.h.search:974)
        at org.apache.jsp.h.search._jspService(org.apache.jsp.h.search:187)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:93)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:373)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:477)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:371)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
        at com.zimbra.webClient.filters.SetHeaderFilter.doFilter(SetHeaderFilter.java:312)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
        at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
        at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:132)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:712)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:405)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.handler.RewriteHandler.handle(RewriteHandler.java:176)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.Server.handle(Server.java:313)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:830)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:514)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:396)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)

The above might be related to some bad zimlet behavior though.

Code:

2007-10-16 06:41:13,608 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:41:43,613 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:42:13,617 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:42:43,621 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:43:13,626 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:43:43,631 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:44:13,635 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:44:43,640 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:45:13,644 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:45:43,649 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:46:13,654 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:46:43,659 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:47:13,663 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:47:43,668 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:48:13,673 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:48:43,678 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:49:13,682 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:49:43,687 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:50:13,692 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:50:43,696 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-16 06:51:13,710 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=1, after=0 (9ms)

Code:

2007-10-16 08:30:42,105 INFO  [ImapServer-3] [name=josh@prismon.net;mid=3;ip=67.176.47.54;] MailboxIndex - Initialized Index for mailbox 7 directory: org.apa
che.lucene.store.FSDirectory@/opt/zimbra/index/0/7/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@1ff5c98
2007-10-16 08:30:42,105 INFO  [ImapServer-3] [name=josh@prismon.net;mid=3;ip=67.176.47.54;] cache - Initializing folder and tag caches for mailbox 7
2007-10-16 08:30:42,516 INFO  [ImapServer-3] [name=josh@prismon.net;mid=3;ip=67.176.47.54;] imap - LIST failed: wildcards not permitted in username /home/%
2007-10-16 08:30:42,563 INFO  [ImapServer-3] [name=josh@prismon.net;mid=3;ip=67.176.47.54;] imap - LIST failed: wildcards not permitted in username /home/%/%
2007-10-16 08:30:56,078 INFO  [ImapServer-4] [] imap - [67.176.47.54] connected
2007-10-16 08:31:17,068 INFO  [ImapServer-3] [name=josh@prismon.net;mid=3;ip=67.176.47.54;] imap - [ search is: in:"INBOX" (-tag:\Deleted subject:"[orders]")
 ]
2007-10-16 08:31:39,959 INFO  [btpool0-7] [name=josh@prismon.net;mid=3;ip=168.230.130.248;ua=

Lot of parser errors occur after that.
at com.zimbra.common.service.ServiceException.PARSE_E RROR(ServiceException.java:183)
at com.zimbra.cs.mailbox.calendar.ZCalendar$ZCalendar Builder.buildMulti(ZCalendar.java:924)
at com.zimbra.cs.mailbox.calendar.ZCalendar$ZCalendar Builder.build(ZCalendar.java:884)
at com.zimbra.cs.mime.handler.TextCalendarHandler.ana lyze(TextCalendarHandler.java:63)
at com.zimbra.cs.mime.handler.TextCalendarHandler.get ICalendar(TextCalendarHandler.java:44

Then a ton of errors like this:

Code:

      at com.zimbra.common.service.ServiceException.PARSE_ERROR(ServiceException.java:183)
        at com.zimbra.cs.mailbox.calendar.ZCalendar$ZCalendarBuilder.buildMulti(ZCalendar.java:924)
        at com.zimbra.cs.mailbox.calendar.ZCalendar$ZCalendarBuilder.build(ZCalendar.java:884)
        at com.zimbra.cs.mime.handler.TextCalendarHandler.analyze(TextCalendarHandler.java:63)
        at com.zimbra.cs.mime.handler.TextCalendarHandler.getICalendar(TextCalendarHandler.java:44

and

Code:

2007-10-16 08:49:31,126 INFO  [Thread-331] [] mailbox - Re-Indexing: Mailbox 3 had error on item 3338.  Item will not be indexed.
com.zimbra.cs.mailbox.MailServiceException$NoSuchItemException: no such message: 3338
        at com.zimbra.cs.mailbox.MailServiceException.NO_SUCH_MSG(MailServiceException.java:160)
        at com.zimbra.cs.mailbox.MailItem.noSuchItem(MailItem.java:1127)
        at com.zimbra.cs.db.DbMailItem.getById(DbMailItem.java:1689)
        at com.zimbra.cs.mailbox.MailItem.getById(MailItem.java:1067)
        at com.zimbra.cs.mailbox.Mailbox.getItemById(Mailbox.java:1789)
        at com.zimbra.cs.mailbox.Mailbox.getItemById(Mailbox.java:1758)
        at com.zimbra.cs.mailbox.Mailbox.reIndex(Mailbox.java:1613)

grep -i com.zimbra.cs.mailbox.MailServiceException.NO_SUCH _MSG * |wc -l
3171

The only interesting imap specific problem I see looks like a socket close in a middle of a transaction:

Code:

2007-10-16 08:49:04,013 WARN  [Thread-331] [] ParsedMessage - Message had parse errors in 1 parts (Message-Id: 38531.370879629627_34126322693184, Subject: Starland Screening - Dark Water)
2007-10-16 08:49:07,315 INFO  [ImapServer-9] [] imap - [67.176.47.54] connected
2007-10-16 08:49:08,071 INFO  [ImapServer-5] [] ProtocolHandler - Exception occurred while handling connection
java.net.SocketException: Socket closed
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
        at com.zimbra.cs.tcpserver.TcpServerInputStream.readLine(TcpServerInputStream.java:71)
        at com.zimbra.cs.imap.TcpImapRequest.continuation(TcpImapRequest.java:73)
        at com.zimbra.cs.imap.TcpImapHandler.processCommand(TcpImapHandler.java:103)
        at com.zimbra.cs.tcpserver.ProtocolHandler.processConnection(ProtocolHandler.java:210)
        at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:177)
        at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:619)
2007-10-16 08:49:08,074 INFO  [ImapServer-5] [] ProtocolHandler - Handler exiting normally
2007-10-16 08:49:14,805 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)

jholder · #4 (**permalink**) 10-16-2007, 10:29 PM

The illegal state thing is known. It's Bug 20915 - DemoWatch: java.lang.IllegalStateException: Committed and we first saw it on the hosted demo.

That's not IMAP related.

I'm just as stumped as you are. I know it's annoying, but I'm thinking you might just have to manually remove the dupes.

At any type you feel like you have enough info, please file a bug. If it is thunderbird, file a bug in our DB anyway.

p24t · #5 (**permalink**) 10-17-2007, 06:10 AM

I tried this using 5.0 RC1 and Tbird 2.0.0.6, and got the same result. All of the messages moved from folder to folder end up identical. Also tested with Evolution 2.10.1, and got the same result.

Other than me sending myself a test message, I don't see anything interesting in mailbox.log from this time:

Code:

2007-10-17 07:59:20,766 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=0, after=2 (0ms)
2007-10-17 07:59:35,029 INFO  [ImapSSLServer-3] [name=aarmagost@zimbra2.bog3d.com;mid=3;ip=192.168.1.74;] mailbox - Added message: id=379, digest=oosjTK,O,ir7o83bTdtwJr9wAGM=, folderId=5, folderName=Sent
2007-10-17 07:59:35,065 INFO  [LmtpServer-55] [ip=192.168.1.71;] lmtp - Delivering message: sender=aarmagost@zimbra2.bog3d.com, recipient(s)={aarmagost@zimbra2.bog3d.com}, size=1455 bytes
2007-10-17 07:59:35,187 INFO  [LmtpServer-55] [name=aarmagost@zimbra2.bog3d.com;mid=3;ip=192.168.1.71;msgid=<471607A1.5080105@zimbra2.bog3d.com>;] mailbox - Added message: id=380, digest=WDx7,wK49PQQ5MQYCG+7+EnFziA=, folderId=2, folderName=Inbox
2007-10-17 07:59:35,188 INFO  [LmtpServer-55] [] ProtocolHandler - Handler exiting normally
2007-10-17 07:59:50,774 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=0, after=2 (0ms)
2007-10-17 08:00:20,782 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=0, after=2 (0ms)
2007-10-17 08:00:50,801 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=0, after=2 (0ms)
2007-10-17 08:01:20,809 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=0, after=2 (0ms)
2007-10-17 08:01:46,919 INFO  [Timer-3] [] SessionCache - Removed 1 idle sessions (SOAP). 4 active sessions remain.
2007-10-17 08:01:50,819 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=2, closed=1, after=1 (2ms)
2007-10-17 08:02:20,825 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:02:50,834 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:03:20,852 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:03:31,164 INFO  [ImapSSLServer-4] [] imap - [192.168.1.74] connected
2007-10-17 08:03:50,860 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:04:20,868 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:04:50,877 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)
2007-10-17 08:05:20,885 INFO  [IndexWritersSweeperThread] [] MailboxIndex - open index writers sweep: before=1, closed=0, after=1 (0ms)

(imap connecting from 1.74 is just me setting up evo)

ryanp · #6 (**permalink**) 10-17-2007, 07:09 AM

The "Remove Duplicate Messages" extension for Thunderbird may be useful to you.

https://addons.mozilla.org/en-US/firefox/addon/956

JoshuaPrismon · #7 (**permalink**) 10-17-2007, 07:48 AM

Quote:

Originally Posted by jholder

The illegal state thing is known. It's Bug 20915 - DemoWatch: java.lang.IllegalStateException: Committed and we first saw it on the hosted demo.

That's not IMAP related.

I'm just as stumped as you are. I know it's annoying, but I'm thinking you might just have to manually remove the dupes.

At any type you feel like you have enough info, please file a bug. If it is thunderbird, file a bug in our DB anyway.

I wasn't clear enough above. This replaced good email messages with duplicates of one. It's not just the duplicates, there is major data loss.
It overwrote 130 messages with two (50 copies of one, 79 copies of another).

p24t · #8 (**permalink**) 10-17-2007, 07:55 AM

Nor was I. I moved the messages in groups. (drag n drop) When moved individually, they are not affected.

JoshuaPrismon · #9 (**permalink**) 10-17-2007, 07:58 AM

Quote:

Originally Posted by JoshuaPrismon

I wasn't clear enough above. This replaced good email messages with duplicates of one. It's not just the duplicates, there is major data loss.
It overwrote 130 messages with two (50 copies of one, 79 copies of another).

I just duplicated this behavior using Eudora and Evolution.

Steps to reproduce: Using Zimbra RC1:

1) Log in using a IMAP client using a GUI browser - firebird or Evolution
2) Select 6 messages (multiple) and drag and drop them into a second folder
3) Go into the new folder
4) Observe that one or two messages have overwritten all of the rest.

I will file a bug ASAP, because this looks like a massive IMAP corruption bug. This wiped out almost 10 years of stored email. I have a backup, but it's at least a week out of date.

Edited: Bug 21117 has been created for this.

Zimbra

Downloads

Product Information

Toolbox

Why Join?