Upgrade 4.0.3 to 5.0.2 fails in migrate-MailboxGroup.sql

[pacsteel]

A year or so ago, I posted how I got Zimbra 4.0.3 mostly stable on Ubuntu 6.06.1 LTS and haven't had anything but minor problems with it since. Lately the spam filter has been showing it's age, so I decided it was time to upgrade.

Everything seemed to be going pretty well, until the database schema upgrade, where it did this:

Executing SQL statements in /tmp/migrate-MailboxGroup.sql
mysql invocation failed, exit code = 256:  at /opt/zimbra/libexec/scripts/migrate20060911-MailboxGroup.pl line 76, 
 line 258.
Script failed with code 256:  - exiting
UPGRADE FAILED - exiting

which is the same error tachijuan
got when upgrading 4.0.2GA to 4.5.4GA. I never saw a post on solving that issue.

Reading back through my install log (the entirety of which I've attached as a txt file), I see an interesting spot that I didn't notice during the install :

Verifying integrity of message store databases.  This may take a while.
mysqld is alive
/opt/zimbra/mysql/bin/mysqlcheck: Got error: 2013: Lost connection to MySQL server during query when executing 'CHECK TABLE ...  CHANGED'
Generating report
No errors found
command failed

At a guess, I'd say the check table timed out or something, and the Zimbra install didn't see any of the errors it was looking for (maybe "Got error: 2013" didn't fit the case statement? ), and went on it's way.

Is this something anyone else has seen?
Any idea where the "Generating report" line might have stashed such a report?

[jholder]

What's in your /opt/zimbra/db/data/(hostname).err?

[pacsteel]

Sorry for the delay in my answer, I saved a copy of the partition before I restored from backup, but it took me a while to cobble a machine together to access it on.

/opt/zimbra/db/data/mail.err

080219 22:08:00  mysqld started
080219 22:08:00 [Warning] Changed limits: max_open_files: 1024  max_connections: 16  table_cache: 499
080219 22:08:01  InnoDB: Started; log sequence number 1 3397511598
080219 22:08:01 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.45-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
InnoDB: Error: the size of single-table tablespace file ./mailbox192/tombstone.ibd
InnoDB: is only 0 4096, should be at least 65536!
080219 22:13:24InnoDB: Assertion failure in thread 2489510832 in file fil0fil.c line 564
InnoDB: Failing assertion: 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
080219 22:13:24 - mysqld got signal 11;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388600
read_buffer_size=1044480
max_used_connections=1
max_connections=16
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 40895 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x93d1ac0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Cannot determine thread, fp=0x9462abe8, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x8176361
0x836e9c4
0x836f081
0x8379c26
0x8350dc9
0x8345f86
0x8303e47
0x830434a
0x82bcf07
0x82c3242
0x824f1c0
0x8241139
0x81c8672
0x81bd83d
0x81c1138
0x81c1b12
0x81c1e4f
0x818ce8d
0x8196567
0x8196bab
0x81981ed
0x8198cea
0xb7f31341
0xb7e614ee
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x93e7980 = SELECT 192, sequence, date, ids
  INTO OUTFILE '/tmp/migrate20060911-17014-mbox192-tombstone.dat'
  FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' LINES TERMINATED BY '\n'
  FROM mailbox192.tombstone
thd->thread_id=10
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
080219 22:13:24  mysqld restarted
080219 22:13:24 [Warning] Changed limits: max_open_files: 1024  max_connections: 16  table_cache: 499
080219 22:13:24  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
080219 22:13:26  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 1 3496228619.
InnoDB: Doing recovery: scanned up to log sequence number 1 3501471232
InnoDB: Doing recovery: scanned up to log sequence number 1 3506714112
InnoDB: Doing recovery: scanned up to log sequence number 1 3511956992
InnoDB: Doing recovery: scanned up to log sequence number 1 3517199872
InnoDB: Doing recovery: scanned up to log sequence number 1 3522442752
InnoDB: Doing recovery: scanned up to log sequence number 1 3527685632
InnoDB: Doing recovery: scanned up to log sequence number 1 3532928512
InnoDB: Doing recovery: scanned up to log sequence number 1 3538171392
InnoDB: Doing recovery: scanned up to log sequence number 1 3543414272
InnoDB: Doing recovery: scanned up to log sequence number 1 3548657152
InnoDB: Doing recovery: scanned up to log sequence number 1 3553900032
InnoDB: Doing recovery: scanned up to log sequence number 1 3559142912
InnoDB: Doing recovery: scanned up to log sequence number 1 3564385792
InnoDB: Doing recovery: scanned up to log sequence number 1 3569628672
InnoDB: Doing recovery: scanned up to log sequence number 1 3574871552
InnoDB: Doing recovery: scanned up to log sequence number 1 3580114432
InnoDB: Doing recovery: scanned up to log sequence number 1 3585357312
InnoDB: Doing recovery: scanned up to log sequence number 1 3590600192
InnoDB: Doing recovery: scanned up to log sequence number 1 3595843072
InnoDB: Doing recovery: scanned up to log sequence number 1 3601085952
InnoDB: Doing recovery: scanned up to log sequence number 1 3606328832
InnoDB: Doing recovery: scanned up to log sequence number 1 3611571712
InnoDB: Doing recovery: scanned up to log sequence number 1 3616814592
InnoDB: Doing recovery: scanned up to log sequence number 1 3622057472
InnoDB: Doing recovery: scanned up to log sequence number 1 3627300352
InnoDB: Doing recovery: scanned up to log sequence number 1 3632543232
InnoDB: Doing recovery: scanned up to log sequence number 1 3637786112
InnoDB: Doing recovery: scanned up to log sequence number 1 3643028992
InnoDB: Doing recovery: scanned up to log sequence number 1 3648271872
InnoDB: Doing recovery: scanned up to log sequence number 1 3653480327
080219 22:13:52  InnoDB: Error: table 'mailbox192/tombstone'
InnoDB: in InnoDB data dictionary has tablespace id 775,
InnoDB: but tablespace with that id or name does not exist. Have
InnoDB: you deleted or moved .ibd files?
InnoDB: This may also be a table created with CREATE TEMPORARY TABLE
InnoDB: whose .ibd and .frm files MySQL automatically removed, but the
InnoDB: table still exists in the InnoDB internal data dictionary.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/innodb-troubleshooting.html
InnoDB: for how to resolve the issue.
080219 22:13:52  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
080219 22:14:37  InnoDB: Started; log sequence number 1 3653480327
080219 22:14:37 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.45-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
080219 23:49:51 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

080219 23:49:51  InnoDB: Starting shutdown...
080219 23:49:52  InnoDB: Shutdown completed; log sequence number 1 3653549307
080219 23:49:52 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete

080219 23:49:52  mysqld ended

080220 00:29:59  mysqld started
080220  0:30:00 [Warning] Changed limits: max_open_files: 1024  max_connections: 16  table_cache: 499
080220  0:30:04  InnoDB: Started; log sequence number 1 3653549307
080220  0:30:05 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.45-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
080220  0:30:11 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

080220  0:30:11  InnoDB: Starting shutdown...

[pacsteel]

Interestingly enough, the listing of that directory shows that tombstone.ibd thinks it's a directory.

drwx------   3 zimbra zimbra   4096 Dec  6  2006 .
drwxr-xr-x 262 zimbra zimbra   8192 Feb 20 15:42 ..
-rw-rw----   1 zimbra zimbra   8674 Dec  6  2006 appointment.frm
-rw-rw----   1 zimbra zimbra 114688 Dec  6  2006 appointment.ibd
-rw-rw----   1 zimbra zimbra     61 Dec  6  2006 db.opt
-rw-rw----   1 zimbra zimbra   9222 Dec  6  2006 mail_item.frm
-rw-rw----   1 zimbra zimbra 344064 Feb 20 17:45 mail_item.ibd
-rw-rw----   1 zimbra zimbra   8596 Dec  6  2006 open_conversation.frm
-rw-rw----   1 zimbra zimbra 114688 Feb 20 16:41 open_conversation.ibd
-rw-rw----   1 zimbra zimbra   8626 Dec  6  2006 tombstone.frm
drwx-w--wT   2 zimbra zimbra   4096 Dec  6  2006 tombstone.ibd

A couple of months ago the server had an operator-induced power outage. (The operator decided the server was hung because the screen was black and wiggling the mouse didn't change it. Of course since it is running Ubuntu server version, there is no GUI and the mouse doesn't do anything. Hitting a key on the keyboard would have worked, but he "forgot" to do that. Since it was 'Hung" he unplugged it . I thought I had it all cleaned up, but I guess not. Looking back through the FSCK log, I found the following, which explains this situation:

Entry 'tombstone.ibd' in /opt/zimbra/db/data/mailbox192 (3555434) has an incorrect filetype (was 1, should be 2).

Do you suppose deleting that user's account and re-creating it would clean this up?

[pacsteel]

To try to answer my own question: Maybe.

Using the Zimbra control panel to delete the user gives a system failure message box (the full error is below)

It did, however, make the user's account disappear from Zimbra, and deleted most of the files in the directory. I manually deleted the bad file-thinking-it-is-a-directory, and then deleted the /opt/zimbra/db/data/mailbox192 directory


Full Error for system failure dialog:

Message:  system failure: dropMailboxDatabase(192)
com.zimbra.cs.service.ServiceException: system failure: dropMailboxDatabase(192)
	at com.zimbra.cs.service.ServiceException.FAILURE(ServiceException.java:174)
	at com.zimbra.cs.db.DbMailbox.dropMailboxDatabase(DbMailbox.java:179)
	at com.zimbra.cs.mailbox.Mailbox.deleteMailbox(Mailbox.java:1518)
	at com.zimbra.cs.mailbox.Mailbox.deleteMailbox(Mailbox.java:1490)
	at com.zimbra.cs.service.admin.DeleteAccount.handle(DeleteAccount.java:79)
	at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:261)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:162)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:84)
	at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:223)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
	at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:173)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
	at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:667)
	at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
	at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
	at java.lang.Thread.run(Thread.java:595)
