Apple Event: May 7th at 7 am PT

Looks like no one’s replied in a while. To start the conversation again, simply ask a new question.

Throttling respawn loop?

Hi,

I just had a look at my Server System log and I seem to have an issue as I am getting the same repeating entries:

Aug 4 11:45:11 discussion postfix/master[92044]: fatal: bind: private/smtpd: Invalid argument

Aug 4 11:45:12 discussion com.apple.launchd[1] (org.postfix.master[92044]): Exited with code: 1

Aug 4 11:45:12 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 4 11:45:21 discussion postfix/master[92047]: fatal: bind: private/smtpd: Invalid argument

Aug 4 11:45:22 discussion com.apple.launchd[1] (org.postfix.master[92047]): Exited with code: 1

Aug 4 11:45:22 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 4 11:45:31 discussion postfix/master[92049]: fatal: bind: private/smtpd: Invalid argument

Aug 4 11:45:32 discussion com.apple.launchd[1] (org.postfix.master[92049]): Exited with code: 1

Aug 4 11:45:32 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

I have a new Mac Pro with 10.7.4 OS X Server installed.

Is the above anything to worry about?

Thanks

Posted on Aug 4, 2012 3:48 AM

42 replies

jaydisc

Level 4

1,464 points

Aug 7, 2012 2:06 AM in response to jaydisc

That port list is clean... it's not that. I'm still thinking it's ACLs.

Aug 7, 2012 2:08 AM in response to jaydisc

Hi,

I followed your suggestions ealier if that is what you mean?

discussion:~ tony$ sudo chmod -R -N /etc/postfix /var/spool/postfix /Library/Server/Mail/Data

chmod: Failed to clear ACL on file anvil: Invalid argument

chmod: Failed to clear ACL on file bounce: Invalid argument

chmod: Failed to clear ACL on file defer: Invalid argument

chmod: Failed to clear ACL on file discard: Invalid argument

chmod: Failed to clear ACL on file dnsblog: Invalid argument

chmod: Failed to clear ACL on file dovecot: Invalid argument

chmod: Failed to clear ACL on file error: Invalid argument

chmod: Failed to clear ACL on file lmtp: Invalid argument

chmod: Failed to clear ACL on file local: Invalid argument

chmod: Failed to clear ACL on file policy: Invalid argument

chmod: Failed to clear ACL on file proxymap: Invalid argument

chmod: Failed to clear ACL on file proxywrite: Invalid argument

chmod: Failed to clear ACL on file relay: Invalid argument

chmod: Failed to clear ACL on file retry: Invalid argument

chmod: Failed to clear ACL on file rewrite: Invalid argument

chmod: Failed to clear ACL on file sacl-cache: Invalid argument

chmod: Failed to clear ACL on file scache: Invalid argument

chmod: Failed to clear ACL on file smtp: Invalid argument

chmod: Failed to clear ACL on file smtp-amavis: Invalid argument

chmod: Failed to clear ACL on file smtpd: Invalid argument

chmod: Failed to clear ACL on file tlsmgr: Invalid argument

chmod: Failed to clear ACL on file tlsproxy: Invalid argument

chmod: Failed to clear ACL on file trace: Invalid argument

chmod: Failed to clear ACL on file verify: Invalid argument

chmod: Failed to clear ACL on file virtual: Invalid argument

chmod: Failed to clear ACL on file cleanup: Invalid argument

chmod: Failed to clear ACL on file flush: Invalid argument

chmod: Failed to clear ACL on file pickup: Invalid argument

chmod: Failed to clear ACL on file qmgr: Invalid argument

chmod: Failed to clear ACL on file showq: Invalid argument

discussion:~ tony$

jaydisc

Level 4

1,464 points

Aug 7, 2012 2:11 AM in response to Antony-D-Emanuele

Are you checking the output in system.log after each of these? I'm suspecting it's unchanged?

This is interesting. We're seeing the same "invalid argument". Let's see which one of those three parths generated those errors.

sudo chmod -R -N /etc/postfix

sudo chmod -R -N /var/spool/postfix

sudo chmod -R -N /Library/Server/Mail/Data

Aug 7, 2012 2:17 AM in response to jaydisc

I have just checked the logs and I think we may have fixed it (well you did!), here is the output, do you still want me to enter the three commands in your last post?

Aug 7 10:07:02 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 7 10:07:12 discussion postfix/master[1099]: fatal: bind: private/smtpd: Invalid argument

Aug 7 10:07:13 discussion com.apple.launchd[1] (org.postfix.master[1099]): Exited with code: 1

Aug 7 10:07:13 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 7 10:07:22 discussion postfix/master[1101]: fatal: bind: private/smtpd: Invalid argument

Aug 7 10:07:23 discussion com.apple.launchd[1] (org.postfix.master[1101]): Exited with code: 1

Aug 7 10:07:23 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 7 10:07:32 discussion postfix/master[1111]: fatal: bind: private/smtpd: Invalid argument

Aug 7 10:07:33 discussion com.apple.launchd[1] (org.postfix.master[1111]): Exited with code: 1

