# HG changeset patch
# User meillo@marmaro.de
# Date 1277902859 -7200
# Node ID a80ebfa16cd5a558bd84cc68d5eebb9333bf26a5
# Parent  c93023f58cc7ccb5e7743d8a75b021a0f15bc807
better debugging output (thanks to Paolo)

diff -r c93023f58cc7 -r a80ebfa16cd5 src/alias.c
--- a/src/alias.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/alias.c	Wed Jun 30 15:00:59 2010 +0200
@@ -32,6 +32,8 @@
 		if (fnmatch(dom_node->data, addr->domain, FNM_CASEFOLD) == 0) {
 			foreach(conf.not_local_addresses, addr_node) {
 				a = create_address_qualified(addr_node->data, TRUE, conf.host_name);
+				DEBUG(6) debugf("not_local_addresses: addr_node->data=%s a->address=%s\n",
+				                addr_node->data, a->address);
 				if (addr_isequal(a, addr)) {
 					destroy_address(a);
 					return FALSE;
@@ -43,6 +45,8 @@
 	}
 	foreach(conf.local_addresses, addr_node) {
 		a = create_address_qualified(addr_node->data, TRUE, conf.host_name);
+		DEBUG(6) debugf("local_addresses: addr_node->data=%s a->address=%s\n",
+		                addr_node->data, a->address);
 		if (addr_isequal(a, addr)) {
 			destroy_address(a);
 			return TRUE;
diff -r c93023f58cc7 -r a80ebfa16cd5 src/conf.c
--- a/src/conf.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/conf.c	Wed Jun 30 15:00:59 2010 +0200
@@ -99,6 +99,7 @@
 		fgets(buf, 255, fptr);
 		if (buf[0] && (buf[0] != '#') && (buf[0] != '\n')) {
 			g_strchomp(buf);
+			DEBUG(6) fprintf(stderr,"parse_list_file: item = %s\n", buf);
 			list = g_list_append(list, g_strdup(buf));
 		}
 	}
@@ -115,7 +116,7 @@
 	gchar buf[256];
 	gchar *p, *q;
 
-	DEBUG(6) fprintf(stderr, "parsing list %s\n", line);
+	DEBUG(6) fprintf(stderr, "parsing list %s, file?:%d\n", line, read_file);
 
 	p = line;
 	while (*p != '\0') {
@@ -132,7 +133,7 @@
 			/* just a normal item */
 			list = g_list_append(list, g_strdup(buf));
 
-		DEBUG(6) printf("item = %s\n", buf);
+		DEBUG(6) fprintf(stderr, "item = %s\n", buf);
 
 		if (*p)
 			p++;
@@ -214,6 +215,7 @@
 		iface->port = atoi(p);
 	} else
 		iface->port = def_port;
+	DEBUG(6) fprintf(stderr,"rval=%s, address:port=%s:%i\n",line, iface->address, iface->port);
 
 	return iface;
 }
@@ -401,19 +403,18 @@
 	if (!eat_comments(in))
 		return FALSE;
 
-	DEBUG(6) fprintf(stderr, "read_statement() 1\n");
-
 	if (!read_lval(in, lval, lsize)) {
 		return FALSE;
 	}
 
-	DEBUG(6) fprintf(stderr, "lval = %s\n", lval);
+	DEBUG(6) fprintf(stderr, "  lval = %s\n", lval);
 	if ((c = fgetc(in) == '=')) {
 		if (read_rval(in, rval, rsize)) {
-			DEBUG(6) fprintf(stderr, "rval = %s\n", rval);
+			DEBUG(6) fprintf(stderr, "  rval = %s\n", rval);
 			return TRUE;
 		}
 	} else {
+		DEBUG(6) fprintf(stderr,"  '=' expected after %s, char was '%c'\n", lval, c);
 		fprintf(stderr, "'=' expected after %s, char was '%c'\n", lval, c);
 	}
 	return FALSE;
@@ -437,6 +438,7 @@
 
 	gchar lval[256], rval[2048];
 	while (read_statement(in, lval, 256, rval, 2048)) {
+		DEBUG(6) fprintf(stderr,"read_conf(): lval=%s\n", lval);
 		if (strcmp(lval, "debug_level") == 0)
 			conf.debug_level = atoi(rval);
 		else if (strcmp(lval, "run_as_user") == 0) {
diff -r c93023f58cc7 -r a80ebfa16cd5 src/connect.c
--- a/src/connect.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/connect.c	Wed Jun 30 15:00:59 2010 +0200
@@ -53,9 +53,9 @@
 
 		/* clumsy, but makes compiler happy: */
 		saddr.sin_addr = *(struct in_addr *) (&(addr->ip));
-		DEBUG(5) debugf("trying ip %s port %d\n", inet_ntoa(saddr.sin_addr), port);
+		DEBUG(5) debugf("  trying ip %s port %d\n", inet_ntoa(saddr.sin_addr), port);
 		if (connect(*psockfd, (struct sockaddr *) (&saddr), sizeof(saddr)) == 0) {
-			DEBUG(5) debugf("connected to %s\n", inet_ntoa(saddr.sin_addr));
+			DEBUG(5) debugf("  connected to %s\n", inet_ntoa(saddr.sin_addr));
 			return addr;
 		} else {
 			int saved_errno = errno;
@@ -115,7 +115,7 @@
 
 	foreach(res_func_list, res_node) {
 		resolve_func res_func;
-		DEBUG(6) debugf("connect_resolvelist 1a\n");
+		DEBUG(6) debugf("  foreach() body\n");
 		res_func = (resolve_func) (res_node->data);
 
 		if (res_func == NULL) {
diff -r c93023f58cc7 -r a80ebfa16cd5 src/deliver.c
--- a/src/deliver.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/deliver.c	Wed Jun 30 15:00:59 2010 +0200
@@ -693,8 +693,11 @@
 		GList *localnet_rcpt_list = NULL;
 		GList *other_rcpt_list;
 
-		if (!spool_lock(msgout->msg->uid))
+		if (!spool_lock(msgout->msg->uid)) {
+			DEBUG(5) debugf("spool_lock(%s) failed.\n", msgout->msg->uid);
 			continue;
+		}
+		DEBUG(5) debugf("spool_lock(%s)\n", msgout->msg->uid);
 
 		rcpt_list = g_list_copy(msgout->msg->rcpt_list);
 		if (conf.log_user) {
@@ -751,6 +754,7 @@
 
 	/* actual delivery */
 	if (local_msgout_list != NULL) {
+		DEBUG(5) debugf("local_msgout_list\n");
 		foreach(local_msgout_list, msgout_node) {
 			msg_out *msgout = (msg_out *) (msgout_node->data);
 			if (!deliver_local(msgout))
@@ -763,6 +767,7 @@
 		GList *route_list = NULL;
 		GList *route_node;
 
+		DEBUG(5) debugf("localnet_msgout_list\n");
 		if (conf.local_net_routes)
 			route_list = read_route_list(conf.local_net_routes, TRUE);
 		else
@@ -778,6 +783,7 @@
 	}
 
 	if (other_msgout_list != NULL) {
+		DEBUG(5) debugf("other_msgout_list\n");
 		if (!deliver_msgout_list_online(other_msgout_list))
 			ok = FALSE;
 		destroy_msg_out_list(other_msgout_list);
@@ -785,7 +791,12 @@
 
 	foreach(msgout_list, msgout_node) {
 		msg_out *msgout = (msg_out *) (msgout_node->data);
-		spool_unlock(msgout->msg->uid);
+		if (spool_unlock(msgout->msg->uid)) {
+			DEBUG(5) debugf("spool_unlock(%s)\n", msgout->msg->uid);
+		} else {
+			DEBUG(5) debugf("spool_unlock(%s) failed.\n", msgout->msg->uid);
+		}
+
 	}
 
 	destroy_msg_out_list(msgout_list);
diff -r c93023f58cc7 -r a80ebfa16cd5 src/local.c
--- a/src/local.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/local.c	Wed Jun 30 15:00:59 2010 +0200
@@ -70,8 +70,7 @@
 			}
 		}
 
-		DEBUG(5) debugf("running as euid %d\n", geteuid());
-		DEBUG(5) debugf("running as egid %d\n", getegid());
+		DEBUG(5) debugf("running as euid %d, egid %d\n", geteuid(), getegid());
 
 		if (uid_ok && gid_ok) {
 			gchar *filename;
@@ -168,15 +167,14 @@
 			}
 		}
 
-		DEBUG(5) debugf("running as euid %d\n", geteuid());
-		DEBUG(5) debugf("running as egid %d\n", getegid());
+		DEBUG(5) debugf("running as euid %d, egid %d\n", geteuid(), getegid());
 
 		if (uid_ok && gid_ok) {
 			char *path = g_strdup_printf("%s/Maildir", pw->pw_dir);
 			struct stat statbuf;
 			int ret;
 
-			DEBUG(5) debugf("path = %s\n", path);
+			DEBUG(5) debugf("  path = %s\n", path);
 
 			ok = TRUE;
 			ret = stat(path, &statbuf);
diff -r c93023f58cc7 -r a80ebfa16cd5 src/parse.c
--- a/src/parse.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/parse.c	Wed Jun 30 15:00:59 2010 +0200
@@ -349,7 +349,7 @@
 /*
   allocate address, reading from string.
   On failure, returns NULL.
-  after call, end contatins a pointer to the end of the parsed string
+  after call, end contains a pointer to the end of the parsed string
   end may be NULL, if we are not interested.
 
   parses both rfc 821 and rfc 822 addresses, depending on flag is_rfc821
diff -r c93023f58cc7 -r a80ebfa16cd5 src/queue.c
--- a/src/queue.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/queue.c	Wed Jun 30 15:00:59 2010 +0200
@@ -97,6 +97,7 @@
 	if (msg_list != NULL) {
 		ok = deliver_msg_list(msg_list, DLVR_ALL);
 		destroy_msg_list(msg_list);
+		logwrite(LOG_NOTICE, "  deliver_msg_list()=%d.\n", ok);
 	}
 	logwrite(LOG_NOTICE, "Finished queue run.\n");
 
diff -r c93023f58cc7 -r a80ebfa16cd5 src/route.c
--- a/src/route.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/route.c	Wed Jun 30 15:00:59 2010 +0200
@@ -321,7 +321,8 @@
 			debugf("rcpts for routed delivery, route = %s, id = %s\n", route->name, msg->uid);
 			foreach(rcpt_list, node) {
 				address *rcpt = (address *) (node->data);
-				debugf("rcpt for routed delivery: <%s@%s>\n", rcpt->local_part, rcpt->domain);
+				debugf("  rcpt for routed delivery: <%s@%s>\n",
+				       rcpt->local_part, rcpt->domain);
 			}
 		}
 
diff -r c93023f58cc7 -r a80ebfa16cd5 src/smtp_out.c
--- a/src/smtp_out.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/smtp_out.c	Wed Jun 30 15:00:59 2010 +0200
@@ -262,8 +262,9 @@
 
 					DEBUG(4) {
 						gint i = 0;
+						debugf("in check_helo_response()\n");
 						while (psb->auth_names[i]) {
-							debugf("offered AUTH %s\n", psb->auth_names[i]);
+							debugf("  offered AUTH %s\n", psb->auth_names[i]);
 							i++;
 						}
 					}
@@ -277,9 +278,9 @@
 	}
 
 	DEBUG(4) {
-		debugf(psb->use_size ? "uses SIZE\n" : "no size\n");
-		debugf(psb->use_pipelining ? "uses PIPELINING\n" : "no pipelining\n");
-		debugf(psb->use_auth ? "uses AUTH\n" : "no auth\n");
+		debugf("  %s\n", psb->use_size ? "uses SIZE" : "no size");
+		debugf("  %s\n", psb->use_pipelining ? "uses PIPELINING" : "no pipelining");
+		debugf("  %s\n", psb->use_auth ? "uses AUTH" : "no auth");
 	}
 
 	return TRUE;
@@ -555,10 +556,10 @@
 			unsigned int digest_len;
 #endif
 
-			DEBUG(5) debugf("encoded challenge = %s\n", chall64);
-			DEBUG(5) debugf("decoded challenge = %s, size = %d\n", chall, chall_size);
-
-			DEBUG(5) debugf("secret = %s\n", psb->auth_secret);
+			DEBUG(5) debugf("smtp_out_auth_cram_md5():\n");
+			DEBUG(5) debugf("  encoded challenge = %s\n", chall64);
+			DEBUG(5) debugf("  decoded challenge = %s, size = %d\n", chall, chall_size);
+			DEBUG(5) debugf("  secret = %s\n", psb->auth_secret);
 
 #ifdef USE_LIB_CRYPTO
 			HMAC(EVP_md5(), psb->auth_secret, strlen(psb->auth_secret), chall, chall_size, digest, &digest_len);
@@ -570,17 +571,17 @@
 				sprintf(&(digest_string[i + i]), "%02x", (unsigned int) (digest[i]));
 			digest_string[32] = '\0';
 
-			DEBUG(5) debugf("digest = %s\n", digest_string);
+			DEBUG(5) debugf("  digest = %s\n", digest_string);
 
 			reply = g_strdup_printf("%s %s", psb->auth_login, digest_string);
-			DEBUG(5) debugf("unencoded reply = %s\n", reply);
+			DEBUG(5) debugf("  unencoded reply = %s\n", reply);
 
 			reply64 = base64_encode(reply, strlen(reply));
-			DEBUG(5) debugf("encoded reply = %s\n", reply64);
+			DEBUG(5) debugf("  encoded reply = %s\n", reply64);
 
 			fprintf(psb->out, "%s\r\n", reply64);
 			fflush(psb->out);
-			DEBUG(4) debugf("%s\n", reply64);
+			DEBUG(4) debugf("  reply64 = %s\n", reply64);
 
 			if ((ok = read_response(psb, SMTP_CMD_TIMEOUT)))
 				ok = check_response(psb, FALSE);
@@ -607,11 +608,12 @@
 			gint resp_size;
 			gchar *reply64;
 
+			DEBUG(5) debugf("smtp_out_auth_login():\n");
 			resp64 = get_response_arg(&(psb->buffer[4]));
-			DEBUG(5) debugf("encoded response = %s\n", resp64);
+			DEBUG(5) debugf("  encoded response = %s\n", resp64);
 			resp = base64_decode(resp64, &resp_size);
 			g_free(resp64);
-			DEBUG(5) debugf("decoded response = %s, size = %d\n", resp, resp_size);
+			DEBUG(5) debugf("  decoded response = %s, size = %d\n", resp, resp_size);
 			g_free(resp);
 			reply64 = base64_encode(psb->auth_login, strlen(psb->auth_login));
 			fprintf(psb->out, "%s\r\n", reply64);
@@ -620,10 +622,10 @@
 			if ((ok = read_response(psb, SMTP_CMD_TIMEOUT))) {
 				if ((ok = check_response(psb, TRUE))) {
 					resp64 = get_response_arg(&(psb->buffer[4]));
-					DEBUG(5) debugf("encoded response = %s\n", resp64);
+					DEBUG(5) debugf("  encoded response = %s\n", resp64);
 					resp = base64_decode(resp64, &resp_size);
 					g_free(resp64);
-					DEBUG(5) debugf("decoded response = %s, size = %d\n", resp, resp_size);
+					DEBUG(5) debugf("  decoded response = %s, size = %d\n", resp, resp_size);
 					g_free(resp);
 					reply64 = base64_encode(psb->auth_secret, strlen(psb->auth_secret));
 					fprintf(psb->out, "%s\r\n", reply64);
@@ -712,7 +714,8 @@
 
 	/* respect maximum size given by server: */
 	if ((psb->max_size > 0) && (size > psb->max_size)) {
-		logwrite(LOG_WARNING, "%s == host=%s message size (%d) > fixed maximum message size of server (%d)",
+		logwrite(LOG_WARNING, "%s == host=%s message size (%d) > "
+		                      "fixed maximum message size of server (%d)",
 		         msg->uid, psb->remote_host, size, psb->max_size);
 		psb->error = smtp_cancel;
 		ok = FALSE;
@@ -747,7 +750,7 @@
 							ok = FALSE;
 							break;
 						} else {
-							logwrite(LOG_NOTICE, "%s == %s host=%s failed: %s",
+							logwrite(LOG_NOTICE, "%s == %s host=%s failed: %s\n",
 							         msg->uid, addr_string(rcpt), psb->remote_host, psb->buffer);
 							if (psb->error == smtp_trylater) {
 								addr_mark_defered(rcpt);
@@ -798,7 +801,7 @@
 										ok = FALSE;
 										break;
 									} else {
-										logwrite(LOG_NOTICE, "%s == %s host=%s failed: %s", msg->uid,
+										logwrite(LOG_NOTICE, "%s == %s host=%s failed: %s\n", msg->uid,
 										         addr_string(rcpt), psb->remote_host, psb->buffer);
 										if (psb->error == smtp_trylater) {
 											addr_mark_defered(rcpt);
@@ -840,9 +843,10 @@
 	}
 
 	DEBUG(5) {
-		debugf("psb->error = %d\n", psb->error);
-		debugf("ok = %d\n", ok);
-		debugf("rcpt_accept = %d\n", rcpt_accept);
+		debugf("smtp_out_msg():\n");
+		debugf("  psb->error = %d\n", psb->error);
+		debugf("  ok = %d\n", ok);
+		debugf("  rcpt_accept = %d\n", rcpt_accept);
 	}
 
 	if (psb->error == smtp_ok) {
diff -r c93023f58cc7 -r a80ebfa16cd5 src/spool.c
--- a/src/spool.c	Wed Jun 30 13:23:49 2010 +0200
+++ b/src/spool.c	Wed Jun 30 15:00:59 2010 +0200
@@ -206,11 +206,14 @@
 	msg = create_message();
 	msg->uid = g_strdup(uid);
 
+	DEBUG(4) debugf("msg_spool_read():\n");
 	/* header spool: */
 	ok = spool_read_header(msg);
+	DEBUG(4) debugf("  spool_read_header()=%d, do_readdata=%d\n", ok, do_readdata);
 	if (ok && do_readdata) {
 		/* data spool: */
 		ok = spool_read_data(msg);
+		DEBUG(4) debugf("  spool_read_data()=%d\n", ok);
 	}
 	return msg;
 }