Timeouts

[robinwit]

I'm truing to use the milter so I can add dmarc + bimi to my postfix setup.
The processes are hitting fatal errors and complaining about timeouts, but I am unsure what is wrong.

Postfix config:

milter_default_action = accept
milter_protocol = 6
smtpd_milters = inet:localhost:12345
non_smtpd_milters = $smtpd_milters

/etc/authentication_milter.json:

{
   "addheader_timeout" : 30,
   "authserv_id" : "",
   "cache_dir" : "/var/cache/authentication_milter",
   "cache_dns_timeouts" : 1,
   "check_for_dequeue" : 60,
   "command_timeout" : 30,
   "connect_timeout" : 30,
   "connection" : "inet:12345@localhost",
   "content_timeout" : 300,
   "debug" : 0,
   "dequeue_timeout" : 300,
   "dns_retry" : 2,
   "dns_timeout" : 10,
   "dryrun" : 0,
   "error_log" : "/var/log/authentication_milter.err",
   "extended_log" : 1,
   "handlers" : {
      "ARC" : {
         "arcseal_algorithm" : "rsa-sha256",
         "arcseal_domain" : null,
         "arcseal_headers" : null,
         "arcseal_key" : null,
         "arcseal_keyfile" : null,
         "arcseal_selector" : null,
         "hide_none" : 0,
         "no_strict" : 0,
         "rbl_whitelist" : "",
         "trusted_domains" : []
      },
      "AbusixDataFeed" : {
         "feed_dest" : "server:port",
         "feed_key" : "this_is_a_secret",
         "feed_name" : "name_of_feed",
         "listening_port" : "25"
      },
      "AddID" : {},
      "AlignedFrom" : {},
      "Auth" : {},
      "BIMI" : {
         "bimi_options" : {},
         "rbl_allowlist" : "",
         "rbl_blocklist" : "",
         "rbl_no_evidence_allowlist" : ""
      },
      "Blocker" : {
         "blocker_configs" : [
            "/tmpfs/authmilter-blocker.toml"
         ]
      },
      "DKIM" : {
         "adsp_hide_none" : 0,
         "check_adsp" : 1,
         "extra_properties" : 0,
         "hide_domainkeys" : 0,
         "hide_none" : 0,
         "no_strict" : 0,
         "show_default_adsp" : 0
      },
      "DMARC" : {
         "arc_before_list" : 0,
         "config_file" : "/etc/mail-dmarc.ini",
         "detect_list_id" : 1,
         "hard_reject" : 0,
         "hide_none" : 0,
         "hide_report_to" : 0,
         "no_list_reject" : 1,
         "no_list_reject_disposition" : "none",
         "no_reject_disposition" : "quarantine",
         "no_report" : 0,
         "policy_rbl_lookup" : {},
         "quarantine_on_multifrom" : 20,
         "reject_on_multifrom" : 30,
         "report_skip_to" : [
            "my_report_from_address@example.com"
         ],
         "report_suppression_email_list" : "rbl.example.com",
         "report_suppression_list" : "rbl.example.com",
         "skip_on_multifrom" : 10,
         "strict_multifrom" : 0,
         "use_arc" : 1,
         "whitelisted" : []
      },
      "IPRev" : {},
      "LocalIP" : {},
      "Logger" : {
         "connect" : 0,
         "envfrom" : 0,
         "envrcpt" : 0,
         "header" : [
            "from",
            "to",
            "message-id"
         ],
         "helo" : 0
      },
      "PTR" : {},
      "RBLDNS" : {
         "rbls" : {
            "list1" : {
               "add_authresults" : 1,
               "add_header" : "X-List1",
               "base_url" : "list1.example.com",
               "default_state" : "clean",
               "states" : {
                  "*" : "baz",
                  "127.0.0.2" : "foo",
                  "127.0.0.3" : "bar"
               }
            },
            "list2" : {
               "add_header" : "X-List2",
               "base_url" : "list2.example.com",
               "default_state" : "clean",
               "states" : {
                  "*" : "baz",
                  "127.0.0.2" : "foo",
                  "127.0.0.3" : "bar"
               }
            }
         }
      },
      "ReturnOK" : {},
      "SPF" : {
         "best_guess" : 0,
         "hide_none" : 0,
         "hide_received-spf_header" : 0,
         "spfu_detection" : 0
      },
      "Sanitize" : {
         "extra_auth_results_types" : [
            "X-Authentication-Results"
         ],
         "hosts_to_remove" : [
            "example.com",
            "example.net"
         ],
         "remove_headers" : "yes"
      },
      "SenderID" : {
         "hide_none" : 1
      },
      "Size" : {},
      "TLS" : {},
      "TestTimeout" : {},
      "TrustedIP" : {
         "trusted_ip_list" : []
      },
      "XGoogleDKIM" : {
         "hide_none" : 0
      }
   },
   "ip_map" : {},
   "legacy_log" : 0,
   "lib_dir" : "/var/lib/authentication_milter",
   "listen_backlog" : 20,
   "lock_file" : "",
   "logtoerr" : 0,
   "max_children" : 200,
   "max_requests_per_child" : 200,
   "max_spare_children" : 20,
   "milter_quarantine" : "0",
   "min_children" : 20,
   "min_spare_children" : 10,
   "protocol" : "milter",
   "runas" : "nobody",
   "rungroup" : "nogroup",
   "spool_dir" : "/var/spool/",
   "tempfail_on_error" : "1",
   "tempfail_on_error_authenticated" : "0",
   "tempfail_on_error_local" : "0",
   "tempfail_on_error_trusted" : "0",
   "umask" : "0000"
}

