TLS loglevel inbetween =1 & =2 ?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

TLS loglevel inbetween =1 & =2 ?

robgane
At

        smtpd_tls_loglevel=2

I get ALL of this in my logs

        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:before SSL initialization
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:before SSL initialization
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read client hello
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server hello
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write certificate
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write key exchange
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server done
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server done
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read client key exchange
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read change cipher spec
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read finished
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: em-sj-88.mktroute.com[199.15.215.88]: Issuing session ticket, key expiration: 1501689808
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write session ticket
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write change cipher spec
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write finished
        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: Anonymous TLS connection established from em-sj-88.mktroute.com[199.15.215.88]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)

At

        smtpd_tls_loglevel=1

I get none of it.

Is there a Postfix setting to get a sort of "loglevel= 1 1/2" so I get ONLY the

        Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: Anonymous TLS connection established from em-sj-88.mktroute.com[199.15.215.88]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)

If not I can play with rsyslog scripting.  Which I'm already looking at *anyway* to get at effective per-domain TLS verbose logging.  It would be handy to have both of those just in Postfix setup.

Rob
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: TLS loglevel inbetween =1 & =2 ?

Viktor Dukhovni
On Wed, Aug 02, 2017 at 08:52:59AM -0700, [hidden email] wrote:

> At
>
> smtpd_tls_loglevel=2
>
> I get ALL of this in my logs
>
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:before SSL initialization
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:before SSL initialization
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read client hello
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server hello
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write certificate
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write key exchange
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server done
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write server done
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read client key exchange
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read change cipher spec
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS read finished
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: em-sj-88.mktroute.com[199.15.215.88]: Issuing session ticket, key expiration: 1501689808
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write session ticket
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write change cipher spec
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: SSL_accept:SSLv3/TLS write finished
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: Anonymous TLS connection established from em-sj-88.mktroute.com[199.15.215.88]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)
>
> At
>
> smtpd_tls_loglevel=1
>
> I get none of it.

Sorry, perhaps your syslog is lossy, but the below *is* logged at level 1.

> Is there a Postfix setting to get a sort of "loglevel= 1 1/2" so I get ONLY the
>
> Aug  2 03:19:26 maryland postfix/handoff/smtpd[40383]: Anonymous TLS connection established from em-sj-88.mktroute.com[199.15.215.88]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)

This is logged at level 1.

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: TLS loglevel inbetween =1 & =2 ?

robgane

On Wed, Aug 2, 2017, at 09:11 AM, Viktor Dukhovni wrote:
> This is logged at level 1.

Ok.  Then I've got this morning's mystery!

If my syslog was 'lossy', it woulnd't log it in the loglevel = 2 case would it?

Until I figure out what's going wrong here, just

        edit main.cf
                - smtpd_tls_loglevel=2
                + smtpd_tls_loglevel=1
        postfix reload

make those entries DISappear, and

        edit main.cf
                - smtpd_tls_loglevel=1
                + smtpd_tls_loglevel=2
        postfix reload

gets them to display again.

Rob
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: TLS loglevel inbetween =1 & =2 ?

Bill Cole-3
On 2 Aug 2017, at 12:20, [hidden email] wrote:

> On Wed, Aug 2, 2017, at 09:11 AM, Viktor Dukhovni wrote:
>> This is logged at level 1.
>
> Ok.  Then I've got this morning's mystery!
>
> If my syslog was 'lossy', it woulnd't log it in the loglevel = 2 case
> would it?

Maybe. There's wide variation in syslog implementations

>
> Until I figure out what's going wrong here, just
>
> edit main.cf
> - smtpd_tls_loglevel=2
> + smtpd_tls_loglevel=1
> postfix reload
>
> make those entries DISappear, and
>
> edit main.cf
> - smtpd_tls_loglevel=1
> + smtpd_tls_loglevel=2
> postfix reload
>
> gets them to display again.

Something is wrong with your syslog implementation or its config. You
can confirm in the code that what Viktor says is true and I have an
example of it being so in operation. I have not touched the TLS config
on this system for many months (at least) and here's a couple of line
counts from today's log:

