(source_info_option): New option

(struct message_data.msgid): New member
(priv_get): Init msgid
(mailfromd_msgid,mailfromd_timestr): New functions
(trace, transcript): Use mailfromd_msgid()
(check_on_host): Print exit code on debug level 1


git-svn-id: file:///svnroot/mailfromd/trunk@512 7a8a7f39-df28-0410-adc6-e0d955640f24

1 files changed, 105 insertions, 26 deletions

diff --git a/src/main.c b/src/main.c
index 369f7adc..885960f0 100644
--- a/src/main.c
+++ b/src/main.c
@@ -96,6 +96,7 @@ double predict_rate;             /* Prediction rate for --list --format=rates*/
 
 int ignore_failed_reads_option;
 #endif
+int source_info_option;          /* Debug messages include source locations */
 
 char *file_option;               /* File name for DB management commands */
 struct db_format *format_option;
@@ -116,6 +117,7 @@ struct message_data {
 	struct smtp_io_data *io;
 	mu_list_t hdr;
 	char *helostr;
+	char msgid[64];
 };
 
 #define MLFIPRIV(ctx)  ((struct message_data*) smfi_getpriv(ctx))
@@ -138,9 +140,22 @@ priv_get(SMFICTX *ctx)
 			md->hdr = NULL;
 			md->io = NULL;
 			md->helostr = NULL;
+			md->msgid[0] = 0;
 			smfi_setpriv(ctx, md);
 		}
 	}
+	if (!md->msgid[0]) {
+		char *p = smfi_getsymval(ctx, "i");
+		if (p) {
+			size_t len = strlen(p);
+			if (len > sizeof md->msgid - 3)
+				len = sizeof md->msgid - 3;
+			memcpy(md->msgid, p, len);
+			md->msgid[len++] = ':';
+			md->msgid[len++] = ' ';
+			md->msgid[len] = 0;
+		}
+	}
 	return md;
 }
 
@@ -154,6 +169,22 @@ priv_set_io(SMFICTX *ctx, struct smtp_io_data *io)
 	return 0;
 }
 
+const char *
+mailfromd_msgid(SMFICTX *ctx)
+{
+	struct message_data *md = priv_get(ctx);
+	return md->msgid;
+}
+
+char *
+mailfromd_timestr(time_t timestamp, char *timebuf, size_t bufsize)
+{
+	struct tm tm;
+	gmtime_r(&timestamp, &tm);
+	strftime(timebuf, bufsize, "%c", &tm);
+	return timebuf;
+}
+	
 int
 priv_store_header_command(SMFICTX *ctx, struct header_node *node)
 {
@@ -251,21 +282,6 @@ logmsg(int prio, const char *fmt, ...)
 }
 
 void
-transcript(char *prefix, const char *msg)
-{
-	if (do_transcript) {
-		int len = strlen(msg);
-		if (msg[len-1] == '\n') {
-			--len;
-			if (len > 0 && msg[len-1] == '\r')
-				--len;
-		}
-		if (len)
-			logmsg(LOG_INFO, "%s %*.*s", prefix, len, len, msg);
-	}
-}
-
-void
 trace(const char *fmt, ...)
 {
 	if (do_trace) {
@@ -289,15 +305,14 @@ void
 log_status(sfsistat status, SMFICTX *ctx)
 {
 	if (debug_level >= 1) {
-		char *id = smfi_getsymval(ctx, "i");
 		const char *str = sfsistat_str(status);
 		if (str)
 			logmsg(LOG_INFO,
-			       "%s: %s", id ? id : "(nil)", str);
+			       "%s%s", mailfromd_msgid(ctx), str);
 		else
 			logmsg(LOG_INFO,
-			       "%s: status %d",
-			       id ? id : "(nil)", status);
+			       "%sstatus %d",
+			       mailfromd_msgid(ctx), status);
 	}
 }
 
@@ -406,6 +421,23 @@ struct smtp_io_data {
 	int code;            /* Reply code */
 };
 