Aug 7 10:07:33 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 7 10:07:42 discussion postfix/master[1113]: fatal: bind: private/smtpd: Invalid argument

Aug 7 10:07:43 discussion com.apple.launchd[1] (org.postfix.master[1113]): Exited with code: 1

Aug 7 10:07:43 discussion com.apple.launchd[1] (org.postfix.master): Throttling respawn: Will start in 9 seconds

Aug 7 10:07:53 discussion dovecot[1131]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:53 discussion dovecot[1131]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:54 discussion dovecot[1188]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:54 discussion dovecot[1188]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:54 discussion dovecot[1191]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:54 discussion dovecot[1191]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:55 discussion dovecot[1192]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:55 discussion dovecot[1192]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:55 discussion dovecot[1193]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:55 discussion dovecot[1193]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:56 discussion dovecot[1199]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:56 discussion dovecot[1199]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:56 discussion dovecot[1201]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:56 discussion dovecot[1201]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:57 discussion dovecot[1202]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:57 discussion dovecot[1202]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:57 discussion dovecot[1203]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:57 discussion dovecot[1203]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:58 discussion dovecot[1204]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:58 discussion dovecot[1204]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:58 discussion dovecot[1205]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:58 discussion dovecot[1205]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:59 discussion dovecot[1206]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:59 discussion dovecot[1206]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:07:59 discussion dovecot[1207]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:07:59 discussion dovecot[1207]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:08:00 discussion dovecot[1208]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:08:00 discussion dovecot[1208]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:08:00 discussion dovecot[1209]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:08:00 discussion dovecot[1209]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:08:01 discussion dovecot[1211]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:08:01 discussion dovecot[1211]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:08:01 discussion dovecot[1212]: lda: Error: userdb lookup: connect(/var/run/dovecot/auth-userdb) failed: Operation timed out

Aug 7 10:08:01 discussion dovecot[1212]: lda: Fatal: Internal error occurred. Refer to server log for more information.

Aug 7 10:12:26 discussion collabd[1319]: [main.m:103 40a280 +8ms] HTTP server listening at loopback:4444

Aug 7 10:12:26 discussion com.apple.collabd[1319]: Aug 7 10:12:26 discussion.pharmweb.net collabd[1319] <Warning>: [main.m:103 40a280 +8ms] HTTP server listening at loopback:4444

Aug 7 10:12:26 discussion com.apple.launchd[1] (com.apple.collabd[1319]): Tried to setup shared memory more than once

Aug 7 10:12:26 discussion wikiadmin[1326]: Updating schema...

Aug 7 10:12:26 discussion com.apple.collabd[1319]: 2012-08-07 10:12:26.190 wikiadmin[1326:307] Updating schema...

Aug 7 10:12:26 discussion wikiadmin[1326]: Schema updates completed.

Aug 7 10:12:26 discussion com.apple.collabd[1319]: 2012-08-07 10:12:26.192 wikiadmin[1326:307] Schema updates completed.

Aug 7 10:12:31 discussion collabd[1355]: [main.m:103 40a280 +0ms] HTTP server listening at loopback:4444

Aug 7 10:12:31 discussion com.apple.collabd[1355]: Aug 7 10:12:31 discussion.pharmweb.net collabd[1355] <Warning>: [main.m:103 40a280 +0ms] HTTP server listening at loopback:4444

Aug 7 10:12:31 discussion com.apple.launchd[1] (com.apple.collabd[1355]): Tried to setup shared memory more than once

Aug 7 10:12:31 discussion wikiadmin[1359]: Updating schema...

Aug 7 10:12:31 discussion com.apple.collabd[1355]: 2012-08-07 10:12:31.719 wikiadmin[1359:307] Updating schema...

Aug 7 10:12:31 discussion wikiadmin[1359]: Schema updates completed.

Aug 7 10:12:31 discussion com.apple.collabd[1355]: 2012-08-07 10:12:31.721 wikiadmin[1359:307] Schema updates completed.

System logs now seems to have gone quiet? Have we resolved. Spoke too soon, this just came out:

Aug 7 10:12:31 discussion com.apple.collabd[1355]: Aug 7 10:12:31 discussion.pharmweb.net collabd[1355] <Warning>: [main.m:103 40a280 +0ms] HTTP server listening at loopback:4444

Aug 7 10:12:31 discussion com.apple.launchd[1] (com.apple.collabd[1355]): Tried to setup shared memory more than once

Aug 7 10:12:31 discussion wikiadmin[1359]: Updating schema...

Aug 7 10:12:31 discussion com.apple.collabd[1355]: 2012-08-07 10:12:31.719 wikiadmin[1359:307] Updating schema...

Aug 7 10:12:31 discussion wikiadmin[1359]: Schema updates completed.

Aug 7 10:12:31 discussion com.apple.collabd[1355]: 2012-08-07 10:12:31.721 wikiadmin[1359:307] Schema updates completed.

Aug 7 10:16:12 discussion servermgrd[92924]: -[AccountsRequestHandler(AccountsSystemConfigurationObservation) registerForKeychainEventNotifications]: SecKeychainAddCallback() status: -25297

