From 4dcd092f7f780f07913be558253bc0ba2e48ca87 Mon Sep 17 00:00:00 2001
From: Stephan Bosch <stephan@rename-it.nl>
Date: Sat, 17 Jul 2010 12:11:58 +0200
Subject: [PATCH] Improved runtime trace debugging output for core Sieve
 language.

---
 TODO                                |  2 --
 src/lib-sieve/cmd-discard.c         |  2 +-
 src/lib-sieve/cmd-keep.c            |  3 +-
 src/lib-sieve/cmd-redirect.c        |  3 +-
 src/lib-sieve/cmd-stop.c            |  2 +-
 src/lib-sieve/ext-envelope.c        |  3 ++
 src/lib-sieve/ext-fileinto.c        |  2 +-
 src/lib-sieve/ext-reject.c          |  4 +--
 src/lib-sieve/sieve-address-parts.c |  5 ++++
 src/lib-sieve/sieve-code.c          |  6 ++--
 src/lib-sieve/sieve-interpreter.c   | 19 ++++++++++--
 src/lib-sieve/sieve-match.c         | 45 +++++++++++++++--------------
 src/lib-sieve/sieve-match.h         |  2 +-
 src/lib-sieve/sieve-runtime-trace.c | 11 +++----
 src/lib-sieve/tst-address.c         |  3 ++
 src/lib-sieve/tst-exists.c          | 11 +++++--
 src/lib-sieve/tst-header.c          |  6 ++++
 src/sieve-tools/sieve-test.c        |  4 +--
 18 files changed, 86 insertions(+), 47 deletions(-)

diff --git a/TODO b/TODO
index 16492e004..5b936e961 100644
--- a/TODO
+++ b/TODO
@@ -2,8 +2,6 @@ Current activities:
 
 * Improve debugging support in the sieve-test tool:
 	- Improve trace debugging towards something more intuitively readable.
-	- Give trace debugging multiple levels of verbosity (e.g. to include more 
-    messy output like value matching).
 
 Next (in order of descending priority/precedence):
 
diff --git a/src/lib-sieve/cmd-discard.c b/src/lib-sieve/cmd-discard.c
index 1d43cb26c..69a6821a6 100644
--- a/src/lib-sieve/cmd-discard.c
+++ b/src/lib-sieve/cmd-discard.c
@@ -110,7 +110,7 @@ static int cmd_discard_operation_execute
 	/* Source line */
 	source_line = sieve_runtime_get_command_location(renv);
 
-	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, "discard action");
+	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, "discard action; cancel implicit keep");
 
 	return ( sieve_result_add_action
 		(renv, NULL, &act_discard, NULL, source_line, NULL, 0) >= 0 );
diff --git a/src/lib-sieve/cmd-keep.c b/src/lib-sieve/cmd-keep.c
index 2838fd892..27f3782c9 100644
--- a/src/lib-sieve/cmd-keep.c
+++ b/src/lib-sieve/cmd-keep.c
@@ -102,7 +102,8 @@ static int cmd_keep_operation_execute
 	 * Perform operation
 	 */
 
-	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, "keep action");
+	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, 
+		"keep action; store message in default mailbox");
 	
 	/* Add keep action to result. 
 	 */
diff --git a/src/lib-sieve/cmd-redirect.c b/src/lib-sieve/cmd-redirect.c
index 98f26ae9e..7f77b0fe9 100644
--- a/src/lib-sieve/cmd-redirect.c
+++ b/src/lib-sieve/cmd-redirect.c
@@ -219,7 +219,8 @@ static int cmd_redirect_operation_execute
 	/* FIXME: perform address normalization if the string is not a string literal
 	 */
 
-	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, "redirect action (\"%s\")",
+	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, 
+		"redirect action; forward message to address `%s'",
 		str_sanitize(str_c(redirect), 64));
 	
 	/* Add redirect action to the result */
diff --git a/src/lib-sieve/cmd-stop.c b/src/lib-sieve/cmd-stop.c
index f908285e7..a28f9c2ca 100644
--- a/src/lib-sieve/cmd-stop.c
+++ b/src/lib-sieve/cmd-stop.c
@@ -77,7 +77,7 @@ static bool cmd_stop_generate
 static int opc_stop_execute
 (const struct sieve_runtime_env *renv,  sieve_size_t *address ATTR_UNUSED)
 {	
-	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "STOP");
+	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "stop");
 	
 	sieve_interpreter_interrupt(renv->interp);
 
