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

Re: Postscreen: bad command startup -- throttling issues

Expand Messages
  • Wietse Venema
    ... Report THE FIRST error. http://www.postfix.org/DEBUG_README.html#logging % egrep (warning|error|fatal|panic): /some/log/file | more Note: the most
    Message 1 of 11 , Feb 12, 2013
    • 0 Attachment
      LDB:
      > On 02/12/2013 07:42 AM, LDB wrote:
      > >
      > >
      > > I have re-installed Postfix (using version 2.8.11 on openSUSE 12.2) and simply
      > > reconfigured without many changes. I am still failing to determine where
      > > postscreen is failing with the following errors:
      > >
      > >
      > > Feb 12 15:29:01 server postfix/master[28061]: warning: process
      > > /usr/lib/postfix/postscreen pid 28085 exit status 1
      > > Feb 12 15:29:01 server postfix/master[28061]: warning:
      > > /usr/lib/postfix/postscreen: bad command startup -- throttling

      Report THE FIRST error.

      http://www.postfix.org/DEBUG_README.html#logging

      % egrep '(warning|error|fatal|panic):' /some/log/file | more

      Note: the most important message is near the BEGINNING of the output.
      Error messages that come later are less useful.

      Wietse
    • LDB
      ... Thank you for the response. I apologize for the delay. The log entries you requested are as follows and since then the postfix service has been restarted
      Message 2 of 11 , Feb 12, 2013
      • 0 Attachment
        On 02/12/2013 08:35 AM, Wietse Venema wrote:
        > egrep '(warning|error|fatal|panic):' /some/log/file | more

        Thank you for the response. I apologize for the delay.

        The log entries you requested are as follows and since then the postfix service
        has been restarted many times:

        Feb 12 03:47:06 key postfix/master[8209]: warning: service smtp: ignoring
        inet_interfaces change
        Feb 12 03:47:06 key postfix/master[8209]: warning: to change inet_interfaces,
        stop and start Postfix
        Feb 12 03:47:06 key postfix/master[8209]: warning: service smtp: ignoring
        inet_interfaces change
        Feb 12 03:47:06 key postfix/master[8209]: warning: to change inet_interfaces,
        stop and start Postfix
        Feb 12 03:47:40 key postfix/master[8209]: warning: process
        /usr/lib/postfix/postscreen pid 8307 exit status 1
        Feb 12 03:47:40 key postfix/master[8209]: warning: /usr/lib/postfix/postscreen:
        bad command startup -- throttling
        Feb 12 03:48:12 key postfix/master[8405]: warning: process
        /usr/lib/postfix/postscreen pid 8434 exit status 1
        Feb 12 03:48:12 key postfix/master[8405]: warning: /usr/lib/postfix/postscreen:
        bad command startup -- throttling
        Feb 12 03:49:13 key postfix/master[8405]: warning: process
        /usr/lib/postfix/postscreen pid 8446 exit status 1
        Feb 12 03:49:13 key postfix/master[8405]: warning: /usr/lib/postfix/postscreen:
        bad command startup -- throttling




        telneting locally or remotely to port 25 yields the following:

        server# telnet example.net 25
        Trying x.x.x.x...
        Connected to example.net.
        Escape character is '^]'.
      • Wietse Venema
        ... You show only WARNING messages. postscreen logs an ERROR mesage before exiting with status 1. Are you using a syslog configuration that logs ERRORS and
        Message 3 of 11 , Feb 12, 2013
        • 0 Attachment
          LDB:
          > On 02/12/2013 08:35 AM, Wietse Venema wrote:
          > > egrep '(warning|error|fatal|panic):' /some/log/file | more
          >
          > Thank you for the response. I apologize for the delay.
          >
          > The log entries you requested are as follows and since then the postfix service
          > has been restarted many times:

          You show only WARNING messages.

          postscreen logs an ERROR mesage before exiting with status 1.

          Are you using a syslog configuration that logs ERRORS and WARNINGS
          to different files?

          Wietse
        • LDB
          ... My /var/log/mail.err file is empty. I am not seeing any other postscreen messages in any of the mail or mail.{info,err,warn} logs. Thanks, LDB
          Message 4 of 11 , Feb 13, 2013
          • 0 Attachment
            On Feb 12, 2013, at 5:05 PM, Wietse Venema <wietse@...> wrote:

            > LDB:
            >> On 02/12/2013 08:35 AM, Wietse Venema wrote:
            >>> egrep '(warning|error|fatal|panic):' /some/log/file | more
            >>
            >> Thank you for the response. I apologize for the delay.
            >>
            >> The log entries you requested are as follows and since then the postfix service
            >> has been restarted many times:
            >
            > You show only WARNING messages.
            >
            > postscreen logs an ERROR mesage before exiting with status 1.
            >
            > Are you using a syslog configuration that logs ERRORS and WARNINGS
            > to different files?
            >
            > Wietse

            My /var/log/mail.err file is empty. I am not seeing any other postscreen messages in any of the mail or mail.{info,err,warn} logs.

            Thanks,

            LDB
          • LDB
            ... I increased the debugging output in master.cf using -D -vvvvv . eb 13 21:23:14 server postfix/postfix-script[364]: stopping the Postfix mail system Feb 13
            Message 5 of 11 , Feb 13, 2013
            • 0 Attachment
              On 2/13/13 8:24 AM, LDB wrote:
              >
              >
              > On Feb 12, 2013, at 5:05 PM, Wietse Venema <wietse@...> wrote:
              >
              >> LDB:
              >>> On 02/12/2013 08:35 AM, Wietse Venema wrote:
              >>>> egrep '(warning|error|fatal|panic):' /some/log/file | more
              >>>
              >>> Thank you for the response. I apologize for the delay.
              >>>
              >>> The log entries you requested are as follows and since then the postfix service
              >>> has been restarted many times:
              >>
              >> You show only WARNING messages.
              >>
              >> postscreen logs an ERROR mesage before exiting with status 1.
              >>
              >> Are you using a syslog configuration that logs ERRORS and WARNINGS
              >> to different files?
              >>
              >> Wietse
              >
              > My /var/log/mail.err file is empty. I am not seeing any other postscreen messages in any of the mail or mail.{info,err,warn} logs.
              >
              > Thanks,
              >
              > LDB
              >

              I increased the debugging output in master.cf using "-D -vvvvv".


              eb 13 21:23:14 server postfix/postfix-script[364]: stopping the Postfix
              mail system
              Feb 13 21:23:14 server postfix/master[29847]: terminating on signal 15
              Feb 13 21:23:14 server postfix/postfix-script[451]: starting the Postfix
              mail system
              Feb 13 21:23:14 server postfix/master[452]: daemon started -- version
              2.8.11, configuration /etc/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              syslog_facility = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: mail
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const mail
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              syslog_facility = mail
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              inet_protocols = ipv4
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: ipv4
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const ipv4
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_directories = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              multi_instance_directories =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_group = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              multi_instance_group =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              multi_instance_name =
              Feb 13 21:23:46 server postfix/postscreen[476]: name_mask: ipv4
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myhostname
              = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: myhostname
              = key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mail_name =
              (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: Postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const Postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: mail_name =
              Postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: syslog_name
              = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              ${multi_instance_name:postfix}${multi_instance_name?$multi_instance_name}
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_name =
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_name =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              ${multi_instance_name:postfix}${multi_instance_name?$multi_instance_name} ->
              postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: syslog_name
              = postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mail_owner
              = postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              setgid_group = maildrop
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: maildrop
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const maildrop
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain,
              mail.$mydomain
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $myhostname,
              localhost.$mydomain, localhost, $mydomain, mail.$mydomain
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myhostname
              = key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              $myhostname, localhost.$mydomain, localhost, $mydomain, mail.$mydomain
              -> key.example.net, localhost.example.net, localhost, example.net,
              mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myorigin =
              $myhostname
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $myhostname
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myhostname
              = key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              $myhostname -> key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: relayhost =
              (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: relayhost =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              daemon_directory = /usr/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: /usr/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              /usr/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              data_directory = /var/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: /var/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              /var/lib/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              command_directory = /usr/sbin
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: /usr/sbin
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const /usr/sbin
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              queue_directory = /var/spool/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              /var/spool/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              /var/spool/postfix
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              process_id_directory = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: pid
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const pid
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              process_id_directory = pid
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              inet_interfaces = $myhostname
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $myhostname
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myhostname
              = key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              $myhostname -> key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              proxy_interfaces = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              proxy_interfaces =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              double_bounce_sender = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: double-bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              double-bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              double_bounce_sender = double-bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              default_privs = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: nobody
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const nobody
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              default_privs = nobody
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              alias_database = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: hash:/etc/aliases
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              hash:/etc/aliases
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              alias_database = hash:/etc/aliases
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              mail_release_date = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: 20120520
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const 20120520
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              mail_release_date = 20120520
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              mail_version = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: 2.8.11
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const 2.8.11
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              mail_version = 2.8.11
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              default_database_type = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: hash
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const hash
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              default_database_type = hash
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              hash_queue_names = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: deferred, defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              deferred, defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              hash_queue_names = deferred, defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              recipient_delimiter = +
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: +
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const +
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              relay_domains = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $mydestination
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain,
              mail.$mydomain
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $myhostname,
              localhost.$mydomain, localhost, $mydomain, mail.$mydomain
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: myhostname
              = key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: key.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: mydomain =
              example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              $mydestination -> key.example.net, localhost.example.net, localhost,
              example.net, mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              relay_domains = key.example.net, localhost.example.net, localhost,
              example.net, mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              fast_flush_domains = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: $relay_domains
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              relay_domains = key.example.net, localhost.example.net, localhost,
              example.net, mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              key.example.net, localhost.example.net, localhost, example.net,
              mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: expand
              $relay_domains -> key.example.net, localhost.example.net, localhost,
              example.net, mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              fast_flush_domains = key.example.net, localhost.example.net, localhost,
              example.net, mail.example.net
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              export_environment = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: TZ
              MAIL_CONFIG LANG
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const TZ
              MAIL_CONFIG LANG
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              export_environment = TZ MAIL_CONFIG LANG
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              import_environment = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: MAIL_CONFIG
              MAIL_DEBUG MAIL_LOGTAG TZ XAUTHORITY DISPLAY LANG=C
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              MAIL_CONFIG MAIL_DEBUG MAIL_LOGTAG TZ XAUTHORITY DISPLAY LANG=C
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              import_environment = MAIL_CONFIG MAIL_DEBUG MAIL_LOGTAG TZ XAUTHORITY
              DISPLAY LANG=C
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              mynetworks_style = subnet
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: subnet
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const subnet
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              debug_peer_list = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              debug_peer_list =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              default_verp_delimiters = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: +=
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const +=
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              default_verp_delimiters = +=
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              verp_delimiter_filter = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: -=+
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const -=+
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              verp_delimiter_filter = -=+
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              parent_domain_matches_subdomains = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              debug_peer_list,fast_flush_domains,mynetworks,permit_mx_backup_networks,qmqpd_authorized_clients,relay_domains,smtpd_access_maps
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              debug_peer_list,fast_flush_domains,mynetworks,permit_mx_backup_networks,qmqpd_authorized_clients,relay_domains,smtpd_access_maps
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              parent_domain_matches_subdomains =
              debug_peer_list,fast_flush_domains,mynetworks,permit_mx_backup_networks,qmqpd_authorized_clients,relay_domains,smtpd_access_maps
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              alternate_config_directories = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              alternate_config_directories =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              bounce_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              bounce_service_name = bounce
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              cleanup_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: cleanup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const cleanup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              cleanup_service_name = cleanup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              defer_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              defer_service_name = defer
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              pickup_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: pickup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const pickup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              pickup_service_name = pickup
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              queue_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: qmgr
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const qmgr
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              queue_service_name = qmgr
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              rewrite_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: rewrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const rewrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              rewrite_service_name = rewrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              showq_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: showq
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const showq
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              showq_service_name = showq
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              error_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: error
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const error
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              error_service_name = error
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              flush_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: flush
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const flush
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              flush_service_name = flush
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              address_verify_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: verify
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const verify
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              address_verify_service_name = verify
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              trace_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: trace
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const trace
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              trace_service_name = trace
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              proxymap_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: proxymap
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const proxymap
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              proxymap_service_name = proxymap
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              proxywrite_service_name = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: proxywrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const proxywrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              proxywrite_service_name = proxywrite
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              internal_mail_filter_classes = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              internal_mail_filter_classes =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              multi_instance_wrapper = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse:
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              multi_instance_wrapper =
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: max_use =
              (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: max_use = 100
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup: dont_remove
              = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update: dont_remove = 0
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              line_length_limit = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              line_length_limit = 2048
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              message_size_limit = 0
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: 0
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const 0
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              hash_queue_depth = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              hash_queue_depth = 1
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              fork_attempts = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              fork_attempts = 5
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              deliver_lock_attempts = (notfound)
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_update:
              deliver_lock_attempts = 20
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              debug_peer_level = 2
              Feb 13 21:23:46 server postfix/postscreen[476]: mac_parse: 2
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_eval: const 2
              Feb 13 21:23:46 server postfix/postscreen[476]: dict_lookup:
              fault_injection_code = (notfound)
              .
              .
              .
              .
              .
              .
              .
              .
              $daemon_directory/$process_name $process_id & sleep 5 ->
              PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin? ddd
              /usr/lib/postfix/postscreen 476 & sleep 5
              Feb 13 21:23:46 server postfix/postscreen[476]: running:
              PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin? ddd
              /usr/lib/postfix/postscreen 476 & sleep 5
              Feb 13 21:23:51 server postfix/postscreen[476]: match_string: mynetworks
              ~? debug_peer_list
              Feb 13 21:23:51 server postfix/postscreen[476]: match_string: mynetworks
              ~? fast_flush_domains
              Feb 13 21:23:51 server postfix/postscreen[476]: match_string: mynetworks
              ~? mynetworks
              Feb 13 21:23:51 server postfix/postscreen[476]: dict_open: calling hash
              open routine
              Feb 13 21:23:51 server postfix/postscreen[476]: Compiled against
              Berkeley DB: 4.8.30?
              Feb 13 21:23:51 server postfix/postscreen[476]: Run-time linked against
              Berkeley DB: 4.8.30?
              Feb 13 21:23:52 server postfix/master[452]: warning: process
              /usr/lib/postfix/postscreen pid 476 exit status 1
              Feb 13 21:23:52 server postfix/master[452]: warning:
              /usr/lib/postfix/postscreen: bad command startup -- throttling
            • Wietse Venema
              ... I did not ask you to do that. postscreen logs the error message and you just need to learn where to find it. Adding more logging just makes the information
              Message 6 of 11 , Feb 13, 2013
              • 0 Attachment
                LDB:
                > >> You show only WARNING messages.
                > >>
                > >> postscreen logs an ERROR mesage before exiting with status 1.
                > >>
                > >> Are you using a syslog configuration that logs ERRORS and WARNINGS
                > >> to different files?
                > >>
                > >> Wietse
                > >
                > > My /var/log/mail.err file is empty. I am not seeing any other postscreen messages in any of the mail or mail.{info,err,warn} logs.
                >
                > I increased the debugging output in master.cf using "-D -vvvvv".

                I did not ask you to do that. postscreen logs the error message
                and you just need to learn where to find it. Adding more logging
                just makes the information harder to find.

                Start with /etc/syslog.conf and examine EVERY FILE listed there.

                Wietse
              • LDB
                ... I agree and I understood. Although, here is the impetus behind my change to produce more verbose logs. Postfix is seemingly logging to the correct
                Message 7 of 11 , Feb 13, 2013
                • 0 Attachment
                  On Feb 13, 2013, at 3:14 PM, Wietse Venema <wietse@...> wrote:

                  > LDB:
                  >>>> You show only WARNING messages.
                  >>>>
                  >>>> postscreen logs an ERROR mesage before exiting with status 1.
                  >>>>
                  >>>> Are you using a syslog configuration that logs ERRORS and WARNINGS
                  >>>> to different files?
                  >>>>
                  >>>> Wietse
                  >>>
                  >>> My /var/log/mail.err file is empty. I am not seeing any other postscreen messages in any of the mail or mail.{info,err,warn} logs.
                  >>
                  >> I increased the debugging output in master.cf using "-D -vvvvv".
                  >
                  > I did not ask you to do that. postscreen logs the error message
                  > and you just need to learn where to find it. Adding more logging
                  > just makes the information harder to find.
                  >
                  > Start with /etc/syslog.conf and examine EVERY FILE listed there.
                  >
                  > Wietse

                  I agree and I understood. Although, here is the impetus behind my change to produce more verbose logs.


                  Postfix is seemingly logging to the correct facility:

                  server:/var/log # postconf -d | grep syslog
                  syslog_facility = mail
                  syslog_name = ${multi_instance_name:postfix}${multi_instance_name?$multi_instance_name}



                  Syslog is seemingly configured properly, as well:

                  server:/var/log # grep mail /etc/rsyslog.conf
                  # email-messages
                  mail.* -/var/log/mail
                  mail.info -/var/log/mail.info
                  mail.warning -/var/log/mail.warn
                  mail.err /var/log/mail.err
                  *.*;mail.none;news.none -/var/log/messages



                  But yet, /var/log/mail.err, remains empty.

                  Once again, I am refraining from changing much of the defaults in Postfix or within the OS.

                  Thank you,

                  LDB
                • Wietse Venema
                  ... I asked you to examine EVERY FILE listed there. Apparently, you don t understand plain English. Maybe someone else has more patience. I am done with this
                  Message 8 of 11 , Feb 13, 2013
                  • 0 Attachment
                    > >> I increased the debugging output in master.cf using "-D -vvvvv".
                    > >
                    > > I did not ask you to do that. postscreen logs the error message
                    > > and you just need to learn where to find it. Adding more logging
                    > > just makes the information harder to find.
                    > >
                    > > Start with /etc/syslog.conf and examine EVERY FILE listed there.

                    > server:/var/log # grep mail /etc/rsyslog.conf

                    I asked you to examine EVERY FILE listed there. Apparently, you
                    don't understand plain English.

                    Maybe someone else has more patience. I am done with this thread.

                    Wietse
                  • Reindl Harald
                    ... and what is in the others? cat /var/log/mail* would have been the minimum i expected as reply and a look in /var/log/messages is also not wrong
                    Message 9 of 11 , Feb 14, 2013
                    • 0 Attachment
                      Am 13.02.2013 22:14, schrieb LDB:
                      > Syslog is seemingly configured properly, as well:
                      >
                      > server:/var/log # grep mail /etc/rsyslog.conf
                      > # email-messages
                      > mail.* -/var/log/mail
                      > mail.info -/var/log/mail.info
                      > mail.warning -/var/log/mail.warn
                      > mail.err /var/log/mail.err
                      > *.*;mail.none;news.none -/var/log/messages
                      >
                      > But yet, /var/log/mail.err, remains empty

                      and what is in the others?

                      "cat /var/log/mail*" would have been the minimum i expected as
                      reply and a look in /var/log/messages is also not wrong
                    Your message has been successfully submitted and would be delivered to recipients shortly.