Allow filters to log information through stderr. This simplifies and

unifies the way filters need to get their logging to the right location.

Log-messages are read line by line and are logged at LOG_ERR level via
the lookup process.

OK gilles@

4 files changed, 83 insertions, 6 deletions

diff --git a/usr.sbin/smtpd/lka.c b/usr.sbin/smtpd/lka.c
index d5d55410231..6548700e33a 100644
--- a/usr.sbin/smtpd/lka.c
+++ b/usr.sbin/smtpd/lka.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: lka.c,v 1.234 2019/06/13 11:45:34 eric Exp $	*/
+/*	$OpenBSD: lka.c,v 1.235 2019/06/27 05:14:49 martijn Exp $	*/
 
 /*
  * Copyright (c) 2008 Pierre-Yves Ritschard <pyr@openbsd.org>
@@ -360,9 +360,21 @@ lka_imsg(struct mproc *p, struct imsg *imsg)
 		m_get_string(&m, &procname);
 		m_end(&m);
 
+		m_create(p, IMSG_LKA_PROCESSOR_ERRFD, 0, 0, -1);
+		m_add_string(p, procname);
+		m_close(p);
+
 		lka_proc_forked(procname, imsg->fd);
 		return;
 
+	case IMSG_LKA_PROCESSOR_ERRFD:
+		m_msg(&m, imsg);
+		m_get_string(&m, &procname);
+		m_end(&m);
+
+		lka_proc_errfd(procname, imsg->fd);
+		shutdown(imsg->fd, SHUT_WR);
+		return;
 
 	case IMSG_REPORT_SMTP_LINK_CONNECT:
 		m_msg(&m, imsg);
diff --git a/usr.sbin/smtpd/lka_proc.c b/usr.sbin/smtpd/lka_proc.c
index fb3a4137628..eeee41481e7 100644
--- a/usr.sbin/smtpd/lka_proc.c
+++ b/usr.sbin/smtpd/lka_proc.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: lka_proc.c,v 1.6 2018/12/21 19:07:47 gilles Exp $	*/
+/*	$OpenBSD: lka_proc.c,v 1.7 2019/06/27 05:14:49 martijn Exp $	*/
 
 /*
  * Copyright (c) 2018 Gilles Chehade <gilles@poolp.org>
@@ -41,10 +41,12 @@ static struct dict		processors;
 struct processor_instance {
 	char			*name;
 	struct io		*io;
+	struct io		*errfd;
 	int			 ready;
 };
 
 static void	processor_io(struct io *, int, void *);
+static void	processor_errfd(struct io *, int, void *);
 int		lka_filter_process_response(const char *, const char *);
 
 int
@@ -81,6 +83,20 @@ lka_proc_forked(const char *name, int fd)
 	dict_xset(&processors, name, processor);
 }
 
+void
+lka_proc_errfd(const char *name, int fd)
+{
+	struct processor_instance	*processor;
+
+	processor = dict_xget(&processors, name);
+
+	io_set_nonblocking(fd);
+
+	processor->errfd = io_new();
+	io_set_fd(processor->errfd, fd);
+	io_set_callback(processor->errfd, processor_errfd, processor->name);
+}
+
 struct io *
 lka_proc_get_io(const char *name)
 {
@@ -137,3 +153,17 @@ processor_io(struct io *io, int evt, void *arg)
 		goto nextline;
 	}
 }
+
+static void
+processor_errfd(struct io *io, int evt, void *arg)
+{
+	const char	*name = arg;
+	char		*line = NULL;
+	ssize_t		 len;
+
+	switch (evt) {
+	case IO_DATAIN:
+		while ((line = io_getline(io, &len)) != NULL)
+			log_warnx("%s: %s", name, line);
+	}
+}
diff --git a/usr.sbin/smtpd/smtpd.c b/usr.sbin/smtpd/smtpd.c
index d2c4da6b070..02fcbde52e7 100644
--- a/usr.sbin/smtpd/smtpd.c
+++ b/usr.sbin/smtpd/smtpd.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: smtpd.c,v 1.320 2019/06/13 11:45:35 eric Exp $	*/
+/*	$OpenBSD: smtpd.c,v 1.321 2019/06/27 05:14:49 martijn Exp $	*/
 
 /*
  * Copyright (c) 2008 Gilles Chehade <gilles@poolp.org>
@@ -156,11 +156,12 @@ static void
 parent_imsg(struct mproc *p, struct imsg *imsg)
 {
 	struct forward_req	*fwreq;
+	struct processor	*processor;
 	struct deliver		 deliver;
 	struct child		*c;
 	struct msg		 m;
 	const void		*data;
-	const char		*username, *password, *cause;
+	const char		*username, *password, *cause, *procname;
 	uint64_t		 reqid;
 	size_t			 sz;
 	void			*i;
@@ -253,6 +254,17 @@ parent_imsg(struct mproc *p, struct imsg *imsg)
 		m_end(&m);
 		profiling = v;
 		return;
+
+	case IMSG_LKA_PROCESSOR_ERRFD:
+		m_msg(&m, imsg);
+		m_get_string(&m, &procname);
+		m_end(&m);
+
+		processor = dict_xget(env->sc_processors_dict, procname);
+		m_create(p_lka, IMSG_LKA_PROCESSOR_ERRFD, 0, 0, processor->errfd);
+		m_add_string(p_lka, procname);
+		m_close(p_lka);
+		return;
 	}
 
 	errx(1, "parent_imsg: unexpected %s imsg from %s",
@@ -1260,7 +1272,9 @@ static void
 fork_processor(const char *name, const char *command, const char *user, const char *group, const char *chroot_path)
 {
 	pid_t		 pid;
-	int		 sp[2];
+	struct processor	*processor;
+	char		 buf;
+	int		 sp[2], errfd[2];
 	struct passwd	*pw;
 	struct group	*gr;
 
@@ -1280,14 +1294,19 @@ fork_processor(const char *name, const char *command, const char *user, const ch
 
 	if (socketpair(AF_UNIX, SOCK_STREAM, PF_UNSPEC, sp) == -1)
 		err(1, "socketpair");
+	if (socketpair(AF_UNIX, SOCK_STREAM, PF_UNSPEC, errfd) == -1)
+		err(1, "socketpair");
 
 	if ((pid = fork()) < 0)
 		err(1, "fork");
 
 	/* parent passes the child fd over to lka */
 	if (pid > 0) {
+		processor = dict_xget(env->sc_processors_dict, name);
+		processor->errfd = errfd[1];
 		child_add(pid, CHILD_PROCESSOR, name);
 		close(sp[0]);
+		close(errfd[0]);
 		m_create(p_lka, IMSG_LKA_PROCESSOR_FORK, 0, 0, sp[1]);
 		m_add_string(p_lka, name);
 		m_close(p_lka);
@@ -1295,8 +1314,10 @@ fork_processor(const char *name, const char *command, const char *user, const ch
 	}
 
 	close(sp[1]);
+	close(errfd[1]);
 	dup2(sp[0], STDIN_FILENO);
 	dup2(sp[0], STDOUT_FILENO);
+	dup2(errfd[0], STDERR_FILENO);
 
 	if (chroot_path) {
 		if (chroot(chroot_path) != 0 || chdir("/") != 0)
@@ -1319,6 +1340,16 @@ fork_processor(const char *name, const char *command, const char *user, const ch
 	    signal(SIGHUP, SIG_DFL) == SIG_ERR)
 		err(1, "signal");
 
+	/*
+	 * Wait for lka to acknowledge that it received the fd.
+	 * This prevents a race condition between the filter sending an error
+	 * message, and exiting and lka not being able to log it because of
+	 * SIGCHLD.
+	 * (Ab)use read to determine if the fd is installed; since stderr is
+	 * never going to be read from we can shutdown(2) the write-end in lka.
+	 */
+	if (read(STDERR_FILENO, &buf, 1) != 0)
+		errx(1, "lka didn't properly close write end of error socket");
 	if (system(command) == -1)
 		err(1, NULL);
 
@@ -2003,6 +2034,7 @@ imsg_to_str(int type)
 	CASE(IMSG_SMTP_EVENT_DISCONNECT);
 
 	CASE(IMSG_LKA_PROCESSOR_FORK);
+	CASE(IMSG_LKA_PROCESSOR_ERRFD);
 
 	CASE(IMSG_REPORT_SMTP_LINK_CONNECT);
 	CASE(IMSG_REPORT_SMTP_LINK_DISCONNECT);
diff --git a/usr.sbin/smtpd/smtpd.h b/usr.sbin/smtpd/smtpd.h
index 87bc1d1dccb..e231f5375ec 100644
--- a/usr.sbin/smtpd/smtpd.h
+++ b/usr.sbin/smtpd/smtpd.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: smtpd.h,v 1.624 2019/06/14 19:55:25 eric Exp $	*/
+/*	$OpenBSD: smtpd.h,v 1.625 2019/06/27 05:14:49 martijn Exp $	*/
 
 /*
  * Copyright (c) 2008 Gilles Chehade <gilles@poolp.org>
@@ -305,6 +305,7 @@ enum imsg_type {
 	IMSG_SMTP_EVENT_DISCONNECT,
 
 	IMSG_LKA_PROCESSOR_FORK,
+	IMSG_LKA_PROCESSOR_ERRFD,
 
 	IMSG_REPORT_SMTP_LINK_CONNECT,
 	IMSG_REPORT_SMTP_LINK_DISCONNECT,
@@ -1025,6 +1026,7 @@ struct processor {
 	const char		       *user;
 	const char		       *group;
 	const char		       *chroot;
+	int				errfd;
 };
 
 enum filter_type {
@@ -1317,6 +1319,7 @@ int lka(void);
 /* lka_proc.c */
 int lka_proc_ready(void);
 void lka_proc_forked(const char *, int);
+void lka_proc_errfd(const char *, int);
 struct io *lka_proc_get_io(const char *);