diff --git a/src/lib-sieve/ext-envelope.c b/src/lib-sieve/ext-envelope.c
index e81cdbc74..97f8fe472 100644
--- a/src/lib-sieve/ext-envelope.c
+++ b/src/lib-sieve/ext-envelope.c
@@ -458,6 +458,9 @@ static int ext_envelope_operation_execute
 		(result=sieve_coded_stringlist_next_item(envp_list, &envp_item)) 
 		&& envp_item != NULL ) {
 		const struct sieve_envelope_part *epart;
+
+		sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
+            "  matching envelope part `%s'", str_sanitize(str_c(envp_item), 80));
 			
 		if ( (epart=_envelope_part_find(str_c(envp_item))) != NULL ) {
 			const struct sieve_address * const *addresses = NULL;
diff --git a/src/lib-sieve/ext-fileinto.c b/src/lib-sieve/ext-fileinto.c
index 0197c5503..9a1b453ca 100644
--- a/src/lib-sieve/ext-fileinto.c
+++ b/src/lib-sieve/ext-fileinto.c
@@ -179,7 +179,7 @@ static int ext_fileinto_operation_execute
 
 	mailbox = str_sanitize(str_c(folder), 64);
 	sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS, 
-		"fileinto action (\"%s\")", mailbox);
+		"fileinto action; store message in mailbox `%s'", mailbox);
 		
 	/* Add action to result */	
 	ret = sieve_act_store_add_to_result
diff --git a/src/lib-sieve/ext-reject.c b/src/lib-sieve/ext-reject.c
index 8736b6537..7251ebffe 100644
--- a/src/lib-sieve/ext-reject.c
+++ b/src/lib-sieve/ext-reject.c
@@ -292,10 +292,10 @@ static int ext_reject_operation_execute
 
 	if ( sieve_operation_is(oprtn, ereject_operation) )
 		sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS,
-			"ereject action (\"%s\")", str_sanitize(str_c(reason), 64));
+			"ereject action; reject message with reason `%s'", str_sanitize(str_c(reason), 64));
 	else
 		sieve_runtime_trace(renv, SIEVE_TRLVL_ACTIONS,
-			"reject action (\"%s\")", str_sanitize(str_c(reason), 64));
+			"reject action; reject message with reason `%s'", str_sanitize(str_c(reason), 64));
 
 	/* Add reject action to the result */
 	pool = sieve_result_pool(renv->result);
diff --git a/src/lib-sieve/sieve-address-parts.c b/src/lib-sieve/sieve-address-parts.c
index d163e8ce7..9cae114ab 100644
--- a/src/lib-sieve/sieve-address-parts.c
+++ b/src/lib-sieve/sieve-address-parts.c
@@ -7,6 +7,7 @@
 #include "hash.h"
 #include "array.h"
 #include "message-address.h"
+#include "str-sanitize.h"
 
 #include "sieve-extensions.h"
 #include "sieve-code.h"
@@ -234,9 +235,13 @@ int sieve_address_match
 (const struct sieve_address_part *addrp, struct sieve_match_context *mctx, 		
 	const char *data)
 {
+	const struct sieve_runtime_env *renv = mctx->runenv;
 	int result = FALSE;
 	const struct message_address *addr;
 
+	sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
+            "  matching addresses `%s'", str_sanitize(data, 80));
+
 	T_BEGIN {
 		bool valid = TRUE;
 		const struct message_address *aitem;
diff --git a/src/lib-sieve/sieve-code.c b/src/lib-sieve/sieve-code.c
index 6f15607ac..02cb48415 100644
--- a/src/lib-sieve/sieve-code.c
+++ b/src/lib-sieve/sieve-code.c
@@ -1058,8 +1058,7 @@ static int opc_jmptrue_execute
 {	
 	bool result = sieve_interpreter_get_test_result(renv->interp);
 	
-	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "jump if true (%s)", 
-		result ? "true" : "false");
+	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "jump if result is true");
 	
 	return sieve_interpreter_program_jump(renv->interp, result);
 }
