[SOLVED] 6.0.4 takes 21 minutes to accept on port 443

[Rich Graves]

So I upgraded a working test server from 6.0.3 to 6.0.4_GA_2038.RHEL5_64_20091214174341 NETWORK.

The installation featured the following ten-minute timeout/failure:

[] INFO: Enabling Zimlet com_zimbra_attachmail
Wed Dec 16 20:07:04 2009 done.
Wed Dec 16 20:07:04 2009 Finished updating non-standard zimlets.
Wed Dec 16 20:07:04 2009 checking isEnabled zimbra-store
Wed Dec 16 20:07:04 2009 zimbra-store is enabled
Wed Dec 16 20:07:04 2009 Returning cached global config attribute: zimbraNotebookAccount=wiki@carleton.edu
Wed Dec 16 20:07:04 2009 Upgrading Document templates...
Wed Dec 16 20:07:04 2009 *** Running as zimbra user: /opt/zimbra/bin/zmprov ut -h mail6.carleton.edu /opt/zimbra/wiki/Template
ERROR: zclient.IO_ERROR (invoke Read timed out, server: localhost) (cause: java.net.SocketTimeoutException Read timed out)
Wed Dec 16 20:17:06 2009 failed.
Wed Dec 16 20:17:06 2009 Restarting mailboxd...
Wed Dec 16 20:17:06 2009 *** Running as zimbra user: /opt/zimbra/bin/zmmailboxdctl restart
Stopping mailboxd...done.
Starting mailboxd...done.
Wed Dec 16 20:18:30 2009 done.
Wed Dec 16 20:18:30 2009 Setting up zimbra crontab...

I was later able to run "zmprov ut" manually with success.

And then mailboxd hung again upon restart. On port 443 only. IMAP-over-SSL works, but openssl s_client -connect localhost:443 hangs for 21 minutes.

I don't see any errors in mailboxd.log, but for every single account on the server I get

2009-12-16 20:56:11,074 INFO  [main] [] mbxmgr - Mailbox 4036 account 7a7e6ace-a0b6-4eac-8ef5-bed37289ca17 LOADED
2009-12-16 20:56:11,119 INFO  [main] [] index - Initialized Index for mailbox 1128 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/1128/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@1f8a6890
2009-12-16 20:56:11,119 INFO  [main] [] cache - initializing folder and tag caches for mailbox 1128

Why does it want to open every single account before accepting connections? And why does that take so long?

I have zmdiaglog. I'll open a support case if I don't find anything interesting on my own in the morning.

We have a 5.x to 6.x upgrade planned for this weekend. Interesting times.

[stiller]

This one, perhaps?

Bug 43220 – jetty https unresponsiveness

[Rich Graves]

That should have been fixed in 6.0.4. Externally visible symptoms are similar, but I don't see those log entries.

[stiller]

I know, but it does sound awfully similar. Especially considering the last minute nature of the bug + fix.

[Rich Graves]

Case number 00047310.

Yeah, there's no errors in the log.

mailboxd service was restarted at 09:08. IMAP/POP/LMTP services started at 09:10. And then, the server decides to initialize every mailbox, which takes about half a second, on average (the first per mboxgroup is slow, because mysql caches are cold, but the speed picks up).

Only after every single mailbox has been initialized do ports 80/443/7071 start working.

In previous releases of ZCS, there was index recovery, but it was asynchronous.