+void
+transcript(struct smtp_io_data *io, char *prefix, const char *msg)
+{
+	if (do_transcript) {
+		int len = strlen(msg);
+		if (msg[len-1] == '\n') {
+			--len;
+			if (len > 0 && msg[len-1] == '\r')
+				--len;
+		}
+		if (len) 
+			logmsg(LOG_INFO, "%s%s %*.*s",
+			       mailfromd_msgid(io->ctx),
+			       prefix, len, len, msg);
+	}
+}
+
 int
 smtp_io_data_init(struct smtp_io_data *dat, SMFICTX *ctx, mu_stream_t stream)
 {
@@ -474,7 +506,7 @@ smtp_send(struct smtp_io_data *dat, char *command)
 	int attempt = 0;
 	size_t len = strlen(command);
 
-	transcript("SEND:", command);
+	transcript(dat, "SEND:", command);
 	do {
 		size_t nb;
 		int rc = mu_stream_write(dat->stream, command, len,
@@ -602,7 +634,7 @@ smtp_recv(struct smtp_io_data *dat)
 		int rc = smtp_recvline(dat);
 		if (rc)
 			return -1;
-		transcript("RECV:", dat->reply);
+		transcript(dat, "RECV:", dat->reply);
 		code = strtoul (dat->reply, &p, 0);
 		if (p - dat->reply != 3 || (*p != '-' && *p != ' ')) {
 			mu_error("Unexpected reply from server: %s",
@@ -622,6 +654,29 @@ smtp_recv(struct smtp_io_data *dat)
 	return 0;
 }
 
+const char *
+smtp_last_sent(struct smtp_io_data *dat)
+{
+	if (dat->command) {
+		size_t len = strcspn(dat->command, "\r\n");
+		dat->command[len] = 0;
+		return dat->command;
+	}
+	return "";
+}
+
+const char *
+smtp_last_received(struct smtp_io_data *dat)
+{
+	if (dat->reply) {
+		size_t len = strcspn(dat->reply, "\r\n");
+		dat->reply[len] = 0;
+		return dat->reply;
+	}
+	return dat->reply ? dat->reply : "";
+}
+
+
 
 /* Milter-specific functions */
 
@@ -641,7 +696,9 @@ check_on_host(SMFICTX *ctx, char *email, char *client_addr,
 						  source_address,
 						  MU_STREAM_NONBLOCK);
 	if (rc) {
-		mu_error ("tcp_stream_create: %s", mu_strerror (rc));
+		mu_error("%scannot connect to `%s': %s",
+			 mailfromd_msgid(ctx), client_addr,
+			 mu_strerror (rc));
 		return mf_temp_failure;
 	}
 
@@ -653,7 +710,8 @@ check_on_host(SMFICTX *ctx, char *email, char *client_addr,
 			if (rc == 0)
 				continue;
 		}
-		mu_error("stream_open: %s, %d", mu_strerror(rc), count);
+		mu_error("%sstream_open: %s, %d",
+			  mailfromd_msgid(ctx), mu_strerror(rc), count);
 		mu_stream_destroy(&stream, mu_stream_get_owner(stream));
 		if (rc == EAGAIN || rc == EINPROGRESS)
 			return mf_temp_failure;
@@ -710,8 +768,15 @@ check_on_host(SMFICTX *ctx, char *email, char *client_addr,
 				break;
 			}
 		} while (0);
-		smtp_send2(&io, "QUIT", NULL);
 
+		debug4(1,
+	             "%spoll exited with status: %s; sent \"%s\", got \"%s\"",
+		       mailfromd_msgid(ctx), 
+		       mf_status_str(status),
+		       smtp_last_sent(&io),
+		       smtp_last_received(&io));
+		
+		smtp_send2(&io, "QUIT", NULL);
 		smtp_io_data_destroy(&io);
 	}
 	
@@ -1289,6 +1354,12 @@ set_group(void *value)
 	/* do nothing */
 }
 
+void
+set_source_info(void *value)
+{
+	source_info_option = (int) value;
+}
+
 int
 option_string(char *opt, void **pval, char *newval)
 {
@@ -1452,6 +1523,7 @@ struct option_cache {
 } option_cache[] = {
 	{ "ehlo", NULL, option_string, set_ehlo },
 	{ "debug", NULL, option_debug, set_debug },
+	{ "source-info", NULL, option_boolean, set_source_info },
 	{ "expire-interval", NULL, option_time, set_expire },
 	{ "positive-expire-interval", NULL, option_time, set_positive_expire },
 	{ "negative-expire-interval", NULL, option_time, set_negative_expire },
@@ -1529,6 +1601,7 @@ enum mailfromd_option {
 	OPTION_PREDICT_NEXT,
 	OPTION_RETRY,
 	OPTION_SHOW_DEFAULTS,
+	OPTION_SOURCE_INFO,
 	OPTION_SYSLOG,
 	OPTION_TIMEOUT,
 	OPTION_TRACE,
@@ -1646,6 +1719,8 @@ static struct argp_option options[] = {
 	  "Log to syslog (default)", GRP+1 },
 	{ "log-tag", 'L', "STRING", 0,
 	  "Set the identifier used in syslog messages to STRING",GRP+1 },
+	{ "source-info", OPTION_SOURCE_INFO, NULL, 0,
+	  "Debug messages include source information", GRP+1 },
 #undef GRP
 	{ NULL }
 };
@@ -1810,6 +1885,10 @@ parse_opt (int key, char *arg, struct argp_state *state)
 		need_config = 0;
 		break;
 
+	case OPTION_SOURCE_INFO:
+		set_option("source-info", "yes", 1);
+		break;
+		
 	case OPTION_SYSLOG:
 		log_to_stderr = 0;
 		break;
@@ -1919,7 +1998,6 @@ switch_to_privs(uid_t uid, gid_t gid)
 {
 	int rc = 0;
 	gid_t *emptygidset;
-	int i;
 	size_t size = 1, j = 1;
 	mu_iterator_t itr;
 
@@ -2130,6 +2208,8 @@ mailfromd_daemon()
 	} else {
 		umask(0117);
 		rc = smfi_main();
+		mu_error("smfi_main failed: rc=%d errno=%s",
+			 rc, strerror (errno));
 	}
 	exit(rc);
 }
@@ -2209,7 +2289,6 @@ mailfromd_list(int argc, char **argv)
 void
 mailfromd_expire()
 {
-	int rc;
 	char *name = get_db_name();
 	
 	if (!format_option->expire) {