Logs:

Mar 21 12:45:54 mail authentication_milter[503643]: NOQUEUE.C321CA7C0A7: ERROR: Connect callback error Timeout - Connect callback timeout
Mar 21 12:45:54 mail authentication_milter[503643]: NOQUEUE.C321CA7C0A7: ERROR: TempFail set
Mar 21 12:45:54 mail authentication_milter[503643]: NOQUEUE.C321CA7C0A7: ERROR: Close error Timeout - Close callback timeout
Mar 21 12:45:54 mail authentication_milter[503643]: NOQUEUE.C321CA7C0A7: ERROR: TempFail set
Mar 21 12:45:54 mail authentication_milter[503643]: Child process 503643 shutting down due to fatal error: exit_on_close requested - Exit on close requested<LF>Connect callback error Timeout - Connect callback timeout<LF>Close error Timeout - Close callback timeout
Mar 21 12:46:02 mail authentication_milter[503644]: NOQUEUE.F02AB3BF449: ERROR: Connect callback error Timeout - Connect callback timeout
Mar 21 12:46:02 mail authentication_milter[503644]: NOQUEUE.F02AB3BF449: ERROR: TempFail set
Mar 21 12:46:02 mail authentication_milter[503644]: NOQUEUE.F02AB3BF449: ERROR: Close error Timeout - Close callback timeout
Mar 21 12:46:02 mail authentication_milter[503644]: NOQUEUE.F02AB3BF449: ERROR: TempFail set
Mar 21 12:46:02 mail authentication_milter[503644]: Child process 503644 shutting down due to fatal error: exit_on_close requested - Exit on close requested<LF>Connect callback error Timeout - Connect callback timeout<LF>Close error Timeout - Close callback timeout
Mar 21 12:46:07 mail authentication_milter[503645]: NOQUEUE.4E89973FD17: ERROR: Connect callback error Timeout - Connect callback timeout
Mar 21 12:46:07 mail authentication_milter[503645]: NOQUEUE.4E89973FD17: ERROR: TempFail set
Mar 21 12:46:07 mail authentication_milter[503645]: NOQUEUE.4E89973FD17: ERROR: Close error Timeout - Close callback timeout
Mar 21 12:46:07 mail authentication_milter[503645]: NOQUEUE.4E89973FD17: ERROR: TempFail set
Mar 21 12:46:07 mail authentication_milter[503645]: Child process 503645 shutting down due to fatal error: exit_on_close requested - Exit on close requested<LF>Connect callback error Timeout - Connect callback timeout<LF>Close error Timeout - Close callback timeout