2009-12-17 09:10:25,540 INFO  [LmtpServer] [] TcpServer/7025 - starting accept loop
2009-12-17 09:10:25,541 INFO  [Pop3Server] [] TcpServer/110 - starting accept loop
2009-12-17 09:10:25,543 INFO  [Pop3SSLServer] [] TcpServer/995 - starting accept loop
2009-12-17 09:10:25,547 INFO  [ImapServer] [] TcpServer/143 - starting accept loop
2009-12-17 09:10:25,550 INFO  [ImapSSLServer] [] TcpServer/993 - starting accept loop
2009-12-17 09:10:26,055 INFO  [main] [] scheduler - Loaded 1993 scheduled data source tasks
2009-12-17 09:10:26,935 INFO  [main] [] index - Initialized Index for mailbox 1812 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/1812/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@117c50b9
2009-12-17 09:10:26,936 INFO  [main] [] cache - initializing folder and tag caches for mailbox 1812
2009-12-17 09:10:29,083 INFO  [main] [] sqltrace - Slow execution (2130ms): SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.volume_id, mi.blob_digest, mi.unread, mi.flags, mi.tags, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content FROM mboxgroup12.mail_item AS mi WHERE mailbox_id = 1812 AND type IN (1,2,13,3)
2009-12-17 09:10:29,240 INFO  [main] [] mbxmgr - Mailbox 1812 account 064a07d9-57a1-482b-9c16-087c6ecef75a LOADED
...
2009-12-17 09:30:24,491 INFO  [main] [] index - Initialized Index for mailbox 2519 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/2519/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@117c50b9
2009-12-17 09:30:24,491 INFO  [main] [] cache - initializing folder and tag caches for mailbox 2519
2009-12-17 09:30:25,617 INFO  [main] [] mbxmgr - Mailbox 2519 account 8944da2d-1035-478c-a3d8-1dd17a7bd8a9 LOADED
2009-12-17 09:30:25,662 INFO  [main] [] index - Initialized Index for mailbox 2200 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/2200/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@117c50b9
2009-12-17 09:30:25,662 INFO  [main] [] cache - initializing folder and tag caches for mailbox 2200
2009-12-17 09:30:25,715 INFO  [main] [] mbxmgr - Mailbox 2200 account 698a2bb2-198f-4816-bd20-6b4ad9d23eee LOADED
2009-12-17 09:30:25,760 INFO  [main] [] index - Initialized Index for mailbox 2201 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/2201/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@117c50b9
2009-12-17 09:30:25,760 INFO  [main] [] cache - initializing folder and tag caches for mailbox 2201
2009-12-17 09:30:26,170 INFO  [main] [] mbxmgr - Mailbox 2201 account 6e2967b1-1e17-4183-9098-880515a665c7 LOADED

[mmorse]

I've seen that above happen once on the hosted demo so I kind of smell a bug, between the 'Initilizing folder, tag, index' lines there was a bit on updating a particular rss datasource folder for each so I assumed it was some type of redolog replay on startup that didn't commit properly before - causing several thousand accounts to be loaded into memory since they're identical - mailboxd reported itself as up, but essentially useless until it finished (had no problem running ldap commands while I waited). Your log seems slightly different but there is a "scheduler - Loaded 1993 scheduled data source tasks" at the top.

[Rich Graves]

You might see RSS update for every account if every single account on the hosted demo has an RSS feed.

For the small number of my accounts with external POP data sources, I get polling during the "Initializing..." steps, but that's not the trigger. *Every* account gets touched, not just those with external data sources.

AdminServlet/UserServlet/SslSelectChannelConnector need to start up earlier.

Edit: About 2000 of my 3000 users do have a remote iCal feeds. But only about 12 polled the iCal server during the mailboxd outage.

[mmorse]

That servlet thing sounds about right - so the imap/pop/lmtp/socket acceptor/even mailbox purge threads are runnable with btpool sitting around waiting, but main hasn't finished yet (if you look at the thread dump below those servlets are part of the main thread even though their java:# is lower).

Except for the fact that you reported loading of even those without datasources/still possible something else is triggering, the thought was Bug 35688 - Scheduled task initialization blocks server startup (maybe put in franklin and not gnr).

5.0.16_GA_2903.RHEL4_64_20090421031503

1. provision account A.
2. set up an datasource sync for account A.
3. stop zcs.
4. restart zcs.

Before fix:
whenever we start the zcs server, A will be loaded.

After fix:
whenever we restart the zcs server, A will be loaded if we set the Sync interval to non-zero value. mailbox will be initialized but it's done by thread such as "ScheduledTask-X". The "main" thread is up right away without being blocked.

And your init does happen on main:

