I found the "-T" (trace) flag to smtpd(8), and it gives me this, which AFAICT
confirms my suspicions:
[...]
rule #2 matched: match from src allowed-hosts for any => translate
lookup: lookup "[email protected]" as ALIAS in table
static:translations -> 0
lookup: lookup "athompso" as ALIAS in table static:translations -> 0
lookup: lookup "@athompso.net" as ALIAS in table static:translations -> 0
lookup: lookup "@" as ALIAS in table static:translations -> 0
expand: lka_expand: no aliases for virtual
mproc: lka -> pony : 53 IMSG_SMTP_EXPAND_RCPT
expand: 0x154201b89018: clearing expand tree
imsg: pony <- lka: IMSG_SMTP_EXPAND_RCPT (len=53)
smtp: 0x1127a72e6000: >>> 524 5.2.4 Mailing list expansion problem
[...]
complete output attached below, I've changed to @old.athompso.net and
@new.athompso.net during testing since the last email.
On the sending side, from another host (listed in <allowed-hosts>), I'm running:
swaks --to [email protected] --from [email protected]
--server XXXX
which faithfully reports the 5.2.4 error.
I'm slightly disappointed, I still like OpenSMTPd's concise configuration
syntax. Postfix could still rewrite source addresses last time I checked, I
hope it's still there - I do NOT want to run sendmail, thank you very much.
-Adam
Smtpd(8) trace output including invocation:
===from here to end of message===
bhs# smtpd -d -T all -v -d
debug: init ssl-tree
debug: init ca-tree
debug: init ssl-tree
debug: using "fs" queue backend
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
info: OpenSMTPD 6.4.0 starting
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ca-tree
debug: init ca-tree
debug: init ca-tree
debug: init ca-tree
debug: init ca-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ssl-tree
debug: init ca-tree
debug: using "fs" queue backend
debug: using "fs" queue backend
debug: using "fs" queue backend
debug: using "fs" queue backend
debug: using "fs" queue backend
debug: init ssl-tree
debug: using "ramqueue" scheduler backend
debug: using "ramqueue" scheduler backend
debug: using "ramqueue" scheduler backend
debug: using "ramqueue" scheduler backend
debug: using "ramqueue" scheduler backend
debug: using "fs" queue backend
debug: using "ram" stat backend
setup_peer: klondike -> control[63932] fd=4
setup_peer: klondike -> pony express[40666] fd=5
setup_done: ca[35575] done
debug: using "ram" stat backend
setup_peer: control -> klondike[35575] fd=4
setup_peer: control -> lookup[49698] fd=5
setup_peer: control -> pony express[40666] fd=6
setup_peer: control -> queue[21502] fd=7
setup_peer: control -> scheduler[14152] fd=8
setup_done: control[63932] done
debug: using "ram" stat backend
setup_peer: lookup -> control[63932] fd=4
setup_peer: lookup -> pony express[40666] fd=5
setup_peer: lookup -> queue[21502] fd=6
setup_done: lka[49698] done
debug: using "ram" stat backend
setup_peer: pony express -> control[63932] fd=4
setup_peer: pony express -> klondike[35575] fd=5
setup_peer: pony express -> lookup[49698] fd=6
setup_peer: pony express -> queue[21502] fd=7
setup_done: pony[40666] done
debug: using "ram" stat backend
setup_peer: queue -> control[63932] fd=4
setup_peer: queue -> pony express[40666] fd=5
setup_peer: queue -> lookup[49698] fd=6
setup_peer: queue -> scheduler[14152] fd=7
setup_done: queue[21502] done
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
setup_peer: scheduler -> control[63932] fd=4
setup_peer: scheduler -> queue[21502] fd=5
setup_done: scheduler[14152] done
smtpd: setup done
mproc: parent -> control: enabled
mproc: parent -> lka: enabled
mproc: parent -> queue: enabled
mproc: parent -> ca: enabled
mproc: parent -> pony: enabled
debug: parent_send_config_ruleset: reloading
mproc: parent -> lka : 0 IMSG_CONF_START
mproc: parent -> lka : 0 IMSG_CONF_END
debug: parent_send_config: configuring pony process
mproc: parent -> pony : 0 IMSG_CONF_START
mproc: parent -> pony : 0 IMSG_CONF_END
debug: parent_send_config: configuring ca process
mproc: parent -> ca : 0 IMSG_CONF_START
mproc: parent -> ca : 0 IMSG_CONF_END
setup_proc: klondike done
setup_proc: control done
setup_proc: lookup done
setup_proc: pony express done
setup_proc: queue done
setup_proc: scheduler done
mproc: ca -> control: enabled
debug: bounce warning after 4h
mproc: ca -> parent: enabled
mproc: ca -> pony: enabled
mproc: ca -> pony: disabled
mproc: pony -> parent: enabled
mproc: scheduler -> control: enabled
imsg: ca <- parent: IMSG_CONF_START (len=0)
mproc: lka -> parent: enabled
mproc: pony -> queue: enabled
mproc: scheduler -> queue: enabled
scheduler: getting batch: mask=0x3f, count=10
debug: /--- ramqueue: scheduler_ram_batch()
debug: \---
scheduler: got r=0, delay=-1, count=10
scheduler: sleeping
imsg: ca <- parent: IMSG_CONF_END (len=0)
debug: init private ssl-tree
mproc: ca -> pony: enabled
ramstat: init
ramstat: set: uptime
ramstat: uptime: n/a -> n/a
mproc: lka -> queue: enabled
mproc: lka -> control: enabled
mproc: lka -> pony: enabled
mproc: lka -> pony: disabled
imsg: lka <- parent: IMSG_CONF_START (len=0)
imsg: lka <- parent: IMSG_CONF_END (len=0)
TABLE "<anydestination>" type=LIST config=""
"*"
"bhs"
TABLE "<anyhost>" type= config=""
"0.0.0.0/0"
"::/0"
"local"
TABLE "<getpwnam>" type=DYNAMIC config=""
TABLE "<localhost>" type= config=""
"127.0.0.1"
"144.217.89.103"
"ipv6:2607:5300:201:3100::6893"
"ipv6:::1"
"ipv6:fe80::1%lo0"
"ipv6:fe80::ecd0:b4f4:9b5:1638%vio0"
"local"
TABLE "<localnames>" type=LIST config=""
"127.0.0.1"
"144.217.89.103"
"[127.0.0.1]"
"[144.217.89.103]"
"[ipv6:2607:5300:201:3100::6893]"
"[ipv6:::1]"
"[ipv6:fe80::1%lo0]"
"[ipv6:fe80::ecd0:b4f4:9b5:1638%vio0]"
"[ipv6:ipv6:2607:5300:201:3100::6893]"
"[ipv6:ipv6:::1]"
"[ipv6:ipv6:fe80::1%lo0]"
"[ipv6:ipv6:fe80::ecd0:b4f4:9b5:1638%vio0]"
"bhs.header-rewrite.net"
"ipv6:2607:5300:201:3100::6893"
"ipv6:::1"
"ipv6:fe80::1%lo0"
"ipv6:fe80::ecd0:b4f4:9b5:1638%vio0"
"localhost"
TABLE "allowed-hosts" type=LIST config="/etc/mail/allowed-hosts"
"204.16.144.114"
"2607:5300:201:2100::9a6"
"54.39.183.132"
"54.39.85.16"
"home.athompso.net"
"mail.athompso.net"
TABLE "translations" type=HASH config="/etc/mail/translations"
"@old.athompso.net" -> "new.athompso.net"
mproc: lka -> pony: enabled
mproc: pony -> lka: enabled
mproc: pony -> control: enabled
mproc: pony -> ca: enabled
debug: ca_engine_init: using RSA privsep engine
imsg: pony <- parent: IMSG_CONF_START (len=0)
imsg: pony <- parent: IMSG_CONF_END (len=0)
debug: smtp: listen on IPv6:::1 port 25 flags 0xc00 pki "" ca ""
debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0xc00 pki "" ca ""
debug: smtp: listen on 127.0.0.1 port 25 flags 0xc00 pki "" ca ""
debug: smtp: listen on 144.217.89.103 port 25 flags 0xc00 pki "" ca ""
debug: smtp: listen on IPv6:fe80::ecd0:b4f4:9b5:1638%vio0 port 25 flags 0xc00
pki "" ca ""
debug: smtp: listen on IPv6:2607:5300:201:3100::6893 port 25 flags 0xc00 pki ""
ca ""
debug: smtp: will accept at most 499 clients
mproc: control -> scheduler: enabled
mproc: control -> queue: enabled
mproc: control -> parent: enabled
mproc: control -> lka: enabled
mproc: control -> pony: enabled
mproc: control -> ca: enabled
queue-backend: queue_init(1) -> 1
mproc: queue -> parent: enabled
mproc: queue -> control: enabled
mproc: queue -> lka: enabled
mproc: queue -> scheduler: enabled
mproc: queue -> pony: enabled
queue-backend: queue_envelope_walk() -> -1 (0000000000000000)
debug: queue: done loading queue into scheduler
debug: smtpd: scanning offline queue...
debug: smtpd: offline scanning done
smtp: 0x1127a72e6000: connected to listener 0x112862dcc000
[hostname=bhs.header-rewrite.net, port=25, tag=]
mproc: pony -> lka: realloc 0 -> 128
mproc: pony -> lka : 28 IMSG_GETNAMEINFO
mproc: pony -> control: realloc 0 -> 128
mproc: pony -> control : 45 IMSG_STAT_INCREMENT
mproc: pony -> control : 51 IMSG_STAT_INCREMENT
imsg: lka <- pony: IMSG_GETNAMEINFO (len=28)
imsg: control <- pony: IMSG_STAT_INCREMENT (len=45)
ramstat: increment: smtp.session
mproc: lka -> pony: realloc 0 -> 128
mproc: lka -> pony : 31 IMSG_GETNAMEINFO
imsg: pony <- lka: IMSG_GETNAMEINFO (len=31)
smtp: 0x1127a72e6000: STATE_NEW -> STATE_CONNECTED
d3a5ff63e6a0e04e smtp connected address=54.39.183.132 host=mail.athompso.net
smtp: 0x1127a72e6000: >>> 220 bhs.header-rewrite.net ESMTP OpenSMTPD
smtp: 0x1127a72e6000: IO_LOWAT <io:0x11284ad86400 fd=15 to=300000 fl=W ib=0
ob=0>
ramstat: smtp.session (0x1d3c3a072500): 0 -> 1
imsg: control <- pony: IMSG_STAT_INCREMENT (len=51)
ramstat: increment: smtp.session.inet4
ramstat: smtp.session.inet4 (0x1d3c616c4640): 0 -> 1
smtp: 0x1127a72e6000: IO_DATAIN <io:0x11284ad86400 fd=15 to=300000 fl=R ib=24
ob=0>
smtp: 0x1127a72e6000: <<< EHLO mail.athompso.net
smtp: 0x1127a72e6000: STATE_CONNECTED -> STATE_HELO
smtp: 0x1127a72e6000: >>> 250-bhs.header-rewrite.net Hello mail.athompso.net
[54.39.183.132], pleased to meet you
smtp: 0x1127a72e6000: >>> 250-8BITMIME
smtp: 0x1127a72e6000: >>> 250-ENHANCEDSTATUSCODES
smtp: 0x1127a72e6000: >>> 250-SIZE 104857600
smtp: 0x1127a72e6000: >>> 250-DSN
smtp: 0x1127a72e6000: >>> 250 HELP
smtp: 0x1127a72e6000: IO_LOWAT <io:0x11284ad86400 fd=15 to=300000 fl=W ib=0
ob=0>
smtp: 0x1127a72e6000: IO_DATAIN <io:0x11284ad86400 fd=15 to=300000 fl=R ib=39
ob=0>
smtp: 0x1127a72e6000: <<< MAIL FROM:<[email protected]>
mproc: pony -> queue: realloc 0 -> 128
mproc: pony -> queue : 8 IMSG_SMTP_MESSAGE_CREATE
imsg: queue <- pony: IMSG_SMTP_MESSAGE_CREATE (len=8)
queue-backend: queue_message_create() -> 1 (d7bf0ff6)
mproc: queue -> pony: realloc 0 -> 128
mproc: queue -> pony : 16 IMSG_SMTP_MESSAGE_CREATE
imsg: pony <- queue: IMSG_SMTP_MESSAGE_CREATE (len=16)
smtp: 0x1127a72e6000: >>> 250 2.0.0: Ok
smtp: 0x1127a72e6000: IO_LOWAT <io:0x11284ad86400 fd=15 to=300000 fl=W ib=0
ob=0>
smtp: 0x1127a72e6000: IO_DATAIN <io:0x11284ad86400 fd=15 to=300000 fl=R ib=33
ob=0>
smtp: 0x1127a72e6000: <<< RCPT TO:<[email protected]>
mproc: pony -> lka: realloc 128 -> 512
mproc: pony -> lka : 283 IMSG_SMTP_EXPAND_RCPT
imsg: lka <- pony: IMSG_SMTP_EXPAND_RCPT (len=283)
expand: 0x154201b89018: expand_insert() called for
address:[email protected][parent=0x0, rule=0x0]
expand: 0x154201b89018: inserted node 0x1541802cb000
expand: lka_expand: address: [email protected] [depth=0]
lookup: check "54.39.183.132" as NETADDR in table static:<localhost> -> 0
lookup: check "54.39.183.132" as NETADDR in table static:allowed-hosts -> found
lookup: check "athompso.net" as DOMAIN in table static:<anydestination> -> found
rule #2 matched: match from src allowed-hosts for any => translate
lookup: lookup "[email protected]" as ALIAS in table static:translations -> 0
lookup: lookup "athompso" as ALIAS in table static:translations -> 0
lookup: lookup "@athompso.net" as ALIAS in table static:translations -> 0
lookup: lookup "@" as ALIAS in table static:translations -> 0
expand: lka_expand: no aliases for virtual
mproc: lka -> pony : 53 IMSG_SMTP_EXPAND_RCPT
expand: 0x154201b89018: clearing expand tree
imsg: pony <- lka: IMSG_SMTP_EXPAND_RCPT (len=53)
smtp: 0x1127a72e6000: >>> 524 5.2.4 Mailing list expansion problem
d3a5ff63e6a0e04e smtp failed-command address=54.39.183.132
host=mail.athompso.net command="RCPT TO:<[email protected]>" result="524
5.2.4 Mailing list expansion problem"
smtp: 0x1127a72e6000: IO_LOWAT <io:0x11284ad86400 fd=15 to=300000 fl=W ib=0
ob=0>
smtp: 0x1127a72e6000: IO_DATAIN <io:0x11284ad86400 fd=15 to=300000 fl=R ib=6
ob=0>
smtp: 0x1127a72e6000: <<< QUIT
smtp: 0x1127a72e6000: >>> 221 2.0.0: Bye
smtp: 0x1127a72e6000: STATE_HELO -> STATE_QUIT
smtp: 0x1127a72e6000: IO_LOWAT <io:0x11284ad86400 fd=15 to=300000 fl=W ib=0
ob=0>
d3a5ff63e6a0e04e smtp disconnected address=54.39.183.132 host=mail.athompso.net
reason=quit
mproc: pony -> queue : 4 IMSG_SMTP_MESSAGE_ROLLBACK
mproc: pony -> control : 45 IMSG_STAT_DECREMENT
imsg: queue <- pony: IMSG_SMTP_MESSAGE_ROLLBACK (len=4)
imsg: control <- pony: IMSG_STAT_DECREMENT (len=45)
ramstat: decrement: smtp.session
ramstat: smtp.session (0x1d3c1e55aec0): 1 -> 0
queue-backend: queue_message_delete(d7bf0ff6) -> 1
mproc: queue -> scheduler: realloc 0 -> 128
mproc: queue -> scheduler : 4 IMSG_QUEUE_MESSAGE_ROLLBACK
imsg: scheduler <- queue: IMSG_QUEUE_MESSAGE_ROLLBACK (len=4)
scheduler: aborting msg:d7bf0ff6
scheduler: getting batch: mask=0x3f, count=10
debug: /--- ramqueue: scheduler_ram_batch()
debug: \---
scheduler: got r=0, delay=-1, count=10
scheduler: sleeping
^Cdebug: got signal 2
debug: clearing p=ca, fd=4, pid=35575
debug: ca -> parent: pipe closed
debug: ca agent exiting
debug: control -> klondike: pipe closed
debug: control agent exiting
debug: pony -> klondike: pipe closed
debug: pony agent exiting
debug: lka -> control: pipe closed
debug: lookup agent exiting
debug: queue -> control: pipe closed
debug: queue agent exiting
debug: scheduler -> control: pipe closed
debug: scheduler agent exiting
debug: clearing p=pony, fd=7, pid=40666
debug: clearing p=control, fd=5, pid=63932
debug: clearing p=lka, fd=6, pid=49698
debug: clearing p=scheduler, fd=9, pid=14152
debug: clearing p=queue, fd=8, pid=21502
Exiting
bhs#
--
You received this mail because you are subscribed to [email protected]
To unsubscribe, send a mail to: [email protected]