@@ -1069,8 +1068,7 @@ static int opc_jmpfalse_execute
 {	
 	bool result = sieve_interpreter_get_test_result(renv->interp);
 	
-	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "jump if false (%s)",
-		result ? "true" : "false" );
+	sieve_runtime_trace(renv, SIEVE_TRLVL_COMMANDS, "jump if result is false");
 	
 	return sieve_interpreter_program_jump(renv->interp, !result);
 }	
diff --git a/src/lib-sieve/sieve-interpreter.c b/src/lib-sieve/sieve-interpreter.c
index 68260ea5b..3b2c9a074 100644
--- a/src/lib-sieve/sieve-interpreter.c
+++ b/src/lib-sieve/sieve-interpreter.c
@@ -425,10 +425,23 @@ int sieve_interpreter_program_jump
 		jmp_start + jmp_offset > 0 ) 
 	{	
 		if ( jump ) {
-			sieve_runtime_trace_here(renv, SIEVE_TRLVL_COMMANDS, "jump to #%08llx", 
-				(long long unsigned int) jmp_start + jmp_offset);
+			sieve_size_t jmp_addr = jmp_start + jmp_offset;
+
+			if ( sieve_runtime_trace_active(renv, SIEVE_TRLVL_COMMANDS) ) {
+				unsigned int jmp_line = 
+					sieve_runtime_get_source_location(renv, jmp_addr);
+
+				if ( (renv->trace_config.flags & SIEVE_TRFLG_ADDRESSES) > 0 ) {
+					sieve_runtime_trace(renv, 0, "jumping to line %d [%08llx]", 
+						jmp_line, (long long unsigned int) jmp_addr);
+				} else {
+					sieve_runtime_trace(renv, 0, "jumping to line %d", jmp_line);
+				}
+			}
 
-			*address = jmp_start + jmp_offset;
+			*address = jmp_addr;
+		} else {
+			sieve_runtime_trace(renv, 0, "not jumping");	
 		}
 		
 		return SIEVE_EXEC_OK;
diff --git a/src/lib-sieve/sieve-match.c b/src/lib-sieve/sieve-match.c
index 523e1791e..0d4c8bb93 100644
--- a/src/lib-sieve/sieve-match.c
+++ b/src/lib-sieve/sieve-match.c
@@ -61,20 +61,25 @@ int sieve_match_value
 	const struct sieve_runtime_env *renv = mctx->runenv;
 	const struct sieve_match_type *mcht = mctx->match_type;
 	sieve_coded_stringlist_reset(mctx->key_list);
+	bool trace = sieve_runtime_trace_active(renv, SIEVE_TRLVL_MATCHING);
 	bool ok = TRUE;
+	int ret = 0;
 
 	/* Reject unimplemented match-type */
-	if ( mcht->def == NULL || mcht->def->match == NULL )
+	if ( mcht->def == NULL || mcht->def->match == NULL ) {
+		mctx->status = FALSE;
 		return FALSE;
+	}
 
-	sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
-		"  matching value `%s'", str_sanitize(value, 80));
+	if ( trace ) {
+		sieve_runtime_trace(renv, 0,
+			"  matching value `%s'", str_sanitize(value, 80));
+	}
 
 	/* Match to all key values */
 	if ( mcht->def->is_iterative ) {
 		unsigned int key_index = 0;
 		string_t *key_item = NULL;
-		int ret = 0;
 	
 		while ( (ok=sieve_coded_stringlist_next_item(mctx->key_list, &key_item)) 
 			&& key_item != NULL ) {				
@@ -91,8 +96,10 @@ int sieve_match_value
 							ret = mcht->def->match
 								(mctx, value, val_size, key, key_size, key_index);
 						
-							sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
-								"    with key `%s' => %d", str_sanitize(key, 80), ret);
+							if ( trace ) {
+								sieve_runtime_trace(renv, 0,
+									"    with key `%s' => %d", str_sanitize(key, 80), ret);
+							}
 
 							if ( ret != 0 ) break;
 						}
@@ -101,8 +108,10 @@ int sieve_match_value
 					ret = mcht->def->match(mctx, value, val_size, str_c(key_item), 
 							str_len(key_item), key_index);
 
-					sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
-						"    with key `%s' => %d", str_sanitize(str_c(key_item), 80), ret);
+					if ( trace ) {
+						sieve_runtime_trace(renv, 0,
+							"    with key `%s' => %d", str_sanitize(str_c(key_item), 80), ret);
+					}
 				}
 			} T_END;
 			