2009-12-17 09:10:26,055 INFO [main] [] scheduler - Loaded 1993 scheduled data source tasks
2009-12-17 09:10:26,935 INFO [main] [] index - Initialized Index for mailbox 1812 directory: LuceneIndex at com.zimbra.cs.index.Z23FSDirectory@/opt/zimbra/index/0/1812/index/0 Analyzer=com.zimbra.cs.index.ZimbraAnalyzer@117c50 b9
2009-12-17 09:10:26,936 INFO [main] [] cache - initializing folder and tag caches for mailbox 1812
[...]
2009-12-17 09:33:47,789 INFO [main] [] cache - initializing folder and tag caches for mailbox 1128
2009-12-17 09:33:48,004 INFO [main] [] mbxmgr - Mailbox 1128 account eb69e226-db37-4bf3-bc03-3a2a25e2841a LOADED
2009-12-17 09:33:48,005 INFO [main] [] purge - Starting purge thread with sleep interval 1m.
2009-12-17 09:33:48,007 INFO [MailboxPurge] [] purge - Purge thread sleeping for 1800000ms before doing work.
2009-12-17 09:33:48,044 INFO [main] [] extensions - Post-Initializing extensions
2009-12-17 09:33:48,203 INFO [main] [] soap - Servlet AdminServlet starting up
2009-12-17 09:33:48,287 INFO [main] [] ContentServlet - Servlet ContentServlet starting up
2009-12-17 09:33:48,288 INFO [main] [] account - Servlet PreAuthServlet starting up
2009-12-17 09:33:48,288 INFO [main] [] PublicICalServlet - Servlet PublicICalServlet starting up
2009-12-17 09:33:48,310 INFO [main] [] mailbox - Servlet UserServlet starting up
2009-12-17 09:33:48,314 INFO [main] [] FileUploadServlet - Servlet FileUploadServlet starting up
2009-12-17 09:33:48,315 INFO [main] [] StatsImageServlet - Servlet StatsImageServlet starting up
2009-12-17 09:33:48,712 INFO [main] [] log - Started SslSelectChannelConnector@0.0.0.0:443
2009-12-17 09:33:48,713 INFO [main] [] log - Started SslSelectChannelConnector@0.0.0.0:7071

