Retry DNS lookup for remote loghost.

If DNS lookup for a remote loghost configured in syslog.conf did
not work at startup, the entry was ignored.  Better retry the lookup
in intervals until it succeeds.  Improve debug output to print IP
address after resolution.  Unify retry code that resolves DNS for
UDP and connects to TCP server.

testing and feedback from Paul de Weerd; OK deraadt@

3 files changed, 163 insertions, 54 deletions

diff --git a/usr.sbin/syslogd/privsep.c b/usr.sbin/syslogd/privsep.c
index 2edbbbca971..3e89894ab46 100644
--- a/usr.sbin/syslogd/privsep.c
+++ b/usr.sbin/syslogd/privsep.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: privsep.c,v 1.76 2023/08/11 04:45:06 guenther Exp $	*/
+/*	$OpenBSD: privsep.c,v 1.77 2023/10/12 22:36:54 bluhm Exp $	*/
 
 /*
  * Copyright (c) 2003 Anil Madhavapeddy <anil@recoil.org>
@@ -742,8 +742,8 @@ priv_config_parse_done(void)
 /* Name/service to address translation.  Response is placed into addr.
  * Return 0 for success or < 0 for error like getaddrinfo(3) */
 int
-priv_getaddrinfo(char *proto, char *host, char *serv, struct sockaddr *addr,
-    size_t addr_len)
+priv_getaddrinfo(const char *proto, const char *host, const char *serv,
+    struct sockaddr *addr, size_t addr_len)
 {
 	char protocpy[5], hostcpy[NI_MAXHOST], servcpy[NI_MAXSERV];
 	int cmd, ret_len;
diff --git a/usr.sbin/syslogd/syslogd.c b/usr.sbin/syslogd/syslogd.c
index 289c3cb68a9..e878a30d5ee 100644
--- a/usr.sbin/syslogd/syslogd.c
+++ b/usr.sbin/syslogd/syslogd.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: syslogd.c,v 1.277 2023/03/16 18:22:08 bluhm Exp $	*/
+/*	$OpenBSD: syslogd.c,v 1.278 2023/10/12 22:36:54 bluhm Exp $	*/
 
 /*
  * Copyright (c) 2014-2021 Alexander Bluhm <bluhm@genua.de>
@@ -156,9 +156,12 @@ struct filed {
 			struct sockaddr_storage	 f_addr;
 			struct buffertls	 f_buftls;
 			struct bufferevent	*f_bufev;
+			struct event		 f_ev;
 			struct tls		*f_ctx;
+			char			*f_ipproto;
 			char			*f_host;
-			int			 f_reconnectwait;
+			char			*f_port;
+			int			 f_retrywait;
 		} f_forw;		/* forwarding address */
 		char	f_fname[PATH_MAX];
 		struct {
@@ -319,7 +322,9 @@ void	 tcp_dropcb(struct bufferevent *, void *);
 void	 tcp_writecb(struct bufferevent *, void *);
 void	 tcp_errorcb(struct bufferevent *, short, void *);
 void	 tcp_connectcb(int, short, void *);
-void	 tcp_connect_retry(struct bufferevent *, struct filed *);
+int	 loghost_resolve(struct filed *);
+void	 loghost_retry(struct filed *);
+void	 udp_resolvecb(int, short, void *);
 int	 tcpbuf_countmsg(struct bufferevent *bufev);
 void	 die_signalcb(int, short, void *);
 void	 mark_timercb(int, short, void *);
@@ -962,12 +967,15 @@ socket_bind(const char *proto, const char *host, const char *port,
 		    res->ai_socktype | SOCK_NONBLOCK, res->ai_protocol)) == -1)
 			continue;
 
