Re: filter-spamassassin crashes smtpd on boot

[Joerg Jung]

Yes, me introduced this buggy behaviour in the recent snapshots in the 
resolving function and 
due to the refactoring to non-blocking IO. The resolving should and will be 
changed to happen async 
and non-blocking as well. As I said, known bug, and we are working on this, 
sorry for the inconvenience. 

> On 30 Jun 2016, at 07:24, Jason Tubnor  wrote:
> 
> Same applies when smtpd is started at boot on OpenBSD as the smtpd instance 
> in the system starts before pkg_scripts (spamassassin), thus breaking and not 
> processing email until smtpd has been restarted.
> 
> On 30 June 2016 at 14:42, Joerg Jung mailto:m...@umaxx.net>> 
> wrote:
> 
> 
> > Am 30.06.2016 um 00:41 schrieb Simon McFarlane  > >:
> >
> > Hi,
> >
> > I have a rather uninteresting setup consisting of Dovecot and OpenSMTPD 
> > with few configuration tweaks on an OpenBSD system. The only filter I have 
> > is filter-spamassassin. I'm running the latest -current snapshot and filter 
> > and extras from pkg.
> >
> > I can rcctl start smtpd just fine, however, smtpd fails to start 
> > automatically on boot. Every time I reboot the system, I have to shell back 
> > in and start smtpd manually. I get this in /var/log/maillog:
> >
> > Jun 29 22:24:01 mx smtpd[76577]: info: OpenSMTPD 5.9.1 starting
> > Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> control[77736] fd=4
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> klondike[64252] fd=5
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> control[77736] fd=8
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> lookup[45356] fd=6
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> control[77736] fd=6
> > Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> pony 
> > express[82409] fd=5
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> pony express[82409] 
> > fd=7
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> pony express[82409] 
> > fd=9
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> queue[65295] fd=8
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> pony express[82409] 
> > fd=7
> > Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> control[77736] 
> > fd=9
> > Jun 29 22:24:01 mx smtpd[64252]: setup_proc: klondike done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: ca[64252] done
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> lookup[45356] fd=10
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> scheduler[50073] 
> > fd=9
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> queue[65295] fd=8
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> control[77736] 
> > fd=7
> > Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> queue[65295] fd=10
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> scheduler[50073] fd=11
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: control[77736] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> 
> > klondike[64252] fd=8
> > Jun 29 22:24:01 mx smtpd[77736]: setup_proc: control done
> > Jun 29 22:24:01 mx smtpd[45356]: setup_proc: lookup done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> lookup[45356] 
> > fd=9
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: lka[45356] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> queue[65295] 
> > fd=10
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: pony[82409] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_proc: pony express done
> > Jun 29 22:24:01 mx smtpd[65295]: setup_proc: queue done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: queue[65295] done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: scheduler[50073] done
> > Jun 29 22:24:01 mx smtpd[50073]: setup_proc: scheduler done
> > Jun 29 22:24:01 mx smtpd[79591]: smtpd: setup done
> > Jun 29 22:24:01 mx filter-spamassassin[81659]: fatal: resolve: failed
> > Jun 29 22:24:01 mx smtpd[82409]: warn: pony -> filter-spamassassin: pipe 
> > closed
> > Jun 29 22:24:01 mx smtpd[82409]: warn: filter "filter-spamassassin" closed 
> > unexpectedly
> > Jun 29 22:24:01 mx smtpd[82409]: fatal: exiting
> > Jun 29 22:24:01 mx smtpd[79591]: warn: parent -> pony: pipe closed
> > Jun 29 22:24:01 mx smtpd[64252]: warn: ca -> pony express: pipe closed
> > Jun 29 22:24:01 mx smtpd[77736]: warn: control -> pony express: pipe closed
> > Jun 29 22:24:01 mx smtpd[50073]: warn: scheduler -> control: pipe closed
> > Jun 29 22:24:01 mx smtpd[65295]: warn: queue -> pony express: pipe closed
> > Jun 29 22:24:01 mx smtpd[45356]: warn: lka -> control: pipe closed
> >
> > It tries to start, but spamassassin crashes with "fatal: resolve: failed", 
> > bringing smtpd with it.
> >
> > Has anyone seen this before? Is this a bug in filter-spamassassin or a 
> > fault in my setup?
> 
> This usually happens when SpamAssassin spamd is not running at the time
> filter-spamassassin is started. This is considered a bug and a know problem,
> beeing worked on.
> 
> > Thanks,
> > Simo