@@ -112,31 +121,23 @@ int sieve_match_value
 			key_index++;
 		}
 
-		if ( !ok ) 
-			return -1;
-
-		if ( ret < 0 ) 
-			return ret;
-		if ( ret > 0 )
-			return TRUE;
+		if ( !ok ) ret = -1;
 
 	} else {
-		int ret;
-
 		T_BEGIN {
 			ret = mcht->def->match(mctx, value, val_size, NULL, 0, -1);
 		} T_END;
-
-		return ret;
 	}
 
-	return FALSE;
+	mctx->status = ret;
+	return ret;
 }
 
 int sieve_match_end(struct sieve_match_context **mctx)
 {
 	const struct sieve_runtime_env *renv = (*mctx)->runenv;
 	const struct sieve_match_type *mcht = (*mctx)->match_type;
+	int status = (*mctx)->status;
 	int ret = FALSE;
 
 	if ( mcht->def != NULL && mcht->def->match_deinit != NULL ) {
@@ -146,9 +147,11 @@ int sieve_match_end(struct sieve_match_context **mctx)
 	pool_unref(&(*mctx)->pool);
 	*mctx = NULL;
 
+	if ( ret < 0 ) status = ret;
+
 	sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
 		"  finishing match with result: %s", 
-		( ret > 0 ? "true" : ( ret < 0 ? "error" : "false" ) ));
+		( status > 0 ? "true" : ( status < 0 ? "error" : "false" ) ));
 
 	return ret;
 }
diff --git a/src/lib-sieve/sieve-match.h b/src/lib-sieve/sieve-match.h
index cd79c9a00..ed3c1d79c 100644
--- a/src/lib-sieve/sieve-match.h
+++ b/src/lib-sieve/sieve-match.h
@@ -25,7 +25,7 @@ struct sieve_match_context {
 
 	struct sieve_coded_stringlist *key_list;
 
-
+	int status;
 	void *data;
 };
 
diff --git a/src/lib-sieve/sieve-runtime-trace.c b/src/lib-sieve/sieve-runtime-trace.c
index b570fa017..a4bdd8426 100644
--- a/src/lib-sieve/sieve-runtime-trace.c
+++ b/src/lib-sieve/sieve-runtime-trace.c
@@ -11,12 +11,13 @@
 #include "sieve-runtime-trace.h"
 
 static inline string_t *_trace_line_new
