Mail Service Keeps Stopping For No Reason

Question

Level 1

0 points

Mail Service Keeps Stopping For No Reason

Hi There everyone. Over the past few days my Mail Service keeps stopping. Not giving any particular error, the only clue is this log message:-

Jan 6 13:12:39 server master[371]: exiting on SIGTERM/SIGINT

Is that helpful? I can start the service again and it seems OK... for a few hours then it stops again.

I have tried, reconstructing and repairing until I am blue in the face. Any other suggestions please? Thanks in advance.

G5 Dual 2GHz, Mac Mini, Macbook Pro, Mac OS X (10.5.1), Leopard Server 10 User Licence

Posted on Jan 6, 2008 12:14 PM

Reply

Answer 1

Rizlaalzir Author

Level 1

0 points

Jan 7, 2008 2:24 AM in response to Rizlaalzir

It comes up with this in the mail log file just before it stops the mail service:

Jan 7 10:15:26 server master[28278]: exiting on SIGTERM/SIGINT
Jan 7 10:15:26 server master[28370]: getrlimit: max processes limit set to cur=2500 max=2500
Jan 7 10:15:26 server master[28370]: process started
Jan 7 10:15:36 server master[28379]: getrlimit: max processes limit set to cur=2500 max=2500
Jan 7 10:15:36 server master[28379]: process started
Jan 7 10:15:36 server master[28380]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 7 10:15:49 server ctl_cyrusdb[28380]: verifying cyrus databases
Jan 7 10:15:49 server ctl_cyrusdb[28380]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 0 seconds
Jan 7 10:15:49 server ctl_cyrusdb[28380]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 0 seconds
Jan 7 10:16:09 server ctl_cyrusdb[28380]: done verifying cyrus databases
Jan 7 10:16:09 server master[28387]: about to exec /usr/bin/cyrus/bin/idled
Jan 7 10:16:09 server master[28379]: Cyrus POP/IMAP Server v2.3.8 ready for work
Jan 7 10:16:09 server master[28389]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 7 10:16:09 server ctl_cyrusdb[28389]: checkpointing cyrus databases
Jan 7 10:16:09 server ctl_cyrusdb[28389]: archiving database file: /var/imap/annotations.db
Jan 7 10:16:09 server ctl_cyrusdb[28389]: archiving log file: /var/imap/db/log.0000000001
Jan 7 10:16:09 server ctl_cyrusdb[28389]: archiving database file: /var/imap/mailboxes.db
Jan 7 10:16:09 server ctl_cyrusdb[28389]: archiving log file: /var/imap/db/log.0000000001
Jan 7 10:16:12: --- last message repeated 1 time ---

Any ideas?

Reply

Answer 2

Rizlaalzir Author

Level 1

0 points

Jan 8, 2008 11:53 AM in response to Rizlaalzir

Anyone got any ideas? HELP!

Reply

Answer 3

davidh

Level 4

1,890 points

Jan 8, 2008 7:35 PM in response to Rizlaalzir

You might try upping the launchctl limit(s), via:

sudo echo "limit maxproc 1500 3000" > /etc/launchd.conf

and then rebooting the server.

"master" probably refers to cyrusimap, and the question is why you're hitting resource limits.
How much RAM in the server, how many mail users, size of current mailstore ?

Reply

Answer 4

pterobyte

Level 6

11,098 points

Jan 9, 2008 5:26 AM in response to Rizlaalzir

You are showing the log file after Cyrus receives a SIGTERM and you restart it. It would be interesting to see what happens before.

Reply

Answer 5

Rizlaalzir Author

Level 1

0 points

Jan 9, 2008 5:28 AM in response to davidh

Hi and thanks for taking the time to answer the question. I only have 8 users: 1 has a mailbox of 802MB, the other 400MB, 1 has 4MB and the other 1MB, the others are 0 MB. I have 2GB RAM it is a Mac Mini. It is running Time machine server, could that be a problem? I have tried your idea, but it still stops. Any other ideas?