Re: filter-spamassassin crashes smtpd on boot

[Jason Tubnor]

Same applies when smtpd is started at boot on OpenBSD as the smtpd instance
in the system starts before pkg_scripts (spamassassin), thus breaking and
not processing email until smtpd has been restarted.

On 30 June 2016 at 14:42, Joerg Jung  wrote:

>
>
> > Am 30.06.2016 um 00:41 schrieb Simon McFarlane :
> >
> > Hi,
> >
> > I have a rather uninteresting setup consisting of Dovecot and OpenSMTPD
> with few configuration tweaks on an OpenBSD system. The only filter I have
> is filter-spamassassin. I'm running the latest -current snapshot and filter
> and extras from pkg.
> >
> > I can rcctl start smtpd just fine, however, smtpd fails to start
> automatically on boot. Every time I reboot the system, I have to shell back
> in and start smtpd manually. I get this in /var/log/maillog:
> >
> > Jun 29 22:24:01 mx smtpd[76577]: info: OpenSMTPD 5.9.1 starting
> > Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> control[77736]
> fd=4
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> klondike[64252]
> fd=5
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> control[77736] fd=8
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> lookup[45356]
> fd=6
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> control[77736]
> fd=6
> > Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> pony
> express[82409] fd=5
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> pony
> express[82409] fd=7
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> pony
> express[82409] fd=9
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> queue[65295] fd=8
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> pony
> express[82409] fd=7
> > Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> control[77736]
> fd=9
> > Jun 29 22:24:01 mx smtpd[64252]: setup_proc: klondike done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: ca[64252] done
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> lookup[45356] fd=10
> > Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> scheduler[50073]
> fd=9
> > Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> queue[65295] fd=8
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express ->
> control[77736] fd=7
> > Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> queue[65295]
> fd=10
> > Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> scheduler[50073]
> fd=11
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: control[77736] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express ->
> klondike[64252] fd=8
> > Jun 29 22:24:01 mx smtpd[77736]: setup_proc: control done
> > Jun 29 22:24:01 mx smtpd[45356]: setup_proc: lookup done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express ->
> lookup[45356] fd=9
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: lka[45356] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express ->
> queue[65295] fd=10
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: pony[82409] done
> > Jun 29 22:24:01 mx smtpd[82409]: setup_proc: pony express done
> > Jun 29 22:24:01 mx smtpd[65295]: setup_proc: queue done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: queue[65295] done
> > Jun 29 22:24:01 mx smtpd[79591]: setup_done: scheduler[50073] done
> > Jun 29 22:24:01 mx smtpd[50073]: setup_proc: scheduler done
> > Jun 29 22:24:01 mx smtpd[79591]: smtpd: setup done
> > Jun 29 22:24:01 mx filter-spamassassin[81659]: fatal: resolve: failed
> > Jun 29 22:24:01 mx smtpd[82409]: warn: pony -> filter-spamassassin: pipe
> closed
> > Jun 29 22:24:01 mx smtpd[82409]: warn: filter "filter-spamassassin"
> closed unexpectedly
> > Jun 29 22:24:01 mx smtpd[82409]: fatal: exiting
> > Jun 29 22:24:01 mx smtpd[79591]: warn: parent -> pony: pipe closed
> > Jun 29 22:24:01 mx smtpd[64252]: warn: ca -> pony express: pipe closed
> > Jun 29 22:24:01 mx smtpd[77736]: warn: control -> pony express: pipe
> closed
> > Jun 29 22:24:01 mx smtpd[50073]: warn: scheduler -> control: pipe closed
> > Jun 29 22:24:01 mx smtpd[65295]: warn: queue -> pony express: pipe closed
> > Jun 29 22:24:01 mx smtpd[45356]: warn: lka -> control: pipe closed
> >
> > It tries to start, but spamassassin crashes with "fatal: resolve:
> failed", bringing smtpd with it.
> >
> > Has anyone seen this before? Is this a bug in filter-spamassassin or a
> fault in my setup?
>
> This usually happens when SpamAssassin spamd is not running at the time
> filter-spamassassin is started. This is considered a bug and a know
> problem,
> beeing worked on.
>
> > Thanks,
> > Simon
> >
> > --
> > You received this mail because you are subscribed to misc@opensmtpd.org
> > To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org
> >
>
>
> --
> You received this mail because you are subscribed to misc@opensmtpd.org
> To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org
>
>
>


