Upgrade 4.0.3 to 5.0.2 fails in migrate-MailboxGroup.sql

pacsteel · Postby **pacsteel** » Wed Feb 20, 2008 12:41 am

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 [url=tachijuan [/url]

got when upgrading [url=4.0.2GA to 4.5.4GA[/url]. 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?

502installfail.txt

Postby **jholder** » Wed Feb 20, 2008 1:00 pm

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

pacsteel · Postby **pacsteel** » Wed Feb 20, 2008 6:41 pm

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 '
'

  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 · Postby **pacsteel** » Wed Feb 20, 2008 7:07 pm

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 · Postby **pacsteel** » Thu Feb 21, 2008 3:48 pm

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">HttpServlet.service(HttpServlet.java:709)

	at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:173)

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802">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">HttpServlet.service(HttpServlet.java:709)

	at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:173)

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802">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 · Postby **mmorse** » Thu Feb 21, 2008 4:22 pm

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 · Postby **pacsteel** » Thu Feb 21, 2008 5:12 pm

[QUOTE]I would advise stepping through 4.5.x [/QUOTE]

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.
[QUOTE]do you hit this even on a tiny jump to 4.0.5_GA_518.UBUNTU6 etc?[/QUOTE]

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 · Postby **pacsteel** » Wed Feb 27, 2008 6:17 pm

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 '
'

  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.
?

502installfail3.txt

Who is online