net_smtp, net_imap: Improve mail logging and activity visibility.

* net_smtp: Add SMTP transaction logging for debugging.
* mod_mail_events: Flush logfile after each event.
* mod_smtp_delivery_external: Add CLI commands for managing mail queue.
* net_imap: Add CLI commands for IMAP sessions and proxied clients.

configs/net_smtp.conf

@@ -48,6 +48,13 @@ addreceivedmsa=no   ; Whether to include the sender's IP address in the Received
 notifyextfirstmsg=yes ; Whether to send an email to a user's external email address when his/her mailbox is first created.
                       ; Default is yes.
 
+; SMTP log file configuration.
+; This log contains SMTP transaction info in a concise log for archival or debugging purposes.
+; Nitty gritty low-level details are only present in the regular BBS debug messages.
+[logging]
+logfile=/var/log/lbbs/smtp.log ; SMTP logfile. If set, SMTP messages up to the SMTP log level will be logged to this file.
+loglevel=5 ; Log level from 0 to 10 (maximum debug). Default is 5.
+
 [authorized_relays] ; Define remote hosts that are allowed to relay outgoing mail using this server as a smart host.
 ; Configure each authorized relay as an IP/hostname/CIDR range and a list of domains or subdomains for which they are authorized to relay mail.
 ; If a connection matches multiple entries, the relay is allowed as long as it matches one of the entries.

include/net_smtp.h

@@ -24,6 +24,8 @@
 
 struct smtp_session;
 
+void __attribute__ ((format (gnu_printf, 3, 4))) bbs_smtp_log(int level, struct smtp_session *smtp, const char *fmt, ...);
+
 /*! \brief Get the SMTP hostname of the local SMTP server, suitable for use in HELO/EHLO */
 const char *smtp_hostname(void);
 

modules/mod_mail_events.c

@@ -210,6 +210,7 @@ static void mbox_event_callback(struct mailbox_event *event)
 	pthread_mutex_lock(&loglock);
 	log_cb(event);
 	pthread_mutex_unlock(&loglock);
+	fflush(fp); /* Explicitly flush to disk so it immediately appears in the logfile. */
 }
 
 static int load_config(void)

modules/mod_smtp_delivery_external.c

@@ -38,6 +38,7 @@
 #include "include/linkedlists.h"
 #include "include/oauth.h"
 #include "include/base64.h"
+#include "include/cli.h"
 
 #include "include/mod_mail.h"
 #include "include/net_smtp.h"
@@ -612,50 +613,46 @@ static void smtp_trigger_dsn(enum smtp_delivery_action action, struct smtp_tx_da
 	}
 }
 