-- 
"If my calculations are correct, when this baby hits 88MPH, you're gonna to
see some serious shit" - Emmett "Doc" Brown

Re: filter-spamassassin crashes smtpd on boot

[Joerg Jung]

> Am 30.06.2016 um 00:41 schrieb Simon McFarlane :
> 
> Hi,
> 
> I have a rather uninteresting setup consisting of Dovecot and OpenSMTPD with 
> few configuration tweaks on an OpenBSD system. The only filter I have is 
> filter-spamassassin. I'm running the latest -current snapshot and filter and 
> extras from pkg.
> 
> I can rcctl start smtpd just fine, however, smtpd fails to start 
> automatically on boot. Every time I reboot the system, I have to shell back 
> in and start smtpd manually. I get this in /var/log/maillog:
> 
> Jun 29 22:24:01 mx smtpd[76577]: info: OpenSMTPD 5.9.1 starting
> Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> control[77736] fd=4
> Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> klondike[64252] fd=5
> Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> control[77736] fd=8
> Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> lookup[45356] fd=6
> Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> control[77736] fd=6
> Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> pony express[82409] 
> fd=5
> Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> pony express[82409] 
> fd=7
> Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> pony express[82409] fd=9
> Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> queue[65295] fd=8
> Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> pony express[82409] 
> fd=7
> Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> control[77736] fd=9
> Jun 29 22:24:01 mx smtpd[64252]: setup_proc: klondike done
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: ca[64252] done
> Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> lookup[45356] fd=10
> Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> scheduler[50073] fd=9
> Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> queue[65295] fd=8
> Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> control[77736] 
> fd=7
> Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> queue[65295] fd=10
> Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> scheduler[50073] fd=11
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: control[77736] done
> Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> klondike[64252] 
> fd=8
> Jun 29 22:24:01 mx smtpd[77736]: setup_proc: control done
> Jun 29 22:24:01 mx smtpd[45356]: setup_proc: lookup done
> Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> lookup[45356] 
> fd=9
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: lka[45356] done
> Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> queue[65295] 
> fd=10
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: pony[82409] done
> Jun 29 22:24:01 mx smtpd[82409]: setup_proc: pony express done
> Jun 29 22:24:01 mx smtpd[65295]: setup_proc: queue done
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: queue[65295] done
> Jun 29 22:24:01 mx smtpd[79591]: setup_done: scheduler[50073] done
> Jun 29 22:24:01 mx smtpd[50073]: setup_proc: scheduler done
> Jun 29 22:24:01 mx smtpd[79591]: smtpd: setup done
> Jun 29 22:24:01 mx filter-spamassassin[81659]: fatal: resolve: failed
> Jun 29 22:24:01 mx smtpd[82409]: warn: pony -> filter-spamassassin: pipe 
> closed
> Jun 29 22:24:01 mx smtpd[82409]: warn: filter "filter-spamassassin" closed 
> unexpectedly
> Jun 29 22:24:01 mx smtpd[82409]: fatal: exiting
> Jun 29 22:24:01 mx smtpd[79591]: warn: parent -> pony: pipe closed
> Jun 29 22:24:01 mx smtpd[64252]: warn: ca -> pony express: pipe closed
> Jun 29 22:24:01 mx smtpd[77736]: warn: control -> pony express: pipe closed
> Jun 29 22:24:01 mx smtpd[50073]: warn: scheduler -> control: pipe closed
> Jun 29 22:24:01 mx smtpd[65295]: warn: queue -> pony express: pipe closed
> Jun 29 22:24:01 mx smtpd[45356]: warn: lka -> control: pipe closed
> 
> It tries to start, but spamassassin crashes with "fatal: resolve: failed", 
> bringing smtpd with it.
> 
> Has anyone seen this before? Is this a bug in filter-spamassassin or a fault 
> in my setup?

This usually happens when SpamAssassin spamd is not running at the time
filter-spamassassin is started. This is considered a bug and a know problem, 
beeing worked on.

> Thanks,
> Simon
> 
> -- 
> You received this mail because you are subscribed to misc@opensmtpd.org
> To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org
> 


