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

feature request: one line of output from pipe to add to logging for audit purposes

Expand Messages
  • Maarten Vanraes
    hi, I m using pipe for some delivery transport. the logs tell me something like: status=sent (delivered by ) now my transport stores some parts
    Message 1 of 10 , Jun 4, 2014
      hi,

      I'm using pipe for some delivery transport. the logs tell me something like:

      status=sent (delivered by <transportname>)

      now my transport stores some parts in a database and possibly sends it back
      into postfix... so for audit purposes, it would be nice if the pipe transport
      would get the first output line and put it in the logging:

      status=sent (delivered by <transportname> (stored as 235264) )

      or

      status=sent (delivered by <transportname> (250 2.0.0 queued as F3A365EA) )

      or whatever message is there (which is usable to identify correctly the next
      chain in the link...

      possibly a pipe flag could be set for this, i don't mind either way.

      Regards,

      Maarten
      --
      BA NV
      IT & Security
    • Viktor Dukhovni
      ... You should simply log the requisite message from the executed program. You can use postlog(1) if you like. -- Viktor.
      Message 2 of 10 , Jun 4, 2014
        On Wed, Jun 04, 2014 at 04:04:36PM +0200, Maarten Vanraes wrote:

        > I'm using pipe for some delivery transport. the logs tell me something like:
        >
        > status=sent (delivered by <transportname>)
        >
        > now my transport stores some parts in a database and possibly sends it back
        > into postfix... so for audit purposes, it would be nice if the pipe transport
        > would get the first output line and put it in the logging:
        >
        > status=sent (delivered by <transportname> (stored as 235264) )
        >
        > or
        >
        > status=sent (delivered by <transportname> (250 2.0.0 queued as F3A365EA) )
        >
        > or whatever message is there (which is usable to identify correctly the next
        > chain in the link...

        You should simply log the requisite message from the executed program.
        You can use postlog(1) if you like.

        --
        Viktor.
      • Wietse Venema
        ... The pipe daemon expects a specific reponse format, and that format does not include SMTP reply codes. See pipe(8) manpage. I can see benefit in logging
        Message 3 of 10 , Jun 4, 2014
          Maarten Vanraes:
          > hi,
          >
          > I'm using pipe for some delivery transport. the logs tell me something like:
          >
          > status=sent (delivered by <transportname>)
          >
          > now my transport stores some parts in a database and possibly sends it back
          > into postfix... so for audit purposes, it would be nice if the pipe transport
          > would get the first output line and put it in the logging:
          >
          > status=sent (delivered by <transportname> (stored as 235264) )
          >
          > or
          >
          > status=sent (delivered by <transportname> (250 2.0.0 queued as F3A365EA) )
          >
          > or whatever message is there (which is usable to identify correctly the next
          > chain in the link...
          >
          > possibly a pipe flag could be set for this, i don't mind either way.

          The pipe daemon expects a specific reponse format, and that
          format does not include SMTP reply codes. See pipe(8) manpage.

          I can see benefit in logging downstream status information, but it
          will necessarily have to be limited.

          Wietse
        • Maarten Vanraes
          Op woensdag 4 juni 2014 12:49:29 schreef Wietse Venema: [...] ... It would be helpful, because if you re using pipe, to do anything with email, it would help
          Message 4 of 10 , Jun 5, 2014
            Op woensdag 4 juni 2014 12:49:29 schreef Wietse Venema:
            [...]
            > The pipe daemon expects a specific reponse format, and that
            > format does not include SMTP reply codes. See pipe(8) manpage.
            >
            > I can see benefit in logging downstream status information, but it
            > will necessarily have to be limited.

            It would be helpful, because if you're using pipe, to do anything with email,
            it would help to have in that delivered logline a small piece of text which
            then could be used to identify the mail in the downstream...

            eg: my script outputs as a first line to stdout:

            stored as 363752 and sent to 10.0.0.14 (250 2.0.0 queued as E0B375CA)

            (it stores some data and sometimes sends it back to a postfix)

            if this line is added to the delivered by <transportname> it becomes alot
            easier to trace the exact mail if it needs to be.

            if you don't want this as default, you could specify a new flag for in the
            master.cf file?
            --
            BA NV
            IT & Security
          • Viktor Dukhovni
            ... Just pipe this line to postlog , and include the queue-id of the input message (${queue_id} pipe(8) argument used *before* ${recipient} or similar which
            Message 5 of 10 , Jun 5, 2014
              On Thu, Jun 05, 2014 at 04:04:43PM +0200, Maarten Vanraes wrote:

              > Op woensdag 4 juni 2014 12:49:29 schreef Wietse Venema:
              > [...]
              > > The pipe daemon expects a specific reponse format, and that
              > > format does not include SMTP reply codes. See pipe(8) manpage.
              > >
              > > I can see benefit in logging downstream status information, but it
              > > will necessarily have to be limited.
              >
              > It would be helpful, because if you're using pipe, to do anything with email,
              > it would help to have in that delivered logline a small piece of text which
              > then could be used to identify the mail in the downstream...
              >
              > eg: my script outputs as a first line to stdout:
              >
              > stored as 363752 and sent to 10.0.0.14 (250 2.0.0 queued as E0B375CA)

              Just pipe this line to "postlog", and include the queue-id of the input
              message (${queue_id} pipe(8) argument used *before* ${recipient} or
              similar which expands to multiple arguments and must be last unless
              the transport recipient limit is set to 1).

              --
              Viktor.
            • Maarten Vanraes
              ... that is a possibility, but i don t have 2.11 yet. but, iinm some other transports (not pipe) do have downstream information, so wouldn t it be better to
              Message 6 of 10 , Jun 5, 2014
                Op donderdag 5 juni 2014 14:36:26 schreef Viktor Dukhovni:
                > On Thu, Jun 05, 2014 at 04:04:43PM +0200, Maarten Vanraes wrote:
                > > Op woensdag 4 juni 2014 12:49:29 schreef Wietse Venema:
                > > [...]
                > >
                > > > The pipe daemon expects a specific reponse format, and that
                > > > format does not include SMTP reply codes. See pipe(8) manpage.
                > > >
                > > > I can see benefit in logging downstream status information, but it
                > > > will necessarily have to be limited.
                > >
                > > It would be helpful, because if you're using pipe, to do anything with
                > > email, it would help to have in that delivered logline a small piece of
                > > text which then could be used to identify the mail in the downstream...
                > >
                > > eg: my script outputs as a first line to stdout:
                > >
                > > stored as 363752 and sent to 10.0.0.14 (250 2.0.0 queued as E0B375CA)
                >
                > Just pipe this line to "postlog", and include the queue-id of the input
                > message (${queue_id} pipe(8) argument used *before* ${recipient} or
                > similar which expands to multiple arguments and must be last unless
                > the transport recipient limit is set to 1).

                that is a possibility, but i don't have 2.11 yet.

                but, iinm some other transports (not pipe) do have downstream information, so
                wouldn't it be better to have a similar output?

                Regards,

                Maarten
                --
                BA NV
                IT & Security
              • Viktor Dukhovni
                ... You can parse the queue-id out of the topmost received header prepended by Postfix. ... There is no expectation that the first line of output is
                Message 7 of 10 , Jun 5, 2014
                  On Thu, Jun 05, 2014 at 04:51:56PM +0200, Maarten Vanraes wrote:

                  > > Just pipe this line to "postlog", and include the queue-id of the input
                  > > message (${queue_id} pipe(8) argument used *before* ${recipient} or
                  > > similar which expands to multiple arguments and must be last unless
                  > > the transport recipient limit is set to 1).
                  >
                  > that is a possibility, but i don't have 2.11 yet.

                  You can parse the queue-id out of the topmost received header
                  prepended by Postfix.

                  > but, iinm some other transports (not pipe) do have downstream information, so
                  > wouldn't it be better to have a similar output?

                  There is no expectation that the first line of output is particularly
                  meaningful. This is not a well-defined interface, and scripts
                  might unexpectedly output some text before the intended audit output
                  (necessarily late in the script since you're reporting downstream
                  queue-ids for correlation, ...)

                  Logging it with postlog(1) from the script is far cleaner. Do that.
                  Upgrade to 2.11.1 if that's what it takes.

                  --
                  Viktor.
                • Wietse Venema
                  ... True, however there is precedent where the pipe(8) daemon parses command output. When command output starts with a well-formed enhanced status code, then
                  Message 8 of 10 , Jun 5, 2014
                    Viktor Dukhovni:
                    > > but, some other transports (not pipe) do have downstream information, so
                    > > wouldn't it be better to have a similar output?
                    >
                    > There is no expectation that the first line of output is particularly
                    > meaningful. This is not a well-defined interface, and scripts
                    > might unexpectedly output some text before the intended audit output
                    > (necessarily late in the script since you're reporting downstream
                    > queue-ids for correlation, ...)

                    True, however there is precedent where the pipe(8) daemon parses
                    command output. When command output starts with a well-formed
                    enhanced status code, then this may override a non-zero program
                    exit status code, and text after the enhanced status code is logged
                    and returned in delivery status notifications.

                    For example the following script unconditionally defers delivery,
                    regardless of the non-zero exit status used:

                    #!/bin/sh

                    cat >/dev/null
                    echo 4.0.0 We are doomed!
                    exit 1

                    (4.x.x means defer, anything else means bounce).

                    In that light, capturing some text from successful command execution
                    introduces no new problems.

                    With the following patch, the pipe(8) daemon logs some command
                    output after successful delivery as:

                    dsn=2.0.0, status=sent (delivered via XXX service (YYY))"

                    where XXX is the master.cf service name and YYY is command output.
                    The code is somewhat clumsy because it overwrites text with itself.

                    Wietse

                    20140605

                    Feature: the pipe(8) daemon logs some command output after
                    successful delivery as "dsn=2.0.0, status=sent (delivered
                    via XXX service (YYY))" where XXX is the master.cf service
                    name, and YYY is command output. Files: pipe/command.c,
                    pipe.c.

                    diff --exclude=man --exclude=html --exclude=README_FILES --exclude=.indent.pro --exclude=Makefile.in --exclude=INSTALL -cr /var/tmp/postfix-2.12-20140531/src/global/pipe_command.c ./src/global/pipe_command.c
                    *** /var/tmp/postfix-2.12-20140531/src/global/pipe_command.c Mon Dec 6 09:56:06 2010
                    --- ./src/global/pipe_command.c Thu Jun 5 14:27:06 2014
                    ***************
                    *** 675,680 ****
                    --- 676,682 ----
                    vstring_sprintf_append(why->reason, ": \"%s\"", args.command);
                    return (PIPE_STAT_BOUNCE);
                    } else {
                    + vstring_strcpy(why->reason, log_buf);
                    return (PIPE_STAT_OK);
                    }
                    }
                    diff --exclude=man --exclude=html --exclude=README_FILES --exclude=.indent.pro --exclude=Makefile.in --exclude=INSTALL -cr /var/tmp/postfix-2.12-20140531/src/pipe/pipe.c ./src/pipe/pipe.c
                    *** /var/tmp/postfix-2.12-20140531/src/pipe/pipe.c Thu May 15 11:19:26 2014
                    --- ./src/pipe/pipe.c Thu Jun 5 15:01:48 2014
                    ***************
                    *** 1008,1013 ****
                    --- 1008,1016 ----
                    int status;
                    int result = 0;
                    int n;
                    + char *saved_text;
                    + char *reason;
                    + size_t len_reason;

                    /*
                    * Depending on the result, bounce or defer the message, and mark the
                    ***************
                    *** 1015,1023 ****
                    */
                    switch (command_status) {
                    case PIPE_STAT_OK:
                    dsb_update(why, "2.0.0", (attr->flags & PIPE_OPT_FINAL_DELIVERY) ?
                    "delivered" : "relayed", DSB_SKIP_RMTA, DSB_SKIP_REPLY,
                    ! "delivered via %s service", service);
                    (void) DSN_FROM_DSN_BUF(why);
                    for (n = 0; n < request->rcpt_list.len; n++) {
                    rcpt = request->rcpt_list.info + n;
                    --- 1018,1037 ----
                    */
                    switch (command_status) {
                    case PIPE_STAT_OK:
                    + reason = STR(why->reason);
                    + len_reason = trimblanks(reason, VSTRING_LEN(why->reason)) - reason;
                    + if (len_reason > 100)
                    + len_reason = 100;
                    + if (len_reason > 0)
                    + saved_text =
                    + vstring_export(vstring_sprintf(vstring_alloc(len_reason),
                    + " (%.*s)", (int) len_reason, reason));
                    + else
                    + saved_text = mystrdup(""); /* uses shared R/O storage */
                    dsb_update(why, "2.0.0", (attr->flags & PIPE_OPT_FINAL_DELIVERY) ?
                    "delivered" : "relayed", DSB_SKIP_RMTA, DSB_SKIP_REPLY,
                    ! "delivered via %s service%s", service, saved_text);
                    ! myfree(saved_text);
                    (void) DSN_FROM_DSN_BUF(why);
                    for (n = 0; n < request->rcpt_list.len; n++) {
                    rcpt = request->rcpt_list.info + n;
                    diff --exclude=man --exclude=html --exclude=README_FILES --exclude=.indent.pro --exclude=Makefile.in --exclude=INSTALL -cr /var/tmp/postfix-2.12-20140531/src/tls/tls_server.c ./src/tls/tls_server.c
                    *** /var/tmp/postfix-2.12-20140531/src/tls/tls_server.c Sun Apr 6 19:00:17 2014
                    --- ./src/tls/tls_server.c Tue Jun 3 08:43:10 2014
                    ***************
                    *** 164,169 ****
                    --- 164,178 ----
                    */
                    static const char server_session_id_context[] = "Postfix/TLS";

                    + #if OPENSSL_VERSION_NUMBER >= 0x1000000fL
                    + #define GET_SID(s, v, lptr) ((v) = SSL_SESSION_get_id((s), (lptr)))
                    +
                    + #else /* Older OpenSSL releases */
                    + #define GET_SID(s, v, lptr) \
                    + do { (v) = (s)->session_id; *(lptr) = (s)->session_id_length; } while (0)
                    +
                    + #endif /* OPENSSL_VERSION_NUMBER */
                    +
                    /* get_server_session_cb - callback to retrieve session from server cache */

                    static SSL_SESSION *get_server_session_cb(SSL *ssl, unsigned char *session_id,
                    ***************
                    *** 221,234 ****
                    {
                    VSTRING *cache_id;
                    SSL_SESSION *session = SSL_get_session(TLScontext->con);

                    SSL_CTX_remove_session(ctx, session);

                    if (TLScontext->cache_type == 0)
                    return;

                    ! GEN_CACHE_ID(cache_id, session->session_id, session->session_id_length,
                    ! TLScontext->serverid);

                    if (TLScontext->log_mask & TLS_LOG_CACHE)
                    msg_info("%s: remove session %s from %s cache", TLScontext->namaddr,
                    --- 230,245 ----
                    {
                    VSTRING *cache_id;
                    SSL_SESSION *session = SSL_get_session(TLScontext->con);
                    + const unsigned char *sid;
                    + unsigned int sid_length;

                    SSL_CTX_remove_session(ctx, session);

                    if (TLScontext->cache_type == 0)
                    return;

                    ! GET_SID(session, sid, &sid_length);
                    ! GEN_CACHE_ID(cache_id, sid, sid_length, TLScontext->serverid);

                    if (TLScontext->log_mask & TLS_LOG_CACHE)
                    msg_info("%s: remove session %s from %s cache", TLScontext->namaddr,
                    ***************
                    *** 246,257 ****
                    VSTRING *cache_id;
                    TLS_SESS_STATE *TLScontext;
                    VSTRING *session_data;

                    if ((TLScontext = SSL_get_ex_data(ssl, TLScontext_index)) == 0)
                    msg_panic("%s: null TLScontext in new session callback", myname);

                    ! GEN_CACHE_ID(cache_id, session->session_id, session->session_id_length,
                    ! TLScontext->serverid);

                    if (TLScontext->log_mask & TLS_LOG_CACHE)
                    msg_info("%s: save session %s to %s cache", TLScontext->namaddr,
                    --- 257,270 ----
                    VSTRING *cache_id;
                    TLS_SESS_STATE *TLScontext;
                    VSTRING *session_data;
                    + const unsigned char *sid;
                    + unsigned int sid_length;

                    if ((TLScontext = SSL_get_ex_data(ssl, TLScontext_index)) == 0)
                    msg_panic("%s: null TLScontext in new session callback", myname);

                    ! GET_SID(session, sid, &sid_length);
                    ! GEN_CACHE_ID(cache_id, sid, sid_length, TLScontext->serverid);

                    if (TLScontext->log_mask & TLS_LOG_CACHE)
                    msg_info("%s: save session %s to %s cache", TLScontext->namaddr,
                  • Andreas Schulze
                    ... Hello Wietse, I wonder about changes in tls_server.c !? Andreas
                    Message 9 of 10 , Jun 5, 2014
                      Wietse Venema:
                      > With the following patch, the pipe(8) daemon logs some command
                      > output after successful delivery as:
                      ...

                      > --- ./src/global/pipe_command.c Thu Jun 5 14:27:06 2014
                      > --- ./src/pipe/pipe.c Thu Jun 5 15:01:48 2014
                      > --- ./src/tls/tls_server.c Tue Jun 3 08:43:10 2014

                      Hello Wietse,

                      I wonder about changes in tls_server.c !?

                      Andreas
                    • Wietse Venema
                      ... That part does not belong there. ietse
                      Message 10 of 10 , Jun 5, 2014
                        Andreas Schulze:
                        > Wietse Venema:
                        > > With the following patch, the pipe(8) daemon logs some command
                        > > output after successful delivery as:
                        > ...
                        >
                        > > --- ./src/global/pipe_command.c Thu Jun 5 14:27:06 2014
                        > > --- ./src/pipe/pipe.c Thu Jun 5 15:01:48 2014
                        > > --- ./src/tls/tls_server.c Tue Jun 3 08:43:10 2014
                        >
                        > Hello Wietse,
                        >
                        > I wonder about changes in tls_server.c !?

                        That part does not belong there.

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