Loading ...
Sorry, an error occurred while loading the content.

Re: Question about log messages and connection caching

Expand Messages
  • Ralf Hildebrandt
    ... Yes, three in the past and one just now. fgrep postfix1/smtp[18518] /var/log/mail.log (to see the others) -- Ralf Hildebrandt
    Message 1 of 10 , Aug 30, 2008
    • 0 Attachment
      * Per Jessen <per@...>:
      > I'm using postfix 2.5.4.
      >
      > When I read the following in the log:
      >
      > postfix1/smtp[18518]: 4AD0517085: to=<dooley@...>,
      > relay=myserver[myipaddr]:25, conn_use=4, delay=7.8,
      > delays=7.6/0/0.03/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
      > F3241EDAA)
      >
      > I tend to think that _one_ email has been delivered. However, given
      > conn_use is 4, it must have been four emails instead of just one?

      Yes, three in the past and one just now.

      fgrep "postfix1/smtp[18518]" /var/log/mail.log
      (to see the others)

      --
      Ralf Hildebrandt (Ralf.Hildebrandt@...) snickebo@...
      Postfix - Einrichtung, Betrieb und Wartung Tel. +49 (0)30-450 570-155
      http://www.arschkrebs.de I'm looking for a job
      What is this "XP pro"? Does this make "XP" unprofessional?
    • Per Jessen
      ... Thanks - I had been looking for something like that too, but I had expected to see the conn_use number increase sequentially. What I see is: Aug 30
      Message 2 of 10 , Aug 30, 2008
      • 0 Attachment
        Ralf Hildebrandt wrote:

        > * Per Jessen <per@...>:
        >> I'm using postfix 2.5.4.
        >>
        >> When I read the following in the log:
        >>
        >> postfix1/smtp[18518]: 4AD0517085: to=<dooley@...>,
        >> relay=myserver[myipaddr]:25, conn_use=4, delay=7.8,
        >> delays=7.6/0/0.03/0.08, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
        >> as F3241EDAA)
        >>
        >> I tend to think that _one_ email has been delivered. However, given
        >> conn_use is 4, it must have been four emails instead of just one?
        >
        > Yes, three in the past and one just now.
        >
        > fgrep "postfix1/smtp[18518]" /var/log/mail.log
        > (to see the others)

        Thanks - I had been looking for something like that too, but I had
        expected to see the conn_use number increase sequentially. What I see
        is:

        Aug 30 10:49:24 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:49:52 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:49:53 postfix1/smtp[18518]: conn_use=2,
        Aug 30 10:49:54 postfix1/smtp[18518]: conn_use=4,
        Aug 30 10:49:55 postfix1/smtp[18518]: conn_use=6,
        Aug 30 10:49:56 postfix1/smtp[18518]: conn_use=8,
        Aug 30 10:49:56 postfix1/smtp[18518]: conn_use=10,
        Aug 30 10:50:57 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:52:08 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:52:23 postfix1/smtp[18518]: conn_use=2,
        Aug 30 10:53:18 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:54:52 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:56:05 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:56:16 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:56:29 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:56:36 postfix1/smtp[18518]: <no conn_use listed>
        Aug 30 10:56:41 postfix1/smtp[18518]: conn_use=2,
        Aug 30 10:56:44 postfix1/smtp[18518]: conn_use=4,

        The last line is from the first one I quoted (above).
        I guess conn_use is only listed when > 1, but I seem to missing the
        uneven numbers?


        /Per Jessen, Zürich
      • Ralf Hildebrandt
        ... Yes. ... Odd, it works here: # fgrep postfix/smtp[12851] /var/log/mail.log| awk {print $9} delay=0.74, conn_use=2, conn_use=3, delay=0.18, conn_use=4,
        Message 3 of 10 , Aug 30, 2008
        • 0 Attachment
          * Per Jessen <per@...>:

          > Aug 30 10:49:24 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:49:52 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:49:53 postfix1/smtp[18518]: conn_use=2,
          > Aug 30 10:49:54 postfix1/smtp[18518]: conn_use=4,
          > Aug 30 10:49:55 postfix1/smtp[18518]: conn_use=6,
          > Aug 30 10:49:56 postfix1/smtp[18518]: conn_use=8,
          > Aug 30 10:49:56 postfix1/smtp[18518]: conn_use=10,
          > Aug 30 10:50:57 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:52:08 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:52:23 postfix1/smtp[18518]: conn_use=2,
          > Aug 30 10:53:18 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:54:52 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:56:05 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:56:16 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:56:29 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:56:36 postfix1/smtp[18518]: <no conn_use listed>
          > Aug 30 10:56:41 postfix1/smtp[18518]: conn_use=2,
          > Aug 30 10:56:44 postfix1/smtp[18518]: conn_use=4,
          >
          > The last line is from the first one I quoted (above).
          > I guess conn_use is only listed when > 1,

          Yes.

          > but I seem to missing the uneven numbers?

          Odd, it works here:

          # fgrep "postfix/smtp[12851]" /var/log/mail.log| awk '{print $9}'
          delay=0.74,
          conn_use=2,
          conn_use=3,
          delay=0.18,
          conn_use=4,
          conn_use=5,

          --
          Ralf Hildebrandt (Ralf.Hildebrandt@...) snickebo@...
          Postfix - Einrichtung, Betrieb und Wartung Tel. +49 (0)30-450 570-155
          http://www.arschkrebs.de I'm looking for a job
          Murphy's Law is recursive.
          Washing your car to make it rain doesn't work.
        • Per Jessen
          ... I ve got more: fgrep postfix1/smtp[29938] /var/log/mail | awk {print $1 $2 $3 $9} Aug 30 15:05:49 delay=2.1, Aug 30 15:06:12 delay=1.1, Aug 30
          Message 4 of 10 , Aug 30, 2008
          • 0 Attachment
            Ralf Hildebrandt wrote:

            > Odd, it works here:
            >
            > # fgrep "postfix/smtp[12851]" /var/log/mail.log| awk '{print $9}'
            > delay=0.74,
            > conn_use=2,
            > conn_use=3,
            > delay=0.18,
            > conn_use=4,
            > conn_use=5,

            I've got more:

            fgrep "postfix1/smtp[29938]" /var/log/mail | awk '{print
            $1" "$2" "$3" "$9}'

            Aug 30 15:05:49 delay=2.1,
            Aug 30 15:06:12 delay=1.1,
            Aug 30 15:06:17 delay=3,
            Aug 30 15:06:19 conn_use=2,
            Aug 30 15:06:20 conn_use=3,
            Aug 30 15:06:22 conn_use=2,
            Aug 30 15:06:23 conn_use=3,
            Aug 30 15:06:24 conn_use=7,
            Aug 30 15:06:46 delay=1.6,
            Aug 30 15:06:52 delay=3,
            Aug 30 15:08:05 delay=3.1,
            Aug 30 15:08:21 delay=3.9,
            Aug 30 15:08:29 conn_use=2,


            Whilst on the subject of connection caching, I assume postfix will (have
            to) do a RSET between each reuse of a connection? (just a sanity check
            on my part).


            /Per Jessen, Zürich
          • Wietse Venema
            When Postfix reuses an SMTP connection, it may actually be reused in a different SMTP client process. This maximizes reuse and minimizes the time that a
            Message 5 of 10 , Aug 30, 2008
            • 0 Attachment
              When Postfix reuses an SMTP connection, it may actually be reused
              in a different SMTP client process. This maximizes reuse and
              minimizes the time that a connection sits idle.

              This is different from Sendmail or Exim, where a connection can be
              reused only in the process that creates that connection.

              Postfix doesn't log the "name" of a connection, so you can't how
              it changes hands with connection reuse (this would require logging
              the local TCP port number of reusable connections).

              > Whilst on the subject of connection caching, I assume postfix will (have
              > to) do a RSET between each reuse of a connection? (just a sanity check
              > on my part).

              Of course. See http://www.postfix.org/CONNECTION_CACHE_README.html

              Wietse
            • Per Jessen
              ... All of which I think means that the type of tracking Ralf and I tried to do won t work. /Per Jessen, Zürich
              Message 6 of 10 , Aug 30, 2008
              • 0 Attachment
                Wietse Venema wrote:

                > When Postfix reuses an SMTP connection, it may actually be reused
                > in a different SMTP client process. This maximizes reuse and
                > minimizes the time that a connection sits idle.
                >
                > This is different from Sendmail or Exim, where a connection can be
                > reused only in the process that creates that connection.
                >
                > Postfix doesn't log the "name" of a connection, so you can't how
                > it changes hands with connection reuse (this would require logging
                > the local TCP port number of reusable connections).

                All of which I think means that the type of tracking Ralf and I tried to
                do won't work.


                /Per Jessen, Zürich
              • Wietse Venema
                ... You can sort-of reconstruct this, by looking for records that list the same remote SMTP server: conn_use=n relay=x.x.x[y.y.y.y] conn_use=n+1
                Message 7 of 10 , Aug 30, 2008
                • 0 Attachment
                  Per Jessen:
                  > Wietse Venema wrote:
                  >
                  > > When Postfix reuses an SMTP connection, it may actually be reused
                  > > in a different SMTP client process. This maximizes reuse and
                  > > minimizes the time that a connection sits idle.
                  > >
                  > > This is different from Sendmail or Exim, where a connection can be
                  > > reused only in the process that creates that connection.
                  > >
                  > > Postfix doesn't log the "name" of a connection, so you can't how
                  > > it changes hands with connection reuse (this would require logging
                  > > the local TCP port number of reusable connections).
                  >
                  > All of which I think means that the type of tracking Ralf and I tried to
                  > do won't work.

                  You can sort-of reconstruct this, by looking for records
                  that list the same remote SMTP server:

                  conn_use=n relay=x.x.x[y.y.y.y]
                  conn_use=n+1 relay=x.x.x[y.y.y.y]
                  conn_use=n+2 relay=x.x.x[y.y.y.y]

                  But for real detective work you need the local TCP port number.
                  Every reused connection uses the same remote port (25) and the same
                  local one (local port numbers get reused too, but that tends to
                  have a longer cycle).

                  Wietse
                • Per Jessen
                  ... One more question then - by default the smtp client uses caching - do I need to explicitly enable caching for differently named transports that also use
                  Message 8 of 10 , Aug 30, 2008
                  • 0 Attachment
                    Wietse Venema wrote:

                    >> Whilst on the subject of connection caching, I assume postfix will
                    >> (have
                    >> to) do a RSET between each reuse of a connection? (just a sanity
                    >> check on my part).
                    >
                    > Of course. See http://www.postfix.org/CONNECTION_CACHE_README.html
                    >
                    > Wietse

                    One more question then - by default the smtp client uses caching - do I
                    need to explicitly enable caching for differently named transports that
                    also use the smtp client? I.e. if I had a transport named 'klop', do I
                    need klop_connection_cache_on_demand = yes ?


                    /Per Jessen, Zürich
                  • Wietse Venema
                    Per Jessen: [ Charset UTF-8 unsupported, converting... ] ... All parameters are documented. The queue manager provides there is more mail hints regardless of
                    Message 9 of 10 , Aug 30, 2008
                    • 0 Attachment
                      Per Jessen:
                      [ Charset UTF-8 unsupported, converting... ]
                      > Wietse Venema wrote:
                      >
                      > >> Whilst on the subject of connection caching, I assume postfix will
                      > >> (have
                      > >> to) do a RSET between each reuse of a connection? (just a sanity
                      > >> check on my part).
                      > >
                      > > Of course. See http://www.postfix.org/CONNECTION_CACHE_README.html
                      > >
                      > > Wietse
                      >
                      > One more question then - by default the smtp client uses caching - do I
                      > need to explicitly enable caching for differently named transports that
                      > also use the smtp client? I.e. if I had a transport named 'klop', do I
                      > need klop_connection_cache_on_demand = yes ?

                      All parameters are documented.

                      The queue manager provides "there is more mail" hints regardless
                      of the transport name.

                      All delivery agents except smtp/lmtp ignore these hints, regardless
                      of the transport name.

                      Wietse
                    Your message has been successfully submitted and would be delivered to recipients shortly.