diff options
32 files changed, 516 insertions, 325 deletions
diff --git a/usr.sbin/smtpd/aliases.c b/usr.sbin/smtpd/aliases.c index 5c7d8420ad2..4827c8d34d3 100644 --- a/usr.sbin/smtpd/aliases.c +++ b/usr.sbin/smtpd/aliases.c @@ -1,4 +1,4 @@ -/* $OpenBSD: aliases.c,v 1.57 2012/10/13 08:01:47 eric Exp $ */ +/* $OpenBSD: aliases.c,v 1.58 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -68,7 +68,7 @@ aliases_get(objid_t mapid, struct expand *expand, const char *username) expand_free(&map_alias->expand); free(map_alias); - log_debug("aliases_get: returned %zd aliases", nbaliases); + log_debug("debug: aliases_get: returned %zd aliases", nbaliases); return nbaliases; } @@ -110,7 +110,7 @@ aliases_virtual_get(objid_t mapid, struct expand *expand, expand_free(&map_virtual->expand); free(map_virtual); - log_debug("aliases_virtual_get: '%s' resolved to %d nodes", pbuf, nbaliases); + log_debug("debug: aliases_virtual_get: '%s' resolved to %d nodes", pbuf, nbaliases); return nbaliases; } @@ -127,7 +127,7 @@ aliases_vdomain_exists(objid_t mapid, const char *hostname) return (errno ? -1 : 0); /* XXX - for now the map API always allocate */ - log_debug("aliases_vdomain_exist: '%s' exists", hostname); + log_debug("debug: aliases_vdomain_exist: '%s' exists", hostname); expand_free(&map_virtual->expand); free(map_virtual); @@ -146,7 +146,7 @@ aliases_expand_include(struct expand *expand, const char *filename) fp = fopen(filename, "r"); if (fp == NULL) { - log_warn("failed to open include file \"%s\".", filename); + log_warn("warn: failed to open include file \"%s\".", filename); return 0; } @@ -157,11 +157,11 @@ aliases_expand_include(struct expand *expand, const char *filename) } if (! alias_parse(&xn, line)) { - log_warnx("could not parse include entry \"%s\".", line); + log_warnx("warn: could not parse include entry \"%s\".", line); } if (xn.type == EXPAND_INCLUDE) - log_warnx("nested inclusion is not supported."); + log_warnx("warn: nested inclusion is not supported."); else expand_insert(expand, &xn); diff --git a/usr.sbin/smtpd/bounce.c b/usr.sbin/smtpd/bounce.c index 712de82a868..e2f09e6163e 100644 --- a/usr.sbin/smtpd/bounce.c +++ b/usr.sbin/smtpd/bounce.c @@ -1,4 +1,4 @@ -/* $OpenBSD: bounce.c,v 1.51 2012/10/07 15:46:38 chl Exp $ */ +/* $OpenBSD: bounce.c,v 1.52 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2009 Gilles Chehade <gilles@openbsd.org> @@ -111,7 +111,7 @@ bounce_add(uint64_t evpid) bounce->msgid = evpid_to_msgid(evpid); tree_xset(&bounces_by_msgid, bounce->msgid, bounce); - log_debug("bounce: %p: new bounce for msg:%08" PRIx32, + log_debug("debug: bounce: %p: new bounce for msg:%08" PRIx32, bounce, bounce->msgid); TAILQ_INIT(&bounce->envelopes); @@ -121,7 +121,7 @@ bounce_add(uint64_t evpid) evtimer_add(&bounce->evt, &tv); } - log_debug("bounce: %p: adding evp:%16" PRIx64, bounce, evp->id); + log_debug("debug: bounce: %p: adding evp:%16" PRIx64, bounce, evp->id); TAILQ_INSERT_TAIL(&bounce->envelopes, evp, entry); bounce->count += 1; @@ -158,7 +158,7 @@ bounce_run(uint64_t id, int fd) } if ((bounce->msgfp = fdopen(msgfd, "r")) == NULL) { - log_warn("bounce_run: fdopen"); + log_warn("warn: bounce_run: fdopen"); bounce_status(bounce, "error %i in fdopen", errno); bounce_free(bounce); close(msgfd); @@ -203,20 +203,20 @@ bounce_drain() while ((bounce = TAILQ_FIRST(&runnable))) { if (running >= BOUNCE_MAXRUN) { - log_debug("bounce: max session reached"); + log_debug("debug: bounce: max session reached"); return; } TAILQ_REMOVE(&runnable, bounce, entry); if (TAILQ_FIRST(&bounce->envelopes) == NULL) { - log_debug("bounce: %p: no envelopes", bounce); + log_debug("debug: bounce: %p: no envelopes", bounce); bounce_free(bounce); continue; } tree_xset(&bounces_by_uid, bounce->id, bounce); - log_debug("bounce: %p: requesting enqueue socket with id 0x%016" PRIx64, + log_debug("debug: bounce: %p: requesting enqueue socket with id 0x%016" PRIx64, bounce, bounce->id); imsg_compose_event(env->sc_ievs[PROC_SMTP], IMSG_SMTP_ENQUEUE, @@ -408,7 +408,7 @@ bounce_free(struct bounce *bounce) { struct envelope *evp; - log_debug("bounce: %p: deleting session", bounce); + log_debug("debug: bounce: %p: deleting session", bounce); /* if the envelopes where not sent, it is still in the tree */ tree_pop(&bounces_by_msgid, bounce->msgid); diff --git a/usr.sbin/smtpd/control.c b/usr.sbin/smtpd/control.c index ad85a35c6aa..e1eb8a925a9 100644 --- a/usr.sbin/smtpd/control.c +++ b/usr.sbin/smtpd/control.c @@ -1,4 +1,4 @@ -/* $OpenBSD: control.c,v 1.77 2012/10/15 18:32:25 eric Exp $ */ +/* $OpenBSD: control.c,v 1.78 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2012 Gilles Chehade <gilles@openbsd.org> @@ -36,6 +36,7 @@ #include <stdio.h> #include <stdlib.h> #include <string.h> +#include <time.h> #include <unistd.h> #include "smtpd.h" @@ -64,11 +65,15 @@ static void control_close(struct ctl_conn *); static void control_sig_handler(int, short, void *); static void control_dispatch_ext(int, short, void *); +static void control_digest_update(const char *, size_t, int); + static struct stat_backend *stat_backend = NULL; extern const char *backend_stat; static TAILQ_HEAD(, ctl_conn) ctl_conns; +static struct stat_digest digest; + #define CONTROL_FD_RESERVE 5 static void @@ -96,12 +101,14 @@ control_imsg(struct imsgev *iev, struct imsg *imsg) key = (char*)imsg->data + sizeof (val); if (stat_backend) stat_backend->increment(key, val.u.counter); + control_digest_update(key, val.u.counter, 1); return; case IMSG_STAT_DECREMENT: memmove(&val, imsg->data, sizeof (val)); key = (char*)imsg->data + sizeof (val); if (stat_backend) stat_backend->decrement(key, val.u.counter); + control_digest_update(key, val.u.counter, 0); return; case IMSG_STAT_SET: memmove(&val, imsg->data, sizeof (val)); @@ -221,6 +228,9 @@ control(void) TAILQ_INIT(&ctl_conns); + bzero(&digest, sizeof digest); + digest.startup = time(NULL); + config_pipes(peers, nitems(peers)); config_peers(peers, nitems(peers)); control_listen(); @@ -235,7 +245,7 @@ control(void) static void control_shutdown(void) { - log_info("control process exiting"); + log_info("info: control process exiting"); unlink(SMTPD_SOCKET); _exit(0); } @@ -287,7 +297,7 @@ control_accept(int listenfd, short event, void *arg) return; pause: - log_warnx("ctl client limit hit, disabling new connections"); + log_warnx("warn: ctl client limit hit, disabling new connections"); event_del(&control_state.ev); } @@ -318,11 +328,54 @@ control_close(struct ctl_conn *c) return; if (!event_pending(&control_state.ev, EV_READ, NULL)) { - log_warnx("re-enabling ctl connections"); + log_warnx("warn: re-enabling ctl connections"); event_add(&control_state.ev, NULL); } } +static void +control_digest_update(const char *key, size_t value, int incr) +{ + size_t *p; + + p = NULL; + + if (!strcmp(key, "smtp.session")) { + if (incr) + p = &digest.clt_connect; + else + digest.clt_disconnect += value; + } + else if (!strcmp(key, "scheduler.envelope")) { + if (incr) + p = &digest.evp_enqueued; + else + digest.evp_dequeued += value; + } + else if (!strcmp(key, "scheduler.envelope.expired")) + p = &digest.evp_expired; + else if (!strcmp(key, "scheduler.envelope.removed")) + p = &digest.evp_removed; + else if (!strcmp(key, "scheduler.delivery.ok")) + p = &digest.dlv_ok; + else if (!strcmp(key, "scheduler.delivery.permfail")) + p = &digest.dlv_permfail; + else if (!strcmp(key, "scheduler.delivery.tempfail")) + p = &digest.dlv_tempfail; + else if (!strcmp(key, "scheduler.delivery.loop")) + p = &digest.dlv_loop; + + else if (!strcmp(key, "queue.bounce")) + p = &digest.evp_bounce; + + if (p) { + if (incr) + *p = *p + value; + else + *p = *p - value; + } +} + /* ARGSUSED */ static void control_dispatch_ext(int fd, short event, void *arg) @@ -342,7 +395,7 @@ control_dispatch_ext(int fd, short event, void *arg) fatal("getpeereid"); if ((c = control_connbyfd(fd)) == NULL) { - log_warn("control_dispatch_ext: fd %d: not found", fd); + log_warn("warn: control_dispatch_ext: fd %d: not found", fd); return; } @@ -387,6 +440,14 @@ control_dispatch_ext(int fd, short event, void *arg) imsg_compose_event(&c->iev, IMSG_STATS, 0, 0, -1, NULL, 0); break; + case IMSG_DIGEST: + if (euid) + goto badcred; + digest.timestamp = time(NULL); + imsg_compose_event(&c->iev, IMSG_DIGEST, 0, 0, -1, + &digest, sizeof digest); + break; + case IMSG_STATS_GET: if (euid) goto badcred; @@ -403,7 +464,7 @@ control_dispatch_ext(int fd, short event, void *arg) case IMSG_CTL_SHUTDOWN: /* NEEDS_FIX */ - log_debug("received shutdown request"); + log_debug("debug: received shutdown request"); if (euid) goto badcred; @@ -443,7 +504,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("mda paused"); + log_info("info: mda paused"); env->sc_flags |= SMTPD_MDA_PAUSED; imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_PAUSE_MDA, 0, 0, -1, NULL, 0); @@ -459,7 +520,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("mta paused"); + log_info("info: mta paused"); env->sc_flags |= SMTPD_MTA_PAUSED; imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_PAUSE_MTA, 0, 0, -1, NULL, 0); @@ -475,7 +536,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("smtp paused"); + log_info("info: smtp paused"); env->sc_flags |= SMTPD_SMTP_PAUSED; imsg_compose_event(env->sc_ievs[PROC_SMTP], IMSG_SMTP_PAUSE, 0, 0, -1, NULL, 0); @@ -491,7 +552,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("mda resumed"); + log_info("info: mda resumed"); env->sc_flags &= ~SMTPD_MDA_PAUSED; imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_RESUME_MDA, 0, 0, -1, NULL, 0); @@ -507,7 +568,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("mta resumed"); + log_info("info: mta resumed"); env->sc_flags &= ~SMTPD_MTA_PAUSED; imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_RESUME_MTA, 0, 0, -1, NULL, 0); @@ -523,7 +584,7 @@ control_dispatch_ext(int fd, short event, void *arg) NULL, 0); break; } - log_info("smtp resumed"); + log_info("info: smtp resumed"); env->sc_flags &= ~SMTPD_SMTP_PAUSED; imsg_compose_event(env->sc_ievs[PROC_SMTP], IMSG_SMTP_RESUME, 0, 0, -1, NULL, 0); @@ -566,7 +627,7 @@ control_dispatch_ext(int fd, short event, void *arg) break; default: - log_debug("control_dispatch_ext: " + log_debug("debug: control_dispatch_ext: " "error handling %s imsg", imsg_to_str(imsg.hdr.type)); break; diff --git a/usr.sbin/smtpd/dns.c b/usr.sbin/smtpd/dns.c index 3d00e4ee223..c3dad9f77a3 100644 --- a/usr.sbin/smtpd/dns.c +++ b/usr.sbin/smtpd/dns.c @@ -1,4 +1,4 @@ -/* $OpenBSD: dns.c,v 1.60 2012/10/08 08:46:24 eric Exp $ */ +/* $OpenBSD: dns.c,v 1.61 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -128,10 +128,10 @@ dns_async(struct imsgev *asker, int type, struct dns *query) switch (type) { case IMSG_DNS_HOST: - log_debug("dns: lookup host \"%s\"", query->host); + log_debug("debug: dns: lookup host \"%s\"", query->host); if (sockaddr_from_str((struct sockaddr*)&query->ss, PF_UNSPEC, query->host) == 0) { - log_debug("dns: \"%s\" is an IP address", query->host); + log_debug("debug: dns: \"%s\" is an IP address", query->host); query->error = DNS_OK; dns_reply(query, IMSG_DNS_HOST); dns_reply(query, IMSG_DNS_HOST_END); @@ -149,23 +149,23 @@ dns_async(struct imsgev *asker, int type, struct dns *query) s->query.host, sizeof(s->query.host), NULL, 0, 0, NULL); stat_increment("lka.session.cname", 1); if (s->as == NULL) { - log_debug("dns_async: asr_query_cname error"); + log_debug("debug: dns_async: asr_query_cname error"); break; } dns_asr_dispatch_cname(s); return; case IMSG_DNS_MX: - log_debug("dns: lookup mx \"%s\"", query->host); + log_debug("debug: dns: lookup mx \"%s\"", query->host); s->as = res_query_async(query->host, C_IN, T_MX, NULL, 0, NULL); stat_increment("lka.session.mx", 1); if (s->as == NULL) { - log_debug("dns_async: asr_query_dns error"); + log_debug("debug: dns_async: asr_query_dns error"); break; } dns_asr_dispatch_mx(s); return; default: - log_debug("dns_async: bad request"); + log_debug("debug: dns_async: bad request"); break; } @@ -294,7 +294,7 @@ next: if (mx == NULL || (s->preference != -1 && s->preference <= mx->preference)) { if (mx) - log_debug("dns: ignoring mx with lower preference"); + log_debug("debug: dns: ignoring mx with lower preference"); if (s->mxfound) query->error = DNS_OK; dns_reply(query, IMSG_DNS_HOST_END); @@ -302,7 +302,7 @@ next: return; } - log_debug("dns: resolving address for \"%s\"", mx->host); + log_debug("debug: dns: resolving address for \"%s\"", mx->host); memset(&hints, 0, sizeof(hints)); hints.ai_family = PF_UNSPEC; @@ -321,7 +321,7 @@ next: if (ar.ar_gai_errno == 0) { for (ai = ar.ar_addrinfo; ai; ai = ai->ai_next) { memcpy(&query->ss, ai->ai_addr, ai->ai_addrlen); - log_debug("dns: got address %s", ss_to_text(&query->ss)); + log_debug("debug: dns: got address %s", ss_to_text(&query->ss)); dns_reply(query, IMSG_DNS_HOST); s->mxfound++; } @@ -393,7 +393,7 @@ dnssession_mx_insert(struct dnssession *s, const char *host, int preference) mx->host = xstrdup(host, "dnssession_mx_insert"); mx->preference = preference; - log_debug("dns: found mx \"%s\" with preference %i", host, preference); + log_debug("debug: dns: found mx \"%s\" with preference %i", host, preference); TAILQ_FOREACH(e, &s->mx, entry) { if (mx->preference <= e->preference) { @@ -407,7 +407,7 @@ dnssession_mx_insert(struct dnssession *s, const char *host, int preference) end: if (s->preference == -1 && s->query.backup[0] && !strcasecmp(host, s->query.backup)) { - log_debug("dns: found our backup preference"); + log_debug("debug: dns: found our backup preference"); s->preference = preference; } } diff --git a/usr.sbin/smtpd/enqueue.c b/usr.sbin/smtpd/enqueue.c index c5aeb83ec6f..2254a74c208 100644 --- a/usr.sbin/smtpd/enqueue.c +++ b/usr.sbin/smtpd/enqueue.c @@ -1,4 +1,4 @@ -/* $OpenBSD: enqueue.c,v 1.63 2012/09/27 20:34:15 chl Exp $ */ +/* $OpenBSD: enqueue.c,v 1.64 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2005 Henning Brauer <henning@bulabula.org> @@ -406,13 +406,17 @@ send_line(FILE *fp, int v, char *fmt, ...) int ret; va_list ap; - if (v) - printf(">>> "); va_start(ap, fmt); ret = vfprintf(fp, fmt, ap); - if (v) - ret = vprintf(fmt, ap); va_end(ap); + + if (v) { + va_start(ap, fmt); + printf(">>> "); + ret = vprintf(fmt, ap); + va_end(ap); + } + return (ret); } diff --git a/usr.sbin/smtpd/forward.c b/usr.sbin/smtpd/forward.c index 247cb000859..ff1a5580f68 100644 --- a/usr.sbin/smtpd/forward.c +++ b/usr.sbin/smtpd/forward.c @@ -1,4 +1,4 @@ -/* $OpenBSD: forward.c,v 1.31 2012/09/27 17:47:49 chl Exp $ */ +/* $OpenBSD: forward.c,v 1.32 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -82,7 +82,7 @@ forwards_get(int fd, struct expand *expand) cp = p; if (! alias_parse(&xn, buf)) { - log_debug("bad entry in ~/.forward"); + log_debug("debug: bad entry in ~/.forward"); continue; } diff --git a/usr.sbin/smtpd/ioev.c b/usr.sbin/smtpd/ioev.c index 3f66fc6667b..4905c108444 100644 --- a/usr.sbin/smtpd/ioev.c +++ b/usr.sbin/smtpd/ioev.c @@ -1,4 +1,4 @@ -/* $OpenBSD: ioev.c,v 1.7 2012/10/25 18:14:24 eric Exp $ */ +/* $OpenBSD: ioev.c,v 1.8 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2012 Eric Faurot <eric@openbsd.org> * @@ -543,7 +543,7 @@ io_dispatch(int fd, short ev, void *humppa) if (ev & EV_WRITE && (w = io_queued(io))) { if ((n = iobuf_write(io->iobuf, io->sock)) < 0) { if (n == IOBUF_ERROR || n == IOBUF_WANT_WRITE) - log_warn("io_dispatch: iobuf_write"); + log_warn("warn: io_dispatch: iobuf_write"); if (n == IOBUF_WANT_WRITE) /* kqueue bug? */ goto read; io_callback(io, n == IOBUF_CLOSED ? @@ -558,7 +558,7 @@ io_dispatch(int fd, short ev, void *humppa) if (ev & EV_READ) { if ((n = iobuf_read(io->iobuf, io->sock)) < 0) { if (n == IO_ERROR) - log_warn("io_dispatch: iobuf_read"); + log_warn("warn: io_dispatch: iobuf_read"); io_callback(io, n == IOBUF_CLOSED ? IO_DISCONNECTED : IO_ERROR); goto leave; diff --git a/usr.sbin/smtpd/lka.c b/usr.sbin/smtpd/lka.c index 0b260b8ef20..eb412c50992 100644 --- a/usr.sbin/smtpd/lka.c +++ b/usr.sbin/smtpd/lka.c @@ -1,4 +1,4 @@ -/* $OpenBSD: lka.c,v 1.145 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: lka.c,v 1.146 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Pierre-Yves Ritschard <pyr@openbsd.org> @@ -107,7 +107,7 @@ lka_imsg(struct imsgev *iev, struct imsg *imsg) secret = imsg->data; map = map_findbyname(secret->mapname); if (map == NULL) { - log_warn("lka: credentials map %s is missing", + log_warn("warn: lka: credentials map %s is missing", secret->mapname); imsg_compose_event(iev, IMSG_LKA_SECRET, 0, 0, -1, secret, sizeof *secret); @@ -115,15 +115,15 @@ lka_imsg(struct imsgev *iev, struct imsg *imsg) } map_credentials = map_lookup(map->m_id, secret->host, K_CREDENTIALS); - log_debug("lka: %s credentials lookup (%d)", secret->host, + log_debug("debug: lka: %s credentials lookup (%d)", secret->host, map_credentials != NULL); secret->secret[0] = '\0'; if (map_credentials == NULL) - log_warnx("%s credentials not found", + log_warnx("warn: %s credentials not found", secret->host); else if (lka_encode_credentials(secret->secret, sizeof secret->secret, map_credentials) == 0) - log_warnx("%s credentials parse fail", + log_warnx("warn: %s credentials parse fail", secret->host); imsg_compose_event(iev, IMSG_LKA_SECRET, 0, 0, -1, secret, sizeof *secret); @@ -211,7 +211,7 @@ lka_imsg(struct imsgev *iev, struct imsg *imsg) case IMSG_LKA_UPDATE_MAP: map = map_findbyname(imsg->data); if (map == NULL) { - log_warnx("lka: no such map \"%s\"", + log_warnx("warn: lka: no such map \"%s\"", (char *)imsg->data); return; } @@ -247,7 +247,7 @@ lka_sig_handler(int sig, short event, void *p) void lka_shutdown(void) { - log_info("lookup agent exiting"); + log_info("info: lookup agent exiting"); _exit(0); } diff --git a/usr.sbin/smtpd/lka_session.c b/usr.sbin/smtpd/lka_session.c index 754aba5c9b6..9885c549625 100644 --- a/usr.sbin/smtpd/lka_session.c +++ b/usr.sbin/smtpd/lka_session.c @@ -1,4 +1,4 @@ -/* $OpenBSD: lka_session.c,v 1.48 2012/10/16 11:10:38 eric Exp $ */ +/* $OpenBSD: lka_session.c,v 1.49 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2011 Gilles Chehade <gilles@openbsd.org> @@ -113,12 +113,12 @@ lka_session_forward_reply(struct forward_req *fwreq, int fd) if (fd == -1 && fwreq->status) { /* no .forward, just deliver to local user */ - log_debug("lka: no .forward for user %s, just deliver", + log_debug("debug: lka: no .forward for user %s, just deliver", fwreq->as_user); lka_submit(lks, rule, xn); } else if (fd == -1) { - log_debug("lka: opening .forward failed for user %s", + log_debug("debug: lka: opening .forward failed for user %s", fwreq->as_user); lks->ss.code = 530; lks->flags |= F_ERROR; @@ -159,7 +159,7 @@ lka_resume(struct lka_session *lks) /* delivery list is empty, reject */ if (TAILQ_FIRST(&lks->deliverylist) == NULL) { - log_info("lka_done: expansion led to empty delivery list"); + log_debug("debug: lka_done: expansion led to empty delivery list"); lks->flags |= F_ERROR; } error: @@ -200,7 +200,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) int r; if (xn->depth >= EXPAND_DEPTH) { - log_debug("lka_expand: node too deep."); + log_debug("debug: lka_expand: node too deep."); lks->flags |= F_ERROR; lks->ss.code = 530; return; @@ -213,7 +213,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) break; case EXPAND_ADDRESS: - log_debug("lka_expand: expanding address: %s@%s [depth=%d]", + log_debug("debug: lka_expand: expanding address: %s@%s [depth=%d]", xn->u.mailaddr.user, xn->u.mailaddr.domain, xn->depth); /* Pass the node through the ruleset */ @@ -246,7 +246,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) else if (r == 0) { lks->flags |= F_ERROR; lks->ss.code = 530; - log_debug("lka_expand: no aliases for virtual"); + log_debug("debug: lka_expand: no aliases for virtual"); } } else { @@ -261,10 +261,10 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) break; case EXPAND_USERNAME: - log_debug("lka_expand: expanding username: %s [depth=%d]", xn->u.user, xn->depth); + log_debug("debug: lka_expand: expanding username: %s [depth=%d]", xn->u.user, xn->depth); if (xn->sameuser) { - log_debug("lka_expand: same user, submitting"); + log_debug("debug: lka_expand: same user, submitting"); lka_submit(lks, rule, xn); break; } @@ -276,7 +276,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) if (rule->r_amap) { r = aliases_get(rule->r_amap, &lks->expand, xn->u.user); if (r == -1) { - log_debug("lka_expand: error in alias lookup"); + log_debug("debug: lka_expand: error in alias lookup"); lks->flags |= F_ERROR; lks->ss.code = 451; } @@ -286,7 +286,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) /* a username should not exceed the size of a system user */ if (strlen(xn->u.user) >= sizeof fwreq.as_user) { - log_debug("lka_expand: user-part too long to be a system user"); + log_debug("debug: lka_expand: user-part too long to be a system user"); lks->flags |= F_ERROR; lks->ss.code = 530; break; @@ -294,7 +294,7 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) pw = getpwnam(xn->u.user); if (pw == NULL) { - log_debug("lka_expand: user-part does not match system user"); + log_debug("debug: lka_expand: user-part does not match system user"); lks->flags |= F_ERROR; lks->ss.code = 530; break; @@ -311,12 +311,12 @@ lka_expand(struct lka_session *lks, struct rule *rule, struct expandnode *xn) break; case EXPAND_FILENAME: - log_debug("lka_expand: expanding filename: %s [depth=%d]", xn->u.buffer, xn->depth); + log_debug("debug: lka_expand: expanding filename: %s [depth=%d]", xn->u.buffer, xn->depth); lka_submit(lks, rule, xn); break; case EXPAND_FILTER: - log_debug("lka_expand: expanding filter: %s [depth=%d]", xn->u.buffer, xn->depth); + log_debug("debug: lka_expand: expanding filter: %s [depth=%d]", xn->u.buffer, xn->depth); lka_submit(lks, rule, xn); break; } @@ -328,7 +328,7 @@ lka_find_ancestor(struct expandnode *xn, enum expand_type type) while(xn && (xn->type != type)) xn = xn->parent; if (xn == NULL) { - log_warnx("lka_find_ancestor: no ancestors of type %i", type); + log_warnx("warn: lka_find_ancestor: no ancestors of type %i", type); fatalx(NULL); } return (xn); @@ -407,7 +407,7 @@ lka_submit(struct lka_session *lks, struct rule *rule, struct expandnode *xn) sizeof(ep->agent.mda.buffer), ep)) { lks->flags |= F_ERROR; lks->ss.code = 451; - log_warnx("format string result too long while " + log_warnx("warn: format string result too long while " " expanding for user %s", ep->agent.mda.user); free(ep); return; diff --git a/usr.sbin/smtpd/map.c b/usr.sbin/smtpd/map.c index 5eb39173e16..2adbe2e55c8 100644 --- a/usr.sbin/smtpd/map.c +++ b/usr.sbin/smtpd/map.c @@ -1,4 +1,4 @@ -/* $OpenBSD: map.c,v 1.34 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: map.c,v 1.35 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -102,7 +102,7 @@ map_lookup(objid_t mapid, const char *key, enum map_kind kind) backend = map_backend_lookup(map->m_src); hdl = backend->open(map); if (hdl == NULL) { - log_warn("map_lookup: can't open %s", map->m_config); + log_warn("warn: map_lookup: can't open %s", map->m_config); if (errno == 0) errno = ENOTSUP; return NULL; @@ -133,7 +133,7 @@ map_compare(objid_t mapid, const char *key, enum map_kind kind, backend = map_backend_lookup(map->m_src); hdl = backend->open(map); if (hdl == NULL) { - log_warn("map_compare: can't open %s", map->m_config); + log_warn("warn: map_compare: can't open %s", map->m_config); if (errno == 0) errno = ENOTSUP; return 0; @@ -203,14 +203,14 @@ map_add(struct map *m, const char *key, const char * val) errx(1, "map_add: cannot add to map"); me = xcalloc(1, sizeof(*me), "map_add"); - n = strlcpy(me->me_key.med_string, key, sizeof(me->me_key.med_string)); - if (n >= sizeof(me->me_key.med_string)) + n = strlcpy(me->me_key, key, sizeof(me->me_key)); + if (n >= sizeof(me->me_key)) errx(1, "map_add: key too long"); if (val) { - n = strlcpy(me->me_val.med_string, val, - sizeof(me->me_val.med_string)); - if (n >= sizeof(me->me_val.med_string)) + n = strlcpy(me->me_val, val, + sizeof(me->me_val)); + if (n >= sizeof(me->me_val)) errx(1, "map_add: value too long"); } @@ -226,7 +226,7 @@ map_delete(struct map *m, const char *key) errx(1, "map_add: cannot delete from map"); TAILQ_FOREACH(me, &m->m_contents, me_entry) { - if (strcmp(me->me_key.med_string, key) == 0) + if (strcmp(me->me_key, key) == 0) break; } if (me == NULL) diff --git a/usr.sbin/smtpd/map_db.c b/usr.sbin/smtpd/map_db.c index 4e33ac6c149..afbd2e1cd1c 100644 --- a/usr.sbin/smtpd/map_db.c +++ b/usr.sbin/smtpd/map_db.c @@ -1,4 +1,4 @@ -/* $OpenBSD: map_db.c,v 1.11 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: map_db.c,v 1.12 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2011 Gilles Chehade <gilles@openbsd.org> @@ -125,7 +125,7 @@ map_db_compare(void *hdl, const char *key, enum map_kind kind, for (r = db->seq(db, &dbk, &dbd, R_FIRST); !r; r = db->seq(db, &dbk, &dbd, R_NEXT)) { buf = xmemdup(dbk.data, dbk.size + 1, "map_db_compare"); - log_debug("key: %s, buf: %s", key, buf); + log_debug("debug: key: %s, buf: %s", key, buf); if (func(key, buf)) ret = 1; free(buf); diff --git a/usr.sbin/smtpd/map_file.c b/usr.sbin/smtpd/map_file.c index 8d9e612fcad..47977dcf523 100644 --- a/usr.sbin/smtpd/map_file.c +++ b/usr.sbin/smtpd/map_file.c @@ -1,4 +1,4 @@ -/* $OpenBSD: map_file.c,v 1.1 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: map_file.c,v 1.2 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2012 Gilles Chehade <gilles@openbsd.org> @@ -112,7 +112,7 @@ map_file_open(struct map *map) map->m_handle = mp; - log_info("map_file_open: initialized map \"%s\" from %s", + log_debug("debug: map_file_open: initialized map \"%s\" from %s", map->m_name, map->m_config); return mp; @@ -135,8 +135,8 @@ map_file_update(struct map *map) fp = fopen(map->m_config, "r"); if (fp == NULL) { - log_info("map_file_update: could not update map \"%s\" from %s: %s", - map->m_name, map->m_config, strerror(errno)); + log_warn("warn: Could not update map \"%s\" from %s", + map->m_name, map->m_config); return; } @@ -150,8 +150,7 @@ map_file_update(struct map *map) } map->m_handle = mp; - log_info("map_file_update: updated map \"%s\" from %s", - map->m_name, map->m_config); + log_info("info: Updated map \"%s\" from %s", map->m_name, map->m_config); } static void diff --git a/usr.sbin/smtpd/map_static.c b/usr.sbin/smtpd/map_static.c index c66da1025b1..9f998243fec 100644 --- a/usr.sbin/smtpd/map_static.c +++ b/usr.sbin/smtpd/map_static.c @@ -1,4 +1,4 @@ -/* $OpenBSD: map_static.c,v 1.8 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: map_static.c,v 1.9 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2012 Gilles Chehade <gilles@openbsd.org> @@ -78,10 +78,10 @@ map_static_lookup(void *hdl, const char *key, enum map_kind kind) line = NULL; TAILQ_FOREACH(me, &m->m_contents, me_entry) { - if (strcmp(key, me->me_key.med_string) == 0) { - if (me->me_val.med_string == NULL) + if (strcmp(key, me->me_key) == 0) { + if (me->me_val == NULL) return NULL; - line = strdup(me->me_val.med_string); + line = strdup(me->me_val); break; } } @@ -126,7 +126,7 @@ map_static_compare(void *hdl, const char *key, enum map_kind kind, int ret = 0; TAILQ_FOREACH(me, &m->m_contents, me_entry) { - if (! func(key, me->me_key.med_string)) + if (! func(key, me->me_key)) continue; ret = 1; break; diff --git a/usr.sbin/smtpd/mda.c b/usr.sbin/smtpd/mda.c index e7a1ffe03a3..95c4a812481 100644 --- a/usr.sbin/smtpd/mda.c +++ b/usr.sbin/smtpd/mda.c @@ -1,4 +1,4 @@ -/* $OpenBSD: mda.c,v 1.83 2012/11/02 16:02:33 eric Exp $ */ +/* $OpenBSD: mda.c,v 1.84 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -107,7 +107,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) ep = xmemdup(imsg->data, sizeof *ep, "mda_imsg"); if (evpcount >= MDA_MAXEVP) { - log_debug("mda: too many envelopes"); + log_debug("debug: mda: too many envelopes"); envelope_set_errormsg(ep, "Global envelope limit reached"); imsg_compose_event(env->sc_ievs[PROC_QUEUE], @@ -122,7 +122,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) if (!strcmp(name, u->name)) break; if (u && u->evpcount >= MDA_MAXEVPUSER) { - log_debug("mda: too many envelopes for \"%s\"", + log_debug("debug: mda: too many envelopes for \"%s\"", u->name); envelope_set_errormsg(ep, "User envelope limit reached"); @@ -139,7 +139,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) TAILQ_INSERT_TAIL(&users, u, entry); } if (u->runnable == 0 && u->running < MDA_MAXSESSUSER) { - log_debug("mda: \"%s\" immediatly runnable", + log_debug("debug: mda: \"%s\" immediatly runnable", u->name); TAILQ_INSERT_TAIL(&runnable, u, entry_runnable); u->runnable = 1; @@ -158,7 +158,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) s = tree_xget(&sessions, id); if (imsg->fd == -1) { - log_debug("mda: cannot get message fd"); + log_debug("debug: mda: cannot get message fd"); envelope_set_errormsg(s->evp, "Cannot get message fd"); mda_done(s, IMSG_QUEUE_DELIVERY_TEMPFAIL); @@ -166,7 +166,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) } if ((s->datafp = fdopen(imsg->fd, "r")) == NULL) { - log_warn("mda: fdopen"); + log_warn("warn: mda: fdopen"); envelope_set_errormsg(s->evp, "fdopen failed"); mda_done(s, IMSG_QUEUE_DELIVERY_TEMPFAIL); return; @@ -174,7 +174,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) /* check delivery loop */ if (mda_check_loop(s->datafp, s->evp)) { - log_debug("mda: loop detected"); + log_debug("debug: mda: loop detected"); envelope_set_errormsg(s->evp, "Loop detected"); mda_done(s, IMSG_QUEUE_DELIVERY_LOOP); return; @@ -194,7 +194,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) s->evp->rcpt.user, s->evp->rcpt.domain); if (n == -1) { - log_warn("mda: fail to write delivery info"); + log_warn("warn: mda: fail to write delivery info"); envelope_set_errormsg(s->evp, "Out of memory"); mda_done(s, IMSG_QUEUE_DELIVERY_TEMPFAIL); return; @@ -256,7 +256,7 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) case IMSG_PARENT_FORK_MDA: s = tree_xget(&sessions, imsg->hdr.peerid); if (imsg->fd == -1) { - log_warn("mda: fail to retreive mda fd"); + log_warn("warn: mda: fail to retreive mda fd"); envelope_set_errormsg(s->evp, "Cannot get mda fd"); mda_done(s, IMSG_QUEUE_DELIVERY_TEMPFAIL); @@ -297,7 +297,8 @@ mda_imsg(struct imsgev *iev, struct imsg *imsg) envelope_set_errormsg(s->evp, "%s", error); snprintf(stat, sizeof stat, "Error (%s)", error); } - log_envelope(s->evp, NULL, error ? stat : "Delivered"); + log_envelope(s->evp, NULL, error ? "TempFail" : "Ok", + error ? stat : "Delivered"); mda_done(s, msg); return; @@ -326,7 +327,7 @@ mda_sig_handler(int sig, short event, void *p) static void mda_shutdown(void) { - log_info("mail delivery agent exiting"); + log_info("info: mail delivery agent exiting"); _exit(0); } @@ -429,7 +430,7 @@ mda_io(struct io *io, int evt) } if (ferror(s->datafp)) { - log_debug("mda_io: %p: ferror", s); + log_debug("debug: mda_io: %p: ferror", s); snprintf(buf, sizeof buf, "Error reading body"); imsg_compose_event(env->sc_ievs[PROC_PARENT], IMSG_PARENT_KILL_MDA, s->id, 0, -1, @@ -445,22 +446,22 @@ mda_io(struct io *io, int evt) return; case IO_TIMEOUT: - log_debug("mda_io: timeout"); + log_debug("debug: mda_io: timeout"); io_pause(io, IO_PAUSE_OUT); return; case IO_ERROR: - log_debug("mda_io: io error: %s", strerror(errno)); + log_debug("debug: mda_io: io error: %s", strerror(errno)); io_pause(io, IO_PAUSE_OUT); return; case IO_DISCONNECTED: - log_debug("mda_io: disconnected"); + log_debug("debug: mda_io: disconnected"); io_pause(io, IO_PAUSE_OUT); return; default: - log_debug("mda_io: unexpected io event: %i", evt); + log_debug("debug: mda_io: unexpected io event: %i", evt); io_pause(io, IO_PAUSE_OUT); return; } @@ -521,13 +522,13 @@ mda_getlastline(int fd, char *dst, size_t dstsz) size_t len; if (lseek(fd, 0, SEEK_SET) < 0) { - log_warn("mda: lseek"); + log_warn("warn: mda: lseek"); close(fd); return (-1); } fp = fdopen(fd, "r"); if (fp == NULL) { - log_warn("mda: fdopen"); + log_warn("warn: mda: fdopen"); close(fd); return (-1); } @@ -561,11 +562,11 @@ mda_drain(void) while ((user = (TAILQ_FIRST(&runnable)))) { if (running >= MDA_MAXSESS) { - log_debug("mda: maximum number of session reached"); + log_debug("debug: mda: maximum number of session reached"); return; } - log_debug("mda: new session for user \"%s\"", user->name); + log_debug("debug: mda: new session for user \"%s\"", user->name); s = xcalloc(1, sizeof *s, "mda_drain"); s->user = user; @@ -601,7 +602,7 @@ mda_drain(void) user->running < MDA_MAXSESSUSER) { TAILQ_INSERT_TAIL(&runnable, user, entry_runnable); user->runnable = 1; - log_debug("mda: user \"%s\" still runnable", user->name); + log_debug("debug: mda: user \"%s\" still runnable", user->name); } } } @@ -620,13 +621,13 @@ mda_done(struct mda_session *s, int msg) stat_decrement("mda.running", 1); if (TAILQ_FIRST(&s->user->envelopes) == NULL && s->user->running == 0) { - log_debug("mda: all done for user \"%s\"", s->user->name); + log_debug("debug: mda: all done for user \"%s\"", s->user->name); TAILQ_REMOVE(&users, s->user, entry); free(s->user); } else if (s->user->runnable == 0 && TAILQ_FIRST(&s->user->envelopes) && s->user->running < MDA_MAXSESSUSER) { - log_debug("mda: user \"%s\" becomes runnable", + log_debug("debug: mda: user \"%s\" becomes runnable", s->user->name); TAILQ_INSERT_TAIL(&runnable, s->user, entry_runnable); s->user->runnable = 1; diff --git a/usr.sbin/smtpd/mfa.c b/usr.sbin/smtpd/mfa.c index 261ccca0996..921d75052c3 100644 --- a/usr.sbin/smtpd/mfa.c +++ b/usr.sbin/smtpd/mfa.c @@ -1,4 +1,4 @@ -/* $OpenBSD: mfa.c,v 1.72 2012/10/25 14:06:08 eric Exp $ */ +/* $OpenBSD: mfa.c,v 1.73 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -121,7 +121,7 @@ mfa_imsg(struct imsgev *iev, struct imsg *imsg) case IMSG_CONF_END: TAILQ_FOREACH(filter, env->sc_filters, f_entry) { - log_info("forking filter: %s", filter->name); + log_info("info: Forking filter: %s", filter->name); if (! mfa_fork_filter(filter)) fatalx("could not fork filter"); } @@ -168,7 +168,7 @@ mfa_shutdown(void) pid = waitpid(WAIT_MYPGRP, NULL, 0); } while (pid != -1 || (pid == -1 && errno == EINTR)); - log_info("mail filter exiting"); + log_info("info: mail filter exiting"); _exit(0); } diff --git a/usr.sbin/smtpd/mta.c b/usr.sbin/smtpd/mta.c index 20f90bccec1..4e414c072c7 100644 --- a/usr.sbin/smtpd/mta.c +++ b/usr.sbin/smtpd/mta.c @@ -1,4 +1,4 @@ -/* $OpenBSD: mta.c,v 1.147 2012/10/11 21:52:59 gilles Exp $ */ +/* $OpenBSD: mta.c,v 1.148 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Pierre-Yves Ritschard <pyr@openbsd.org> @@ -119,7 +119,7 @@ mta_imsg(struct imsgev *iev, struct imsg *imsg) /* XXX honour route->maxrcpt */ TAILQ_INSERT_TAIL(&task->envelopes, e, entry); stat_increment("mta.envelope", 1); - log_debug("mta: received evp:%016" PRIx64 " for <%s@%s>", + log_debug("debug: mta: received evp:%016" PRIx64 " for <%s@%s>", e->id, e->dest.user, e->dest.domain); return; @@ -209,7 +209,7 @@ mta_sig_handler(int sig, short event, void *p) static void mta_shutdown(void) { - log_info("mail transfer agent exiting"); + log_info("info: mail transfer agent exiting"); _exit(0); } @@ -305,6 +305,22 @@ mta_response_delivery(const char *r) } const char * +mta_response_prefix(const char *r) +{ + switch (r[0]) { + case '2': + return "Ok"; + case '5': + case '6': + if (r[1] == '4' && r[2] == '6') + return "Loop"; + return "PermFail"; + default: + return "TempFail"; + } +} + +const char * mta_response_text(const char *r) { return (r + 4); @@ -315,13 +331,13 @@ mta_route_error(struct mta_route *route, const char *error) { route->nfail += 1; strlcpy(route->errorline, error, sizeof route->errorline); - log_warnx("mta: %s error: %s", mta_route_to_text(route), error); + log_warnx("warn: mta: %s error: %s", mta_route_to_text(route), error); } void mta_route_ok(struct mta_route *route) { - log_debug("mta: %s ready", mta_route_to_text(route)); + log_debug("debug: mta: %s ready", mta_route_to_text(route)); route->nfail = 0; } @@ -465,7 +481,7 @@ mta_route_drain(struct mta_route *route) struct mta_task *task; struct envelope *e; - log_debug("mta: draining %s (tasks=%i, refs=%i, sessions=%i)", + log_debug("debug: mta: draining %s (tasks=%i, refs=%i, sessions=%i)", mta_route_to_text(route), route->ntask, route->refcount, route->nsession); @@ -476,7 +492,7 @@ mta_route_drain(struct mta_route *route) } if (route->ntask == 0) { - log_debug("mta: no task for %s", mta_route_to_text(route)); + log_debug("debug: mta: no task for %s", mta_route_to_text(route)); return; } @@ -484,7 +500,7 @@ mta_route_drain(struct mta_route *route) /* Three connection errors in a row: consider that the route * has a problem. */ - log_debug("mta: too many failures on %s", + log_debug("debug: mta: too many failures on %s", mta_route_to_text(route)); while ((task = TAILQ_FIRST(&route->tasks))) { @@ -504,7 +520,7 @@ mta_route_drain(struct mta_route *route) while (route->nsession < route->ntask) { /* if we have reached the max number of session, wait */ if (route->nsession >= route->maxconn) { - log_debug("mta: max conn reached for %s", + log_debug("debug: mta: max conn reached for %s", mta_route_to_text(route)); return; } @@ -516,13 +532,13 @@ mta_route_drain(struct mta_route *route) static void mta_envelope_done(struct mta_task *task, struct envelope *e, const char *status) { - char relay[MAX_LINE_SIZE]; + char relay[MAX_LINE_SIZE]; envelope_set_errormsg(e, "%s", status); snprintf(relay, sizeof relay, "relay=%s, ", task->route->hostname); - log_envelope(e, relay, e->errorline); + log_envelope(e, relay, mta_response_prefix(e->errorline), e->errorline); imsg_compose_event(env->sc_ievs[PROC_QUEUE], mta_response_delivery(e->errorline), 0, 0, -1, e, sizeof(*e)); TAILQ_REMOVE(&task->envelopes, e, entry); diff --git a/usr.sbin/smtpd/mta_session.c b/usr.sbin/smtpd/mta_session.c index 832a4a9a37c..9ad17e642af 100644 --- a/usr.sbin/smtpd/mta_session.c +++ b/usr.sbin/smtpd/mta_session.c @@ -1,4 +1,4 @@ -/* $OpenBSD: mta_session.c,v 1.25 2012/11/06 09:25:37 eric Exp $ */ +/* $OpenBSD: mta_session.c,v 1.26 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Pierre-Yves Ritschard <pyr@openbsd.org> @@ -151,7 +151,7 @@ mta_session(struct mta_route *route) session->flags |= MTA_ALLOW_PLAIN; } - log_debug("mta: %p: spawned for %s", session, mta_route_to_text(route)); + log_debug("debug: mta: %p: spawned for %s", session, mta_route_to_text(route)); stat_increment("mta.session", 1); mta_enter_state(session, MTA_INIT); } @@ -179,7 +179,7 @@ mta_session_imsg(struct imsgev *iev, struct imsg *imsg) fatal("mta: fdopen"); if (mta_check_loop(s->datafp)) { - log_debug("mta: loop detected"); + log_debug("debug: mta: loop detected"); fclose(s->datafp); s->datafp = NULL; mta_status(s, 0, "646 Loop detected"); @@ -240,12 +240,12 @@ mta_session_imsg(struct imsgev *iev, struct imsg *imsg) strlcpy(host->fqdn, "<unknown>", sizeof host->fqdn); else strlcpy(host->fqdn, dns->host, sizeof host->fqdn); - log_debug("mta: %p: connected to %s", s, host->fqdn); + log_debug("debug: mta: %p: connected to %s", s, host->fqdn); /* check if we need to start tls now... */ if (((s->flags & MTA_FORCE_ANYSSL) && host->used == 1) || (s->flags & MTA_FORCE_SMTPS)) { - log_debug("mta: %p: trying smtps (ssl=%p)...", s, s->ssl); + log_debug("debug: mta: %p: trying smtps (ssl=%p)...", s, s->ssl); if ((ptr = ssl_mta_init(s->ssl)) == NULL) fatalx("mta: ssl_mta_init"); io_start_tls(&s->io, ptr); @@ -344,7 +344,7 @@ mta_enter_state(struct mta_session *s, int newstate) } host->used++; - log_debug("mta: %p: connecting to %s...", s, + log_debug("debug: mta: %p: connecting to %s...", s, ss_to_text(&host->sa)); sa = (struct sockaddr *)&host->sa; @@ -361,7 +361,7 @@ mta_enter_state(struct mta_session *s, int newstate) io_init(&s->io, -1, s, mta_io, &s->iobuf); io_set_timeout(&s->io, 10000); if (io_connect(&s->io, sa, NULL) == -1) { - log_debug("mta: %p: connection failed: %s", s, + log_debug("debug: mta: %p: connection failed: %s", s, strerror(errno)); iobuf_clear(&s->iobuf); /* @@ -384,7 +384,7 @@ mta_enter_state(struct mta_session *s, int newstate) /* * Kill the mta session. */ - log_debug("mta: %p: session done", s); + log_debug("debug: mta: %p: session done", s); io_clear(&s->io); iobuf_clear(&s->iobuf); if (s->task) @@ -432,7 +432,7 @@ mta_enter_state(struct mta_session *s, int newstate) if (s->secret && s->flags & MTA_TLS) mta_send(s, "AUTH PLAIN %s", s->secret); else if (s->secret) { - log_debug("mta: %p: not using AUTH on non-TLS session", + log_debug("debug: mta: %p: not using AUTH on non-TLS session", s); mta_enter_state(s, MTA_CONNECT); } else { @@ -447,11 +447,11 @@ mta_enter_state(struct mta_session *s, int newstate) mta_route_ok(s->route); } if (s->msgcount >= s->route->maxmail) { - log_debug("mta: %p: cannot send more message to %s", s, + log_debug("debug: mta: %p: cannot send more message to %s", s, mta_route_to_text(s->route)); mta_enter_state(s, MTA_SMTP_QUIT); } else if ((s->task = TAILQ_FIRST(&s->route->tasks))) { - log_debug("mta: %p: handling next task for %s", s, + log_debug("debug: mta: %p: handling next task for %s", s, mta_route_to_text(s->route)); TAILQ_REMOVE(&s->route->tasks, s->task, entry); s->route->ntask -= 1; @@ -460,7 +460,7 @@ mta_enter_state(struct mta_session *s, int newstate) stat_increment("mta.task.running", 1); mta_enter_state(s, MTA_DATA); } else { - log_debug("mta: %p: no pending task for %s", s, + log_debug("debug: mta: %p: no pending task for %s", s, mta_route_to_text(s->route)); /* XXX stay open for a while? */ mta_enter_state(s, MTA_SMTP_QUIT); @@ -711,7 +711,7 @@ mta_io(struct io *io, int evt) iobuf_normalize(&s->iobuf); if (iobuf_len(&s->iobuf)) { - log_debug("mta: remaining data in input buffer"); + log_debug("debug: mta: remaining data in input buffer"); mta_status(s, 1, "150 Remote sent too much data"); mta_enter_state(s, MTA_DONE); } @@ -726,7 +726,7 @@ mta_io(struct io *io, int evt) break; case IO_TIMEOUT: - log_debug("mta: %p: connection timeout", s); + log_debug("debug: mta: %p: connection timeout", s); if (!s->ready) { mta_enter_state(s, MTA_CONNECT); break; @@ -736,7 +736,7 @@ mta_io(struct io *io, int evt) break; case IO_ERROR: - log_debug("mta: %p: IO error: %s", s, strerror(errno)); + log_debug("debug: mta: %p: IO error: %s", s, strerror(errno)); if (!s->ready) { mta_enter_state(s, MTA_CONNECT); break; @@ -746,7 +746,7 @@ mta_io(struct io *io, int evt) break; case IO_DISCONNECTED: - log_debug("mta: %p: disconnected in state %s", s, mta_strstate(s->state)); + log_debug("debug: mta: %p: disconnected in state %s", s, mta_strstate(s->state)); if (!s->ready) { mta_enter_state(s, MTA_CONNECT); break; @@ -851,7 +851,8 @@ mta_envelope_done(struct mta_task *task, struct envelope *e, const char *status) snprintf(stat, sizeof stat, "%s (%s)", mta_response_status(e->errorline), mta_response_text(e->errorline)); - log_envelope(e, relay, stat); + + log_envelope(e, relay, mta_response_prefix(e->errorline), stat); imsg_compose_event(env->sc_ievs[PROC_QUEUE], mta_response_delivery(e->errorline), 0, 0, -1, e, sizeof(*e)); diff --git a/usr.sbin/smtpd/parse.y b/usr.sbin/smtpd/parse.y index 8f8a194b233..017eb61e382 100644 --- a/usr.sbin/smtpd/parse.y +++ b/usr.sbin/smtpd/parse.y @@ -1,4 +1,4 @@ -/* $OpenBSD: parse.y,v 1.109 2012/10/14 11:58:23 gilles Exp $ */ +/* $OpenBSD: parse.y,v 1.110 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -119,12 +119,12 @@ typedef struct { %} -%token AS QUEUE COMPRESSION CIPHER INTERVAL SIZE LISTEN ON ANY PORT EXPIRE -%token MAP HASH LIST SINGLE SSL SMTPS CERTIFICATE ENCRYPTION +%token AS QUEUE COMPRESSION SIZE LISTEN ON ANY PORT EXPIRE +%token MAP HASH LIST SINGLE SSL SMTPS CERTIFICATE %token DB LDAP FILE DOMAIN SOURCE %token RELAY BACKUP VIA DELIVER TO MAILDIR MBOX HOSTNAME %token ACCEPT REJECT INCLUDE ERROR MDA FROM FOR -%token ARROW AUTH TLS LOCAL VIRTUAL TAG ALIAS FILTER KEY DIGEST +%token ARROW AUTH TLS LOCAL VIRTUAL TAG ALIAS FILTER KEY %token AUTH_OPTIONAL TLS_REQUIRE %token <v.string> STRING %token <v.number> NUMBER @@ -313,14 +313,11 @@ compression : COMPRESSION STRING { | /* empty */ { $$ = NULL; } ; -main : QUEUE INTERVAL interval { - conf->sc_qintval = $3; - } - | QUEUE compression { +main : QUEUE compression { if ($2) { conf->sc_queue_flags |= QUEUE_COMPRESS; conf->sc_queue_compress_algo = strdup($2); - log_debug("queue compress using %s", + log_debug("debug: queue compress using %s", conf->sc_queue_compress_algo); } if ($2 == NULL) { @@ -943,13 +940,10 @@ lookup(char *s) { "auth-optional", AUTH_OPTIONAL }, { "backup", BACKUP }, { "certificate", CERTIFICATE }, - { "cipher", CIPHER }, { "compression", COMPRESSION }, { "db", DB }, { "deliver", DELIVER }, - { "digest", DIGEST }, { "domain", DOMAIN }, - { "encryption", ENCRYPTION }, { "expire", EXPIRE }, { "file", FILE }, { "filter", FILTER }, @@ -958,7 +952,6 @@ lookup(char *s) { "hash", HASH }, { "hostname", HOSTNAME }, { "include", INCLUDE }, - { "interval", INTERVAL }, { "key", KEY }, { "ldap", LDAP }, { "list", LIST }, @@ -1248,15 +1241,15 @@ check_file_secrecy(int fd, const char *fname) struct stat st; if (fstat(fd, &st)) { - log_warn("cannot stat %s", fname); + log_warn("warn: cannot stat %s", fname); return (-1); } if (st.st_uid != 0 && st.st_uid != getuid()) { - log_warnx("%s: owner not root or current user", fname); + log_warnx("warn: %s: owner not root or current user", fname); return (-1); } if (st.st_mode & (S_IRWXG | S_IRWXO)) { - log_warnx("%s: group/world readable/writeable", fname); + log_warnx("warn: %s: group/world readable/writeable", fname); return (-1); } return (0); @@ -1268,16 +1261,16 @@ pushfile(const char *name, int secret) struct file *nfile; if ((nfile = calloc(1, sizeof(struct file))) == NULL) { - log_warn("malloc"); + log_warn("warn: malloc"); return (NULL); } if ((nfile->name = strdup(name)) == NULL) { - log_warn("malloc"); + log_warn("warn: malloc"); free(nfile); return (NULL); } if ((nfile->stream = fopen(nfile->name, "r")) == NULL) { - log_warn("%s", nfile->name); + log_warn("warn: %s", nfile->name); free(nfile->name); free(nfile); return (NULL); @@ -1330,7 +1323,7 @@ parse_config(struct smtpd *x_conf, const char *filename, int opts) conf->sc_listeners == NULL || conf->sc_ssl == NULL || conf->sc_filters == NULL) { - log_warn("cannot allocate memory"); + log_warn("warn: cannot allocate memory"); free(conf->sc_maps); free(conf->sc_rules); free(conf->sc_listeners); @@ -1352,8 +1345,6 @@ parse_config(struct smtpd *x_conf, const char *filename, int opts) SPLAY_INIT(&conf->sc_sessions); conf->sc_qexpire = SMTPD_QUEUE_EXPIRY; - conf->sc_qintval.tv_sec = SMTPD_QUEUE_INTERVAL; - conf->sc_qintval.tv_usec = 0; conf->sc_opts = opts; if ((file = pushfile(filename, 0)) == NULL) { @@ -1391,14 +1382,14 @@ parse_config(struct smtpd *x_conf, const char *filename, int opts) } if (TAILQ_EMPTY(conf->sc_rules)) { - log_warnx("no rules, nothing to do"); + log_warnx("warn: no rules, nothing to do"); errors++; } if (strlen(conf->sc_hostname) == 0) if (gethostname(conf->sc_hostname, sizeof(conf->sc_hostname)) == -1) { - log_warn("could not determine host name"); + log_warn("warn: could not determine host name"); bzero(conf->sc_hostname, sizeof(conf->sc_hostname)); errors++; } @@ -1544,7 +1535,7 @@ host_dns(const char *s, const char *tag, const char *cert, if (error == EAI_AGAIN || error == EAI_NODATA || error == EAI_NONAME) return (0); if (error) { - log_warnx("host_dns: could not parse \"%s\": %s", s, + log_warnx("warn: host_dns: could not parse \"%s\": %s", s, gai_strerror(error)); return (-1); } @@ -1583,7 +1574,7 @@ host_dns(const char *s, const char *tag, const char *cert, cnt++; } if (cnt == max && res) { - log_warnx("host_dns: %s resolves to more than %d hosts", + log_warnx("warn: host_dns: %s resolves to more than %d hosts", s, max); } freeaddrinfo(res0); diff --git a/usr.sbin/smtpd/queue.c b/usr.sbin/smtpd/queue.c index bc6635827c6..239d31f4731 100644 --- a/usr.sbin/smtpd/queue.c +++ b/usr.sbin/smtpd/queue.c @@ -1,4 +1,4 @@ -/* $OpenBSD: queue.c,v 1.140 2012/10/25 09:51:08 eric Exp $ */ +/* $OpenBSD: queue.c,v 1.141 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -146,7 +146,8 @@ queue_imsg(struct imsgev *iev, struct imsg *imsg) id = *(uint64_t*)(imsg->data); if (queue_envelope_load(id, &evp) == 0) errx(1, "cannot load evp:%016" PRIx64, id); - log_envelope(&evp, NULL, "Removed by administrator"); + log_envelope(&evp, NULL, "Remove", + "Removed by administrator"); queue_envelope_delete(&evp); return; @@ -156,7 +157,7 @@ queue_imsg(struct imsgev *iev, struct imsg *imsg) errx(1, "cannot load evp:%016" PRIx64, id); envelope_set_errormsg(&evp, "Envelope expired"); queue_bounce(&evp); - log_envelope(&evp, NULL, evp.errorline); + log_envelope(&evp, NULL, "Expire", evp.errorline); queue_envelope_delete(&evp); return; @@ -290,19 +291,20 @@ queue_bounce(struct envelope *e) b.expire = 3600 * 24 * 7; if (e->type == D_BOUNCE) { - log_warnx("queue: double bounce!"); + log_warnx("warn: queue: double bounce!"); } else if (e->sender.user[0] == '\0') { - log_warnx("queue: no return path!"); + log_warnx("warn: queue: no return path!"); } else if (!queue_envelope_create(&b)) { - log_warnx("queue: cannot bounce!"); + log_warnx("warn: queue: cannot bounce!"); } else { - log_debug("queue: bouncing evp:%016" PRIx64 + log_debug("debug: queue: bouncing evp:%016" PRIx64 " as evp:%016" PRIx64, e->id, b.id); imsg_compose_event(env->sc_ievs[PROC_SCHEDULER], IMSG_QUEUE_SUBMIT_ENVELOPE, 0, 0, -1, &b, sizeof b); msgid = evpid_to_msgid(b.id); imsg_compose_event(env->sc_ievs[PROC_SCHEDULER], IMSG_QUEUE_COMMIT_MESSAGE, 0, 0, -1, &msgid, sizeof msgid); + stat_increment("queue.bounce", 1); } } @@ -322,7 +324,7 @@ queue_sig_handler(int sig, short event, void *p) static void queue_shutdown(void) { - log_info("queue handler exiting"); + log_info("info: queue handler exiting"); _exit(0); } @@ -404,41 +406,49 @@ static void queue_timeout(int fd, short event, void *p) { static struct qwalk *q = NULL; - static uint32_t last_msgid = 0; + static uint32_t msgid = 0; + static size_t evpcount = 0; struct event *ev = p; struct envelope envelope; struct timeval tv; uint64_t evpid; if (q == NULL) { - log_debug("queue: loading queue into scheduler"); + log_debug("debug: queue: loading queue into scheduler"); q = qwalk_new(0); } while (qwalk(q, &evpid)) { - if (queue_envelope_load(evpid, &envelope)) + if (! queue_envelope_load(evpid, &envelope)) + log_warnx("warn: Failed to load envelope %016"PRIx64, + evpid); + else { imsg_compose_event(env->sc_ievs[PROC_SCHEDULER], IMSG_QUEUE_SUBMIT_ENVELOPE, 0, 0, -1, &envelope, sizeof envelope); + evpcount++; + } - if (last_msgid && evpid_to_msgid(evpid) != last_msgid) + if (msgid && evpid_to_msgid(evpid) != msgid && evpcount) { imsg_compose_event(env->sc_ievs[PROC_SCHEDULER], - IMSG_QUEUE_COMMIT_MESSAGE, 0, 0, -1, &last_msgid, - sizeof last_msgid); + IMSG_QUEUE_COMMIT_MESSAGE, 0, 0, -1, &msgid, + sizeof msgid); + evpcount = 0; + } - last_msgid = evpid_to_msgid(evpid); + msgid = evpid_to_msgid(evpid); tv.tv_sec = 0; tv.tv_usec = 0; evtimer_add(ev, &tv); return; } - if (last_msgid) { + if (msgid && evpcount) { imsg_compose_event(env->sc_ievs[PROC_SCHEDULER], - IMSG_QUEUE_COMMIT_MESSAGE, 0, 0, -1, &last_msgid, - sizeof last_msgid); + IMSG_QUEUE_COMMIT_MESSAGE, 0, 0, -1, &msgid, sizeof msgid); + evpcount = 0; } - log_debug("queue: done loading queue into scheduler"); + log_debug("debug: queue: done loading queue into scheduler"); qwalk_close(q); } diff --git a/usr.sbin/smtpd/queue_backend.c b/usr.sbin/smtpd/queue_backend.c index 9de7e2ecd49..27cef8be6fb 100644 --- a/usr.sbin/smtpd/queue_backend.c +++ b/usr.sbin/smtpd/queue_backend.c @@ -1,4 +1,4 @@ -/* $OpenBSD: queue_backend.c,v 1.39 2012/10/09 13:39:00 eric Exp $ */ +/* $OpenBSD: queue_backend.c,v 1.40 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2011 Gilles Chehade <gilles@openbsd.org> @@ -287,7 +287,7 @@ queue_envelope_load(uint64_t evpid, struct envelope *ep) ep->id = evpid; return (1); } - log_debug("invalid envelope %016" PRIx64 ": %s", ep->id, e); + log_debug("debug: invalid envelope %016" PRIx64 ": %s", ep->id, e); } return (0); } diff --git a/usr.sbin/smtpd/queue_fsqueue.c b/usr.sbin/smtpd/queue_fsqueue.c index 87b11046cbf..6bfb812e7ab 100644 --- a/usr.sbin/smtpd/queue_fsqueue.c +++ b/usr.sbin/smtpd/queue_fsqueue.c @@ -1,4 +1,4 @@ -/* $OpenBSD: queue_fsqueue.c,v 1.54 2012/10/22 21:58:14 chl Exp $ */ +/* $OpenBSD: queue_fsqueue.c,v 1.55 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2011 Gilles Chehade <gilles@openbsd.org> @@ -129,14 +129,14 @@ fsqueue_envelope_dump_atomic(char *dest, char *evpbuf, size_t evplen) w = write(fd, evpbuf, evplen); if (w == -1) { - log_warn("fsqueue_envelope_dump_atomic: write"); + log_warn("warn: fsqueue_envelope_dump_atomic: write"); if (errno == ENOSPC) goto tempfail; fatal("fsqueue_envelope_dump_atomic: write"); } if ((size_t) w != evplen) { - log_warnx("fsqueue_envelope_dump_atomic: partial write"); + log_warnx("warn: fsqueue_envelope_dump_atomic: partial write"); goto tempfail; } @@ -145,7 +145,7 @@ fsqueue_envelope_dump_atomic(char *dest, char *evpbuf, size_t evplen) close(fd); if (rename(evpname, dest) == -1) { - log_warn("fsqueue_envelope_dump_atomic: rename"); + log_warn("warn: fsqueue_envelope_dump_atomic: rename"); if (errno == ENOSPC) goto tempfail; fatal("fsqueue_envelope_dump_atomic: rename"); @@ -493,13 +493,13 @@ fsqueue_qwalk(void *hdl, uint64_t *evpid) case FTS_D: q->depth += 1; if (q->depth == 2 && e->fts_namelen != 2) { - log_debug("fsqueue: bogus directory %s", + log_debug("debug: fsqueue: bogus directory %s", e->fts_path); fts_set(q->fts, e, FTS_SKIP); break; } if (q->depth == 3 && e->fts_namelen != 8) { - log_debug("fsqueue: bogus directory %s", + log_debug("debug: fsqueue: bogus directory %s", e->fts_path); fts_set(q->fts, e, FTS_SKIP); break; @@ -528,7 +528,7 @@ fsqueue_qwalk(void *hdl, uint64_t *evpid) tmp = NULL; *evpid = strtoull(e->fts_name, &tmp, 16); if (tmp && *tmp != '\0') { - log_debug("fsqueue: bogus file %s", + log_debug("debug: fsqueue: bogus file %s", e->fts_path); break; } diff --git a/usr.sbin/smtpd/ruleset.c b/usr.sbin/smtpd/ruleset.c index 259d021bfff..42399f93bb9 100644 --- a/usr.sbin/smtpd/ruleset.c +++ b/usr.sbin/smtpd/ruleset.c @@ -1,4 +1,4 @@ -/* $OpenBSD: ruleset.c,v 1.25 2012/10/13 08:01:47 eric Exp $ */ +/* $OpenBSD: ruleset.c,v 1.26 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2009 Gilles Chehade <gilles@openbsd.org> @@ -78,8 +78,7 @@ ruleset_match(const struct envelope *evp) if (map->m_src == S_NONE) { TAILQ_FOREACH(me, &map->m_contents, me_entry) { - if (hostname_match(maddr->domain, - me->me_key.med_string)) + if (hostname_match(maddr->domain, me->me_key)) return r; } } @@ -143,12 +142,11 @@ ruleset_check_source(struct map *map, const struct sockaddr_storage *ss) if (map->m_src == S_NONE) { TAILQ_FOREACH(me, &map->m_contents, me_entry) { if (ss->ss_family == AF_LOCAL) { - if (!strcmp(me->me_key.med_string, "local")) + if (!strcmp(me->me_key, "local")) return 1; continue; } - if (ruleset_cmp_source(ss_to_text(ss), - me->me_key.med_string)) + if (ruleset_cmp_source(ss_to_text(ss), me->me_key)) return 1; } } diff --git a/usr.sbin/smtpd/scheduler.c b/usr.sbin/smtpd/scheduler.c index feca49392a6..44f0f15eec1 100644 --- a/usr.sbin/smtpd/scheduler.c +++ b/usr.sbin/smtpd/scheduler.c @@ -1,4 +1,4 @@ -/* $OpenBSD: scheduler.c,v 1.22 2012/11/02 14:46:43 eric Exp $ */ +/* $OpenBSD: scheduler.c,v 1.23 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -172,11 +172,11 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg) case IMSG_SCHEDULER_SCHEDULE: id = *(uint64_t *)(imsg->data); if (id == 0) - log_debug("scheduler: scheduling all envelopes"); + log_debug("debug: scheduler: scheduling all envelopes"); else if (id <= 0xffffffffL) - log_debug("scheduler: scheduling msg:%08" PRIx64, id); + log_debug("debug: scheduler: scheduling msg:%08" PRIx64, id); else - log_debug("scheduler: scheduling evp:%016" PRIx64, id); + log_debug("debug: scheduler: scheduling evp:%016" PRIx64, id); backend->schedule(id); scheduler_reset_events(); return; @@ -184,9 +184,9 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg) case IMSG_SCHEDULER_REMOVE: id = *(uint64_t *)(imsg->data); if (id <= 0xffffffffL) - log_debug("scheduler: removing msg:%08" PRIx64, id); + log_debug("debug: scheduler: removing msg:%08" PRIx64, id); else - log_debug("scheduler: removing evp:%016" PRIx64, id); + log_debug("debug: scheduler: removing evp:%016" PRIx64, id); backend->remove(id); scheduler_reset_events(); return; @@ -211,7 +211,7 @@ scheduler_sig_handler(int sig, short event, void *p) static void scheduler_shutdown(void) { - log_info("scheduler handler exiting"); + log_info("info: scheduler handler exiting"); _exit(0); } @@ -359,7 +359,7 @@ scheduler_process_remove(struct scheduler_batch *batch) while ((e = batch->evpids)) { batch->evpids = e->next; - log_debug("scheduler: evp:%016" PRIx64 " removed", + log_debug("debug: scheduler: evp:%016" PRIx64 " removed", e->id); imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_REMOVE, 0, 0, -1, &e->id, sizeof e->id); @@ -377,7 +377,7 @@ scheduler_process_expire(struct scheduler_batch *batch) while ((e = batch->evpids)) { batch->evpids = e->next; - log_debug("scheduler: evp:%016" PRIx64 " expired", + log_debug("debug: scheduler: evp:%016" PRIx64 " expired", e->id); imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_QUEUE_EXPIRE, 0, 0, -1, &e->id, sizeof e->id); @@ -395,7 +395,7 @@ scheduler_process_bounce(struct scheduler_batch *batch) while ((e = batch->evpids)) { batch->evpids = e->next; - log_debug("scheduler: evp:%016" PRIx64 " scheduled (bounce)", + log_debug("debug: scheduler: evp:%016" PRIx64 " scheduled (bounce)", e->id); imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_SMTP_ENQUEUE, 0, 0, -1, &e->id, sizeof e->id); @@ -412,7 +412,7 @@ scheduler_process_mda(struct scheduler_batch *batch) while ((e = batch->evpids)) { batch->evpids = e->next; - log_debug("scheduler: evp:%016" PRIx64 " scheduled (mda)", + log_debug("debug: scheduler: evp:%016" PRIx64 " scheduled (mda)", e->id); imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_MDA_SESS_NEW, 0, 0, -1, &e->id, sizeof e->id); @@ -432,7 +432,7 @@ scheduler_process_mta(struct scheduler_batch *batch) while ((e = batch->evpids)) { batch->evpids = e->next; - log_debug("scheduler: evp:%016" PRIx64 " scheduled (mta)", + log_debug("debug: scheduler: evp:%016" PRIx64 " scheduled (mta)", e->id); imsg_compose_event(env->sc_ievs[PROC_QUEUE], IMSG_BATCH_APPEND, 0, 0, -1, &e->id, sizeof e->id); diff --git a/usr.sbin/smtpd/scheduler_ramqueue.c b/usr.sbin/smtpd/scheduler_ramqueue.c index 1425e414fcf..055d2c8b4d2 100644 --- a/usr.sbin/smtpd/scheduler_ramqueue.c +++ b/usr.sbin/smtpd/scheduler_ramqueue.c @@ -1,4 +1,4 @@ -/* $OpenBSD: scheduler_ramqueue.c,v 1.23 2012/11/02 14:46:43 eric Exp $ */ +/* $OpenBSD: scheduler_ramqueue.c,v 1.24 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2012 Gilles Chehade <gilles@openbsd.org> @@ -612,16 +612,16 @@ rq_queue_dump(struct rq_queue *rq, const char * name) void *i, *j; uint64_t id; - log_debug("/--- ramqueue: %s", name); + log_debug("debug: /--- ramqueue: %s", name); i = NULL; while((tree_iter(&rq->messages, &i, &id, (void*)&message))) { - log_debug("| msg:%08" PRIx32, message->msgid); + log_debug("debug: | msg:%08" PRIx32, message->msgid); j = NULL; while((tree_iter(&message->envelopes, &j, &id, (void*)&envelope))) - log_debug("| %s", + log_debug("debug: | %s", rq_envelope_to_text(envelope)); } - log_debug("\\---"); + log_debug("debug: \\---"); } diff --git a/usr.sbin/smtpd/smtp.c b/usr.sbin/smtpd/smtp.c index 461c5d89343..73067afcd74 100644 --- a/usr.sbin/smtpd/smtp.c +++ b/usr.sbin/smtpd/smtp.c @@ -1,4 +1,4 @@ -/* $OpenBSD: smtp.c,v 1.120 2012/10/07 15:46:38 chl Exp $ */ +/* $OpenBSD: smtp.c,v 1.121 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -259,13 +259,13 @@ smtp_imsg(struct imsgev *iev, struct imsg *imsg) return; case IMSG_SMTP_PAUSE: - log_debug("smtp: pausing listening sockets"); + log_debug("debug: smtp: pausing listening sockets"); smtp_pause(); env->sc_flags |= SMTPD_SMTP_PAUSED; return; case IMSG_SMTP_RESUME: - log_debug("smtp: resuming listening sockets"); + log_debug("debug: smtp: resuming listening sockets"); env->sc_flags &= ~SMTPD_SMTP_PAUSED; smtp_resume(); return; @@ -291,7 +291,7 @@ smtp_sig_handler(int sig, short event, void *p) static void smtp_shutdown(void) { - log_info("smtp server exiting"); + log_info("info: smtp server exiting"); _exit(0); } @@ -366,7 +366,7 @@ smtp_setup_events(void) struct listener *l; TAILQ_FOREACH(l, env->sc_listeners, entry) { - log_debug("smtp: listen on %s port %d flags 0x%01x" + log_debug("debug: smtp: listen on %s port %d flags 0x%01x" " cert \"%s\"", ss_to_text(&l->ss), ntohs(l->port), l->flags, l->ssl_cert_name); @@ -381,7 +381,7 @@ smtp_setup_events(void) ssl_setup(l); } - log_debug("smtp: will accept at most %d clients", + log_debug("debug: smtp: will accept at most %d clients", (getdtablesize() - getdtablecount())/2 - SMTP_FD_RESERVE); } @@ -463,14 +463,14 @@ smtp_accept(int fd, short event, void *p) socklen_t len; if ((s = smtp_new(l)) == NULL) { - log_warnx("smtp: client limit hit, disabling incoming connections"); + log_warnx("warn: smtp: client limit hit, disabling incoming connections"); goto pause; } len = sizeof(s->s_ss); if ((s->s_io.sock = accept(fd, (struct sockaddr *)&s->s_ss, &len)) == -1) { if (errno == ENFILE || errno == EMFILE) { - log_warnx("smtp: fd exhaustion, disabling incoming connections"); + log_warnx("warn: smtp: fd exhaustion, disabling incoming connections"); goto pause; } if (errno == EINTR || errno == ECONNABORTED) @@ -495,7 +495,7 @@ smtp_new(struct listener *l) { struct session *s; - log_debug("smtp: new client on listener: %p", l); + log_debug("debug: smtp: new client on listener: %p", l); if (env->sc_flags & SMTPD_SMTP_PAUSED) fatalx("smtp_new: unexpected client"); @@ -537,7 +537,7 @@ smtp_destroy(struct session *session) return; if (env->sc_flags & SMTPD_SMTP_DISABLED) { - log_warnx("smtp: fd exaustion over, re-enabling incoming connections"); + log_warnx("warn: smtp: fd exaustion over, re-enabling incoming connections"); env->sc_flags &= ~SMTPD_SMTP_DISABLED; smtp_resume(); } diff --git a/usr.sbin/smtpd/smtp_session.c b/usr.sbin/smtpd/smtp_session.c index dbfb0535a03..39637ffc58c 100644 --- a/usr.sbin/smtpd/smtp_session.c +++ b/usr.sbin/smtpd/smtp_session.c @@ -1,4 +1,4 @@ -/* $OpenBSD: smtp_session.c,v 1.174 2012/11/02 19:30:57 eric Exp $ */ +/* $OpenBSD: smtp_session.c,v 1.175 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -28,12 +28,15 @@ #include <netinet/in.h> #include <ctype.h> +#include <errno.h> #include <event.h> #include <imsg.h> +#include <inttypes.h> #include <resolv.h> #include <stdio.h> #include <stdlib.h> #include <unistd.h> +#include <vis.h> #include <openssl/ssl.h> @@ -309,12 +312,12 @@ session_rfc1652_mail_handler(struct session *s, char *args) *body++ = '\0'; if (strncasecmp(body, "AUTH=", 5) == 0) { - log_debug("smtp: AUTH in MAIL FROM command, skipping"); + log_debug("debug: smtp: AUTH in MAIL FROM command, skipping"); continue; } if (strncasecmp(body, "BODY=", 5) == 0) { - log_debug("smtp: BODY in MAIL FROM command"); + log_debug("debug: smtp: BODY in MAIL FROM command"); if (strncasecmp("body=7bit", body, 9) == 0) { s->s_flags &= ~F_8BITMIME; @@ -648,6 +651,8 @@ session_io(struct io *io, int evt) io_set_write(&s->s_io); session_respond(s, SMTPD_BANNER, env->sc_hostname); } + log_info("smtp-in: Started TLS on session %016" PRIx64 ": %s", + s->s_id, ssl_to_text(s->s_io.ssl)); s->kickcount = 0; session_enter_state(s, S_GREETED); break; @@ -686,6 +691,7 @@ session_io(struct io *io, int evt) return; } + strlcpy(s->cmd, line, sizeof s->cmd); session_line(s, line, len); if (s->s_flags & F_KICK) { session_destroy(s, "kick"); @@ -697,6 +703,8 @@ session_io(struct io *io, int evt) case IO_LOWAT: if (s->s_state == S_QUIT) { + log_info("smtp-in: Closing session %016" PRIx64, + s->s_id); session_destroy(s, "done"); break; } @@ -711,14 +719,20 @@ session_io(struct io *io, int evt) break; case IO_TIMEOUT: + log_info("smtp-in: Disconnecting session %016" PRIx64 + ": session timeout", s->s_id); session_destroy(s, "timeout"); break; case IO_DISCONNECTED: + log_info("smtp-in: Received disconnect from session %016" PRIx64, + s->s_id); session_destroy(s, "disconnected"); break; case IO_ERROR: + log_info("smtp-in: Disconnecting session %016" PRIx64 + ": IO error: %s", s->s_id, strerror(errno)); session_destroy(s, "error"); break; @@ -730,6 +744,7 @@ session_io(struct io *io, int evt) void session_pickup(struct session *s, struct submit_status *ss) { + char user[MAXLOGNAME]; void *ssl; s->s_flags &= ~F_WAITIMSG; @@ -747,6 +762,10 @@ session_pickup(struct session *s, struct submit_status *ss) case S_CONNECTED: session_enter_state(s, S_INIT); + log_info("smtp-in: New session %016" PRIx64 " from host %s [%s]", + s->s_id, + s->s_hostname, + ss_to_text(&s->s_ss)); s->s_msg.session_id = s->s_id; s->s_msg.ss = s->s_ss; session_imsg(s, PROC_MFA, IMSG_MFA_CONNECT, 0, 0, -1, @@ -755,6 +774,8 @@ session_pickup(struct session *s, struct submit_status *ss) case S_INIT: if (ss->code != 250) { + log_info("smtp-in: Disconnecting session %016" PRIx64 + ": rejected by filter", s->s_id); session_destroy(s, "rejected by filter"); return; } @@ -771,11 +792,17 @@ session_pickup(struct session *s, struct submit_status *ss) break; case S_AUTH_FINALIZE: + strnvis(user, s->s_auth.user, sizeof user, VIS_WHITE | VIS_SAFE); if (s->s_flags & F_AUTHENTICATED) { session_respond(s, "235 Authentication succeeded"); + log_info("smtp-in: Accepted authentication for user %s " + "on session %016" PRIx64, user, s->s_id); s->kickcount = 0; - } else + } else { + log_info("smtp-in: Failed authentication for user %s " + "on session %016" PRIx64, user, s->s_id); session_respond(s, "535 Authentication failed"); + } session_enter_state(s, S_HELO); break; @@ -889,18 +916,16 @@ session_pickup(struct session *s, struct submit_status *ss) case S_DONE: session_respond(s, "250 2.0.0 %08x Message accepted for delivery", evpid_to_msgid(s->s_msg.id)); - log_info("%08x: from=<%s%s%s>, size=%ld, nrcpts=%zu, proto=%s, " - "relay=%s [%s]", + log_info("smtp-in: Accepted message %08x on session %016" PRIx64 + ": from=<%s%s%s>, size=%ld, nrcpts=%zu, proto=%s", evpid_to_msgid(s->s_msg.id), + s->s_id, s->s_msg.sender.user, s->s_msg.sender.user[0] == '\0' ? "" : "@", s->s_msg.sender.domain, s->s_datalen, s->rcptcount, - s->s_flags & F_EHLO ? "ESMTP" : "SMTP", - s->s_hostname, - ss_to_text(&s->s_ss)); - + s->s_flags & F_EHLO ? "ESMTP" : "SMTP"); session_enter_state(s, S_HELO); s->s_msg.id = 0; s->mailcount++; @@ -923,6 +948,8 @@ session_line(struct session *s, char *line, size_t len) if (s->s_state != S_DATACONTENT) { log_trace(TRACE_SMTP, "smtp: %p: <<< %s", s, line); if (++s->kickcount >= SMTP_KICKTHRESHOLD) { + log_info("smtp-in: Disconnecting session %016" PRIx64 + ": session not moving forward", s->s_id); s->s_flags |= F_KICK; stat_increment("smtp.kick", 1); return; @@ -969,7 +996,7 @@ session_line(struct session *s, char *line, size_t len) break; default: - log_debug("session_read: %i", s->s_state); + log_debug("debug: session_read: %i", s->s_state); fatalx("session_read: unexpected state"); } @@ -1046,7 +1073,7 @@ session_destroy(struct session *s, const char * reason) { uint32_t msgid; - log_debug("smtp: %p: deleting session: %s", s, reason); + log_debug("debug: smtp: %p: deleting session: %s", s, reason); if (s->s_flags & F_ZOMBIE) goto finalize; @@ -1126,7 +1153,7 @@ session_respond(struct session *s, char *fmt, ...) { va_list ap; int n, delay; - char buf[SMTP_LINE_MAX]; + char buf[SMTP_LINE_MAX], tmp[SMTP_LINE_MAX]; va_start(ap, fmt); n = vsnprintf(buf, sizeof buf, fmt, ap); @@ -1147,11 +1174,9 @@ session_respond(struct session *s, char *fmt, ...) switch (buf[0]) { case '5': case '4': - log_info("%08x: from=<%s@%s>, relay=%s [%s], stat=LocalError (%.*s)", - evpid_to_msgid(s->s_msg.id), - s->s_msg.sender.user, s->s_msg.sender.domain, - s->s_hostname, ss_to_text(&s->s_ss), - n, buf); + strnvis(tmp, s->cmd, sizeof tmp, VIS_SAFE | VIS_CSTYLE); + log_info("smtp-in: Failed command on session %016" PRIx64 + ": \"%s\" => %.*s", s->s_id, tmp, n, buf); break; } diff --git a/usr.sbin/smtpd/smtpctl.c b/usr.sbin/smtpd/smtpctl.c index da5f871e06a..757024da491 100644 --- a/usr.sbin/smtpd/smtpctl.c +++ b/usr.sbin/smtpd/smtpctl.c @@ -1,4 +1,4 @@ -/* $OpenBSD: smtpctl.c,v 1.94 2012/10/26 19:16:42 chl Exp $ */ +/* $OpenBSD: smtpctl.c,v 1.95 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2006 Pierre-Yves Ritschard <pyr@openbsd.org> @@ -56,6 +56,7 @@ static void getflag(uint *, int, char *, char *, size_t); static void display(const char *); static void show_envelope(const char *); static void show_message(const char *); +static void show_monitor(struct stat_digest *); int proctype; struct imsgbuf *ibuf; @@ -228,7 +229,8 @@ connected: break; } case MONITOR: - /* XXX */ + again: + imsg_compose(ibuf, IMSG_DIGEST, 0, 0, -1, NULL, 0); break; case LOG_VERBOSE: verbose = 1; @@ -280,7 +282,12 @@ connected: case NONE: break; case UPDATE_MAP: + break; case MONITOR: + show_monitor(imsg.data); + imsg_free(&imsg); + sleep(1); + goto again; break; default: err(1, "unexpected reply (%d)", res->action); @@ -351,7 +358,7 @@ again: if (strcmp(kvp->key, "uptime") == 0) { duration = time(NULL) - kvp->val.u.counter; - printf("uptime=%zd\n", duration); + printf("uptime=%zd\n", (size_t)duration); printf("uptime.human=%s\n", duration_to_text(duration)); } else { @@ -535,3 +542,52 @@ show_message(const char *s) display(buf); } + +static void +show_monitor(struct stat_digest *d) +{ + static int init = 0; + static size_t count = 0; + static struct stat_digest last; + + if (init == 0) { + init = 1; + bzero(&last, sizeof last); + } + + if (count % 25 == 0) { + if (count != 0) + printf("\n"); + printf("--- client --- " + "-- envelope -- " + "---- relay/delivery --- " + "------- misc -------\n" + "curr conn disc " + "curr enq deq " + "ok tmpfail prmfail loop " + "expire remove bounce\n"); + } + printf("%4zu %4zu %4zu " + "%4zu %4zu %4zu " + "%4zu %4zu %4zu %4zu " + "%4zu %4zu %4zu\n", + d->clt_connect - d->clt_disconnect, + d->clt_connect - last.clt_connect, + d->clt_disconnect - last.clt_disconnect, + + d->evp_enqueued - d->evp_dequeued, + d->evp_enqueued - last.evp_enqueued, + d->evp_dequeued - last.evp_dequeued, + + d->dlv_ok - last.dlv_ok, + d->dlv_tempfail - last.dlv_tempfail, + d->dlv_permfail - last.dlv_permfail, + d->dlv_loop - last.dlv_loop, + + d->evp_expired - last.evp_expired, + d->evp_removed - last.evp_removed, + d->evp_bounce - last.evp_bounce); + + last = *d; + count++; +} diff --git a/usr.sbin/smtpd/smtpd.c b/usr.sbin/smtpd/smtpd.c index 545ce6c825d..ffb57be4e46 100644 --- a/usr.sbin/smtpd/smtpd.c +++ b/usr.sbin/smtpd/smtpd.c @@ -1,4 +1,4 @@ -/* $OpenBSD: smtpd.c,v 1.180 2012/11/02 16:02:33 eric Exp $ */ +/* $OpenBSD: smtpd.c,v 1.181 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -174,7 +174,7 @@ parent_imsg(struct imsgev *iev, struct imsg *imsg) c->cause == NULL) break; if (!n) { - log_debug("smptd: kill request: proc not found"); + log_debug("debug: smptd: kill request: proc not found"); return; } len = imsg->hdr.len - sizeof imsg->hdr; @@ -185,7 +185,7 @@ parent_imsg(struct imsgev *iev, struct imsg *imsg) "parent_imsg"); c->cause[len - 1] = '\0'; } - log_debug("smptd: kill requested for %u: %s", + log_debug("debug: smptd: kill requested for %u: %s", c->pid, c->cause); kill(c->pid, SIGTERM); return; @@ -247,7 +247,7 @@ parent_shutdown(void) pid = waitpid(WAIT_MYPGRP, NULL, 0); } while (pid != -1 || (pid == -1 && errno == EINTR)); - log_warnx("parent terminating"); + log_warnx("warn: parent terminating"); exit(0); } @@ -268,7 +268,7 @@ parent_send_config_listeners(void) struct iovec iov[5]; int opt; - log_debug("parent_send_config: configuring smtp"); + log_debug("debug: parent_send_config: configuring smtp"); imsg_compose_event(env->sc_ievs[PROC_SMTP], IMSG_CONF_START, 0, 0, -1, NULL, 0); @@ -314,7 +314,7 @@ parent_send_config_client_certs(void) struct ssl *s; struct iovec iov[3]; - log_debug("parent_send_config_client_certs: configuring smtp"); + log_debug("debug: parent_send_config_client_certs: configuring smtp"); imsg_compose_event(env->sc_ievs[PROC_MTA], IMSG_CONF_START, 0, 0, -1, NULL, 0); @@ -346,7 +346,7 @@ parent_send_config_ruleset(int proc) struct mapel *mapel; struct filter *f; - log_debug("parent_send_config_ruleset: reloading rules and maps"); + log_debug("debug: parent_send_config_ruleset: reloading rules and maps"); imsg_compose_event(env->sc_ievs[proc], IMSG_CONF_START, 0, 0, -1, NULL, 0); @@ -422,7 +422,7 @@ parent_sig_handler(int sig, short event, void *p) case CHILD_DAEMON: die = 1; if (fail) - log_warnx("lost child: %s %s", + log_warnx("warn: lost child: %s %s", child->title, cause); break; @@ -448,7 +448,7 @@ parent_sig_handler(int sig, short event, void *p) case CHILD_ENQUEUE_OFFLINE: if (fail) - log_warnx("smtpd: couldn't enqueue offline " + log_warnx("warn: smtpd: couldn't enqueue offline " "message %s; smtpctl %s", child->path, cause); else unlink(child->path); @@ -516,7 +516,7 @@ main(int argc, char *argv[]) else if (strstr(optarg, "stat=") == optarg) backend_stat = strchr(optarg, '=') + 1; else - log_warnx("invalid backend specifier %s", optarg); + log_warnx("warn: invalid backend specifier %s", optarg); break; case 'd': debug = 2; @@ -524,7 +524,7 @@ main(int argc, char *argv[]) break; case 'D': if (cmdline_symset(optarg) < 0) - log_warnx("could not parse macro definition %s", + log_warnx("warn: could not parse macro definition %s", optarg); break; case 'n': @@ -558,7 +558,7 @@ main(int argc, char *argv[]) else if (!strcmp(optarg, "all")) verbose |= ~TRACE_VERBOSE; else - log_warnx("unknown trace flag \"%s\"", optarg); + log_warnx("warn: unknown trace flag \"%s\"", optarg); break; case 'P': if (!strcmp(optarg, "smtp")) @@ -647,10 +647,10 @@ main(int argc, char *argv[]) if (daemon(0, 0) == -1) err(1, "failed to daemonize"); - log_debug("using \"%s\" queue backend", backend_queue); - log_debug("using \"%s\" scheduler backend", backend_scheduler); - log_debug("using \"%s\" stat backend", backend_stat); - log_info("startup%s", (debug > 1)?" [debug mode]":""); + log_debug("debug: using \"%s\" queue backend", backend_queue); + log_debug("debug: using \"%s\" scheduler backend", backend_scheduler); + log_debug("debug: using \"%s\" stat backend", backend_stat); + log_info("info: startup%s", (debug > 1)?" [debug mode]":""); if (env->sc_hostname[0] == '\0') errx(1, "machine does not have a hostname set"); @@ -814,12 +814,12 @@ purge_task(int fd, short ev, void *arg) n++; closedir(d); } else - log_warn("purge_task: opendir"); + log_warn("warn: purge_task: opendir"); if (n > 2) { switch(purge_pid = fork()) { case -1: - log_warn("purge_task: fork"); + log_warn("warn: purge_task: fork"); break; case 0: if (chroot(PATH_SPOOL PATH_PURGE) == -1) @@ -856,7 +856,7 @@ forkmda(struct imsgev *iev, uint32_t id, pid_t pid; int n, allout, pipefd[2]; - log_debug("forkmda: to \"%s\" as %s", deliver->to, deliver->user); + log_debug("debug: forkmda: to \"%s\" as %s", deliver->to, deliver->user); bzero(&u, sizeof (u)); ub = user_backend_lookup(USER_PWD); @@ -971,7 +971,7 @@ offline_scan(int fd, short ev, void *arg) int n = 0; if (dir == NULL) { - log_debug("smtpd: scanning offline queue..."); + log_debug("debug: smtpd: scanning offline queue..."); if ((dir = opendir(PATH_SPOOL PATH_OFFLINE)) == NULL) errx(1, "smtpd: opendir"); } @@ -981,7 +981,7 @@ offline_scan(int fd, short ev, void *arg) continue; if (offline_add(d->d_name)) { - log_warnx("smtpd: could not add offline message %s", d->d_name); + log_warnx("warn: smtpd: could not add offline message %s", d->d_name); continue; } @@ -994,7 +994,7 @@ offline_scan(int fd, short ev, void *arg) } } - log_debug("smtpd: offline scanning done"); + log_debug("debug: smtpd: offline scanning done"); closedir(dir); } @@ -1008,19 +1008,19 @@ offline_enqueue(char *name) struct passwd *pw; if (!bsnprintf(t, sizeof t, "%s/%s", PATH_SPOOL PATH_OFFLINE, name)) { - log_warnx("smtpd: path name too long"); + log_warnx("warn: smtpd: path name too long"); return (-1); } if ((path = strdup(t)) == NULL) { - log_warn("smtpd: strdup"); + log_warn("warn: smtpd: strdup"); return (-1); } - log_debug("smtpd: enqueueing offline message %s", path); + log_debug("debug: smtpd: enqueueing offline message %s", path); if ((pid = fork()) == -1) { - log_warn("smtpd: fork"); + log_warn("warn: smtpd: fork"); free(path); return (-1); } @@ -1034,25 +1034,25 @@ offline_enqueue(char *name) bzero(&args, sizeof(args)); if (lstat(path, &sb) == -1) { - log_warn("smtpd: lstat: %s", path); + log_warn("warn: smtpd: lstat: %s", path); _exit(1); } if (chflags(path, 0) == -1) { - log_warn("smtpd: chflags: %s", path); + log_warn("warn: smtpd: chflags: %s", path); _exit(1); } pw = getpwuid(sb.st_uid); if (pw == NULL) { - log_warnx("smtpd: getpwuid for uid %d failed", + log_warnx("warn: smtpd: getpwuid for uid %d failed", sb.st_uid); _exit(1); } if (! S_ISREG(sb.st_mode)) { - log_warnx("smtpd: file %s (uid %d) not regular", + log_warnx("warn: smtpd: file %s (uid %d) not regular", path, sb.st_uid); _exit(1); } @@ -1159,12 +1159,12 @@ parent_forward_open(char *username) if (fd == -1) { if (errno == ENOENT) return -2; - log_warn("smtpd: parent_forward_open: %s", pathname); + log_warn("warn: smtpd: parent_forward_open: %s", pathname); return -1; } if (! secure_file(fd, pathname, u.directory, u.uid, 1)) { - log_warnx("smtpd: %s: unsecure file", pathname); + log_warnx("warn: smtpd: %s: unsecure file", pathname); close(fd); return -1; } @@ -1366,6 +1366,7 @@ imsg_to_str(int type) CASE(IMSG_STAT_DECREMENT); CASE(IMSG_STAT_SET); + CASE(IMSG_DIGEST); CASE(IMSG_STATS); CASE(IMSG_STATS_GET); default: diff --git a/usr.sbin/smtpd/smtpd.h b/usr.sbin/smtpd/smtpd.h index 44f2fc9dc71..5c3b342bd9b 100644 --- a/usr.sbin/smtpd/smtpd.h +++ b/usr.sbin/smtpd/smtpd.h @@ -1,4 +1,4 @@ -/* $OpenBSD: smtpd.h,v 1.394 2012/11/02 19:30:57 eric Exp $ */ +/* $OpenBSD: smtpd.h,v 1.395 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org> @@ -54,8 +54,6 @@ #define PATH_SMTPCTL "/usr/sbin/smtpctl" -#define DIRHASH_BUCKETS 4096 - #define PATH_SPOOL "/var/spool/smtpd" #define PATH_OFFLINE "/offline" #define PATH_PURGE "/purge" @@ -193,6 +191,7 @@ enum imsg_type { IMSG_STAT_DECREMENT, IMSG_STAT_SET, + IMSG_DIGEST, IMSG_STATS, IMSG_STATS_GET, }; @@ -248,25 +247,16 @@ enum map_kind { K_NETADDR }; -enum mapel_type { - ME_STRING, - ME_NET, - ME_NETMASK -}; - struct mapel { TAILQ_ENTRY(mapel) me_entry; - union mapel_data { - char med_string[MAX_LINE_SIZE]; - } me_key; - union mapel_data me_val; + char me_key[MAX_LINE_SIZE]; + char me_val[MAX_LINE_SIZE]; }; struct map { TAILQ_ENTRY(map) m_entry; char m_name[MAX_LINE_SIZE]; objid_t m_id; - enum mapel_type m_eltype; enum map_src m_src; char m_config[MAXPATHLEN]; TAILQ_HEAD(mapel_list, mapel) m_contents; @@ -340,8 +330,8 @@ enum delivery_type { }; enum delivery_status { - DS_PERMFAILURE = 0x1, - DS_TEMPFAILURE = 0x2, + DS_PERMFAILURE = 1, + DS_TEMPFAILURE = 2, }; enum delivery_flags { @@ -545,6 +535,8 @@ struct session { struct timeval s_tv; struct envelope s_msg; short s_nresp[STATE_COUNT]; + + char cmd[SMTP_LINE_MAX]; size_t kickcount; size_t mailcount; size_t rcptcount; @@ -577,7 +569,6 @@ struct smtpd { uint32_t sc_queue_flags; #define QUEUE_COMPRESS 0x00000001 char *sc_queue_compress_algo; - struct timeval sc_qintval; int sc_qexpire; struct event sc_ev; int *sc_pipes[PROC_COUNT] @@ -901,6 +892,25 @@ struct stat_backend { int (*iter)(void **, char **, struct stat_value *); }; +struct stat_digest { + time_t startup; + time_t timestamp; + + size_t clt_connect; + size_t clt_disconnect; + + size_t evp_enqueued; + size_t evp_dequeued; + + size_t evp_expired; + size_t evp_removed; + size_t evp_bounce; + + size_t dlv_ok; + size_t dlv_permfail; + size_t dlv_tempfail; + size_t dlv_loop; +}; extern struct smtpd *env; extern void (*imsg_callback)(struct imsgev *, struct imsg *); @@ -1014,6 +1024,7 @@ void mfa_session(struct submit_status *, enum session_state); /* mta.c */ pid_t mta(void); int mta_response_delivery(const char *); +const char *mta_response_prefix(const char *); const char *mta_response_status(const char *); const char *mta_response_text(const char *); void mta_route_ok(struct mta_route *); @@ -1105,6 +1116,7 @@ int ssl_load_certfile(const char *, uint8_t); void ssl_setup(struct listener *); void *ssl_smtp_init(void *); void *ssl_mta_init(struct ssl *); +const char *ssl_to_text(void *); int ssl_cmp(struct ssl *, struct ssl *); SPLAY_PROTOTYPE(ssltree, ssl, ssl_nodes, ssl_cmp); @@ -1189,7 +1201,8 @@ char *xstrdup(const char *, const char *); void *xmemdup(const void *, size_t, const char *); void iobuf_xinit(struct iobuf *, size_t, size_t, const char *); void iobuf_xfqueue(struct iobuf *, const char *, const char *, ...); -void log_envelope(const struct envelope *, const char *, const char *); +void log_envelope(const struct envelope *, const char *, const char *, + const char *); void session_socket_blockmode(int, enum blockmodes); void session_socket_no_linger(int); int session_socket_error(int); diff --git a/usr.sbin/smtpd/ssl.c b/usr.sbin/smtpd/ssl.c index 5201f95320f..3ecf57b47c3 100644 --- a/usr.sbin/smtpd/ssl.c +++ b/usr.sbin/smtpd/ssl.c @@ -1,4 +1,4 @@ -/* $OpenBSD: ssl.c,v 1.49 2012/10/14 14:26:31 halex Exp $ */ +/* $OpenBSD: ssl.c,v 1.50 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2008 Pierre-Yves Ritschard <pyr@openbsd.org> @@ -77,13 +77,13 @@ ssl_load_file(const char *name, off_t *len, mode_t perm) if (fstat(fd, &st) != 0) goto fail; if (st.st_uid != 0) { - log_info("%s: not owned by uid 0", name); + log_warnx("warn: %s: not owned by uid 0", name); errno = EACCES; goto fail; } if (st.st_mode & (S_IRWXU | S_IRWXG | S_IRWXO) & ~perm) { strmode(perm, mode); - log_info("%s: insecure permissions: must be at most %s", + log_warnx("warn: %s: insecure permissions: must be at most %s", name, &mode[1]); errno = EACCES; goto fail; @@ -142,7 +142,7 @@ ssl_load_certfile(const char *name, uint8_t flags) if (strlcpy(key.ssl_name, name, sizeof(key.ssl_name)) >= sizeof(key.ssl_name)) { - log_warn("ssl_load_certfile: certificate name truncated"); + log_warnx("warn: ssl_load_certfile: certificate name truncated"); return -1; } @@ -182,7 +182,7 @@ ssl_load_certfile(const char *name, uint8_t flags) if (s->ssl_ca == NULL) { if (errno == EACCES) goto err; - log_info("no CA found in %s", certfile); + log_warnx("warn: no CA found in %s", certfile); } if (! bsnprintf(certfile, sizeof(certfile), @@ -193,8 +193,8 @@ ssl_load_certfile(const char *name, uint8_t flags) if (s->ssl_dhparams == NULL) { if (errno == EACCES) goto err; - log_info("no DH parameters found in %s", certfile); - log_info("using built-in DH parameters"); + log_info("info: No DH parameters found in %s: " + "using built-in parameters", certfile); } SPLAY_INSERT(ssltree, env->sc_ssl, s); @@ -271,7 +271,7 @@ ssl_setup(struct listener *l) ssl_set_ephemeral_key_exchange(l->ssl_ctx, dh); DH_free(dh); - log_debug("ssl_setup: ssl setup finished for listener: %p", l); + log_debug("debug: ssl_setup: ssl setup finished for listener: %p", l); return; err: @@ -282,6 +282,18 @@ err: return; } +const char * +ssl_to_text(void *ssl) { + static char buf[256]; + + snprintf(buf, sizeof buf, "version=%s, cipher=%s, bits=%i", + SSL_get_cipher_version(ssl), + SSL_get_cipher_name(ssl), + SSL_get_cipher_bits(ssl, NULL)); + + return (buf); +} + void ssl_error(const char *where) { @@ -293,7 +305,7 @@ ssl_error(const char *where) return; for (; (code = ERR_get_error()) != 0 ;) { ERR_error_string_n(code, errbuf, sizeof(errbuf)); - log_debug("SSL library error: %s: %s", where, errbuf); + log_debug("debug: SSL library error: %s: %s", where, errbuf); } } @@ -381,7 +393,7 @@ ssl_smtp_init(void *ssl_ctx) { SSL *ssl; - log_debug("session_start_ssl: switching to SSL"); + log_debug("debug: session_start_ssl: switching to SSL"); if ((ssl = SSL_new(ssl_ctx)) == NULL) goto err; diff --git a/usr.sbin/smtpd/stat_backend.c b/usr.sbin/smtpd/stat_backend.c index 33bedda9982..4aaa5affd20 100644 --- a/usr.sbin/smtpd/stat_backend.c +++ b/usr.sbin/smtpd/stat_backend.c @@ -55,7 +55,7 @@ stat_increment(const char *name, size_t count) s = buf + sizeof *value; if ((len = strlcpy(s, name, STAT_KEY_SIZE)) >= STAT_KEY_SIZE) { len = STAT_KEY_SIZE - 1; - log_warn("stat_increment: truncated key '%s', ignored", name); + log_warn("warn: stat_increment: truncated key '%s', ignored", name); } imsg_compose_event(env->sc_ievs[PROC_CONTROL], @@ -74,7 +74,7 @@ stat_decrement(const char *name, size_t count) s = buf + sizeof *value; if ((len = strlcpy(s, name, STAT_KEY_SIZE)) >= STAT_KEY_SIZE) { len = STAT_KEY_SIZE - 1; - log_warn("stat_increment: truncated key '%s', ignored", name); + log_warn("warn: stat_increment: truncated key '%s', ignored", name); } imsg_compose_event(env->sc_ievs[PROC_CONTROL], @@ -91,7 +91,7 @@ stat_set(const char *name, const struct stat_value *value) s = buf + sizeof *value; if ((len = strlcpy(s, name, STAT_KEY_SIZE)) >= STAT_KEY_SIZE) { len = STAT_KEY_SIZE - 1; - log_warn("stat_increment: truncated key '%s', ignored", name); + log_warn("warn: stat_increment: truncated key '%s', ignored", name); } imsg_compose_event(env->sc_ievs[PROC_CONTROL], diff --git a/usr.sbin/smtpd/util.c b/usr.sbin/smtpd/util.c index 5f00474ee21..820bbd4cf85 100644 --- a/usr.sbin/smtpd/util.c +++ b/usr.sbin/smtpd/util.c @@ -1,4 +1,4 @@ -/* $OpenBSD: util.c,v 1.87 2012/10/10 19:39:11 gilles Exp $ */ +/* $OpenBSD: util.c,v 1.88 2012/11/12 14:58:53 eric Exp $ */ /* * Copyright (c) 2000,2001 Markus Friedl. All rights reserved. @@ -646,7 +646,7 @@ text_to_netaddr(struct netaddr *netaddr, const char *s) /* XXX - until AF_INET6 support gets in base */ if (errno != EAFNOSUPPORT) { - log_warn("inet_net_pton"); + log_warn("warn: inet_net_pton"); return 0; } bits = temp_inet_net_pton_ipv6(s, @@ -654,7 +654,7 @@ text_to_netaddr(struct netaddr *netaddr, const char *s) sizeof(struct in6_addr)); } if (bits == -1) { - log_warn("inet_net_pton"); + log_warn("warn: inet_net_pton"); return 0; } ssin6.sin6_family = AF_INET6; @@ -1055,7 +1055,8 @@ temp_inet_net_pton_ipv6(const char *src, void *dst, size_t size) } void -log_envelope(const struct envelope *evp, const char *extra, const char *status) +log_envelope(const struct envelope *evp, const char *extra, const char *prefix, + const char *status) { char rcpt[MAX_LINE_SIZE]; char tmp[MAX_LINE_SIZE]; @@ -1086,7 +1087,9 @@ log_envelope(const struct envelope *evp, const char *extra, const char *status) if (extra == NULL) extra = ""; - log_info("%016" PRIx64 ": from=<%s@%s>, to=<%s@%s>, %s%sdelay=%s, %sstat=%s", + log_info("%s: %s for %016" PRIx64 ": from=<%s@%s>, to=<%s@%s>, %s%sdelay=%s, %sstat=%s", + evp->type == D_MDA ? "delivery" : "relay", + prefix, evp->id, evp->sender.user, evp->sender.domain, evp->dest.user, evp->dest.domain, rcpt, |