bigsky:log root# postconf smtpd_tls_loglevel
smtpd_tls_loglevel = 1
bigsky:log root# grep -c 'postfix/.* TLS connection established from '
mail.log
2070
bigsky:log root# grep -c 'postfix/.*SSL' mail.log
0

i.e.: it's logging connection establishment messages but none of the
negotiation messages (which mostly have 'SSL' function names in them.)
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: TLS loglevel inbetween =1 & =2 ?

Viktor Dukhovni
In reply to this post by robgane
On Wed, Aug 02, 2017 at 09:20:46AM -0700, [hidden email] wrote:

> On Wed, Aug 2, 2017, at 09:11 AM, Viktor Dukhovni wrote:
> > This is logged at level 1.
>
> Ok.  Then I've got this morning's mystery!
>
> If my syslog was 'lossy', it woulnd't log it in the loglevel = 2 case would it?

Hard to say why, but the purpose of log level 1 is precisely to
log the TLS connection summary message.

>
> Until I figure out what's going wrong here, just
>
> edit main.cf
> - smtpd_tls_loglevel=2
> + smtpd_tls_loglevel=1
> postfix reload
>
> make those entries DISappear, and
>
> edit main.cf
> - smtpd_tls_loglevel=1
> + smtpd_tls_loglevel=2
> postfix reload
>
> gets them to display again.

Use the "collate" program (included with recent Postfix source,
and posted multiple times to this list) to report the logging from
a single session.  With loglevel 1, I get (folded for clarity):

    Aug  2 16:20:56 amnesiac postfix/smtpd[2134]:
        connect from russian-caravan.cloud9.net[168.100.1.4]

    Aug  2 16:20:56 amnesiac postfix/smtpd[2134]:
        Anonymous TLS connection established from russian-caravan.cloud9.net[168.100.1.4]:
        TLSv1 with cipher ADH-AES256-SHA (256/256 bits)

    Aug  2 16:20:57 amnesiac postfix/smtpd[2134]: 0BB317A3302:
        client=russian-caravan.cloud9.net[168.100.1.4]

    Aug  2 16:20:57 amnesiac postfix/cleanup[29826]: 0BB317A3302:
        message-id=<[hidden email]>

    Aug  2 16:20:57 amnesiac postfix/qmgr[1735]: 0BB317A3302:
        from=<[hidden email]>, size=5193, nrcpt=1 (queue active)

    Aug  2 16:20:57 amnesiac postfix/smtpd[2134]:
        disconnect from russian-caravan.cloud9.net[168.100.1.4]
        ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7

    Aug  2 16:20:58 amnesiac postfix/virtual[19431]: 0BB317A3302:
        to=<[hidden email]>, orig_to=<[hidden email]>,
        relay=virtual, delay=1.4, delays=0.88/0.01/0/0.54, dsn=2.0.0,
        status=sent (delivered to maildir)

    Aug  2 16:20:58 amnesiac postfix/qmgr[1735]: 0BB317A3302:
        removed

The second log entry is the one you're looking for.  You're perhaps
searching for the queue-id, that's not available to the Postfix
TLS layer, (not even possible when receiving mail, because the
queue-id is not assigned until later) and so is not part of the
log entry.  In any case the TLS details are a connection property,
not a message property, and if we ever implement outbound TLS
connection re-use, then again the TLS stream is not directly
associated with a particular queue-id.

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: TLS loglevel inbetween =1 & =2 ?

robgane
> Something is wrong with your syslog implementation or its config.

Doesn't show up as a problem anywhere else afaict

> Hard to say why, but the purpose of log level 1 is precisely to
> log the TLS connection summary message.

Ok.

> Use the "collate" program (included with recent Postfix source,
> and posted multiple times to this list) to report the logging from
> a single session.  With loglevel 1, I get (folded for clarity):

Finally managed to not identify+solve the problem, but just make it go away.

I rebuilt/reinstalled Postfix 3.3.2 and now I've got that TLS line logging.  Really don't care why right now just as long as it's logging the way it should be.  Sounds like it is.  Thanks.

Yeah, I saw collate.pl.  Didn't get around to using it.  Really handy, thanks!

Rod
Loading...