Caused by: java.sql.SQLException: Communications link failure due to underlying exception: 

** BEGIN NESTED EXCEPTION ** 

java.io.EOFException

STACKTRACE:

java.io.EOFException
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1905)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2351)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2862)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1571)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1666)
	at com.mysql.jdbc.Connection.execSQL(Connection.java:2994)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:936)
	at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:773)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:256)
	at com.zimbra.cs.db.DbMailbox.dropMailboxDatabase(DbMailbox.java:174)
	at com.zimbra.cs.mailbox.Mailbox.deleteMailbox(Mailbox.java:1518)
	at com.zimbra.cs.mailbox.Mailbox.deleteMailbox(Mailbox.java:1490)
	at com.zimbra.cs.service.admin.DeleteAccount.handle(DeleteAccount.java:79)
	at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:261)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:162)
	at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:84)
	at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:223)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
	at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:173)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
	at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:667)
	at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
	at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
	at java.lang.Thread.run(Thread.java:595)


** END NESTED EXCEPTION **



Last packet sent to the server was 2361 ms ago.

Query being executed when exception was thrown:

DROP DATABASE IF EXISTS mailbox192
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2563)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2862)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1571)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1666)
	at com.mysql.jdbc.Connection.execSQL(Connection.java:2994)
	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:936)
	at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:773)
	at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:256)
	at com.zimbra.cs.db.DbMailbox.dropMailboxDatabase(DbMailbox.java:174)
	... 25 more

