[SOLVED] Upgrade 5.0.19 > 6.0.6 hangs on "starting mysql..."

[Jay2k1]

Hello.

So I started the upgrade grom 5.0.19 to 6.0.6 Network Edition on CentOS 5 x64. Everything ran smoothly so far, but now it hangs at "starting mysql...".

I had a look into /opt/zimbra/log/mysql-error.log:

100424 16:57:48 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

100424 16:57:49  InnoDB: Starting shutdown...
100424 16:57:55  InnoDB: Shutdown completed; log sequence number 4 1415862554
100424 16:57:55 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete

100424 16:57:55  mysqld ended

100424 17:20:46  mysqld started
100424 17:20:51  InnoDB: Started; log sequence number 4 1415862554
100424 17:20:51 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.0.51a-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
100424 17:44:40 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

100424 17:44:40  InnoDB: Starting shutdown...
100424 17:44:42  InnoDB: Shutdown completed; log sequence number 4 1416207138
100424 17:44:42 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete

100424 17:44:42  mysqld ended

100424 17:46:46  mysqld started
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
100424 17:46:46  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
100424 17:46:46  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 100 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
100424 17:46:49  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 100 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
100424 17:46:52  InnoDB: Started; log sequence number 0 0
100424 17:46:52 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.host' doesn't exist
100424 17:46:52  mysqld ended

100424 17:46:56  mysqld started
InnoDB: Log scan progressed past the checkpoint lsn 0 36808
100424 17:46:57  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...
InnoDB: Doing recovery: scanned up to log sequence number 0 43655
100424 17:46:57  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
100424 17:46:58  InnoDB: Started; log sequence number 0 43655
100424 17:46:58 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.host' doesn't exist
100424 17:46:58  mysqld ended

100424 17:47:07  mysqld started
InnoDB: Log scan progressed past the checkpoint lsn 0 36808
100424 17:47:12  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...
InnoDB: Doing recovery: scanned up to log sequence number 0 43655
100424 17:47:14  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
100424 17:47:14  InnoDB: Started; log sequence number 0 43655
100424 17:47:14 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.host' doesn't exist
100424 17:47:14  mysqld ended

100424 17:47:18  mysqld started
InnoDB: Log scan progressed past the checkpoint lsn 0 36808
100424 17:47:18  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...
InnoDB: Doing recovery: scanned up to log sequence number 0 43655
100424 17:47:18  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
100424 17:47:19  InnoDB: Started; log sequence number 0 43655
100424 17:47:19 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.host' doesn't exist
100424 17:47:19  mysqld ended

Here I cut it because the last parts keep repeating.

This makes me kind of nervous... any suggestions?

Edit: Now the install script added a "done" after "starting mysql" and then said "UPGRADE FAILED - exiting". :S

[Jay2k1]

So it turns out this problem is bigger than I thought. I opened a support ticket and was helped only a few minutes after.

Thanks Rick from Zimbra Support for your great help!

[phoenix]

Originally Posted by Jay2k1

So it turns out this problem is bigger than I thought. I opened a support ticket and was helped only a few minutes after

How about posting the solution for other members to see?

[Jay2k1]

I don't really know what was wrong. He said somehow there was no LDAP data, and that he imported it manually, re-running the install.sh afterwards. But I have absolutely no clue what he did in detail.

[StefanFN]

Hi,

having the solution or at least a hint in this thread, would have been great as I just ran into the very same issue with our FOSS on Ubuntu 8.04.
We are basically suffering a Production Down and I'm trying to resolve it now. I figured out that there's something not quite right with LDAP, since nothing authenticates as the ldap_root_password is not accepted anymore ..even for a simple ldapsearch -x -h ldapi:/// .

/Stefan

[Jay2k1]

Sorry for the late reply, it was 3:39 am here, I was asleep.

Thing is, I don't really have a clue about LDAP. We're just using Zimbra for mail and for the ability to have calendar and contacts in sync. Also, I didn't get a detailed report or log about what the support guy did (he ssh'ed into the server). All I can do is quote his mail:

The first thing I noticed was that ldap had NO data in it. I managed to import ldap data, and copied the mysql data direct from the /zimbra directory; probably a good thing you copied that data. After the data was copied, I reran the installer.

It took him two and a half hours from logging in the first time until he fixed it. After telling me that he's done and that I should try if things work, I asked him for what was wrong, and he replied with the quoted text above.

I'm afraid this is all I can do to help here

Hope this helps,

Jay

[StefanFN]

Hi Jay2k1,

well, now that I managed to get our services back up and running, I'd like to bring up the solution here:
We have /opt/zimbra/db and /opt/zimbra/data symlinked to a faster drive (RAID10).
The update process apparently exports /opt/zimbra/data (or parts of it) and then deletes it (don't know why, but it's the case). I guess this happens because it is symlinked.

I figured that out after running the installer a second time.

Somewhere in the script it then recreates the directory with a new/or empty ldap database. Now of couse none of the services can retrieve their settings from LDAP and therefore fail to start.

Solution in my case was to

root@host#mount --bind /path/to/zimbra/data /opt/zimbra/data

which leads in /etc/fstab to

/path/to/zimbra/data    /opt/zimbra/data    none    rw,bind    0    0

I did the same for the symlinked /opt/zimbra/db directory.

Now our store has all its data in it and the mailboxes are current.

The time consuming thing was learning why it failed and not the solution itself.
Afterall it's been quite frustrating but I'm glad we didn't lose any data.

/Stefan