"main" prio=10 tid=0x0000000043939800 nid=0x3f22 runnable [0x00000000409e0000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream. java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(Read AheadInputStream.java:113)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromU nderlyingStreamIfNecessary(ReadAheadInputStream.ja va:160)
at com.mysql.jdbc.util.ReadAheadInputStream.read(Read AheadInputStream.java:188)
- locked <0x00002aaad41af200> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994 )
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO. java:2411)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.ja va:2916)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:16 31)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java :1723)
at com.mysql.jdbc.Connection.execSQL(Connection.java: 3283)
- locked <0x00002aaad411b7e8> (a java.lang.Object)
at com.mysql.jdbc.PreparedStatement.executeInternal(P reparedStatement.java:1332)
at com.mysql.jdbc.PreparedStatement.executeQuery(Prep aredStatement.java:1467)
- locked <0x00002aaad411b7e8> (a java.lang.Object)
at com.zimbra.cs.db.DebugPreparedStatement.executeQue ry(DebugPreparedStatement.java:160)
at org.apache.commons.dbcp.DelegatingPreparedStatemen t.executeQuery(DelegatingPreparedStatement.java:93 )
at com.zimbra.cs.db.DbMailItem.getFoldersAndTags(DbMa ilItem.java:1728)
at com.zimbra.cs.mailbox.Mailbox.loadFoldersAndTags(M ailbox.java:1492)
at com.zimbra.cs.mailbox.Mailbox.beginTransaction(Mai lbox.java:1196)
at com.zimbra.cs.mailbox.Mailbox.beginTransaction(Mai lbox.java:1147)
at com.zimbra.cs.mailbox.Mailbox.getConfig(Mailbox.ja va:1220) - locked <0x00002aaab16c0ce0> (a com.zimbra.cs.mailbox.Mailbox)
at com.zimbra.cs.mailbox.Mailbox.finishInitialization (Mailbox.java:440)
- locked <0x00002aaab16c0ce0> (a com.zimbra.cs.mailbox.Mailbox)
at com.zimbra.cs.mailbox.MailboxManager.getMailboxByI d(MailboxManager.java:483)
at com.zimbra.cs.mailbox.MailboxManager.getMailboxByI d(MailboxManager.java:380)
at com.zimbra.cs.mailbox.ScheduledTaskManager.startup (ScheduledTaskManager.java:59)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:251)
- locked <0x00002aab456b0268> (a java.lang.Class for com.zimbra.cs.util.Zimbra)
at com.zimbra.cs.util.Zimbra.startup(Zimbra.java:122)
at com.zimbra.soap.SoapServlet.init(SoapServlet.java: 125)
at javax.servlet.GenericServlet.init(GenericServlet.j ava:241)
at org.mortbay.jetty.servlet.ServletHolder.initServle t(ServletHolder.java:440)
at org.mortbay.jetty.servlet.ServletHolder.doStart(Se rvletHolder.java:263)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad3fbaa90> (a java.lang.Object)
at org.mortbay.jetty.servlet.ServletHandler.initializ e(ServletHandler.java:685)
at org.mortbay.jetty.servlet.Context.startContext(Con text.java:140)
at org.mortbay.jetty.webapp.WebAppContext.startContex t(WebAppContext.java:1250)
at org.mortbay.jetty.handler.ContextHandler.doStart(C ontextHandler.java:517)
at org.mortbay.jetty.webapp.WebAppContext.doStart(Web AppContext.java:467)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad3e16010> (a java.lang.Object)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.jetty.handler.ContextHandlerCollection .doStart(ContextHandlerCollection.java:156)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad40c0188> (a java.lang.Object)
at org.mortbay.jetty.handler.HandlerCollection.doStar t(HandlerCollection.java:152)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad411cc20> (a java.lang.Object)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad411cb48> (a java.lang.Object)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.handler.DebugHandler.doStart(Deb ugHandler.java:127)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad411cb18> (a java.lang.Object)
at org.mortbay.jetty.handler.HandlerWrapper.doStart(H andlerWrapper.java:130)
at org.mortbay.jetty.Server.doStart(Server.java:224)
at org.mortbay.setuid.SetUIDServer.doStart(SetUIDServ er.java:158)
at org.mortbay.component.AbstractLifeCycle.start(Abst ractLifeCycle.java:50)
- locked <0x00002aaad40c00f8> (a java.lang.Object)
at org.mortbay.xml.XmlConfiguration.main(XmlConfigura tion.java:985)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Nativ e Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Native MethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(De legatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.mortbay.start.Main.invokeMain(Main.java:194)
at org.mortbay.start.Main.start(Main.java:534)
at org.mortbay.start.Main.start(Main.java:441)
at org.mortbay.start.Main.main(Main.java:119)

[Rich Graves]

Forked off a third test upgrade...

Confirmed, the problem is bugzilla 35688 (fixed in 5.0 but not 6.0), combined with bugzilla 6491 (automatic reloading of feeds is new in 6.0).

Upon a fresh upgrade from 5.0.19, I only have 7 accounts loading at startup. What those 7 accounts have in common is that they had working POP data sources. Apparently, I have more bogus POP data sources than good ones. One user has the POP server set to gmail.com port 110, for example.

Then, I ran zmmailbox syncFolder /Moodle for a random selection of accounts (all students and faculty here have a personal remote iCal feed with their course schedule -- Auto-provisioning calendar data/shared calendars).

Now, each of the accounts that I reloaded manually, gets opened at startup. This happens even if zimbraDataSourceCalendarPollingInterval (default 12h) has not elapsed. And port 443 is not available until every one of those feeds has loaded.

Question: Why didn't this happen on exactly the same server and accounts under 6.0.2 or 6.0.3?

Answer: I didn't get around to verifying our nightly syncFolder job until a couple days before I upgraded to 6.0.4. It's quite likely that the problem would have been triggered under 6.0.0-6.0.3 as well.

So should I file a new bug, or get 35688 reopened?

I think my planned upgrade is still on. I shouldn't start seeing the 20-minute startup delay until after I have both upgraded to 6.0 and reloaded everybody's calendar.

[Rich Graves]

Bug 35688 - Scheduled task initialization blocks server startup has been reopened. Since it was already fixed in 5.0.16, hopefully it shouldn't take too long.

Short-term workaround is to avoid syncFolder operations on the mass iCal feeds, accepting that they will be out of date for a while. The problem only seems to be triggered after a feed is reloaded for the first time under 6.0 by user action or zmmailbox script.

Calling this solved.