What does this log message mean?

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

What does this log message mean?

Gerben Wierda
I’m using the postfix that is part of mac OS Sierra with Server 5.2. Apple has kind of damaged the logging system, so getting logs from sptmd/smtp has become a lot more difficult.

I’ve now found a way to get the logs. While investigating something else, I’ve noticed entries like these in the logs:

2017-03-22 15:09:08.158097+0100 0x5f1534   Info        0x0                  7220   smtp: 1051A8D80CA: to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10024, delay=12965, delays=12962/0.19/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

What could these imply? I don’t have the idea that mail is not coming through.

My guess is that this is the link between postfix and amavisd, from

main.cf:content_filter = smtp-amavis:[127.0.0.1]:10024

But for the rest: I haven’t been able to establish a pattern.

G
Reply | Threaded
Open this post in threaded view
|

RE: What does this log message mean?

angelo

Hi,

I think this is how you read the delay.

 

"delays=a/b/c/d" where a=time before queue manager, including message transmission; b=time in queue manager; c=connection setup time including DNS, HELO and TLS; d=message transmission time

 

That may explain why it’s deferred and not sent.

 

-ALF

 

-Angelo Fazzina

Operating Systems Programmer / Analyst

University of Connecticut,  UITS, SSG, Server Systems

860-486-9075

 

From: [hidden email] [mailto:[hidden email]] On Behalf Of Gerben Wierda
Sent: Thursday, March 23, 2017 3:12 PM
To: Postfix users <[hidden email]>
Subject: What does this log message mean?

 

I’m using the postfix that is part of mac OS Sierra with Server 5.2. Apple has kind of damaged the logging system, so getting logs from sptmd/smtp has become a lot more difficult.

 

I’ve now found a way to get the logs. While investigating something else, I’ve noticed entries like these in the logs:

 

2017-03-22 15:09:08.158097+0100 0x5f1534   Info        0x0                  7220   smtp: 1051A8D80CA: to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10024, delay=12965, delays=12962/0.19/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

 

What could these imply? I don’t have the idea that mail is not coming through.

 

My guess is that this is the link between postfix and amavisd, from

 

main.cf:content_filter = smtp-amavis:[127.0.0.1]:10024



But for the rest: I haven’t been able to establish a pattern.

 

G

Reply | Threaded
Open this post in threaded view
|

Re: What does this log message mean?

Gerben Wierda

On 23 Mar 2017, at 20:16, Fazzina, Angelo <[hidden email]> wrote:

I think this is how you read the delay.
 
"delays=a/b/c/d" where a=time before queue manager, including message transmission; b=time in queue manager; c=connection setup time including DNS, HELO and TLS; d=message transmission time
 
That may explain why it’s deferred and not sent.

I see. But what does that mean? "Lost connection while sending end of data” and what does ‘deferred’ exactly imply here. That it will be picked up later?

G

 
-ALF
 
-Angelo Fazzina
Operating Systems Programmer / Analyst
University of Connecticut,  UITS, SSG, Server Systems
860-486-9075
 
From: [hidden email] [[hidden email]] On Behalf Of Gerben Wierda
Sent: Thursday, March 23, 2017 3:12 PM
To: Postfix users <[hidden email]>
Subject: What does this log message mean?
 
I’m using the postfix that is part of mac OS Sierra with Server 5.2. Apple has kind of damaged the logging system, so getting logs from sptmd/smtp has become a lot more difficult.
 
I’ve now found a way to get the logs. While investigating something else, I’ve noticed entries like these in the logs:
 
2017-03-22 15:09:08.158097+0100 0x5f1534   Info        0x0                  7220   smtp: 1051A8D80CA: to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10024, delay=12965, delays=12962/0.19/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)
 
What could these imply? I don’t have the idea that mail is not coming through.
 
My guess is that this is the link between postfix and amavisd, from
 
main.cf:content_filter = smtp-amavis:[127.0.0.1]:10024


But for the rest: I haven’t been able to establish a pattern.
 
