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

Question about log messages and connection caching

Expand Messages
  • Per Jessen
    I m using postfix 2.5.4. When I read the following in the log: postfix1/smtp[18518]: 4AD0517085: to= , relay=myserver[myipaddr]:25,
    Message 1 of 10 , Aug 30, 2008
      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?
      My problem here is - there is only one recipient and only one 250 OK +
      queueid (from the receiving postfix).
      I'm assuming it could well have been multiple recipients, and certainly
      there should have been four 250 OK responses?
      Or am I just completely and utterly confused?


      /Per Jessen, Zürich
    • 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 2 of 10 , Aug 30, 2008
        * 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 3 of 10 , Aug 30, 2008
          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 4 of 10 , Aug 30, 2008
            * 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 5 of 10 , Aug 30, 2008
              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 6 of 10 , Aug 30, 2008
                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 7 of 10 , Aug 30, 2008
                  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 8 of 10 , Aug 30, 2008
                    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 9 of 10 , Aug 30, 2008
                      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 10 of 10 , Aug 30, 2008
                        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.