Results 1 to 6 of 6

Thread: MTA service stopping and 1m later starting again?

  1. #1
    ArcaneMagus's Avatar
    ArcaneMagus is offline Moderator
    Join Date
    Feb 2007
    Location
    Portland, OR
    Posts
    1,147
    Rep Power
    10

    Default MTA service stopping and 1m later starting again?

    This morning I got 2 messages in the admin mailbox telling me that the MTA service had stopped and then a minute later started back up again.

    This has so far happened 4 times since the server was installed almost 5 months ago. Every time it has been around xx:45:00. It doesn't appear to be causing any issues but I was wondering if anybody has seen anything similar on their servers and knows why it is doing this?

    Log entries that look interesting or might be related:
    /var/log/zimbra.log (and similar entries in /var/log/messages) this one is interesting as it is sending the status messages to the admin account after the mta is supposedly down...
    Code:
    Nov  6 23:46:41 email zmmailboxdmgr[14858]: status requested
    Nov  6 23:46:41 email zmmailboxdmgr[14858]: status OK
    Nov  6 23:46:41 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from running to stopped
    Nov  6 23:46:41 email zmmailboxdmgr[14920]: status requested
    Nov  6 23:46:41 email zmmailboxdmgr[14920]: status OK
    Nov  6 23:46:42 email postfix/pickup[10381]: 4B6CF904001: uid=1001 from=<zimbra>
    Nov  6 23:46:42 email postfix/cleanup[14519]: 4B6CF904001: message-id=<20081107074642.4B6CF904001@email.companyname.com>
    Nov  6 23:46:42 email postfix/qmgr[24061]: 4B6CF904001: from=<zimbra@email.companyname.com>, size=456, nrcpt=1 (queue active)
    Nov  6 23:46:42 email amavis[15022]: (15022-14) ESMTP::10024 /opt/zimbra/data/amavisd/tmp/amavis-20081106T055744-15022: <zimbra@email.companyname.com> -> <admin@companyname.com> SIZE=456 Received: from email.companyname.com ([127.0.0.1]) by localhost (email.companyname.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <admin@companyname.com>; Thu,  6 Nov 2008 23:46:42 -0800 (PST)
    Nov  6 23:46:42 email amavis[15022]: (15022-14) Checking: EgWpViM0arHV <zimbra@email.companyname.com> -> <admin@companyname.com>
    Nov  6 23:46:42 email postfix/smtpd[14523]: connect from localhost.localdomain[127.0.0.1]
    Nov  6 23:46:42 email postfix/smtpd[14523]: B152A904002: client=localhost.localdomain[127.0.0.1]
    Nov  6 23:46:42 email postfix/cleanup[14519]: B152A904002: message-id=<20081107074642.4B6CF904001@email.companyname.com>
    Nov  6 23:46:42 email postfix/qmgr[24061]: B152A904002: from=<zimbra@email.companyname.com>, size=1068, nrcpt=1 (queue active)
    Nov  6 23:46:42 email postfix/smtpd[14523]: disconnect from localhost.localdomain[127.0.0.1]
    Nov  6 23:46:42 email amavis[15022]: (15022-14) FWD via SMTP: <zimbra@email.companyname.com> -> <admin@companyname.com>,BODY=7BIT 250 2.6.0 Ok, id=15022-14, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as B152A904002
    Nov  6 23:46:42 email amavis[15022]: (15022-14) Passed CLEAN, <zimbra@email.companyname.com> -> <admin@companyname.com>, Message-ID: <20081107074642.4B6CF904001@email.companyname.com>, mail_id: EgWpViM0arHV, Hits: -3.35, size: 456, queued_as: B152A904002, 403 ms
    Nov  6 23:46:42 email postfix/smtp[14520]: 4B6CF904001: to=<admin@companyname.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.44, delays=0.04/0/0/0.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as B152A904002)
    Nov  6 23:46:42 email postfix/qmgr[24061]: 4B6CF904001: removed
    Nov  6 23:46:42 email postfix/lmtp[14524]: B152A904002: to=<admin@companyname.com>, relay=email.companyname.com[10.0.1.6]:7025, delay=0.07, delays=0.01/0/0.01/0.05, dsn=2.1.5, status=sent (250 2.1.5 OK)
    Nov  6 23:46:42 email postfix/qmgr[24061]: B152A904002: removed
    Nov  6 23:47:53 email zmmailboxdmgr[15301]: status requested
    Nov  6 23:47:53 email zmmailboxdmgr[15301]: status OK
    Nov  6 23:47:53 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from stopped to running
    Nov  6 23:47:53 email zmmailboxdmgr[15365]: status requested
    Nov  6 23:47:53 email zmmailboxdmgr[15365]: status OK
    Nov  6 23:47:54 email postfix/pickup[10381]: 070F8904001: uid=1001 from=<zimbra>
    Nov  6 23:47:54 email postfix/cleanup[14519]: 070F8904001: message-id=<20081107074754.070F8904001@email.companyname.com>
    Nov  6 23:47:54 email postfix/qmgr[24061]: 070F8904001: from=<zimbra@email.companyname.com>, size=456, nrcpt=1 (queue active)
    Nov  6 23:47:54 email amavis[25660]: (25660-09) ESMTP::10024 /opt/zimbra/data/amavisd/tmp/amavis-20081105T192740-25660: <zimbra@email.companyname.com> -> <admin@companyname.com> SIZE=456 Received: from email.companyname.com ([127.0.0.1]) by localhost (email.companyname.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <admin@companyname.com>; Thu,  6 Nov 2008 23:47:54 -0800 (PST)
    Nov  6 23:47:54 email amavis[25660]: (25660-09) Checking: ffqb4NkzC7bo <zimbra@email.companyname.com> -> <admin@companyname.com>
    Nov  6 23:47:54 email postfix/smtpd[14523]: connect from localhost.localdomain[127.0.0.1]
    Nov  6 23:47:54 email postfix/smtpd[14523]: 3E1A6904002: client=localhost.localdomain[127.0.0.1]
    Nov  6 23:47:54 email postfix/cleanup[14519]: 3E1A6904002: message-id=<20081107074754.070F8904001@email.companyname.com>
    Nov  6 23:47:54 email postfix/qmgr[24061]: 3E1A6904002: from=<zimbra@email.companyname.com>, size=1070, nrcpt=1 (queue active)
    Nov  6 23:47:54 email postfix/smtpd[14523]: disconnect from localhost.localdomain[127.0.0.1]
    Nov  6 23:47:54 email amavis[25660]: (25660-09) FWD via SMTP: <zimbra@email.companyname.com> -> <admin@companyname.com>,BODY=7BIT 250 2.6.0 Ok, id=25660-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3E1A6904002
    Nov  6 23:47:54 email amavis[25660]: (25660-09) Passed CLEAN, <zimbra@email.companyname.com> -> <admin@companyname.com>, Message-ID: <20081107074754.070F8904001@email.companyname.com>, mail_id: ffqb4NkzC7bo, Hits: -3.344, size: 456, queued_as: 3E1A6904002, 204 ms
    Nov  6 23:47:54 email postfix/smtp[14520]: 070F8904001: to=<admin@companyname.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.24, delays=0.03/0/0/0.2, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 3E1A6904002)
    Nov  6 23:47:54 email postfix/qmgr[24061]: 070F8904001: removed
    Nov  6 23:47:54 email postfix/lmtp[14524]: 3E1A6904002: to=<admin@companyname.com>, relay=email.companyname.com[10.0.1.6]:7025, delay=0.08, delays=0/0/0/0.08, dsn=2.1.5, status=sent (250 2.1.5 OK)
    Nov  6 23:47:54 email postfix/qmgr[24061]: 3E1A6904002: removed
    /opt/zimbra/log/audit.log
    Code:
    2008-11-06 23:45:04,208 INFO  [btpool0-136] [ip=10.0.1.6;] security - cmd=AdminAuth; account=zimbra;
    2008-11-06 23:45:04,209 INFO  [btpool0-136] [ip=10.0.1.6;] security - cmd=Auth; account=zimbra; protocol=soap;
    2008-11-06 23:45:04,232 INFO  [btpool0-136] [name=zimbra;ip=10.0.1.6;] security - cmd=DelegateAuth; accountId=d1b39404-f07b-4784-8726-33d75af72871; accountName=spam.kq9iyvza@companyname.com;
    2008-11-06 23:45:06,614 INFO  [btpool0-141] [ip=10.0.1.6;] security - cmd=AdminAuth; account=zimbra;
    2008-11-06 23:45:06,614 INFO  [btpool0-141] [ip=10.0.1.6;] security - cmd=Auth; account=zimbra; protocol=soap;
    2008-11-06 23:45:06,633 INFO  [btpool0-141] [name=zimbra;ip=10.0.1.6;] security - cmd=DelegateAuth; accountId=3a294422-1f01-48d9-8e9d-d1f646af7ef5; accountName=ham.v7ieqbfuyt@companyname.com;
    /opt/zimbra/log/clamd.log
    Code:
    Thu Nov  6 23:46:10 2008 -> SelfCheck: Database status OK.
    /opt/zimbra/log/zmmailboxd.out has 6 of:
    Code:
    java.io.IOException: Connection reset by peer
            at sun.nio.ch.FileDispatcher.read0(Native Method)
            at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
            at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
            at sun.nio.ch.IOUtil.read(IOUtil.java:200)
            at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207)
            at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:232)
            at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:206)
            at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(SocketIoProcessor.java:44)
            at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:506)
            at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:43)
            at java.lang.Thread.run(Thread.java:595)
    but there are no timestamps so I can't tell if they are related or not...

    /opt/zimbra/log/zmmtaconfig.log:
    Code:
    Thu Nov  6 23:45:30 2008  Watchdog: service antivirus status is OK.
    Thu Nov  6 23:46:41 2008  Watchdog: service antivirus status is OK.
    Thu Nov  6 23:47:53 2008  Watchdog: service antivirus status is OK.
    Thu Nov  6 23:49:05 2008  Watchdog: service antivirus status is OK.
    /opt/zimbra/log/zmswatch.out is the last one of interest that I can see:
    Code:
    SMTP notification: Nov  6 23:46:41 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from running to stopped
    SNMP notification: Nov  6 23:46:41 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from running to stopped
    SMTP notification: Nov  6 23:47:53 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from stopped to running
    SNMP notification: Nov  6 23:47:53 email zimbramon[8171]: 8171:err: Service status change: email.companyname.com mta changed from stopped to running

  2. #2
    Tomsauy is offline Starter Member
    Join Date
    Jun 2008
    Posts
    1
    Rep Power
    7

    Default

    Hi,

    I up this thread because I had the same trouble.
    Have you solved this problem ? Is there anybody to help solving this ?

    Thanks in advanced,
    Thomas

  3. #3
    ArcaneMagus's Avatar
    ArcaneMagus is offline Moderator
    Join Date
    Feb 2007
    Location
    Portland, OR
    Posts
    1,147
    Rep Power
    10

    Default

    It was happening about once a month when it occurred, but hasn't happened in quite a while. As it was so rarely and happened when nobody was using the system I ignored it.

    Would certainly help with any debugging if anyone has a suggestion...

  4. #4
    bwesaala is offline New Member
    Join Date
    Nov 2008
    Posts
    3
    Rep Power
    6

    Default mta changed from stopped to running

    HI,

    I have also been having this same issue after recently upgrading to Zimbra 5.0.21. The interval between the restarts varies from 3 to 4 days. Any feedback on this will be appreciated.

    Brian

  5. #5
    ArcaneMagus's Avatar
    ArcaneMagus is offline Moderator
    Join Date
    Feb 2007
    Location
    Portland, OR
    Posts
    1,147
    Rep Power
    10

    Default

    Is there anything in your logs that might suggest a cause?

  6. #6
    bwesaala is offline New Member
    Join Date
    Nov 2008
    Posts
    3
    Rep Power
    6

    Default MTA service stopping and 1m later starting again

    Hi,

    Actually it took a while for the error to appear again...Here is the output from zimbra.log:

    Mar 23 14:41:38 zimbra zimbramon[25804]: 25804:err: Service status change: <our zimbra server> mta changed from running to stopped
    Mar 23 14:42:04 zimbra zimbramon[19683]: 19683:info: 2010-03-23 14:42:01, STATUS: <our zimbra server>: antispam: Running
    .
    .
    Mar 23 14:42:46 zimbra zimbramon[25804]: 25804:err: Service status change: <our zimbra server> mta changed from stopped to running

    Thanks for your assistance!

    Brian

Thread Information

Users Browsing this Thread

There are currently 1 users browsing this thread. (0 members and 1 guests)

Posting Permissions

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