G

Reply | Threaded
Open this post in threaded view
|

RE: What does this log message mean?

angelo

Hi,

you are relaying mail that comes in the box to here

relay=127.0.0.1[127.0.0.1]:10024

 

Then there is a problem sending the message to port 10024

lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once

 

 

maybe up the loglevel, or use tcpdump to capture some packets and see if the postfix logs are correct.

-ALF

 

 

-Angelo Fazzina

Operating Systems Programmer / Analyst

University of Connecticut,  UITS, SSG, Server Systems

860-486-9075

 

From: Gerben Wierda [mailto:[hidden email]]
Sent: Thursday, March 23, 2017 4:25 PM
To: Fazzina, Angelo <[hidden email]>
Cc: Postfix users <[hidden email]>
Subject: Re: What does this log message mean?

 

 

On 23 Mar 2017, at 20:16, Fazzina, Angelo <[hidden email]> wrote:

 

Hi,

I think this is how you read the delay.

 

"delays=a/b/c/d" where a=time before queue manager, including message transmission; b=time in queue manager; c=connection setup time including DNS, HELO and TLS; d=message transmission time

 

That may explain why it’s deferred and not sent.

 

I see. But what does that mean? "Lost connection while sending end of data” and what does ‘deferred’ exactly imply here. That it will be picked up later?

 

G



 

-ALF

 

-Angelo Fazzina

Operating Systems Programmer / Analyst

University of Connecticut,  UITS, SSG, Server Systems

860-486-9075

 

From: [hidden email] [[hidden email]] On Behalf Of Gerben Wierda
Sent: Thursday, March 23, 2017 3:12 PM
To: Postfix users <[hidden email]>
Subject: What does this log message mean?

 

I’m using the postfix that is part of mac OS Sierra with Server 5.2. Apple has kind of damaged the logging system, so getting logs from sptmd/smtp has become a lot more difficult.

 

I’ve now found a way to get the logs. While investigating something else, I’ve noticed entries like these in the logs:

 

2017-03-22 15:09:08.158097+0100 0x5f1534   Info        0x0                  7220   smtp: 1051A8D80CA: to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10024, delay=12965, delays=12962/0.19/0.01/3.1, dsn=4.4.2, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once)

 

What could these imply? I don’t have the idea that mail is not coming through.

 

My guess is that this is the link between postfix and amavisd, from

 

main.cf:content_filter = smtp-amavis:[127.0.0.1]:10024




But for the rest: I haven’t been able to establish a pattern.

 

G

 

Reply | Threaded
Open this post in threaded view
|

Re: What does this log message mean?

Noel Jones-2

>
> 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.

Is this message still in the postfix queue or did it eventually get
delivered?




  -- Noel Jones

Reply | Threaded
Open this post in threaded view
|

Re: What does this log message mean?

Gerben Wierda

On 23 Mar 2017, at 21:59, Noel Jones <[hidden email]> 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
Reply | Threaded
Open this post in threaded view
|

Re: What does this log message mean?

Gerben Wierda
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: <[hidden email]> -> <[hidden email]> 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 <[hidden email]>; 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: <[hidden email]>, a=rsa-sha256, c=relaxed/relaxed, s=proddkim1024, [hidden email]
Mar 22 15:09:08 Dumbledore.local /Applications/Server.app/Contents/ServerRoot/usr/bin/amavisd[7232]: (07232-01) Checking: YWTLjyxWMVoS [108.174.3.206] <[hidden email]> -> <[hidden email]>
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 <[hidden email]> wrote:


On 23 Mar 2017, at 21:59, Noel Jones <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

Re: What does this log message mean?

Noel Jones-2
In reply to this post by Gerben Wierda
On 3/23/2017 4:25 PM, Gerben Wierda wrote:
>> 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


Well, "mailq" or "postqueue -p" will display what's in the queue. No
need to dig around in the spool directory.

At any rate, this appears to be an amavisd problem; postfix is just
the messenger.



  -- Noel Jones