Aug 7 10:16:32 discussion com.apple.backupd[1465]: Starting standard backup

Aug 7 10:16:32 discussion com.apple.backupd[1465]: Backing up to: /Volumes/Time Machine on Mac Pro/Backups.backupdb

Aug 7 10:16:40 discussion ServerBackup[1466]: Error in calling backup command for service postgresql, error :=69

Aug 7 10:16:41 discussion ServerBackup[1466]: SRC := /etc/apache2/

DST := /.ServerBackups/webServer

Aug 7 10:16:41 discussion ServerBackup[1466]: SRC := /etc/certificates/

DST := /.ServerBackups/webServer

Aug 7 10:16:42 discussion com.apple.backupd[1465]: 1.51 GB required (including padding), 307.51 GB available

Aug 7 10:16:43 discussion com.apple.backupd[1465]: Copied 20 files (93 bytes) from volume SuperDuper.

Aug 7 10:16:43 discussion mds[87]: (Error) Volume: Could not find requested backup type:2 for volume

Aug 7 10:16:44 discussion com.apple.backupd[1465]: Starting post-backup thinning

Aug 7 10:16:44 discussion com.apple.backupd[1465]: Deleted /Volumes/Time Machine on Mac Pro/Backups.backupdb/PharmWeb Server/2012-08-06-101641 (24.0 KB)

Aug 7 10:16:44 discussion com.apple.backupd[1465]: Deleted /Volumes/Time Machine on Mac Pro/Backups.backupdb/PharmWeb Server/2012-08-06-092909 (28.0 KB)

Aug 7 10:16:44 discussion com.apple.backupd[1465]: Post-back up thinning complete: 2 expired backups removed

Aug 7 10:16:44 discussion com.apple.backupd[1465]: Backup completed successfully.

Anything in latest logs to worry about??

jaydisc

Level 4

1,464 points

Aug 7, 2012 2:23 AM in response to Antony-D-Emanuele

Hey, lookin' good. I think it was those ACLs.... though not sure exactly which. I'd be careful messing with the privileges in unknown areas. Feel free to set your Tony ACL, but due it say, from /Users or /Groups down... avoid /System, /Library, or especially /.

The later messages aren't related.... collabd and wikiadmin are part of the WIki Service (are you running that?) and then of course all of the backupd messages are Time Machine doing its thing.

Unrelated issue is this error message:

ServerBackup[1466]: Error in calling backup command for service postgresql, error :=69

I got this on all my 10.7.x servers. So I wrote my own little Postgres backup script to comfort me instead, but if you need help with that, best to start a new thread.

Also, while it's very unclear, I'm pretty sure you're in the 10.8 server section (now generically called OS X Server, ala The New iPad), which made me misunderstand your initial query (even though you clearly wrote 10.7.4. My bad, but something worth considering.)

All the best!

Aug 7, 2012 2:41 AM in response to jaydisc

Can I just thank you for your help (and patience) resolving this...

Best wishes

Tony

Aug 8, 2012 10:07 AM in response to jaydisc

Sorry to trouble you again, but I think there may still be some issue with permissions in my my >Library>Server>Mail folder

I use SuperDuper to backup my server and it has been crashing on me, the authors at ShirtPocket pinpointed the issue to a file in Mail and asked me to exclude from backup. I have had a look at the files/folders in Mail and permissions seem odd, have a look at http://www.demanuele.net/screenshot.jpg

I have included some of the info windows with permissions and some folders are not accessible to administrators or system? Is this correct?

jhill287

Level 1

0 points

Aug 30, 2012 7:59 AM in response to Antony-D-Emanuele

I have to give kudos. You're an absolute genius. I was expreiencing the exact same issue, except I do use the mail services and they quit working after applying the 10.8.1 patch. This solved the error issue and got my mail server back up and running! Thank you so much!

Lapog

Level 1

0 points

Nov 8, 2012 12:31 PM in response to jaydisc

Hi jaydisc,

I have the same problem - actually still have the same problem. The console is still spewing out "...Throttling respawn: Will start in 9 seconds"

I followed your instructions; and for:

GopalsMacPro:~ Gopal$ tail /var/log/mail.log

I got this :

Nov 8 14:11:34 GopalsMacPro postfix/master[988]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:11:44 GopalsMacPro postfix/master[990]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:11:54 GopalsMacPro postfix/master[992]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:04 GopalsMacPro postfix/master[994]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:14 GopalsMacPro postfix/master[998]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:24 GopalsMacPro postfix/master[1001]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:34 GopalsMacPro postfix/master[1007]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:44 GopalsMacPro postfix/master[1012]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:12:54 GopalsMacPro postfix/master[1014]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Nov 8 14:13:04 GopalsMacPro postfix/master[1016]: fatal: open lock file /Library/Server/Mail/Data/mta/master.lock: cannot open file: Permission denied

Where do I go from here?

BTW, this is an Early 2008 MacPro, 2x2.8GHz Quad-Core Xeon, 10GB RAM, 500HD.

Thank you in advance.