Hello,
we have 2 PMGs in a cluster in use.
Both with the following configuration:
2 CPU cores (virtual)
16 GB RAM
Avg. load between 0,14 and 0,18
40 GB hard disk
Host system: VMware
Version: pmg-api/6.4-3/225ecb80 (running kernel: 5.4.106-1-pve)
Since March 18 we see an avg. Mail Processing time higher than 8 seconds. There are no special events in the log on or around this day.
To me it looks like this behavior only happens with incoming mails and the problem occures in the pmg-smtp-filter:
These are only examples. We see this high delay with every incoming mail.
I tried many things but I did not find any articels about troubleshooting the smtp filter daemon, maybe somebody has an idea or a point at which we can start again.
Best regards,
Jan
we have 2 PMGs in a cluster in use.
Both with the following configuration:
2 CPU cores (virtual)
16 GB RAM
Avg. load between 0,14 and 0,18
40 GB hard disk
Host system: VMware
Version: pmg-api/6.4-3/225ecb80 (running kernel: 5.4.106-1-pve)
Since March 18 we see an avg. Mail Processing time higher than 8 seconds. There are no special events in the log on or around this day.
To me it looks like this behavior only happens with incoming mails and the problem occures in the pmg-smtp-filter:
Code:
Apr 21 12:12:34 pmg-pub-01 postfix/smtpd[1246]: connect from **removed**
Apr 21 12:12:34 pmg-pub-01 postfix/smtpd[1246]: Anonymous TLS connection established from **removed**:
TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
Apr 21 12:12:40 pmg-pub-01 postfix/smtpd[1246]: 9C85E61D6F: client=**removed**
Apr 21 12:12:40 pmg-pub-01 postfix/cleanup[31757]: 9C85E61D6F: message-id=<**removed**>
Apr 21 12:12:40 pmg-pub-01 postfix/smtpd[1246]: disconnect from **removed** ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Apr 21 12:12:40 pmg-pub-01 postfix/qmgr[17101]: 9C85E61D6F: from=<**removed**>, size=5256, nrcpt=1 (queue active)
Apr 21 12:12:40 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: new mail message-id=<**removed**>#012
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: SA score=0/5 time=15.023 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(0.324),BAYES_00(-1.9),DKIM_INVALID(0.1),DKIM_SIGNED(0.1),HTML_MESSAGE(0.001),KAM_DMARC_STATUS(0.01),SPF_PASS(-0.001),T_SPF_HELO_TEMPERROR(0.01)
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: connect from localhost.localdomain[127.0.0.1]
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: B9E4C61E01: client=localhost.localdomain[127.0.0.1], orig_client=**removed**
Apr 21 12:12:55 pmg-pub-01 postfix/cleanup[28769]: B9E4C61E01: message-id=**removed**>
Apr 21 12:12:55 pmg-pub-01 postfix/qmgr[17101]: B9E4C61E01: from=<**removed**>, size=6131, nrcpt=1 (queue active)
Apr 21 12:12:55 pmg-pub-01 postfix/smtpd[32057]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: accept mail to <**removed**> (B9E4C61E01) (rule: Whitelist)
Apr 21 12:12:55 pmg-pub-01 pmg-smtp-filter[1977]: 61D70608016B8A4067: processing time: 15.095 seconds (15.023, 0.041, 0)
Apr 21 12:12:55 pmg-pub-01 postfix/lmtp[27677]: 9C85E61D6F: to=<**removed**>, relay=127.0.0.1[127.0.0.1]:10024, delay=21, delays=5.7/0/0/15, dsn=2.5.0, status=sent (250 2.5.0 OK (61D70608016B8A4067))
Apr 21 12:12:55 pmg-pub-01 postfix/qmgr[17101]: 9C85E61D6F: removed
Apr 21 12:13:21 pmg-pub-01 postfix/smtp[32501]: B9E4C61E01: to=<**removed**>, relay=**removed**:25, delay=25, delays=0/0/25/0.26, dsn=2.6.0, status=sent (250 2.6.0 <**removed**>
InternalId=105918188486884, Hostname=**removed** 7424 bytes in 0.246, 29.383 KB/sec Queued mail for delivery)
Apr 21 12:13:21 pmg-pub-01 postfix/qmgr[17101]: B9E4C61E01: removed
Code:
Apr 21 13:46:28 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: new mail message-id=<**removed**>
Apr 21 13:46:46 pmg-pub-01 pmg-smtp-filter[25420]: 2021/04/21-13:46:46 CONNECT TCP Peer: "[127.0.0.1]:34522" Local: "[127.0.0.1]:10024"
Apr 21 13:46:46 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: new mail message-id=<**removed**>
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: SA score=0/5 time=20.497 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(0.304),BAYES_00(-1.9),DKIM_INVALID(0.1)
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: accept mail to <**removed**> (5BD342BFEF) (rule: default-accept)
Apr 21 13:46:49 pmg-pub-01 pmg-smtp-filter[27911]: 2C01760802CB4C103D: processing time: 20.629 seconds (20.497, 0.054, 0)
Apr 21 13:47:00 pmg-pub-01 pmg-smtp-filter[24766]: 2021/04/21-13:47:00 CONNECT TCP Peer: "[127.0.0.1]:34536" Local: "[127.0.0.1]:10024"
Apr 21 13:47:00 pmg-pub-01 pmg-smtp-filter[24766]: 2C02260802CD4B6D61: new mail message-id=<**removed**>
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: SA score=0/5 time=17.410 bayes=0.00 autolearn=no autolearn_force=no hits=BAYES_00(-1.9),DKIM_INVALID(0.1),DKIM_SIGNE
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: accept mail to <**removed**> (06D392BFFC) (rule: default-accept)
Apr 21 13:47:04 pmg-pub-01 pmg-smtp-filter[25420]: 2BFCA60802CC6813F7: processing time: 17.503 seconds (17.41, 0.061, 0)These are only examples. We see this high delay with every incoming mail.
Code:
sudo pmgperf
# First node:
CPU BOGOMIPS: 9577.50
REGEX/SECOND: 2917935
HD SIZE: 40.00 GB (rpool/ROOT/pmg-1)
FSYNCS/SECOND: 3023.25
DNS EXT: 361.67 ms
DNS INT: 338.58 ms (**removed**)
# Second node:
CPU BOGOMIPS: 9577.50
REGEX/SECOND: 2671338
HD SIZE: 40.00 GB (rpool/ROOT/pmg-1)
FSYNCS/SECOND: 2756.89
DNS EXT: 367.46 ms
DNS INT: 339.18 ms (**removed**)I tried many things but I did not find any articels about troubleshooting the smtp filter daemon, maybe somebody has an idea or a point at which we can start again.
Best regards,
Jan
Last edited:
