Hi,
I moved a host to new smtpd daemon to test it, and I have issues with a
simple smarthost configuration.
I think it could be a bug (instead of a configuration issue) because
when smptd starts it sucessfully send pending envelopes in queue,
whereas when receiving new envelopes, it couldn't send them (and
restarting the daemon makes them to be send).
Here my smtpd.conf configuration:
All external mails is defered to smarthost available at 192.168.92.2 on
my local network. It runs smtpd on OpenBSD -current (Wed May 9 17:38:06
MDT 2018 - pre-smtpd change). There is no changes on this side: it was
working and still work with other hosts.
# cat /etc/mail/smtpd.conf
# This is the smtpd server system-wide configuration file.
# See smtpd.conf(5) for more information.
table aliases file:/etc/mail/aliases
# listen to localhost only
listen on lo0
# actions
action "local" mbox alias <aliases>
action "xsmarthost" relay host "smtp://192.168.92.2:25"
# matches
match for local action "local"
match for any action "xsmarthost"
root user have .forward file.
# cat /root/.forward
sema...@online.fr
#
As side note, I need to explicity specify the port in relay-url. Having
just "smtp://192.168.92.2" makes smtpd to try to send mail via
smtp://192.168.92.2:14742
# smtpd -dvv
...
1fb042e2104c9a64 mta event=connecting address=smtp://192.168.92.2:14742
host=192.168.92.2
debug: mta: 0x6ed70750: IO error: Connection refused
1fb042e2104c9a64 mta event=error reason=IO Error: Connection refused
debug: mta: 0x6ed70750: session done
...
Now, for the faulty behaviour. Before starting the daemon, the queue is
empty.
# smtpctl show status
smtpctl: smtpd doesn't seem to be running
# smtpctl show queue
# smtpd -dvv
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 ca-tree
debug: init ssl-tree
debug: using "fs" queue backend
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
debug: init ca-tree
debug: init ssl-tree
debug: using "fs" queue backend
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
setup_peer: control -> klondike[73948] fd=4
debug: init ssl-tree
debug: init ssl-tree
debug: init ca-tree
debug: init ca-tree
debug: init ssl-tree
debug: init ssl-tree
debug: using "fs" queue backend
debug: using "fs" queue backend
debug: using "ramqueue" scheduler backend
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
debug: using "ram" stat backend
setup_peer: control -> lookup[33143] fd=5
setup_peer: pony express -> control[46635] fd=4
setup_peer: scheduler -> control[46635] fd=4
setup_peer: klondike -> control[46635] fd=4
setup_peer: pony express -> klondike[73948] fd=5
setup_peer: klondike -> pony express[96431] fd=5
setup_peer: pony express -> lookup[33143] fd=6
setup_peer: scheduler -> queue[77111] fd=5
setup_peer: pony express -> queue[77111] fd=7
setup_peer: control -> pony express[96431] fd=6
setup_peer: control -> queue[77111] fd=7
setup_peer: control -> scheduler[21673] fd=8
setup_done: ca[73948] done
setup_proc: klondike done
setup_proc: control done
setup_done: control[46635] done
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
setup_peer: lookup -> control[46635] fd=4
setup_peer: lookup -> pony express[96431] fd=5
setup_peer: lookup -> queue[77111] fd=6
setup_done: lka[33143] done
setup_proc: pony express done
setup_done: pony[96431] done
setup_proc: lookup done
debug: ca_engine_init: using RSA privsep engine
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
setup_peer: queue -> control[46635] fd=4
setup_peer: queue -> pony express[96431] fd=5
setup_peer: queue -> lookup[33143] fd=6
setup_peer: queue -> scheduler[21673] fd=7
setup_proc: queue done
setup_done: queue[77111] done
setup_proc: scheduler done
debug: bounce warning after 4h
setup_done: scheduler[21673] done
smtpd: setup done
debug: parent_send_config_ruleset: reloading
debug: parent_send_config: configuring pony process
debug: parent_send_config: configuring ca process
debug: smtp: listen on IPv6:::1 port 25 flags 0x400 pki "" ca ""
debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x400 pki "" ca ""
debug: smtp: listen on 127.0.0.1 port 25 flags 0x400 pki "" ca ""
debug: smtp: will accept at most 501 clients
debug: init private ssl-tree
debug: queue: done loading queue into scheduler
debug: smtpd: scanning offline queue...
debug: smtpd: offline scanning done
On another terminal, I send a mail.
$ date | mail root
$
The smtpd log continues as
debug: smtp: new client on listener: 0x44929000
5abe5461bc99f498 smtp event=connected address=local host=bert.local
smtp: 0x4492b000: fd 13 from queue
smtp: 0x4492b000: message fd 13
debug: 0x4492b000: end of message, error=0
5abe5461bc99f498 smtp event=message address=local host=bert.local
msgid=38295bc6 from=<semarie@bert.local> to=<root@bert.local> size=342 ndest=1
proto=ESMTP
debug: scheduler: evp:38295bc6cc8ef6e0 scheduled (mta)
5abe5461bc99f498 smtp event=closed address=local host=bert.local reason=quit
debug: smtp: 0x4492b000: deleting session: done
debug: mta: querying smarthost for xsmarthost:<dynamic:0>...
debug: mta: querying smarthost
warn: Failed to retrieve smarthost for envelope 38295bc6cc8ef6e0
debug: control -> client: pipe closed
debug: clearing p=client, fd=11, pid=0
The daemon failed to send the mail. I stop it with Ctrl+C and restart
it.
^Cdebug: got signal 2
debug: clearing p=ca, fd=4, pid=73948
debug: ca -> parent: pipe closed
debug: ca agent exiting
debug: pony -> klondike: pipe closed
debug: pony agent exiting
debug: lka -> pony express: pipe closed
debug: lookup agent exiting
debug: queue -> pony express: pipe closed
debug: queue agent exiting
debug: scheduler -> queue: pipe closed
debug: scheduler agent exiting
debug: clearing p=pony, fd=7, pid=96431
debug: clearing p=control, fd=5, pid=46635
debug: clearing p=lka, fd=6, pid=33143
debug: clearing p=scheduler, fd=9, pid=21673
debug: clearing p=queue, fd=8, pid=77111
debug: control -> klondike: pipe closed
debug: control agent exiting
Exiting
# smtpd -dvv
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 ca-tree
debug: init ssl-tree
debug: using "fs" queue backend
debug: using "ramqueue" scheduler backend
debug: using "ram" stat backend
setup_peer: klondike -> control[88732] fd=4
setup_peer: klondike -> pony express[98332] fd=5
setup_proc: klondike done
setup_done: ca[3268] done
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
setup_peer: lookup -> control[88732] fd=4
setup_peer: lookup -> pony express[98332] fd=5
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
setup_peer: lookup -> queue[25544] fd=6
setup_peer: queue -> control[88732] fd=4
setup_peer: queue -> pony express[98332] fd=5
setup_peer: queue -> lookup[50620] fd=6
setup_peer: queue -> scheduler[59533] fd=7
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
setup_peer: pony express -> control[88732] fd=4
setup_peer: pony express -> klondike[3268] fd=5
setup_peer: pony express -> lookup[50620] fd=6
setup_peer: pony express -> queue[25544] fd=7
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
setup_peer: control -> klondike[3268] fd=4
setup_peer: control -> lookup[50620] fd=5
setup_peer: control -> pony express[98332] fd=6
setup_peer: control -> queue[25544] fd=7
setup_peer: control -> scheduler[59533] fd=8
setup_done: control[88732] done
setup_proc: lookup done
setup_proc: control done
setup_done: lka[50620] done
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
setup_proc: pony express done
setup_peer: scheduler -> control[88732] fd=4
setup_peer: scheduler -> queue[25544] fd=5
debug: ca_engine_init: using RSA privsep engine
setup_done: pony[98332] done
setup_proc: queue done
setup_done: queue[25544] done
setup_proc: scheduler done
setup_done: scheduler[59533] done
smtpd: setup done
debug: bounce warning after 4h
debug: parent_send_config_ruleset: reloading
debug: parent_send_config: configuring pony process
debug: parent_send_config: configuring ca process
debug: smtp: listen on IPv6:::1 port 25 flags 0x400 pki "" ca ""
debug: init private ssl-tree
debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x400 pki "" ca ""
debug: smtp: listen on 127.0.0.1 port 25 flags 0x400 pki "" ca ""
debug: smtp: will accept at most 501 clients
debug: queue: done loading queue into scheduler
debug: scheduler: evp:38295bc6cc8ef6e0 scheduled (mta)
debug: mta: querying smarthost for xsmarthost:<dynamic:0>...
debug: mta: querying smarthost
debug: mta: received evp:38295bc6cc8ef6e0 for <sema...@online.fr>
debug: mta: draining [relay:192.168.92.2,port=25,mx] refcount=1, ntask=1,
nconnector=0, nconn=0
debug: mta: querying MX for [relay:192.168.92.2,port=25,mx]...
debug: mta: [relay:192.168.92.2,port=25,mx] waiting for MX
debug: MXs for domain 192.168.92.2:
192.168.92.2 preference -1
debug: mta: ... got mx (0x560a5550, 192.168.92.2,
[relay:192.168.92.2,port=25,mx])
debug: mta: draining [relay:192.168.92.2,port=25,mx] refcount=1, ntask=1,
nconnector=0, nconn=0
debug: mta: querying source for [relay:192.168.92.2,port=25,mx]...
debug: mta: ... got source for [relay:192.168.92.2,port=25,mx]: []
debug: mta: new [connector:[]->[relay:192.168.92.2,port=25,mx],0x10000]
debug: mta: connecting with [connector:[]->[relay:192.168.92.2,port=25,mx],0x0]
debug: mta-routing: searching new route for
[connector:[]->[relay:192.168.92.2,port=25,mx],0x0]...
debug: mta-routing: selecting candidate route [] <-> 192.168.92.2
debug: mta-routing: spawning new connection on [] <-> 192.168.92.2
debug: mta: 0x77c48750: spawned for relay [relay:192.168.92.2,port=25,mx]
debug: mta: connecting with [connector:[]->[relay:192.168.92.2,port=25,mx],0x0]
debug: mta: cannot use [relay:192.168.92.2,port=25,mx] before 2s
debug: mta-routing: no route available for
[connector:[]->[relay:192.168.92.2,port=25,mx],0x0]: must wait a bit
debug: mta: retrying to connect on
[connector:[]->[relay:192.168.92.2,port=25,mx],0x0] in 2s...
debug: mta: draining [relay:192.168.92.2,port=25,mx] refcount=3, ntask=1,
nconnector=1, nconn=1
debug: mta: scheduling relay [relay:192.168.92.2,port=25,mx] in 1s...
7957c8186ca01dd6 mta event=connecting address=smtp://192.168.92.2:25
host=192.168.92.2
7957c8186ca01dd6 mta event=connected
debug: mta-routing: route [] <-> 192.168.92.2 (192.168.92.2) is now valid.
debug: mta: connecting with
[connector:[]->[relay:192.168.92.2,port=25,mx],0x20000]
debug: mta: cancelling connector timeout
debug: mta: enough connections already
debug: mta: 0x77c48750: handling next task for relay
[relay:192.168.92.2,port=25,mx]
7957c8186ca01dd6 mta event=delivery evpid=38295bc6cc8ef6e0
from=<semarie@bert.local> to=<sema...@online.fr> rcpt=<root@bert.local>
source="192.168.92.11" relay="192.168.92.2 (192.168.92.2)" delay=1m35s
result="Ok" stat="250 2.0.0: 512ab55a Message accepted for delivery"
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 10s
debug: mta: flush for 38295bc6cc8ef6e0 (-> sema...@online.fr)
debug: smtpd: scanning offline queue...
debug: smtpd: offline scanning done
debug: mta: ... timeout for [relay:192.168.92.2,port=25,mx]
debug: mta: draining [relay:192.168.92.2,port=25,mx] refcount=2, ntask=0,
nconnector=1, nconn=1
debug: mta: all done for [relay:192.168.92.2,port=25,mx]
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 9s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 8s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 7s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 6s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 5s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 4s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 3s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 2s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
mta: debug: last connection: hanging on for 1s
mta: timeout for session hangon
debug: mta: 0x77c48750: no task for relay [relay:192.168.92.2,port=25,mx]
7957c8186ca01dd6 mta event=closed reason=quit messages=1
debug: mta: 0x77c48750: session done
debug: mta_route_collect([] <-> 192.168.92.2 (192.168.92.2))
debug: mta: connecting with [connector:[]->[relay:192.168.92.2,port=25,mx],0x0]
debug: mta: no task for connector
debug: mta: mta_route_unref(): really discarding route [] <-> 192.168.92.2
(192.168.92.2)
debug: mta: freeing [relay:192.168.92.2,port=25,mx]
debug: mta: freeing [connector:[]->[relay:192.168.92.2,port=25,mx],0x0]
The daemon sent the mail without problem. I send a new mail.
$ date | mail root
$
smtpd fails to send it as previously.
debug: smtp: new client on listener: 0x79f89000
7957c8192a148eac smtp event=connected address=local host=bert.local
smtp: 0x79f8b000: fd 13 from queue
smtp: 0x79f8b000: message fd 13
debug: 0x79f8b000: end of message, error=0
7957c8192a148eac smtp event=message address=local host=bert.local
msgid=f1e28283 from=<semarie@bert.local> to=<root@bert.local> size=342 ndest=1
proto=ESMTP
7957c8192a148eac smtp event=closed address=local host=bert.local reason=quit
debug: smtp: 0x79f8b000: deleting session: done
debug: scheduler: evp:f1e282831e1952d0 scheduled (mta)
debug: mta: querying smarthost for xsmarthost:<dynamic:0>...
debug: mta: querying smarthost
warn: Failed to retrieve smarthost for envelope f1e282831e1952d0
debug: control -> client: pipe closed
debug: clearing p=client, fd=11, pid=0
And it will be send when restarting the daemon...
Thanks.
--
Sebastien Marie
