Page 1 of 2 12 LastLast
Results 1 to 10 of 11

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

  1. #1
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

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

    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:

    Code:
    [] 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

    Code:
    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.

  2. #2
    Join Date
    May 2008
    Posts
    92
    Rep Power
    7

    Default

    Snelbij | Uw informatie ter beschikking.
    https://www.snelbij.nl

  3. #3
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

    Default

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

  4. #4
    Join Date
    May 2008
    Posts
    92
    Rep Power
    7

    Default

    I know, but it does sound awfully similar. Especially considering the last minute nature of the bug + fix.
    Snelbij | Uw informatie ter beschikking.
    https://www.snelbij.nl

  5. #5
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

    Default

    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.

    Code:
    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

  6. #6
    Join Date
    May 2006
    Location
    USA
    Posts
    6,242
    Rep Power
    21

    Default

    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.

  7. #7
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

    Default

    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.

  8. #8
    Join Date
    May 2006
    Location
    USA
    Posts
    6,242
    Rep Power
    21

    Default

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

    Quote Originally Posted by bug 35688
    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:
    Quote Originally Posted by carleton mailbox.log
    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
    Quote Originally Posted by carleton threaddump
    "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)

  9. #9
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

    Default

    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 -- http://www.zimbra.com/forums/adminis...calendars.html).

    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.

  10. #10
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    719
    Rep Power
    9

    Default

    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.

Similar Threads

  1. Can't Connect to Port 443 - SSL Not Working
    By ewebzone in forum Administrators
    Replies: 1
    Last Post: 01-27-2009, 11:34 PM
  2. Problem with Mail Server - Need help!
    By joeleo in forum Installation
    Replies: 2
    Last Post: 03-04-2008, 11:03 AM
  3. Access Zimbra on port 443 via apache
    By CatiaL in forum Administrators
    Replies: 1
    Last Post: 06-15-2007, 02:11 AM
  4. Replies: 20
    Last Post: 05-07-2006, 11:34 PM
  5. Change port 443 to other
    By cgarciauy in forum Administrators
    Replies: 1
    Last Post: 04-10-2006, 04:01 PM

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •