Actually, those errors were unrelated. Looking at the time in amavisd log that corresponds with a deferred message in the smtp log:
Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: sd_notify (no socket): STATUS=Starting child process(es), ready for work. Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) ESMTP [127.0.0.1]:10024 /Library/Server/Mail/Data/scanner/amavis/tmp/amavis-20170322T150908-07232-Y4b5mCpx: <m-4xjo29tsly15ue9irg2jxhv37wd90yt919xtxjvclj64kapadlbrckqd...@bounce.linkedin.com> -> <gerben.wie...@rna.nl> SIZE=32374 Received: from mail.rna.nl ([127.0.0.1]) by localhost (dumbledore.local [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <gerben.wie...@rna.nl>; Wed, 22 Mar 2017 15:09:08 +0100 (CET) Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) dkim: VALID Author+Sender signature by d=linkedin.com, From: <groups-nore...@linkedin.com>, a=rsa-sha256, c=relaxed/relaxed, s=proddkim1024, i=@linkedin.com Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) Checking: YWTLjyxWMVoS [108.174.3.206] <m-4xjo29tsly15ue9irg2jxhv37wd90yt919xtxjvclj64kapadlbrckqd...@bounce.linkedin.com> -> <gerben.wie...@rna.nl> Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) p003 1 Content-Type: multipart/alternative Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) p001 1/1 Content-Type: text/plain, QP, size: 1701, SHA1 digest: 87db6c60aeb8cb0aa754e5bbdf0bf838363cd8b4 Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) p002 1/2 Content-Type: text/html, QP, size: 26568, SHA1 digest: 96669988557336e33e9606f995bdb51e80197bc2 Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: sd_notify (no socket): STATUS=Starting child process(es), ready for work. Mar 22 15:09:09 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: sd_notify (no socket): STATUS=Starting child process(es), ready for work. Nothing seems wrong at 15:09. So the smtp message isn’t really linked at an amavisd message of trouble. With respect to the amavisd errors. Somewhere at the start of the amavis logfile it says: Mar 22 22:30:03 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: Creating db in /Library/Server/Mail/Data/scanner/amavis/db/; BerkeleyDB 0.54, libdb 4.7 Mar 22 22:30:03 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: (!!)TROUBLE in pre_loop_hook: db_init: BDB no dbS: Lock table is out of available locker entries, . at (eval 94) line 320. Mar 22 22:30:03 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: sd_notify (no socket): STOPPING=1\nSTATUS=TROUBLE in pre_loop_hook: db_init: BDB no dbS: Lock table is out of available locker entries, . at (eval 94) line 320. Mar 22 22:30:03 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: (!)_DIE: Suicide () TROUBLE in pre_loop_hook: db_init: BDB no dbS: Lock table is out of available locker entries, . at (eval 94) line 320. Amavis::Util, Encode::decode() taint laundering bug, fixed in Encode 2.50 at /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd line 2951. Mar 22 22:30:05 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[60997]: logging initialized, log level 2, logfile: /Library/Logs/Mail/amavis.log Mar 22 22:30:05 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[60997]: sd_notify (no socket): STATUS=Config files have been read, modules loaded. Mar 22 22:30:05 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[60997]: Valid PID file /Library/Server/Mail/Data/scanner/amavis/amavisd.pid (younger than sys uptime 29 13:07:00) Mar 22 22:30:05 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[60997]: No such process [279], supposedly the current amavisd master process Mar 22 22:30:05 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[60997]: starting. /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd at Dumbledore.local amavisd-new-2.11.0 (20160426), Unicode aware which suggests to me that the warm restart of amavisd fixes the BerkelyDB issue. This is getting off topic for postfix, I’ll move elsewhere. G > On 23 Mar 2017, at 22:25, Gerben Wierda <gerben.wie...@rna.nl> wrote: > > >> On 23 Mar 2017, at 21:59, Noel Jones <njo...@megan.vbhcs.org >> <mailto:njo...@megan.vbhcs.org>> wrote: >> >> >>> >>> maybe up the loglevel, or use tcpdump to capture some packets and >>> see if the postfix logs are correct. >>> >> >> Increasing the postfix log level is unlikely to give any further >> useful information -- the other end dropped the connection. >> >> Check the amavisd logs at this same time. If that doesn't provide >> anything useful, maybe increasing the amavisd debug level will help. > > Well, thanks. That at least turns up something: > > Mar 22 21:31:14 Dumbledore.local > /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[279]: sd_notify > (no socket): STATUS=Starting child process(es), ready for work. > Mar 22 21:31:14 Dumbledore.local > /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[13425]: > (!!)TROUBLE in child_init_hook: BDB no dbS: Lock table is out of available > locker entries, . at (eval 94) line 31. > Mar 22 21:31:14 Dumbledore.local > /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[13425]: (!)_DIE: > Suicide in child_init_hook: BDB no dbS: Lock table is out of available locker > entries, . at (eval 94) line 31. > > I looked at amavisd, but there is no code at line 31 or 94, so I’m kind of > stumped. > > And also interesting: after a logfile turnover it went on operating normally, > it seems. > >> Is this message still in the postfix queue or did it eventually get >> delivered? > > II haven’t been able to establish this yet. It’s hard to debug with Apple’s > logging issues. Th spool directory is good as empty (only one entry in > defer/deferred. > > G
