Well it all started a day ago, when mail was being queued and not delivered.... In the log I can see
Nov 5 09:42:42 email postfix/lmtp[10922]: EFF393D184B: to=<ncudmore@newashgreen.net>, relay=none, delay=63724, delays=63719/5.1/0.16/0, dsn=4.4.1, status=deferred (connect to email.newashgreen.net[/var/imap/socket/lmtp]: No such file or directory)
having checked the postfix main.cf
mailbox_transport = lmtp:unix:/var/imap/socket/lmtp
everything points to /var/imap/socket/lmtp, and looks fine.
checking /var/imap/socket/ I can see the following...
drwxr-xr-x 4 _cyrus mail 136 5 Nov 01:03 .
drwxr-xr-x 16 _cyrus mail 544 5 Nov 01:03 ..
srwxrwxrwx 1 _cyrus mail 0 5 Nov 01:03 idle
-rw------- 1 _cyrus mail 0 4 Nov 23:01 lmtpunix-0.lock
which would imply there is indeed no socket for lmtp.
Checking the ownership on the directory I see
drwxr-xr-x 4 _cyrus mail 136 5 Nov 01:03 socket
So, cyrus has ownership, and group access for mail. Checking the group mail gave me
root# grep ^mail /etc/group
mail:*:6:
So, mail has no membership.... Thus, I reason on the fact that postfix has not access to here, checked to find the OS X use to replace the lack of adduser and the nearest find I could get was
You are going down the wrong road and risk messing permissions and the mail system up.
The socket gets created by Cyrus when it starts. The socket not being there, implies that Cyrus is not able to start up (at least partially) properly.
Try and issue:
ps U _cyrus
(this should tell you if and which Cyrus processes are running).
Next make sure logging level for IMAP is set to "Information".
Stop and start mail services:
sudo serveradmin stop mail
sudo serveradmin start mail
and see if /var/log/mailaccess.log and /var/log/system.log show any Cyrus related errors.
Thanks Alex..
Just checked and got the following after the restart..
email:~ root# ps U _cyrus
PID TT STAT TIME COMMAND
13418 ?? Ss 0:00.02 master -l 256
13462 ?? S 0:00.01 idled
13464 ?? S 0:00.03 lmtpd
email:~ root# tail /var/log/mailaccess.log
Nov 5 14:46:11 email master[13464]: about to exec /usr/bin/cyrus/bin/lmtpd
Nov 5 14:46:11 email ctl_cyrusdb[13463]: checkpointing cyrus databases
Nov 5 14:46:11 email lmtpunix[13464]: executed
Nov 5 14:46:11 email ctl_cyrusdb[13463]: archiving database file: /var/imap/annotations.db
Nov 5 14:46:11 email ctl_cyrusdb[13463]: archiving log file: /var/imap/db/log.0000000001
Nov 5 14:46:11 email ctl_cyrusdb[13463]: archiving database file: /var/imap/mailboxes.db
Nov 5 14:46:11 email ctl_cyrusdb[13463]: archiving log file: /var/imap/db/log.0000000001
Nov 5 14:46:12: --- last message repeated 1 time ---
Nov 5 14:46:12 email ctl_cyrusdb[13463]: done checkpointing cyrus databases
Nov 5 14:46:12 email master[13418]: process 13463 exited, status 0
email:~ root# tail /var/log/system.log
Nov 5 14:58:35 email com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[14549]): Stray process with PGID equal to this dead job: PID 14550 PPID 1 ctl_cyrusdb
Nov 5 14:58:35 email com.apple.launchd[1] (edu.cmu.andrew.cyrus.master[14549]): Exited abnormally: User defined signal 1
Nov 5 14:58:35 email master[14584]: process started
Nov 5 14:58:50 email ctl_cyrusdb[14585]: verifying cyrus databases
Nov 5 14:58:50 email ctl_cyrusdb[14585]: skiplist: recovered /var/imap/mailboxes.db (35 records, 6880 bytes) in 0 seconds
Nov 5 14:58:51 email ctl_cyrusdb[14585]: skiplist: recovered /var/imap/annotations.db (0 records, 144 bytes) in 1 second
Nov 5 14:59:19 email ctl_cyrusdb[14585]: done verifying cyrus databases
Nov 5 14:59:19 email master[14584]: Cyrus POP/IMAP Server v2.3.8 ready for work
Nov 5 14:59:19 email ctl_cyrusdb[14640]: checkpointing cyrus databases
Nov 5 14:59:20 email ctl_cyrusdb[14640]: done checkpointing cyrus databases
email:~ root# tail /var/log/mailaccess.log
Nov 5 14:59:19 email master[14641]: about to exec /usr/bin/cyrus/bin/lmtpd
Nov 5 14:59:19 email ctl_cyrusdb[14640]: checkpointing cyrus databases
Nov 5 14:59:19 email ctl_cyrusdb[14640]: archiving database file: /var/imap/annotations.db
Nov 5 14:59:19 email lmtpunix[14641]: executed
Nov 5 14:59:20 email ctl_cyrusdb[14640]: archiving log file: /var/imap/db/log.0000000001
Nov 5 14:59:20 email ctl_cyrusdb[14640]: archiving database file: /var/imap/mailboxes.db
Nov 5 14:59:20 email ctl_cyrusdb[14640]: archiving log file: /var/imap/db/log.0000000001
Nov 5 14:59:20: --- last message repeated 1 time ---
Nov 5 14:59:20 email ctl_cyrusdb[14640]: done checkpointing cyrus databases
Nov 5 14:59:20 email master[14584]: process 14640 exited, status 0
/var/spool/postfix/cyrus-socket/lmtp]: Socket operation on non-socket
email:~ root# tail /var/log/mailaccess.log
Nov 5 15:43:25 email imaps[36260]: starttls: TLSv1 with cipher AES128-SHA (128/128 bits reused) no authentication
Nov 5 15:43:25 email imaps[36260]: AOD: mbr
check_servicemembership with access
allservices
Nov 5 15:43:25 email imaps[36260]: AOD: mail service ACL NOT enabled
Nov 5 15:43:25 email imaps[36260]: login: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore CRAM-MD5+TLS User logged in
Nov 5 15:43:25 email imaps[36260]: quota set to "unlimited" for mailbox user.ncudmore
Nov 5 15:43:25 email imaps[36258]: seen_db: user ncudmore opened /var/imap/user/n/ncudmore.seen
Nov 5 15:43:25 email imaps[36258]: open: user ncudmore opened Deleted Messages
Nov 5 15:43:25 email imaps[36258]: SQUAT failed to open index file
Nov 5 15:43:25 email imaps[36258]: SQUAT failed
Nov 5 15:43:25 email imaps[36258]: Expunged 17 messages from user.ncudmore.Deleted Messages
email:~ root# tail /var/log/system.log
Nov 5 15:45:21 email postfix/tlsmgr[36435]: warning: encryption keys etc. may be predictable
Nov 5 15:45:35 email org.amavis.amavisd_cleanup[36463]: find:
Nov 5 15:45:35 email org.amavis.amavisd_cleanup[36463]: /var/amavis/tmp/amavis-20091103T235142-04569/parts: Permission denied
Nov 5 15:45:35 email org.amavis.amavisd_cleanup[36463]: find:
Nov 5 15:45:35 email org.amavis.amavisd_cleanup[36463]: /var/amavis/tmp/amavis-20091103T235142-04569/parts: Permission denied
Nov 5 15:45:49 email postfix/tlsmgr[36487]: warning: no entropy source specified with parameter tls
randomsource
Nov 5 15:45:49 email postfix/tlsmgr[36487]: warning: encryption keys etc. may be predictable
Nov 5 15:46:00 email postfix/smtpd[36485]: warning: 192.211.85.209.multi.uribl.com: RBL lookup error: Host or domain name not found. Name service error for name=192.211.85.209.multi.uribl.com type=A: Host not found, try again
Nov 5 15:46:50 email postfix/tlsmgr[36575]: warning: no entropy source specified with parameter tls
randomsource
Nov 5 15:46:50 email postfix/tlsmgr[36575]: warning: encryption keys etc. may be predictable
email:~ root# tail /var/log/mail.log
Nov 5 15:46:50 email postfix/smtpd[36574]: connect from localhost[127.0.0.1]
Nov 5 15:46:50 email postfix/smtpd[36574]: 992AE3E25AF: client=localhost[127.0.0.1]
Nov 5 15:46:50 email postfix/cleanup[36579]: 992AE3E25AF: message-id=<686368ca0911050745o51fe360aia9f6e0f3170a8ba9@mail.gmail.com>
Nov 5 15:46:50 email postfix/qmgr[36545]: 992AE3E25AF: from=<ncudmore@googlemail.com>, size=2305, nrcpt=1 (queue active)
Nov 5 15:46:50 email postfix/smtp[36504]: 495CC3E2594: to=<ncudmore@newashgreen.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=61, delays=11/0.05/0.1/50, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=35674-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 992AE3E25AF)
Nov 5 15:46:51 email postfix/lmtp[36581]: 992AE3E25AF: to=<ncudmore@newashgreen.net>, relay=none, delay=0.42, delays=0.12/0.11/0.19/0, dsn=4.4.1, status=deferred (connect to mserver.newashgreen.net[/var/spool/postfix/cyrus-socket/lmtp]: Socket operation on non-socket)
Nov 5 15:47:27 email postfix/postfix-script[36632]: refreshing the Postfix mail system
Nov 5 15:47:27 email postfix/master[35600]: reload configuration /etc/postfix
Nov 5 15:47:27 email postfix/qmgr[36636]: 495CC3E2594: from=<ncudmore@googlemail.com>, size=1837, nrcpt=1 (queue active)
Nov 5 15:47:27 email postfix/qmgr[36636]: 495CC3E2594: removed
email:~ root# ps U _cyrus
PID TT STAT TIME COMMAND
35711 ?? Ss 0:00.06 master -l 256
35764 ?? S 0:00.77 idled
35766 ?? S 0:00.06 lmtpd
36251 ?? S 0:00.32 imapd: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore user.ncu
36257 ?? R 1:09.67 imapd: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore user.ncu
36258 ?? S 0:00.09 imapd: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore user.ncu
36259 ?? S 0:00.07 imapd: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore
36260 ?? S 0:00.07 imapd: Neils-intel-iMac.newashgreen.net [192.168.1.14] ncudmore
email:~ root# ls -la /var/imap/socket
total 0
drwxr-xr-x 5 _cyrus mail 170 Nov 5 15:43 .
drwxr-xr-x 17 _cyrus mail 578 Nov 5 15:43 ..
srwxrwxrwx 1 _cyrus mail 0 Nov 5 15:37 idle
-rw------- 1 _cyrus mail 0 Nov 5 15:43 imaps-1.lock
-rw------- 1 _cyrus mail 0 Nov 5 15:37 lmtpunix-0.lock
/var/spool/postfix/cyrus-socket/lmtp]: Socket operation on non-socket
This path is not right. I'd go through all config files and make very sure you did not inadvertnetly change something. If in doubt, restore config files from backup.
You're right I restored an earlier postfix main.cf which was incorrect.....
Back to the error saying :-
Nov 5 16:41:28 email postfix/lmtp[41433]: EFF393E2778: to=<ncudmore@newashgreen.net>, relay=none, delay=88851, delays=88850/0.34/0.02/0, dsn=4.4.1, status=deferred (connect to mserver.newashgreen.net[/var/imap/socket/lmtp]: No such file or directory)
I think so.... Dates look fine on the restored versions. But you know what it's like, just because it's from a period when the server was working, it will not mean that was the active configuration running at the time.
The server was up for 52 days, and only after a reboot following 10.5.8 being applied did I get any problems.
Doubt, the 10.5.8 from 10.5.7 had anything to do with this but....
email:~ root# ls -la /var/imap/socket
total 0
drwxr-xr-x 6 _cyrus mail 204 Nov 6 16:24 .
drwxr-xr-x 18 _cyrus mail 612 Nov 6 16:24 ..
srwxrwxrwx 1 _cyrus mail 0 Nov 6 16:24 idle
-rw------- 1 _cyrus mail 0 Nov 5 15:43 imaps-1.lock
srwxrwxrwx 1 root mail 0 Nov 6 16:24 lmtp
-rw------- 1 _cyrus mail 0 Nov 5 15:37 lmtpunix-0.lock
so I can now see the lmtp socket, but it's a root process... but now also getting
Nov 6 16:30:24 email postfix/lmtp[82355]: 7DB073E4A83: to=<ncudmore@newashgreen.net>, relay=email.newashgreen.net[/var/imap/socket/lmtp], delay=7179, delays=7179/0.04/0.31/0.07, dsn=5.1.1, status=bounced (host email.newashgreen.net[/var/imap/socket/lmtp] said: 550-Mailbox unknown. Either there is no mailbox associated with this 550-name or you do not have authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO command))
going to chown the socket to _cyrus and see where that leaves me....
Well I chowned the socket to _cyrus:mail, but that's not the problem, as when I restarted the mail
sudo serveradmin start mail
It's ownership went back to root:mail.
So, it look's like now Cyrus can't see the Open directory for delivery. I confirmed this by creating a new account for testing (Fred Flintstone), and whilst I can connect to the server via imap and send email out bound from Fred's account; inbound it's being rejected, then sending back a NDR:-
Nov 7 00:53:28 email postfix/smtp[23100]: C8C9B3E67FD: to=<fflintstone@newashgreen.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=31, delays=0.59/0/0.03/31, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=22936-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as D0E9A3E6818)
Nov 7 00:53:28 email postfix/qmgr[22948]: C8C9B3E67FD: removed
Nov 7 00:53:29 email postfix/smtp[23295]: 18FF63E681C: to=<ncudmore@googlemail.com>, relay=gmail-smtp-in.l.google.com[209.85.219.13]:25, delay=1.1, delays=0.01/0.04/0.26/0.83, dsn=2.0.0, status=sent (250 2.0.0 OK 1257555209 17si1200957ewy.47)
Nov 7 00:53:29 email postfix/qmgr[22948]: 18FF63E681C: removed
in googlemail:-
Final-Recipient: rfc822; fflintstone@newashgreen.net
Original-Recipient: rfc822;fflintstone@newashgreen.net
Action: failed
Status: 5.1.1
Remote-MTA: dns; email.newashgreen.net
Diagnostic-Code: smtp; 550-Mailbox unknown. Either there is no mailbox
associated with this 550-name or you do not have authorization to see it.
550 5.1.1 User unknown
Look's like it's all down to the OD not working correctly.....
Set up a local user and rebooted the whole darn server, and got the following error showing in the system log...
Nov 9 23:33:33 email lmtpunix[69896]: AOD: user opts: get attributes for user: ncudmore@newashgreen.net failed with error: -14479
Nov 9 23:33:33 email lmtpunix[69896]: warning: unable to post message for user: ncudmore@newashgreen.net, mail is not enabled for this user
Checked in Workgroup Manager and yes, I did have mail enabled for myself... changed the setting from POP and IMAP to just IMAP and re-saved and still nothing..
Checked the LDAP Log and can see
Nov 9 23:29:14 email slapd[46]: <= bdb
substringcandidates: (authAuthority) index_param failed (18)
Nov 9 23:38:25 email slapd[46]: @(#) $OpenLDAP: slapd 2.3.27 (Jun 17 2009 19:09:12) $
Nov 9 23:38:29 email slapd[46]: overlay_config(): warning, overlay "dynid" already in list
Nov 9 23:38:45: --- last message repeated 4 times ---
Changed my email setting to forward email to my google account and this works fine..... Change it back and:-
Nov 10 00:19:31 email lmtpunix[3568]: AOD: user opts: get attributes for user: ncudmore@newashgreen.net failed with error: -14479
Nov 10 00:19:31 email lmtpunix[3568]: warning: unable to post message for user: ncudmore@newashgreen.net, mail is not enabled for this user