Reply

Answer 6

Rizlaalzir Author

Level 1

0 points

Jan 12, 2008 12:11 AM in response to davidh

Hi, is there any more info you can suggest to resolve this problem as I am coming to the end of my tether!! If I had to re-install, what do I need to back up and then how do I restore it? Thanks.

Reply

Answer 7

Rizlaalzir Author

Level 1

0 points

Jan 12, 2008 1:09 AM in response to Rizlaalzir

I have just had the same thing happend again today with this in the log file:-

Jan 12 08:52:53 server imap[1413]: AOD: user options: no lookup required for: paul
Jan 12 08:52:53 server imap[1413]: login: localhost [::1] paul plaintext user logged in
Jan 12 08:52:53 server imap[1413]: quota set to "unlimited" for mailbox user.paul
Jan 12 08:52:53 server imap[1413]: open: user paul opened INBOX
Jan 12 08:52:53 server imap[1413]: accepted connection
Jan 12 08:52:53 server imap[1413]: AOD: user options: no lookup required for: paul
Jan 12 08:52:53 server imap[1413]: login: localhost [::1] paul plaintext user logged in
Jan 12 08:52:53 server imap[1413]: quota set to "unlimited" for mailbox user.paul
Jan 12 08:52:53 server imap[1413]: open: user paul opened INBOX
Jan 12 08:52:53: --- last message repeated 2 times ---
Jan 12 08:52:53 server imap[1413]: SQUAT failed to open index file
Jan 12 08:52:53 server imap[1413]: SQUAT failed
Jan 12 08:53:07 server master[367]: process 1399 exited, status 0
Jan 12 08:54:21 server master[367]: process 1413 exited, status 0
Jan 12 09:02:07 server master[51]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:02:07 server master[51]: process started
Jan 12 09:02:08 server master[177]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:02:12 server ctl_cyrusdb[177]: verifying cyrus databases
Jan 12 09:02:14 server ctl_cyrusdb[177]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 2 seconds
Jan 12 09:02:16 server ctl_cyrusdb[177]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 2 seconds
Jan 12 09:02:28 server master[261]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:02:29 server master[261]: process started
Jan 12 09:02:29 server master[262]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:03:42 server master[335]: process started
Jan 12 09:03:42 server master[337]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:04:00 server ctl_cyrusdb[337]: DBERROR db4: unable to join the environment
Jan 12 09:04:15 server ctl_cyrusdb[337]: verifying cyrus databases
Jan 12 09:04:16 server ctl_cyrusdb[337]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 1 second
Jan 12 09:04:16 server ctl_cyrusdb[337]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 0 seconds
Jan 12 09:04:41 server master[352]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:04:41 server master[352]: process started
Jan 12 09:04:41 server master[354]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:04:51 server ctl_cyrusdb[354]: verifying cyrus databases
Jan 12 09:04:51 server ctl_cyrusdb[354]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 0 seconds
Jan 12 09:04:52 server ctl_cyrusdb[354]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 1 second
Jan 12 09:05:17 server master[387]: process started
Jan 12 09:05:27 server master[447]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:05:27 server master[447]: process started
Jan 12 09:05:27 server master[448]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:05:41 server master[451]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:05:41 server master[451]: process started
Jan 12 09:05:41 server master[452]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:05:59 server ctl_cyrusdb[452]: DBERROR db4: unable to join the environment
Jan 12 09:06:01 server ctl_cyrusdb[452]: verifying cyrus databases
Jan 12 09:06:01 server ctl_cyrusdb[452]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 0 seconds
Jan 12 09:06:02 server ctl_cyrusdb[452]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 1 second
Jan 12 09:06:21 server master[479]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:06:21 server master[479]: process started
Jan 12 09:06:21 server master[480]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:06:31 server master[481]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:06:42 server master[483]: getrlimit: max processes limit set to cur=2068 max=2068
Jan 12 09:06:43 server master[483]: process started
Jan 12 09:07:01 server ctl_cyrusdb[485]: DBERROR db4: unable to join the environment
Jan 12 09:07:02 server ctl_cyrusdb[485]: verifying cyrus databases
Jan 12 09:07:02 server ctl_cyrusdb[485]: skiplist: recovered /var/imap/mailboxes.db (15 records, 2784 bytes) in 0 seconds
Jan 12 09:07:02 server ctl_cyrusdb[485]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 0 seconds
Jan 12 09:07:28 server ctl_cyrusdb[485]: done verifying cyrus databases
Jan 12 09:07:28 server master[497]: about to exec /usr/bin/cyrus/bin/idled
Jan 12 09:07:29 server master[483]: Cyrus POP/IMAP Server v2.3.8 ready for work
Jan 12 09:07:29 server master[499]: about to exec /usr/bin/cyrus/bin/ctl_cyrusdb
Jan 12 09:07:29 server ctl_cyrusdb[499]: checkpointing cyrus databases
Jan 12 09:07:29 server ctl_cyrusdb[499]: archiving database file: /var/imap/annotations.db
Jan 12 09:07:29 server ctl_cyrusdb[499]: archiving log file: /var/imap/db/log.0000000001
Jan 12 09:07:29 server ctl_cyrusdb[499]: archiving database file: /var/imap/mailboxes.db
Jan 12 09:07:29 server ctl_cyrusdb[499]: archiving log file: /var/imap/db/log.0000000001
Jan 12 09:07:29: --- last message repeated 1 time ---
Jan 12 09:07:29 server ctl_cyrusdb[499]: done checkpointing cyrus databases
Jan 12 09:07:29 server master[483]: process 499 exited, status 0
Jan 12 09:08:16 server master[512]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:16 server imap[512]: executed
Jan 12 09:08:16 server imap[512]: accepted connection
Jan 12 09:08:16 server master[513]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:16 server imap[513]: executed
Jan 12 09:08:16 server imap[513]: accepted connection
Jan 12 09:08:17 server imap[512]: login: [172.16.1.99] paul plaintext user logged in
Jan 12 09:08:17 server imap[512]: quota set to "unlimited" for mailbox user.paul
Jan 12 09:08:17 server master[514]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:17 server imap[513]: login: [172.16.1.99] florensis CRAM-MD5 User logged in
Jan 12 09:08:17 server imap[513]: quota set to "unlimited" for mailbox user.florensis
Jan 12 09:08:17 server master[515]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:17 server imap[515]: executed
Jan 12 09:08:17 server imap[515]: accepted connection
Jan 12 09:08:17 server master[516]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:17 server imap[516]: executed
Jan 12 09:08:17 server imap[516]: accepted connection
Jan 12 09:08:17 server imap[516]: login: [172.16.1.99] paul plaintext user logged in
Jan 12 09:08:17 server imap[516]: quota set to "unlimited" for mailbox user.paul
Jan 12 09:08:17 server imap[515]: login: [172.16.1.99] florensis CRAM-MD5 User logged in
Jan 12 09:08:17 server imap[515]: quota set to "unlimited" for mailbox user.florensis
Jan 12 09:08:17 server imap[516]: seen_db: user paul opened /var/imap/user/p/paul.seen
Jan 12 09:08:17 server imap[516]: open: user paul opened Junk
Jan 12 09:08:17 server imap[515]: skiplist: recovered /var/imap/user/f/florensis.seen (7 records, 14904 bytes) in 0 seconds
Jan 12 09:08:17 server imap[515]: seen_db: user florensis opened /var/imap/user/f/florensis.seen
Jan 12 09:08:17 server imap[516]: SQUAT failed to open index file
Jan 12 09:08:17 server imap[515]: open: user florensis opened INBOX
Jan 12 09:08:17 server imap[516]: SQUAT failed
Jan 12 09:08:18 server master[517]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:18 server imap[517]: executed
Jan 12 09:08:18 server imap[517]: accepted connection
Jan 12 09:08:18 server imap[517]: login: [172.16.1.99] florensis CRAM-MD5 User logged in
Jan 12 09:08:18 server imap[517]: quota set to "unlimited" for mailbox user.florensis
Jan 12 09:08:18 server master[518]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:18 server imap[518]: executed
Jan 12 09:08:18 server imap[519]: executed
Jan 12 09:08:18 server imap[518]: SQUAT failed to open index file
Jan 12 09:08:18 server imap[518]: SQUAT failed
Jan 12 09:08:18 server master[520]: about to exec /usr/bin/cyrus/bin/imapd
Jan 12 09:08:18 server imap[520]: executed
Jan 12 09:08:18 server imap[520]: accepted connection
Jan 12 09:08:19 server imap[516]: Expunged 7 messages from user.paul.Junk
Jan 12 09:08:19 server imap[520]: login: [172.16.1.99] florensis CRAM-MD5 User logged in
Jan 12 09:08:19 server imap[520]: quota set to "unlimited" for mailbox user.florensis
Jan 12 09:08:19 server imap[517]: seen_db: user florensis opened /var/imap/user/f/florensis.seen
Jan 12 09:08:19 server imap[517]: open: user florensis opened Junk
Jan 12 09:08:19 server imap[517]: SQUAT failed to open index file
Jan 12 09:08:19 server imap[517]: SQUAT failed
Jan 12 09:08:19 server imap[519]: seen_db: user florensis opened /var/imap/user/f/florensis.seen
Jan 12 09:08:19 server imap[519]: open: user florensis opened Apple Mail To Do
Jan 12 09:08:19 server imap[520]: seen_db: user florensis opened /var/imap/user/f/florensis.seen
Jan 12 09:08:19 server imap[520]: open: user florensis opened Deleted Messages
Jan 12 09:08:19 server imap[520]: SQUAT failed to open index file
Jan 12 09:08:19 server imap[520]: SQUAT failed
Jan 12 09:08:20 server imap[513]: accepted connection
Jan 12 09:08:20 server imap[513]: login: [172.16.1.99] paul plaintext user logged in
Jan 12 09:08:20 server imap[513]: quota set to "unlimited" for mailbox user.paul
Jan 12 09:08:20 server imap[514]: Expunged 1 messages from user.paul
Jan 12 09:08:20 server imap[513]: seen_db: user paul opened /var/imap/user/p/paul.seen
Jan 12 09:08:22 server imap[513]: open: user paul opened Apple Mail To Do
Jan 12 09:08:22 server imap[516]: open: user paul opened Sent Messages
Jan 12 09:08:22 server imap[515]: Expunged 1 messages from user.florensis
Jan 12 09:08:23 server imap[517]: open: user florensis opened Apple Mail To Do
Jan 12 09:08:23 server imap[518]: open: user paul opened Junk
Jan 12 09:08:24 server imap[518]: Expunged 1 messages from user.paul.Junk