Error code:  service.FAILURE
Method:  ZmCsfeCommand.prototype.invoke
Details:soap:Receiver

[mmorse]

Your install log tells me you tried to go from 4.0.3_GA_407.UBUNTU6 > 5.0.2_GA_1975.UBUNTU6 I would advise stepping through 4.5.x first.
I know your citing the other 4.0.2 to 4.5.4 case getting the same error, but have you tried anything in that series yet?
That really is a pretty big jump you're making...do you hit this even on a tiny jump to 4.0.5_GA_518.UBUNTU6 etc?

[pacsteel]

I would advise stepping through 4.5.x

Why?

I"m not saying I won't do it (although I'd rather not), I'm just wondering if there is something in the upgrade process that I've missed. All the reading I've done in the upgrade documentation indicates that it should be OK to go from 4.0.3 to 5.0.2 in one fell swoop.

do you hit this even on a tiny jump to 4.0.5_GA_518.UBUNTU6 etc?

I probably would have hit the same error, since it was caused by the file system corruption, and fsck incorrectly deciding that a file should really be a directory.

[pacsteel]

I cleaned up the database errors by using mysql creating the mailbox192 database and the tombstone table and then dropping them. Once the InnoDB data dictionary agreed with Zimbra that the user in question was gone, no more errors were displayed at mysql startup.

This time, the upgrade process ran very smoothly (install log attached), with no errors right up to the point it fails with the message:

Tue Feb 26 20:07:52 2008: Verified schema version 27.
Executing SQL statements in /tmp/migrate-MailboxGroup.sql
mysql invocation failed, exit code = 256: at /opt/zimbra/libexec/scripts/migrate20060911-MailboxGroup.pl line 76,

line 260.
Script failed with code 256: - exiting
UPGRADE FAILED - exiting

There are no longer any errors in /opt/zimbra/db/data/(hostname).err

cat  /opt/zimbra/db/data/mail.err
080226 20:07:26  mysqld started
080226 20:07:26 [Warning] Changed limits: max_open_files: 1024  max_connections: 16  table_cache: 499
080226 20:07:26  InnoDB: Started; log sequence number 1 3509669002
080226 20:07:26 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.45-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
root@mail:/tmp/zcs-5.0.2_GA_1975.UBUNTU6.20080130235804#

Looking at migrate20060911.out.16161, the last command is

SELECT
    192, id, type, parent_id, folder_id, index_id, imap_id,
    date, size, volume_id, blob_digest, unread, flags, tags, sender,
    subject, metadata, mod_metadata, change_date, mod_content
  INTO OUTFILE '/tmp/migrate20060911-16161-mbox192-mail_item.dat'
  FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' LINES TERMINATED BY '\n'
  FROM mailbox192.mail_item

Where is it getting that? The mailbox192 database doesn't exist, mysql doesn't think it exists, Zimbra thinks the associated user's account was deleted. Why is it trying to migrate a mailbox that doesn't exist?

This is starting to get...interesting. In the Chinese curse sense of the word.

?