-(sieve_size_t address, unsigned int cmd_line)
+(const struct sieve_runtime_env *renv, sieve_size_t address, unsigned int cmd_line)
 {
 	string_t *trline;
 	
 	trline = t_str_new(128);
-	str_printfa(trline, "%08llx: ", (unsigned long long) address);
+	if ( (renv->trace_config.flags & SIEVE_TRFLG_ADDRESSES) > 0 )
+		str_printfa(trline, "%08llx: ", (unsigned long long) address);
 	if ( cmd_line > 0 )	
 		str_printfa(trline, "%4d: ", cmd_line); 
 	else
@@ -46,7 +47,7 @@ static inline void _trace_line_print_empty
 void _sieve_runtime_trace_error
 (const struct sieve_runtime_env *renv, const char *fmt, va_list args)
 {
-	string_t *trline = _trace_line_new(renv->pc, 0);
+	string_t *trline = _trace_line_new(renv, renv->pc, 0);
 
 	str_printfa(trline, "%s: #ERROR#: ", sieve_operation_mnemonic(renv->oprtn));
 	str_vprintfa(trline, fmt, args);
@@ -59,7 +60,7 @@ void _sieve_runtime_trace_operand_error
 	const char *field_name, const char *fmt, va_list args)
 {
 	string_t *trline = _trace_line_new
-		(oprnd->address, sieve_runtime_get_source_location(renv, oprnd->address));
+		(renv, oprnd->address, sieve_runtime_get_source_location(renv, oprnd->address));
 
 	str_printfa(trline, "%s: #ERROR#: ", sieve_operation_mnemonic(renv->oprtn));
 
@@ -79,7 +80,7 @@ static inline void _sieve_runtime_trace_vprintf
 (const struct sieve_runtime_env *renv, sieve_size_t address,
 	unsigned int cmd_line, const char *fmt, va_list args)
 {	
-	string_t *trline = _trace_line_new(address, cmd_line);
+	string_t *trline = _trace_line_new(renv, address, cmd_line);
 		
 	str_vprintfa(trline, fmt, args); 
 	
diff --git a/src/lib-sieve/tst-address.c b/src/lib-sieve/tst-address.c
index bdecded82..bf6d83feb 100644
--- a/src/lib-sieve/tst-address.c
+++ b/src/lib-sieve/tst-address.c
@@ -264,6 +264,9 @@ static int tst_address_operation_execute
 		(result=sieve_coded_stringlist_next_item(hdr_list, &hdr_item)) 
 		&& hdr_item != NULL ) {
 		const char *const *headers;
+
+		sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
+            "  matching header `%s'", str_sanitize(str_c(hdr_item), 80));
 			
 		if ( mail_get_headers_utf8
 			(renv->msgdata->mail, str_c(hdr_item), &headers) >= 0 ) {	
diff --git a/src/lib-sieve/tst-exists.c b/src/lib-sieve/tst-exists.c
index ee3851ac6..278faf80c 100644
--- a/src/lib-sieve/tst-exists.c
+++ b/src/lib-sieve/tst-exists.c
@@ -1,6 +1,9 @@
 /* Copyright (c) 2002-2010 Dovecot Sieve authors, see the included COPYING file
  */
 
+#include "lib.h"
+#include "str-sanitize.h"
+
 #include "sieve-common.h"
 #include "sieve-commands.h"
 #include "sieve-code.h"
@@ -132,9 +135,13 @@ static int tst_exists_operation_execute
 			
 		if ( mail_get_headers
 			(renv->msgdata->mail, str_c(hdr_item), &headers) < 0 ||
-			headers[0] == NULL ) {	
+			headers[0] == NULL ) {
 			matched = FALSE;				 
-		}
+		}	
+	
+		sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
+        	"  header `%s' %s", str_sanitize(str_c(hdr_item), 80),
+			( matched ? "exists" : "missing" ));
 	}
 	
 	/* Set test result for subsequent conditional jump */
diff --git a/src/lib-sieve/tst-header.c b/src/lib-sieve/tst-header.c
index 438b2e42e..26ce9311f 100644
--- a/src/lib-sieve/tst-header.c
+++ b/src/lib-sieve/tst-header.c
@@ -1,6 +1,9 @@
 /* Copyright (c) 2002-2010 Dovecot Sieve authors, see the included COPYING file
  */
 
+#include "lib.h"
+#include "str-sanitize.h"
+
 #include "sieve-common.h"
 #include "sieve-commands.h"
 #include "sieve-code.h"
@@ -219,6 +222,9 @@ static int tst_header_operation_execute
 		(result=sieve_coded_stringlist_next_item(hdr_list, &hdr_item)) 
 		&& hdr_item != NULL ) {
 		const char *const *headers;
+
+		sieve_runtime_trace(renv, SIEVE_TRLVL_MATCHING,
+			"  matching header `%s'", str_sanitize(str_c(hdr_item), 80));
 			
 		if ( mail_get_headers_utf8
 			(renv->msgdata->mail, str_c(hdr_item), &headers) >= 0 ) {	
diff --git a/src/sieve-tools/sieve-test.c b/src/sieve-tools/sieve-test.c
index fe5aa36e4..55c05771e 100644
--- a/src/sieve-tools/sieve-test.c
+++ b/src/sieve-tools/sieve-test.c
@@ -120,9 +120,9 @@ static void parse_trace_option
 			i_fatal_status(EX_USAGE, "Unknown -tlevel= trace level: %s", lvl);
 		}
 	} else if ( strcmp(tr_option, "debug") == 0 ) {
-		tr_config->flags = SIEVE_TRFLG_DEBUG;
+		tr_config->flags |= SIEVE_TRFLG_DEBUG;
 	} else if ( strcmp(tr_option, "addresses") == 0 ) {
-		tr_config->flags = SIEVE_TRFLG_ADDRESSES;
+		tr_config->flags |= SIEVE_TRFLG_ADDRESSES;
 	} else {
 		i_fatal_status(EX_USAGE, "Unknown -t trace option value: %s", tr_option);
 	}
-- 
GitLab