ZhangHuangbin wrote:Do you have detailed debug log (after removed from MYNETWORKS)?
Here is from service start:
May 22 07:42:30 mail.domain.tld systemd[1]: Starting iRedAPD (A simple posfix policy server)...
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Starting iRedAPD (version: 2.7, backend: mysql), listening on 127.0.0.1:7777.
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 100): reject_null_sender
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 99): wblist_rdns
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 90): reject_sender_login_mismatch
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 80): greylisting
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 60): throttle
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 50): sql_alias_access_policy
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Loading plugin (priority: 40): amavisd_wblist
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Starting SRS sender rewriting channel, listening on 127.0.0.1:7778.
May 22 07:42:30 mail.domain.tld python2[7892]: iredapd INFO: Starting SRS recipient rewriting channel, listening on 127.0.0.1:7779.
May 22 07:42:30 mail.domain.tld systemd[1]: PID file /run/iredapd.pid not readable (yet?) after start.
May 22 07:42:30 mail.domain.tld systemd[1]: Started iRedAPD (A simple posfix policy server).
Here is are all events at the time of checking this specific address:
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd INFO: [192.168.0.1] RCPT, ping@foreigndomain.tld -> pong@domain.tld, DUNNO [sasl_username=, sender=ping@foreigndomain.tld, client_name=smtp.domain.tld, reverse_client_name=smtp.domain.tld, helo=smtp.domain.tld, encryption_protocol=TLSv1.2, process_time=0.0129s]
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] request=smtpd_access_policy
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] protocol_state=END-OF-MESSAGE
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] protocol_name=ESMTP
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] client_address=192.168.0.1
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] client_name=smtp.domain.tld
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] reverse_client_name=smtp.domain.tld
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] helo_name=smtp.domain.tld
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] sender=ping@foreigndomain.tld
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] recipient=pong@domain.tld
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] recipient_count=1
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] queue_id=B7FE921294E1
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] instance=32f.5ce55ddf.a4570.0
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] size=2023
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] etrn_domain=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] stress=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] sasl_method=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] sasl_username=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] sasl_sender=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] ccert_subject=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] ccert_issuer=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] ccert_fingerprint=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] encryption_protocol=TLSv1.2
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] encryption_cipher=ECDHE-RSA-AES256-GCM-SHA384
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [policy] encryption_keysize=256
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: reject_null_sender (protocol_state != END-OF-MESSAGE)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: wblist_rdns (protocol_state != END-OF-MESSAGE)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: reject_sender_login_mismatch (protocol_state != END-OF-MESSAGE)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: greylisting (protocol_state != END-OF-MESSAGE)
--
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd INFO: [192.168.0.1] sender throttle, ping@foreigndomain.tld -> max_quota (233944/0, period: 86400 seconds, time left: 14 hours, 29 minutes, 51 seconds)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [SQL] Update tracking record(s):
UPDATE throttle_tracking
SET period = 86400,last_time = 1558535647,init_time = 1558501139,cur_msgs = cur_msgs + 1,cur_quota = cur_quota + 2023
WHERE id=10044;
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [OK] Passed all sender throttle settings.
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Check recipient throttling.
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [SQL] query target domain of given alias domain (domain.tld):
SELECT alias_domain.target_domain
FROM alias_domain, domain
WHERE domain.active=1
AND domain.domain=alias_domain.target_domain
AND alias_domain.alias_domain='domain.tld'
LIMIT 1
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [SQL] query result: None
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [SQL] Query throttle setting:
SELECT id, account, priority, period, max_msgs, max_quota, msg_size
FROM throttle
WHERE kind='inbound' AND account IN ('192.168.0.1', '@ip', 'pong@domain.tld', '@domain.tld', '@.', '@.domain.tld', '@.tld', '192.168.0.*', '192.168.*.1')
ORDER BY priority DESC
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: [SQL] Query result: []
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: No recipient throttle setting.
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: <-- Result: DUNNO
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: sql_alias_access_policy (protocol_state != END-OF-MESSAGE)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Skip plugin: amavisd_wblist (protocol_state != END-OF-MESSAGE)
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd DEBUG: Session ended.
May 22 07:34:07 mail.domain.tld python2[19193]: iredapd INFO: [192.168.0.1] END-OF-MESSAGE, ping@foreigndomain.tld -> pong@domain.tld, DUNNO [recipient_count=1, size=2023, process_time=0.0243s]
Here are the events where the sender ping@foreigndomain.tld is exceeding the quote and being throttled:
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd INFO: [192.168.0.1] RCPT, ping@foreigndomain.tld -> pong@domain.tld, DUNNO [sasl_username=, sender=ping@foreigndomain.tld, client_name=smtp.domain.tld, reverse_client_name=smtp.domain.tld, helo=smtp.domain.tld, encryption_protocol=TLSv1.2, process_time=0.0196s]
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] request=smtpd_access_policy
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] protocol_state=END-OF-MESSAGE
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] protocol_name=ESMTP
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] client_address=192.168.0.1
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] client_name=smtp.domain.tld
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] reverse_client_name=smtp.domain.tld
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] helo_name=smtp.domain.tld
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] sender=ping@foreigndomain.tld
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] recipient=pong@domain.tld
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] recipient_count=1
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] queue_id=9B1E020EB512
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] instance=29e1.5ce578d7.8393e.0
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] size=2024
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] etrn_domain=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] stress=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] sasl_method=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] sasl_username=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] sasl_sender=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] ccert_subject=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] ccert_issuer=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] ccert_fingerprint=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] encryption_protocol=TLSv1.2
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] encryption_cipher=ECDHE-RSA-AES256-GCM-SHA384
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [policy] encryption_keysize=256
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: reject_null_sender (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: wblist_rdns (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: reject_sender_login_mismatch (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: greylisting (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: --> Apply plugin: throttle
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Client address (192.168.0.1) is trusted networks (MYNETWORKS).
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Client is sending from trusted network without SMTP AUTH, consider this sender as an internal sender.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Check sender throttling.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] query target domain of given alias domain (foreigndomain.tld):
SELECT alias_domain.target_domain
FROM alias_domain, domain
WHERE domain.active=1
AND domain.domain=alias_domain.target_domain
AND alias_domain.alias_domain='foreigndomain.tld'
LIMIT 1
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] query result: None
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query throttle setting:
SELECT id, account, priority, period, max_msgs, max_quota, msg_size
FROM throttle
WHERE kind='outbound' AND account IN ('192.168.0.1', '@ip', 'ping@foreigndomain.tld', '@foreigndomain.tld', '@.', '@.foreigndomain.tld', '@.tld', '192.168.0.*', '192.168.*.1')
ORDER BY priority DESC
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query result:
[(1L, u'@.', 0, 86400L, 200L, 0L, 0L)]
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: sender throttle setting: msg_size=0 (bytes)/id=1/account=@.; max_msgs=200/id=1/account=@.; max_quota=0 (bytes)/id=1/account=@.;
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query throttle tracking data:
SELECT id, tid, account, cur_msgs, cur_quota, init_time, last_time, last_notify_time
FROM throttle_tracking
WHERE (tid=1 AND account='192.168.0.1') OR (tid=1 AND account='ping@foreigndomain.tld')
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query result:
[(10044L, 1L, u'ping@foreigndomain.tld', 199, 280496L, 1558501139L, 1558542241L, 0L)]
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Tracking IDs: {(1L, u'ping@foreigndomain.tld'): 10044L}
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd INFO: [192.168.0.1] sender throttle, ping@foreigndomain.tld -> msg_size (2024/0, period: 86400 seconds, time left: 12 hours, 34 minutes, 58 seconds)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd INFO: [192.168.0.1] sender throttle, ping@foreigndomain.tld -> max_quota (280496/0, period: 86400 seconds, time left: 12 hours, 34 minutes, 58 seconds)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Update tracking record(s):
UPDATE throttle_tracking
SET period = 86400,last_time = 1558542551,init_time = 1558501139,cur_msgs = cur_msgs + 1,cur_quota = cur_quota + 2024
WHERE id=10044;
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [OK] Passed all sender throttle settings.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Check recipient throttling.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] query target domain of given alias domain (domain.tld):
SELECT alias_domain.target_domain
FROM alias_domain, domain
WHERE domain.active=1
AND domain.domain=alias_domain.target_domain
AND alias_domain.alias_domain='domain.tld'
LIMIT 1
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] query result: None
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query throttle setting:
SELECT id, account, priority, period, max_msgs, max_quota, msg_size
FROM throttle
WHERE kind='inbound' AND account IN ('192.168.0.1', '@ip', 'pong@domain.tld', '@domain.tld', '@.', '@.domain.tld', '@.com', '192.168.0.*', '192.168.*.1')
ORDER BY priority DESC
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: [SQL] Query result:
[]
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: No recipient throttle setting.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: <-- Result: DUNNO
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: sql_alias_access_policy (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Skip plugin: amavisd_wblist (protocol_state != END-OF-MESSAGE)
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd DEBUG: Session ended.
May 22 09:29:11 mail.domain.tld python2[7896]: iredapd INFO: [192.168.0.1] END-OF-MESSAGE, ping@foreigndomain.tld -> pong@domain.tld, DUNNO [recipient_count=1, size=2024, process_time=0.0127s]