-static int on_queue_file(const char *dir_name, const char *filename, void *obj)
-{
+#define MAILQ_FILENAME_SIZE 516
+
+struct mailq_file {
 	FILE *fp;
-	char fullname[516], newname[sizeof(fullname) + 11];
-	char from[1000], recipient[1000], todup[256];
-	char *hostname;
+	unsigned long size;
+	size_t metalen;
 	char *realfrom, *realto;
 	char *user, *domain;
 	char *retries;
 	int newretries;
-	int res = -1;
-	unsigned long size;
-	size_t metalen;
-	char buf[256] = "";
-	struct stringlist mxservers;
 	struct tm created;
-	struct stat st;
-	struct smtp_tx_data tx;
-
-	UNUSED(obj);
-	memset(&tx, 0, sizeof(tx));
+	char fullname[MAILQ_FILENAME_SIZE];
+	char from[1000], recipient[1000], todup[256];
+};
 
-	snprintf(fullname, sizeof(fullname), "%s/%s", dir_name, filename);
+static int mailq_file_load(struct mailq_file *restrict mqf, const char *dir_name, const char *filename)
+{
+	struct stat st;
 
-	fp = fopen(fullname, "r");
-	if (!fp) {
-		bbs_error("Failed to open %s: %s\n", fullname, strerror(errno));
-		return 0;
+	snprintf(mqf->fullname, sizeof(mqf->fullname), "%s/%s", dir_name, filename);
+	mqf->fp = fopen(mqf->fullname, "r");
+	if (!mqf->fp) {
+		bbs_error("Failed to open %s: %s\n", mqf->fullname, strerror(errno));
+		return -1;
 	}
 
-	fseek(fp, 0L, SEEK_END); /* Go to EOF */
-	size = (long unsigned) ftell(fp);
-	rewind(fp); /* Be kind, rewind */
+	fseek(mqf->fp, 0L, SEEK_END); /* Go to EOF */
+	mqf->size = (long unsigned) ftell(mqf->fp);
+	rewind(mqf->fp); /* Be kind, rewind */
 
-	if (!fgets(from, sizeof(from), fp) || !fgets(recipient, sizeof(recipient), fp)) {
-		bbs_error("Failed to read metadata from %s\n", fullname);
+	if (!fgets(mqf->from, sizeof(mqf->from), mqf->fp) || !fgets(mqf->recipient, sizeof(mqf->recipient), mqf->fp)) {
+		bbs_error("Failed to read metadata from %s\n", mqf->fullname);
 		goto cleanup;
 	}
 
-	metalen = strlen(from) + strlen(recipient); /* This already includes the newlines */
+	mqf->metalen = strlen(mqf->from) + strlen(mqf->recipient); /* This already includes the newlines */
 
-	retries = strchr(fullname, '.');
-	if (!retries++ || strlen_zero(retries)) { /* Shouldn't happen for mail queue files legitimately generated by this module, but somebody else might have dumped stuff in. */
-		bbs_error("File name '%s' is non-compliant with our filename format\n", fullname);
+	mqf->retries = strchr(mqf->fullname, '.');
+	if (!mqf->retries++ || strlen_zero(mqf->retries)) { /* Shouldn't happen for mail queue files legitimately generated by this module, but somebody else might have dumped stuff in. */
+		bbs_error("File name '%s' is non-compliant with our filename format\n", mqf->fullname);
 		goto cleanup;
 	}
 
@@ -669,49 +666,91 @@ static int on_queue_file(const char *dir_name, const char *filename, void *obj)
 	 * we'll only see LF . CR LF at the end, and delivery will thus fail.
 	 * Do not modify the mail queue files manually for debugging, unless you really know what you are doing,
 	 * and in particular are preserving the mixed line endings. */
-	bbs_term_line(from);
-	bbs_term_line(recipient);
+	bbs_term_line(mqf->from);
+	bbs_term_line(mqf->recipient);
 
-	realfrom = strchr(from, '<');
-	realto = strchr(recipient, '<');
+	mqf->realfrom = strchr(mqf->from, '<');
+	mqf->realto = strchr(mqf->recipient, '<');
 
-	if (!realfrom) {
-		bbs_error("Mail queue file MAIL FROM missing <>: %s\n", fullname);
+	if (!mqf->realfrom) {
+		bbs_error("Mail queue file MAIL FROM missing <>: %s\n", mqf->fullname);
 		goto cleanup;
-	} else if (!realto) {
-		bbs_error("Mail queue file RCPT TO missing <>: %s\n", fullname);
+	} else if (!mqf->realto) {
+		bbs_error("Mail queue file RCPT TO missing <>: %s\n", mqf->fullname);
 		goto cleanup;
 	}
 
-	realfrom++; /* Skip < */
-	if (strlen_zero(realfrom)) {
-		bbs_error("Malformed MAIL FROM: %s\n", fullname);
+	mqf->realfrom++; /* Skip < */
+	if (strlen_zero(mqf->realfrom)) {
+		bbs_error("Malformed MAIL FROM: %s\n", mqf->fullname);
 		goto cleanup;
 	}
-	bbs_strterm(realfrom, '>'); /* try_send will add <> for us, so strip it here to match */
+	bbs_strterm(mqf->realfrom, '>'); /* try_send will add <> for us, so strip it here to match */
 
-	if (bbs_str_count(realfrom, '<') || bbs_str_count(realfrom, '>') || bbs_str_count(realto, '<') != 1 || bbs_str_count(realto, '>') != 1) {
-		bbs_error("Sender or recipient address malformed %s -> %s\n", realfrom, realto);
+	if (bbs_str_count(mqf->realfrom, '<') || bbs_str_count(mqf->realfrom, '>') || bbs_str_count(mqf->realto, '<') != 1 || bbs_str_count(mqf->realto, '>') != 1) {
+		bbs_error("Sender or recipient address malformed %s -> %s\n", mqf->realfrom, mqf->realto);
 		goto cleanup;
 	}
-	bbs_debug(5, "Processing message from %s -> %s\n", realfrom, realto);
 
-	safe_strncpy(todup, realto, sizeof(todup));
-	if (strlen_zero(realfrom) || bbs_parse_email_address(todup, NULL, &user, &domain)) {
+	safe_strncpy(mqf->todup, mqf->realto, sizeof(mqf->todup));
+	if (strlen_zero(mqf->realfrom) || bbs_parse_email_address(mqf->todup, NULL, &mqf->user, &mqf->domain)) {
 		bbs_error("Address parsing error\n");
 		goto cleanup;
 	}
 
-	bbs_debug(2, "Retrying delivery of %s (%s -> %s)\n", fullname, realfrom, realto);
-	memset(&created, 0, sizeof(created));
-	if (stat(fullname, &st)) {
-		bbs_error("stat(%s) failed: %s\n", fullname, strerror(errno));
+	memset(&mqf->created, 0, sizeof(mqf->created));
+	if (stat(mqf->fullname, &st)) {
+		bbs_error("stat(%s) failed: %s\n", mqf->fullname, strerror(errno));
 	} else {
-		localtime_r(&st.st_mtim.tv_sec, &created);
+		localtime_r(&st.st_mtim.tv_sec, &mqf->created);
+	}
+
+	return 0;
+
+cleanup:
+	fclose(mqf->fp);
+	mqf->fp = NULL;
+	return -1;
+}
+
+static int mailq_file_punt(struct mailq_file *mqf)
+{
+	char newname[MAILQ_FILENAME_SIZE + 11];
+	char tmpbuf[256];
+
+	bbs_strncpy_until(tmpbuf, mqf->fullname, sizeof(tmpbuf), '.');
+	/* Store retry information in the filename itself, so we don't have to modify the file, we can just rename it. Inspired by IMAP. */
+	snprintf(newname, sizeof(newname), "%s.%d", tmpbuf, mqf->newretries);
+	if (rename(mqf->fullname, newname)) {
+		bbs_error("Failed to rename %s to %s\n", mqf->fullname, newname);
+		return -1;
+	}
+	return 0;
+}
+
+static int on_queue_file(const char *dir_name, const char *filename, void *obj)
+{
+	int res = -1;
+	char *hostname;
+	char buf[256] = "";
+	struct stringlist mxservers;
+	struct smtp_tx_data tx;
+	struct mailq_file mqf_stack, *mqf = &mqf_stack;
+
+	UNUSED(obj);
+
+	memset(&mqf_stack, 0, sizeof(mqf_stack));
+	memset(&tx, 0, sizeof(tx));
+
+	if (mailq_file_load(&mqf_stack, dir_name, filename)) {
+		return 0;
 	}
 
+	bbs_debug(5, "Processing message from %s -> %s\n", mqf->realfrom, mqf->realto);
+	bbs_debug(2, "Retrying delivery of %s (%s -> %s)\n", mqf->fullname, mqf->realfrom, mqf->realto);
+
 	memset(&mxservers, 0, sizeof(mxservers));
-	res = lookup_mx_all(domain, &mxservers);
+	res = lookup_mx_all(mqf->domain, &mxservers);
 	if (res == -2) {
 		smtp_tx_data_reset(&tx);
 		/* Do not set tx.hostname, since this message is from us, not the remote server */
@@ -720,68 +759,64 @@ static int on_queue_file(const char *dir_name, const char *filename, void *obj)
 		if (res) {
 			char a_ip[256];
 			/* Fall back to trying the A record */
-			if (bbs_resolve_hostname(domain, a_ip, sizeof(a_ip))) {
-				bbs_warning("Recipient domain %s does not have any MX or A records\n", domain);
+			if (bbs_resolve_hostname(mqf->domain, a_ip, sizeof(a_ip))) {
+				bbs_warning("Recipient domain %s does not have any MX or A records\n", mqf->domain);
 				/* Just treat as undeliverable at this point and return to sender (if no MX records now, probably won't be any the next time we try) */
 				/* Send a delivery failure response, then delete the file. */
-				bbs_warning("Delivery of message %s from %s to %s has failed permanently (no MX records)\n", fullname, realfrom, realto);
+				bbs_warning("Delivery of message %s from %s to %s has failed permanently (no MX records)\n", mqf->fullname, mqf->realfrom, mqf->realto);
 				/* There isn't any SMTP level error at this point yet, we have to make our own error message for the bounce message */
-				snprintf(buf, sizeof(buf), "No MX record(s) located for hostname %s", domain); /* No status code */
+				snprintf(buf, sizeof(buf), "No MX record(s) located for hostname %s", mqf->domain); /* No status code */
 				smtp_tx_data_reset(&tx);
 				/* Do not set tx.hostname, since this message is from us, not the remote server */
-				smtp_trigger_dsn(DELIVERY_FAILED, &tx, &created, realfrom, realto, buf, fileno(fp), metalen, size - metalen);
-				fclose(fp);
-				bbs_delete_file(fullname);
+				smtp_trigger_dsn(DELIVERY_FAILED, &tx, &mqf->created, mqf->realfrom, mqf->realto, buf, fileno(mqf->fp), mqf->metalen, mqf->size - mqf->metalen);
+				fclose(mqf->fp);
+				bbs_delete_file(mqf->fullname);
 				return 0;
 			}
-			bbs_warning("Recipient domain %s does not have any MX records, falling back to A record %s\n", domain, a_ip);
+			bbs_warning("Recipient domain %s does not have any MX records, falling back to A record %s\n", mqf->domain, a_ip);
 			stringlist_push(&mxservers, a_ip);
 		}
 
 		/* Try all the MX servers in order, if necessary */
 		res = -1; /* Make condition true to start */
 		while (res < 0 && (hostname = stringlist_pop(&mxservers))) {
-			res = try_send(NULL, &tx, hostname, DEFAULT_SMTP_PORT, 0, NULL, NULL, realfrom, realto, NULL, NULL, 0, fileno(fp), (off_t) metalen, size - metalen, buf, sizeof(buf));
+			res = try_send(NULL, &tx, hostname, DEFAULT_SMTP_PORT, 0, NULL, NULL, mqf->realfrom, mqf->realto, NULL, NULL, 0, fileno(mqf->fp), (off_t) mqf->metalen, mqf->size - mqf->metalen, buf, sizeof(buf));
 			free(hostname);
 		}
 		stringlist_empty(&mxservers);
 	}
 
-	newretries = atoi(retries); /* This is actually current # of retries, not new # yet */
+	mqf->newretries = atoi(mqf->retries); /* This is actually current # of retries, not new # yet */
 	if (!res) {
 		/* Successful delivery. */
-		bbs_debug(6, "Delivery successful after %d attempt%s, discarding queue file\n", newretries, ESS(newretries));
-		smtp_trigger_dsn(DELIVERY_DELIVERED, &tx, &created, realfrom, realto, buf, fileno(fp), metalen, size - metalen);
-		fclose(fp);
-		bbs_delete_file(fullname);
+		bbs_debug(6, "Delivery successful after %d attempt%s, discarding queue file\n", mqf->newretries, ESS(mqf->newretries));
+		bbs_smtp_log(4, NULL, "Delivery succeeded after queuing: %s -> %s\n", mqf->realfrom, mqf->realto);
+		smtp_trigger_dsn(DELIVERY_DELIVERED, &tx, &mqf->created, mqf->realfrom, mqf->realto, buf, fileno(mqf->fp), mqf->metalen, mqf->size - mqf->metalen);
+		fclose(mqf->fp);
+		bbs_delete_file(mqf->fullname);
 		return 0;
 	}
 
-	newretries++; /* Now it's the new number */
-	bbs_debug(3, "Delivery of %s to %s has been attempted %d/%d times\n", fullname, realto, newretries, max_retries);
-	if (res == -2 || res > 0 || newretries >= (int) max_retries) {
+	mqf->newretries++; /* Now it's the new number */
+	bbs_debug(3, "Delivery of %s to %s has been attempted %d/%d times\n", mqf->fullname, mqf->realto, mqf->newretries, max_retries);
+	if (res == -2 || res > 0 || mqf->newretries >= (int) max_retries) {
 		/* Send a delivery failure response, then delete the file. */
-		bbs_warning("Delivery of message %s from %s to %s has failed permanently after %d retries\n", fullname, realfrom, realto, newretries);
+		bbs_warning("Delivery of message %s from %s to %s has failed permanently after %d retries\n", mqf->fullname, mqf->realfrom, mqf->realto, mqf->newretries);
+		bbs_smtp_log(1, NULL, "Delivery failed permanently after queuing: %s -> %s\n", mqf->realfrom, mqf->realto);
 		/* To the dead letter office we go */
 		/* XXX buf will only contain the last line of the SMTP transaction, since it was using the readline buffer
 		 * Thus, if we got a multiline error, only the last line is currently included in the non-delivery report */
-		smtp_trigger_dsn(DELIVERY_FAILED, &tx, &created, realfrom, realto, buf, fileno(fp), metalen, size - metalen);
-		fclose(fp);
-		bbs_delete_file(fullname);
+		smtp_trigger_dsn(DELIVERY_FAILED, &tx, &mqf->created, mqf->realfrom, mqf->realto, buf, fileno(mqf->fp), mqf->metalen, mqf->size - mqf->metalen);
+		fclose(mqf->fp);
+		bbs_delete_file(mqf->fullname);
 		return 0;
 	} else {
-		char tmpbuf[256];
-		bbs_strncpy_until(tmpbuf, fullname, sizeof(tmpbuf), '.');
-		/* Store retry information in the filename itself, so we don't have to modify the file, we can just rename it. Inspired by IMAP. */
-		snprintf(newname, sizeof(newname), "%s.%d", tmpbuf, newretries);
-		if (rename(fullname, newname)) {
-			bbs_error("Failed to rename %s to %s\n", fullname, newname);
-		}
-		smtp_trigger_dsn(DELIVERY_DELAYED, &tx, &created, realfrom, realto, buf, fileno(fp), metalen, size - metalen);
+		bbs_smtp_log(3, NULL, "Delivery delayed after queuing: %s -> %s\n", mqf->realfrom, mqf->realto);
+		mailq_file_punt(mqf); /* Try again later */
+		smtp_trigger_dsn(DELIVERY_DELAYED, &tx, &mqf->created, mqf->realfrom, mqf->realto, buf, fileno(mqf->fp), mqf->metalen, mqf->size - mqf->metalen);
 	}
 
-cleanup:
-	fclose(fp);
+	fclose(mqf->fp);
 	return 0;
 }
 
@@ -817,6 +852,48 @@ static void *queue_handler(void *unused)
 	return NULL;
 }
 
+static int on_queue_file_cli_mailq(const char *dir_name, const char *filename, void *obj)
+{
+	struct bbs_cli_args *a = obj;
+	struct mailq_file mqf_stack, *mqf = &mqf_stack;
+	char arrival_date[64];
+
+	memset(&mqf_stack, 0, sizeof(mqf_stack));
+
+	if (mailq_file_load(&mqf_stack, dir_name, filename)) {
+		return 0;
+	}
+
+	strftime(arrival_date, sizeof(arrival_date), "%a, %d %b %Y %H:%M:%S %z", &mqf->created);
+
+	/* Ensure the format is synchronized with the heading in cli_mailq */
+	bbs_dprintf(a->fdout, "%-25s %-30s %7d %-30s %s\n", arrival_date, filename, mqf->newretries, mqf->realfrom, mqf->realto);
+	return 0;
+}
+
+static int cli_mailq(struct bbs_cli_args *a)
+{
+	bbs_dprintf(a->fdout, "%-25s %-30s %7s %-30s %s\n", "Orig Date", "Filename", "Retries", "Sender", "Recipient");
+	pthread_mutex_lock(&queue_lock);
+	bbs_dir_traverse(queue_dir, on_queue_file_cli_mailq, a, -1);
+	pthread_mutex_unlock(&queue_lock);
+	return 0;
+}
+
+static int cli_runq(struct bbs_cli_args *a)
+{
+	UNUSED(a);
+	pthread_mutex_lock(&queue_lock);
+	bbs_dir_traverse(queue_dir, on_queue_file, NULL, -1);
+	pthread_mutex_unlock(&queue_lock);
+	return 0;
+}
+
+static struct bbs_cli_entry cli_commands_mailq[] = {
+	BBS_CLI_COMMAND(cli_mailq, "mailq", 1, "Show the current mail queue", NULL),
+	BBS_CLI_COMMAND(cli_runq, "runq", 1, "Retry delivery of all messages in the mail queue", NULL),
+};
+
 /*! \note Enable a workaround for socket connects to mail servers failing if we try to send them synchronously. This effectively always enables sendasync=yes. */
 #define BUGGY_SEND_IMMEDIATE
 
@@ -1127,13 +1204,15 @@ static int load_module(void)
 		pthread_mutex_destroy(&queue_lock);
 		return -1;
 	}
+	bbs_cli_register_multiple(cli_commands_mailq);
 	return smtp_register_delivery_handler(&extdeliver, 90); /* Lowest priority */
 }
 
 static int unload_module(void)
 {
 	int res;
 	res = smtp_unregister_delivery_agent(&extdeliver);
+	bbs_cli_unregister_multiple(cli_commands_mailq);
 	bbs_pthread_cancel_kill(queue_thread);
 	bbs_pthread_join(queue_thread, NULL);
 	pthread_mutex_destroy(&queue_lock);