Hi postfix-users!
We’ve recently encountered an issue where postfix lookup does not find an entry in the hash table while postmap is running. Here’s some logs for a few emails for u...@example.com before/during/after postmap: Oct 3 18:08:07 mx2 postfix/smtpd[3195]: CFEDF299414: client= smtp1-1.example.net[1.1.1.251] Oct 3 18:08:07 mx2 postfix/cleanup[3286]: CFEDF299414: message-id=< i8lliogak3pzixnfr7ekherxulictfxk9uiwibat...@example.net> Oct 3 18:08:07 mx2 postfix/qmgr[23772]: CFEDF299414: from=< donotre...@example.net>, size=3300, nrcpt=1 (queue active) Oct 3 18:08:08 mx2 postfix/smtpd[22419]: 33CEE299417: client=localhost.localdomain[127.0.0.1], orig_queue_id=CFEDF299414, orig_client=smtp1-1.example.net[1.1.1.251] Oct 3 18:08:08 mx2 postfix/smtp[3330]: CFEDF299414: to=<u...@example.org>, orig_to=<u...@example.com>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=9, delay=0.37, delays=0.14/0/0/0.22, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 33CEE299417) Oct 3 18:08:08 mx2 postfix/qmgr[23772]: CFEDF299414: removed Oct 3 18:08:08 mx2 postfix/smtpd[22419]: 33CEE299417: client=localhost.localdomain[127.0.0.1], orig_queue_id=CFEDF299414, orig_client=smtp1-1.example.net[1.1.1.251] Oct 3 18:08:08 mx2 postfix/cleanup[3277]: 33CEE299417: message-id=< i8lliogak3pzixnfr7ekherxulictfxk9uiwibat...@example.net> Oct 3 18:08:08 mx2 postfix/qmgr[23772]: 33CEE299417: from=< donotre...@example.net>, size=4955, nrcpt=1 (queue active) Oct 3 18:08:08 mx2 postfix/smtp[29103]: 33CEE299417: to=<u...@example.org>, relay=ASPMX.L.GOOGLE.com[142.250.102.27]:25, delay=0.31, delays=0/0/0.04/0.27, dsn=2.0.0, status=sent (250 2.0.0 OK 1727978888 4fb4d7f45d1cf-5c8ca4b787csi1174628a12.595 - gsmtp) Oct 3 18:08:08 mx2 postfix/qmgr[23772]: 33CEE299417: removed Then a postmap happens at around 18:10:04, and at the same time another email comes in: Oct 3 18:10:04 mx2 postfix/smtpd[7613]: connect from smtp3-4.example.net [1.1.2.228] Oct 3 18:10:04 mx2 postfix/smtpd[7613]: Anonymous TLS connection established from smtp3-4.example.net[1.1.2.228]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) Oct 3 18:10:05 mx2 postfix/smtpd[7613]: NOQUEUE: reject: RCPT from smtp3-4.example.net[1.1.2.228]: 550 5.1.1 <u...@example.com>: Recipient address rejected: User unknown in local recipient table; from=< donotre...@example.net> to=<u...@example.com> proto=ESMTP helo=< smtp3-4.example.net> Oct 3 18:10:05 mx2 postfix/smtpd[7613]: disconnect from smtp3-4.example.net[1.1.2.228] ehlo=2 starttls=1 mail=1 rcpt=0/1 data=0/1 rset=1 quit=1 commands=6/8 And half a minute later a new email comes in successfully: Oct 3 18:10:36 mx2 postfix/smtpd[8274]: D6062299414: client= smtp3-2.example.net[1.1.2.238] Oct 3 18:10:37 mx2 postfix/cleanup[8261]: D6062299414: message-id=< sxstsgdwbxloozcaxc21hvnmmbkm8xizevnalv5r...@example.net> Oct 3 18:10:37 mx2 postfix/qmgr[23772]: D6062299414: from=< donotre...@example.net>, size=3188, nrcpt=1 (queue active) Oct 3 18:10:37 mx2 postfix/smtpd[8264]: 41F82299415: client=localhost.localdomain[127.0.0.1], orig_queue_id=D6062299414, orig_client=smtp3-2.example.net[1.1.2.238] Oct 3 18:10:37 mx2 postfix/smtp[3288]: D6062299414: to=<u...@example.org>, orig_to=<u...@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.4, delays=0.17/0/0/0.22, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 41F82299415) Oct 3 18:10:37 mx2 postfix/qmgr[23772]: D6062299414: removed Oct 3 18:10:37 mx2 postfix/smtpd[8264]: 41F82299415: client=localhost.localdomain[127.0.0.1], orig_queue_id=D6062299414, orig_client=smtp3-2.example.net[1.1.2.238] Oct 3 18:10:37 mx2 postfix/cleanup[8261]: 41F82299415: message-id=< sxstsgdwbxloozcaxc21hvnmmbkm8xizevnalv5r...@example.net> Oct 3 18:10:37 mx2 postfix/qmgr[23772]: 41F82299415: from=< donotre...@example.net>, size=4843, nrcpt=1 (queue active) Oct 3 18:10:37 mx2 postfix/smtp[31364]: 41F82299415: to=<u...@example.org>, relay=ASPMX.L.GOOGLE.com[142.250.102.27]:25, delay=0.36, delays=0/0/0.03/0.32, dsn=2.0.0, status=sent (250 2.0.0 OK 1727979037 4fb4d7f45d1cf-5c8ca4ddd24si1187636a12.683 - gsmtp) Oct 3 18:10:37 mx2 postfix/qmgr[23772]: 41F82299415: removed There's also a lot of "table hash:/etc/postfix/example-virtual(0,lock|fold_fix|utf8_request) has changed -- restarting" messages around that time (starting at 18:10:04) from cleanup/smtpd/trivial-rewrite and etc. The smtpd[7613] sees the change to file after it rejects the email - the rejection was at 18:10:05, and it sees the file change at 18:10:06: Oct 3 18:10:06 mx2 postfix/smtpd[7613]: table hash:/etc/postfix/example-virtual(0,lock|fold_fix|utf8_request) has changed -- restarting In this situation the changes to example-virtual were removing some entries not related to u...@example.com. The postamp that runs is a simple /usr/sbin/postmap /etc/postfix/example-virtual, the relevant config lines are: virtual_alias_maps = hash:/etc/postfix/virtual hash:/etc/postfix/example-virtual hash:/etc/postfix/example2-virtual hash:/etc/postfix/example3-virtual hash:/etc/postfix/example4-aliases Is this a known issue and how can it be mitigated? Thanks, Alex
_______________________________________________ Postfix-users mailing list -- postfix-users@postfix.org To unsubscribe send an email to postfix-users-le...@postfix.org