Fri Mar 21 12:45:54 2025 authentication_milter[503643] Child exiting
exit_on_close requested - Exit on close requested
Connect callback error Timeout - Connect callback timeout
Close error Timeout - Close callback timeout
	...propagated at /usr/local/share/perl/5.34.0/Mail/Milter/Authentication.pm line 880.
Fri Mar 21 12:46:00 2025 authentication_milter[503644] Warning: print() on closed filehandle $outf at /usr/local/share/perl/5.34.0/Mail/Milter/Authentication/Handler/Blocker.pm line 34.
Fri Mar 21 12:46:02 2025 authentication_milter[503644] Child exiting
exit_on_close requested - Exit on close requested
Connect callback error Timeout - Connect callback timeout
Close error Timeout - Close callback timeout
	...propagated at /usr/local/share/perl/5.34.0/Mail/Milter/Authentication.pm line 880.
Fri Mar 21 12:46:05 2025 authentication_milter[503645] Warning: print() on closed filehandle $outf at /usr/local/share/perl/5.34.0/Mail/Milter/Authentication/Handler/Blocker.pm line 34.
Fri Mar 21 12:46:07 2025 authentication_milter[503645] Child exiting
exit_on_close requested - Exit on close requested
Connect callback error Timeout - Connect callback timeout
Close error Timeout - Close callback timeout
	...propagated at /usr/local/share/perl/5.34.0/Mail/Milter/Authentication.pm line 880.

[notbrokenjemma]

there is not a lot to go on there, can you turn debug on in the config

[dwbotsch]

I'm also seeing timeouts on a fresh compile under RHEL8...

a couple of excerpts from the debug=1 logs:

Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: EnvFrom Sanitize
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: EnvFrom SenderID
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: EnvFrom Size
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: EnvFrom TLS
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: EncryptedAs: TLSv1.3, TLS_AES_256_GCM_SHA384, 256 bits
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: EnvFrom TestTimeout
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: Env From error Timeout - EnvFrom callback timeout
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: TempFail set

.....

Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: Timeout set: Type: content, Section: 300000000, Effective: 300000000
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: Timeout set: 300000000
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header ARC
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header AlignedFrom
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header DKIM
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header DMARC
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header Logger
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header ReturnOK
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header SPF
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header Sanitize
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header SenderID
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header Size
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header TLS
Jan 7 13:51:16 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Header TestTimeout
Jan 7 13:51:17 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: Header error Timeout - Header callback timeout
Jan 7 13:51:17 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: TempFail set

...

Jan 7 13:52:08 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: CALLBACK: Body TestTimeout
Jan 7 13:52:09 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: Body error Timeout - Body callback timeout
Jan 7 13:52:09 package authentication_milter[584558]: 4dmcZD3Tq9zxvg: ERROR: TempFail set

at first glance, those timeouts (and others) seem to be happening in about 1 second...

and the /var/log/authentication_milter.err shows a lot of errors like:
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
Header error Timeout - Header callback timeout
EOH error Timeout - EOH callback timeout
Body error Timeout - Body callback timeout
EOM error Timeout - EOM callback timeout
Abort error Timeout - Abord callback timeout
Abort error Timeout - Abord callback timeout
Close error Timeout - Close callback timeout
...propagated at /opt/fastmail/lib/perl5/Mail/Milter/Authentication.pm line 880.

though it doesn't timestamp its log entries, which makes it impossibel to correlate with the maillog

Thanks