-		if (getnameinfo(res->ai_addr, res->ai_addrlen, hostname,
+		error = getnameinfo(res->ai_addr, res->ai_addrlen, hostname,
 		    sizeof(hostname), servname, sizeof(servname),
 		    NI_NUMERICHOST | NI_NUMERICSERV |
-		    (res->ai_socktype == SOCK_DGRAM ? NI_DGRAM : 0)) != 0) {
-			log_debug("Malformed bind address");
-			hostname[0] = servname[0] = '\0';
+		    (res->ai_socktype == SOCK_DGRAM ? NI_DGRAM : 0));
+		if (error) {
+			log_warnx("malformed bind address host \"%s\": %s",
+			    host, gai_strerror(error));
+			strlcpy(hostname, hostname_unknown, sizeof(hostname));
+			strlcpy(servname, hostname_unknown, sizeof(servname));
 		}
 		if (shutread && shutdown(*fdp, SHUT_RD) == -1) {
 			log_warn("shutdown SHUT_RD "
@@ -1130,7 +1138,7 @@ acceptcb(int lfd, short event, void *arg, int usetls)
 	socklen_t		 sslen;
 	char			 hostname[NI_MAXHOST], servname[NI_MAXSERV];
 	char			*peername;
-	int			 fd;
+	int			 fd, error;
 
 	sslen = sizeof(ss);
 	if ((fd = reserve_accept4(lfd, event, ev, tcp_acceptcb,
@@ -1143,17 +1151,21 @@ acceptcb(int lfd, short event, void *arg, int usetls)
 	}
 	log_debug("Accepting tcp connection");
 
-	if (getnameinfo((struct sockaddr *)&ss, sslen, hostname,
+	error = getnameinfo((struct sockaddr *)&ss, sslen, hostname,
 	    sizeof(hostname), servname, sizeof(servname),
-	    NI_NUMERICHOST | NI_NUMERICSERV) != 0 ||
-	    asprintf(&peername, ss.ss_family == AF_INET6 ?
+	    NI_NUMERICHOST | NI_NUMERICSERV);
+	if (error) {
+		log_warnx("malformed TCP accept address: %s",
+		    gai_strerror(error));
+		peername = hostname_unknown;
+	} else if (asprintf(&peername, ss.ss_family == AF_INET6 ?
 	    "[%s]:%s" : "%s:%s", hostname, servname) == -1) {
-		log_debug("Malformed accept address");
+		log_warn("allocate hostname \"%s\"", hostname);
 		peername = hostname_unknown;
 	}
 	log_debug("Peer address and port %s", peername);
 	if ((p = malloc(sizeof(*p))) == NULL) {
-		log_warn("allocate \"%s\"", peername);
+		log_warn("allocate peername \"%s\"", peername);
 		close(fd);
 		return;
 	}
@@ -1380,7 +1392,7 @@ tcp_writecb(struct bufferevent *bufev, void *arg)
 	 * Successful write, connection to server is good, reset wait time.
 	 */
 	log_debug("loghost \"%s\" successful write", f->f_un.f_forw.f_loghost);
-	f->f_un.f_forw.f_reconnectwait = 0;
+	f->f_un.f_forw.f_retrywait = 0;
 
 	if (f->f_dropped > 0 &&
 	    EVBUFFER_LENGTH(f->f_un.f_forw.f_bufev->output) < MAX_TCPBUF) {
@@ -1440,7 +1452,7 @@ tcp_errorcb(struct bufferevent *bufev, short event, void *arg)
 		f->f_dropped++;
 	}
 
-	tcp_connect_retry(bufev, f);
+	loghost_retry(f);
 
 	/* Log the connection error to the fresh buffer after reconnecting. */
 	log_info(LOG_WARNING, "%s", ebuf);
@@ -1453,8 +1465,15 @@ tcp_connectcb(int fd, short event, void *arg)
 	struct bufferevent	*bufev = f->f_un.f_forw.f_bufev;
 	int			 s;
 
+	if (f->f_un.f_forw.f_addr.ss_family == AF_UNSPEC) {
+		if (loghost_resolve(f) != 0) {
+			loghost_retry(f);
+			return;
+		}
+	}
+
 	if ((s = tcp_socket(f)) == -1) {
-		tcp_connect_retry(bufev, f);
+		loghost_retry(f);
 		return;
 	}
 	log_debug("tcp connect callback: socket success, event %#x", event);
@@ -1503,29 +1522,87 @@ tcp_connectcb(int fd, short event, void *arg)
 	}
 	close(f->f_file);
 	f->f_file = -1;
-	tcp_connect_retry(bufev, f);
+	loghost_retry(f);
+}
+
+int
+loghost_resolve(struct filed *f)
+{
+	char	hostname[NI_MAXHOST];
+	int	error;
+
+	error = priv_getaddrinfo(f->f_un.f_forw.f_ipproto,
+	    f->f_un.f_forw.f_host, f->f_un.f_forw.f_port,
+	    (struct sockaddr *)&f->f_un.f_forw.f_addr,
+	    sizeof(f->f_un.f_forw.f_addr));
+	if (error) {
+		log_warnx("bad hostname \"%s\"", f->f_un.f_forw.f_loghost);
+		f->f_un.f_forw.f_addr.ss_family = AF_UNSPEC;
+		return (error);
+	}
+
+	error = getnameinfo((struct sockaddr *)&f->f_un.f_forw.f_addr,
+	    f->f_un.f_forw.f_addr.ss_len, hostname, sizeof(hostname), NULL, 0,
+	    NI_NUMERICHOST | NI_NUMERICSERV |
+	    (strncmp(f->f_un.f_forw.f_ipproto, "udp", 3) == 0 ? NI_DGRAM : 0));
+	if (error) {
+		log_warnx("malformed UDP address loghost \"%s\": %s",
+		    f->f_un.f_forw.f_loghost, gai_strerror(error));
+		strlcpy(hostname, hostname_unknown, sizeof(hostname));
+	}
+
+	log_debug("resolved loghost \"%s\" address %s",
+	    f->f_un.f_forw.f_loghost, hostname);
+	return (0);
 }
 
 void
-tcp_connect_retry(struct bufferevent *bufev, struct filed *f)
+loghost_retry(struct filed *f)
 {
 	struct timeval		 to;
 
-	if (f->f_un.f_forw.f_reconnectwait == 0)
-		f->f_un.f_forw.f_reconnectwait = 1;
+	if (f->f_un.f_forw.f_retrywait == 0)
+		f->f_un.f_forw.f_retrywait = 1;
 	else
-		f->f_un.f_forw.f_reconnectwait <<= 1;
-	if (f->f_un.f_forw.f_reconnectwait > 600)
-		f->f_un.f_forw.f_reconnectwait = 600;
-	to.tv_sec = f->f_un.f_forw.f_reconnectwait;
+		f->f_un.f_forw.f_retrywait <<= 1;
+	if (f->f_un.f_forw.f_retrywait > 600)
+		f->f_un.f_forw.f_retrywait = 600;
+	to.tv_sec = f->f_un.f_forw.f_retrywait;
 	to.tv_usec = 0;
+	evtimer_add(&f->f_un.f_forw.f_ev, &to);
+
+	log_debug("retry loghost \"%s\" wait %d",
+	    f->f_un.f_forw.f_loghost, f->f_un.f_forw.f_retrywait);
+}
+
+void
+udp_resolvecb(int fd, short event, void *arg)
+{
+	struct filed		*f = arg;
+	struct timeval		 to;
+
+	if (loghost_resolve(f) != 0) {
+		loghost_retry(f);
+		return;
+	}
+
+	switch (f->f_un.f_forw.f_addr.ss_family) {
+	case AF_INET:
+		f->f_file = fd_udp;
+		break;
+	case AF_INET6:
+		f->f_file = fd_udp6;
+		break;
+	}
+	f->f_un.f_forw.f_retrywait = 0;
 
-	log_debug("tcp connect retry: wait %d",
-	    f->f_un.f_forw.f_reconnectwait);
-	bufferevent_setfd(bufev, -1);
-	/* We can reuse the write event as bufferevent is disabled. */
-	evtimer_set(&bufev->ev_write, tcp_connectcb, f);
-	evtimer_add(&bufev->ev_write, &to);
+	if (f->f_dropped > 0) {
+		char ebuf[ERRBUFSIZE];
+
+		snprintf(ebuf, sizeof(ebuf), "to udp loghost \"%s\"",
+		    f->f_un.f_forw.f_loghost);
+		dropped_warn(&f->f_dropped, ebuf);
+	}
 }
 
 int
@@ -1933,6 +2010,11 @@ fprintlog(struct filed *f, int flags, char *msg)
 
 	case F_FORWUDP:
 		log_debug(" %s", f->f_un.f_forw.f_loghost);
+		if (f->f_un.f_forw.f_addr.ss_family == AF_UNSPEC) {
+			log_warnx("not resolved \"%s\"",
+			    f->f_un.f_forw.f_loghost);
+			break;
+		}
 		l = iov[0].iov_len + iov[1].iov_len + iov[2].iov_len +
 		    iov[3].iov_len + iov[4].iov_len + iov[5].iov_len +
 		    iov[6].iov_len;
@@ -2168,9 +2250,13 @@ wallmsg(struct filed *f, struct iovec *iov)
 void
 cvthname(struct sockaddr *f, char *result, size_t res_len)
 {
-	if (getnameinfo(f, f->sa_len, result, res_len, NULL, 0,
-	    NI_NUMERICHOST|NI_NUMERICSERV|NI_DGRAM) != 0) {
-		log_debug("Malformed from address");
+	int error;
+
+	error = getnameinfo(f, f->sa_len, result, res_len, NULL, 0,
+	    NI_NUMERICHOST | NI_NUMERICSERV | NI_DGRAM);
+	if (error) {
+		log_warnx("malformed UDP from address: %s",
+		    gai_strerror(error));
 		strlcpy(result, hostname_unknown, res_len);
 		return;
 	}
@@ -2295,23 +2381,33 @@ init(void)
 			fprintlog(f, 0, (char *)NULL);
 
 		switch (f->f_type) {
+		case F_FORWUDP:
+			evtimer_del(&f->f_un.f_forw.f_ev);
+			free(f->f_un.f_forw.f_ipproto);
+			free(f->f_un.f_forw.f_host);
+			free(f->f_un.f_forw.f_port);
+			break;
 		case F_FORWTLS:
 			if (f->f_un.f_forw.f_ctx) {
 				tls_close(f->f_un.f_forw.f_ctx);
 				tls_free(f->f_un.f_forw.f_ctx);
 			}
-			free(f->f_un.f_forw.f_host);
 			/* FALLTHROUGH */
 		case F_FORWTCP:
+			evtimer_del(&f->f_un.f_forw.f_ev);
 			tcpbuf_dropped += f->f_dropped +
 			     tcpbuf_countmsg(f->f_un.f_forw.f_bufev);
 			bufferevent_free(f->f_un.f_forw.f_bufev);
+			free(f->f_un.f_forw.f_ipproto);
+			free(f->f_un.f_forw.f_host);
+			free(f->f_un.f_forw.f_port);
 			/* FALLTHROUGH */
 		case F_FILE:
 			if (f->f_type == F_FILE) {
 				file_dropped += f->f_dropped;
 				f->f_dropped = 0;
 			}
+			/* FALLTHROUGH */
 		case F_TTY:
 		case F_CONSOLE:
 		case F_PIPE:
@@ -2704,16 +2800,31 @@ cfline(char *line, char *progblock, char *hostblock)
 			    f->f_un.f_forw.f_loghost);
 			break;
 		}
-		if (priv_getaddrinfo(ipproto, host, port,
-		    (struct sockaddr*)&f->f_un.f_forw.f_addr,
-		    sizeof(f->f_un.f_forw.f_addr)) != 0) {
-			log_warnx("bad hostname \"%s\"",
+		f->f_un.f_forw.f_ipproto = strdup(ipproto);
+		f->f_un.f_forw.f_host = strdup(host);
+		f->f_un.f_forw.f_port = strdup(port);
+		if (f->f_un.f_forw.f_ipproto == NULL ||
+		    f->f_un.f_forw.f_host == NULL ||
+		    f->f_un.f_forw.f_port == NULL) {
+			log_warnx("strdup ipproto host port \"%s\"",
 			    f->f_un.f_forw.f_loghost);
+			free(f->f_un.f_forw.f_ipproto);
+			free(f->f_un.f_forw.f_host);
+			free(f->f_un.f_forw.f_port);
 			break;
 		}
 		f->f_file = -1;
+		loghost_resolve(f);
 		if (strncmp(proto, "udp", 3) == 0) {
+			evtimer_set(&f->f_un.f_forw.f_ev, udp_resolvecb, f);
 			switch (f->f_un.f_forw.f_addr.ss_family) {
+			case AF_UNSPEC:
+				log_debug("resolve \"%s\" delayed",
+				    f->f_un.f_forw.f_loghost);
+				to.tv_sec = 0;
+				to.tv_usec = 1;
+				evtimer_add(&f->f_un.f_forw.f_ev, &to);
+				break;
 			case AF_INET:
 				f->f_file = fd_udp;
 				break;
@@ -2727,26 +2838,23 @@ cfline(char *line, char *progblock, char *hostblock)
 			    tcp_dropcb, tcp_writecb, tcp_errorcb, f)) == NULL) {
 				log_warn("bufferevent \"%s\"",
 				    f->f_un.f_forw.f_loghost);
+				free(f->f_un.f_forw.f_ipproto);
+				free(f->f_un.f_forw.f_host);
+				free(f->f_un.f_forw.f_port);
 				break;
 			}
-			if (strncmp(proto, "tls", 3) == 0) {
-				f->f_un.f_forw.f_host = strdup(host);
-				f->f_type = F_FORWTLS;
-			} else {
-				f->f_type = F_FORWTCP;
-			}
 			/*
 			 * If we try to connect to a TLS server immediately
 			 * syslogd gets an SIGPIPE as the signal handlers have
 			 * not been set up.  Delay the connection until the
-			 * event loop is started.  We can reuse the write event
-			 * for that as bufferevent is still disabled.
+			 * event loop is started.
 			 */
+			evtimer_set(&f->f_un.f_forw.f_ev, tcp_connectcb, f);
 			to.tv_sec = 0;
 			to.tv_usec = 1;
-			evtimer_set(&f->f_un.f_forw.f_bufev->ev_write,
-			    tcp_connectcb, f);
-			evtimer_add(&f->f_un.f_forw.f_bufev->ev_write, &to);
+			evtimer_add(&f->f_un.f_forw.f_ev, &to);
+			f->f_type = (strncmp(proto, "tls", 3) == 0) ?
+			    F_FORWTLS : F_FORWTCP;
 		}
 		break;
 
diff --git a/usr.sbin/syslogd/syslogd.h b/usr.sbin/syslogd/syslogd.h
index f483beb52cf..0ff88cb3835 100644
--- a/usr.sbin/syslogd/syslogd.h
+++ b/usr.sbin/syslogd/syslogd.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: syslogd.h,v 1.36 2022/01/13 10:34:07 martijn Exp $ */
+/*	$OpenBSD: syslogd.h,v 1.37 2023/10/12 22:36:54 bluhm Exp $ */
 
 /*
  * Copyright (c) 2014-2017 Alexander Bluhm <bluhm@genua.de>
@@ -34,7 +34,8 @@ FILE *priv_open_utmp(void);
 FILE *priv_open_config(void);
 void  priv_config_parse_done(void);
 int   priv_config_modified(void);
-int   priv_getaddrinfo(char *, char *, char *, struct sockaddr *, size_t);
+int   priv_getaddrinfo(const char *, const char *, const char *,
+    struct sockaddr *, size_t);
 int   priv_getnameinfo(struct sockaddr *, socklen_t, char *, size_t);
 
 #define IOVCNT		7