--
You received this mail because you are subscribed to misc@opensmtpd.org
To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org

filter-spamassassin crashes smtpd on boot

[Simon McFarlane]

Hi,

I have a rather uninteresting setup consisting of Dovecot and OpenSMTPD 
with few configuration tweaks on an OpenBSD system. The only filter I 
have is filter-spamassassin. I'm running the latest -current snapshot 
and filter and extras from pkg.


I can rcctl start smtpd just fine, however, smtpd fails to start 
automatically on boot. Every time I reboot the system, I have to shell 
back in and start smtpd manually. I get this in /var/log/maillog:


Jun 29 22:24:01 mx smtpd[76577]: info: OpenSMTPD 5.9.1 starting
Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> control[77736] fd=4
Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> klondike[64252] fd=5
Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> control[77736] fd=8
Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> lookup[45356] fd=6
Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> control[77736] fd=6
Jun 29 22:24:01 mx smtpd[64252]: setup_peer: klondike -> pony 
express[82409] fd=5
Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> pony 
express[82409] fd=7
Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> pony 
express[82409] fd=9

Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> queue[65295] fd=8
Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> pony 
express[82409] fd=7
Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> control[77736] 
fd=9

Jun 29 22:24:01 mx smtpd[64252]: setup_proc: klondike done
Jun 29 22:24:01 mx smtpd[79591]: setup_done: ca[64252] done
Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> lookup[45356] fd=10
Jun 29 22:24:01 mx smtpd[77736]: setup_peer: control -> scheduler[50073] 
fd=9

Jun 29 22:24:01 mx smtpd[45356]: setup_peer: lookup -> queue[65295] fd=8
Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> 
control[77736] fd=7

Jun 29 22:24:01 mx smtpd[50073]: setup_peer: scheduler -> queue[65295] fd=10
Jun 29 22:24:01 mx smtpd[65295]: setup_peer: queue -> scheduler[50073] fd=11
Jun 29 22:24:01 mx smtpd[79591]: setup_done: control[77736] done
Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> 
klondike[64252] fd=8

Jun 29 22:24:01 mx smtpd[77736]: setup_proc: control done
Jun 29 22:24:01 mx smtpd[45356]: setup_proc: lookup done
Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> 
lookup[45356] fd=9

Jun 29 22:24:01 mx smtpd[79591]: setup_done: lka[45356] done
Jun 29 22:24:01 mx smtpd[82409]: setup_peer: pony express -> 
queue[65295] fd=10

Jun 29 22:24:01 mx smtpd[79591]: setup_done: pony[82409] done
Jun 29 22:24:01 mx smtpd[82409]: setup_proc: pony express done
Jun 29 22:24:01 mx smtpd[65295]: setup_proc: queue done
Jun 29 22:24:01 mx smtpd[79591]: setup_done: queue[65295] done
Jun 29 22:24:01 mx smtpd[79591]: setup_done: scheduler[50073] done
Jun 29 22:24:01 mx smtpd[50073]: setup_proc: scheduler done
Jun 29 22:24:01 mx smtpd[79591]: smtpd: setup done
Jun 29 22:24:01 mx filter-spamassassin[81659]: fatal: resolve: failed
Jun 29 22:24:01 mx smtpd[82409]: warn: pony -> filter-spamassassin: pipe 
closed
Jun 29 22:24:01 mx smtpd[82409]: warn: filter "filter-spamassassin" 
closed unexpectedly

Jun 29 22:24:01 mx smtpd[82409]: fatal: exiting
Jun 29 22:24:01 mx smtpd[79591]: warn: parent -> pony: pipe closed
Jun 29 22:24:01 mx smtpd[64252]: warn: ca -> pony express: pipe closed
Jun 29 22:24:01 mx smtpd[77736]: warn: control -> pony express: pipe closed
Jun 29 22:24:01 mx smtpd[50073]: warn: scheduler -> control: pipe closed
Jun 29 22:24:01 mx smtpd[65295]: warn: queue -> pony express: pipe closed
Jun 29 22:24:01 mx smtpd[45356]: warn: lka -> control: pipe closed

It tries to start, but spamassassin crashes with "fatal: resolve: 
failed", bringing smtpd with it.


Has anyone seen this before? Is this a bug in filter-spamassassin or a 
fault in my setup?


Thanks,
Simon

--
You received this mail because you are subscribed to misc@opensmtpd.org
To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org