Does this help? It then cleared itself??

Reply

Answer 8

pterobyte

Level 6

11,098 points

Jan 12, 2008 7:35 AM in response to Rizlaalzir

Don't see any indication of your mail stopping in the logs you posted.

Reply

Answer 9

davidh

Level 4

1,890 points

Jan 12, 2008 4:04 PM in response to pterobyte

While not about whether or not mail service is stopping,
the "SQUAT" errors are -relatively- benign.

man squatter
for more info.

You should be able to remedy that with
sudo -u _cyrusimap /usr/bin/cyrus/bin/squatter -rv username

the "v" isn't strictly necessary, and in your case it'd be
sudo -u cyrusimap /usr/bin/cyrus/bin/squatter -rv florensis

Technically the user in 10.5 is _cyrus , but cyrusimap (as with/in 10.4) will also work, both usernames are valid for the same UID in 10.5

I'd suggest a known-good backup of mail first.

Regarding the DBERROR, you should probably do a cyrus rebuild - ONLY once you have a known-good backup : )
As well, and specific to the "unable to join the environment" error, I would also try the following (again, only after a good backup):
stop mail services
set aside (don't delete)
/private/var/imap/tls_sessions.db
start mail services and monitor the result.

see
http://asg.web.cmu.edu/archive/message.php?mailbox=archive.info-cyrus&msg=31889
and the reply
http://asg.web.cmu.edu/archive/message.php?mailbox=archive.info-cyrus&msg=31889

I'm curious however about the hardware, and how you installed 10.5 server on it (wipe & clean install ? )

Reply

Answer 10

Feb 15, 2008 8:03 PM in response to Rizlaalzir

After upgrading my 10.5 server to 10.5.2 my IMAP stopped working. After hours of troubleshooting, searching and repairing, I finally figured it out. Here's what my logs looked like:

/var/log/mail.log
Feb 15 22:38:50 home postfix/smtpd[705]: warning: connect to private/anvil: No such file or directory
Feb 15 22:38:50 home postfix/smtpd[705]: warning: problem talking to server private/anvil: No such file or directory
Feb 15 22:40:01 home postfix/postfix-script[745]: fatal: the Postfix mail system is not running

/var/log/mailaccess.log
Feb 15 22:31:32 home deliver[580]: connect(/var/imap/socket/lmtp) failed: Connection refused
Feb 15 22:32:15 home ctl_cyrusdb[590]: DBERROR db4: unable to join the environment
Feb 15 22:32:40 home deliver[600]: connect(/var/imap/socket/lmtp) failed: Connection refused
Feb 15 22:33:00 home ctl_cyrusdb[601]: DBERROR db4: unable to join the environment
Feb 15 22:34:58 home ctl_cyrusdb[629]: DBERROR db4: unable to join the environment
Feb 15 22:38:12 home lmtpunix[657]: DBERROR db4: PANIC: fatal region error detected; run recovery
Feb 15 22:38:12 home lmtpunix[657]: DBERROR: critical database situation

Along with a standard Repair from Server Admin, this command did it:

/etc/postfix/post-install upgrade-configuration

It looks like the OS X upgrade missed a config in postfix that broke imap. I'm not sure how closely this relates to your issue, but hopefully it helps someone. It worked for me.

Reply

Answer 11

Rizlaalzir Author

Level 1

0 points

Feb 18, 2008 10:44 AM in response to EEFranklin

Hi Guys, I thought I'd update you. This issue is related to using the server as a time machine server. If I turn off Time Machine the mail server works perfectly (for 2 weeks now). I have just turned Time Machine server back on as I'd hoped Apple may have fixed this issue in 10.5.2, however it immediately bombs out the mail service by stopping it and causing all types of nonsense!

Reply

Answer 12

pterobyte

Level 6

11,098 points

Feb 18, 2008 11:11 AM in response to Rizlaalzir

I have seen this behaviour related to time machine as well on several clients' servers in the past few weeks. Well, just one more confirmation that Time Machine should not be used on Server.

Reply

Answer 13

Feb 19, 2008 1:52 AM in response to Rizlaalzir

Does this apply to using Time Machine to back up the server itself (like a regular client does), or only when running backups for other local clients over the network?

Reply

Answer 14

pterobyte

Level 6

11,098 points

Feb 19, 2008 2:58 AM in response to Marcus Bointon

It relates to running time machine on the server per se. Doesn't matter what for (at least on the servers I have seen). Running it on the clients is fine.

Reply

Answer 15

Mar 19, 2008 10:14 PM in response to pterobyte

Interestingly I had not had any issues with email early on with Server 10.5... even when running backup on the server machine. I turned of Time Machine for a month to do some drive switching and formating. When I reactivated yesterday my email began quitting for no apparent reason. The only change made was running Time Machine under the most recent update 10.5.2.

To verify the issue I monitored email when starting a backup session and it quit within minutes and would not resume for until the update stopped.

Anyone found a fix for this? Makes Time Machine more troublesome when you have to manually start/stop during late nights to avoid bringing the mail server offline.

Reply