# HG changeset patch
# User Thomas Klausner <tk@giga.or.at>
# Date 1571149547 -7200
# Node ID d70f5f6cb30612543ac7ee7f73a1abe30a788c49
# Parent  6e4737d332e7da667ca1b7b82ab4c57919321a20
rt_ereg: improve logging and locking

diff -r 6e4737d332e7 -r d70f5f6cb306 extensions/rt_ereg/rtereg.c
--- a/extensions/rt_ereg/rtereg.c	Fri Aug 02 20:46:18 2019 +0200
+++ b/extensions/rt_ereg/rtereg.c	Tue Oct 15 16:25:47 2019 +0200
@@ -93,7 +93,7 @@
 		int err = 0;
 		struct fd_list * c;
 
-		TRACE_DEBUG(ANNOYING, "Attempt pattern matching of '%.*s' with rule '%s'", (int)len, value, r->pattern);
+		LOG_D("[rt_ereg] attempting pattern matching of '%.*s' with rule '%s'", (int)len, value, r->pattern);
 
 		#ifdef HAVE_REG_STARTEND
 		{
@@ -118,7 +118,7 @@
 			size_t bl;
 
 			/* Error while compiling the regex */
-			TRACE_DEBUG(INFO, "Error while executing the regular expression '%s':", r->pattern);
+			LOG_E("[rt_ereg] error while executing the regular expression '%s':", r->pattern);
 
 			/* Get the error message size */
 			bl = regerror(err, &r->preg, NULL, 0);
@@ -128,7 +128,7 @@
 
 			/* Get the error message content */
 			regerror(err, &r->preg, errstr, bl);
-			TRACE_DEBUG(INFO, "\t%s", errstr);
+			LOG_E("\t%s", errstr);
 
 			/* Free the buffer, return the error */
 			free(errstr);
@@ -137,12 +137,7 @@
 		}
 
 		/* From this point, the expression matched the AVP value */
-		TRACE_DEBUG(FULL, "[rt_ereg] Match: '%s' to value '%.*s' => '%s' += %d",
-					r->pattern,
-					(int)len,
-					value,
-					r->server,
-					r->score);
+		LOG_D("[rt_ereg] Match: '%s' to value '%.*s' => '%s' += %d", r->pattern, (int)len, value, r->server, r->score);
 
 		for (c = candidates->next; c != candidates; c = c->next) {
 			struct rtd_candidate * cand = (struct rtd_candidate *)c;
@@ -167,7 +162,7 @@
 	/* iterate over all AVPs and try to find a match */
 //	for (i = 0; i<rtereg_conf[j].level; i++) {
 	if (level > rtereg_conf[conf_index].level) {
-		TRACE_DEBUG(INFO, "internal error, dug too deep");
+		LOG_E("internal error, dug too deep");
 		return 1;
 	}
 	what = rtereg_conf[conf_index].avps[level];
@@ -178,11 +173,15 @@
 		CHECK_FCT(fd_msg_avp_hdr(nextavp, &avp_hdr));
 		if ((avp_hdr->avp_code == dictdata.avp_code) && (avp_hdr->avp_vendor == dictdata.avp_vendor)) {
 			if (level != rtereg_conf[conf_index].level - 1) {
-				TRACE_DEBUG(INFO, "[rt_ereg] found grouped AVP %d (vendor %d), digging deeper", avp_hdr->avp_code, avp_hdr->avp_vendor);
+				LOG_D("[rt_ereg] found grouped AVP %d (vendor %d), digging deeper", avp_hdr->avp_code, avp_hdr->avp_vendor);
 				CHECK_FCT(find_avp(nextavp, conf_index, level+1, candidates));
 			} else {
-				TRACE_DEBUG(INFO, "[rt_ereg] found AVP %d (vendor %d)", avp_hdr->avp_code, avp_hdr->avp_vendor);
+				struct dictionary * dict;
+				LOG_D("[rt_ereg] found AVP %d (vendor %d)", avp_hdr->avp_code, avp_hdr->avp_vendor);
+				CHECK_FCT(fd_dict_getdict(what, &dict));
+				CHECK_FCT_DO(fd_msg_parse_dict(nextavp, dict, NULL), /* nothing */);
 				if (avp_hdr->avp_value != NULL) {
+					LOG_A("avp_hdr->avp_value NOT NULL, matching");
 #ifndef HAVE_REG_STARTEND
 					int ret;
 
@@ -223,7 +222,7 @@
 	msg_or_avp *where;
 	int j, ret;
 
-	TRACE_ENTRY("%p %p %p", cbdata, *pmsg, candidates);
+	LOG_A("[rt_ereg] rtereg_out arguments: %p %p %p", cbdata, *pmsg, candidates);
 
 	CHECK_PARAMS(pmsg && *pmsg && candidates);
 
@@ -238,7 +237,7 @@
 
 		for (j=0; j<rtereg_conf_size; j++) {
 			where = *pmsg;
-			TRACE_DEBUG(INFO, "[rt_ereg] iterating over AVP group %d", j);
+			LOG_D("[rt_ereg] iterating over AVP group %d", j);
 			if ((ret=find_avp(where, j, 0, candidates)) != 0) {
 				break;
 			}
@@ -301,12 +300,12 @@
 /* entry point */
 static int rtereg_entry(char * conffile)
 {
-	TRACE_ENTRY("%p", conffile);
+	LOG_A("[rt_ereg] started with conffile '%p'", conffile);
 
 	rt_ereg_config_file = conffile;
 
 	if (rtereg_init() != 0) {
-	    return 1;
+		return 1;
 	}
 
 	/* Register reload callback */
@@ -321,8 +320,8 @@
 {
 	/* Initialize the configuration */
 	if ((rtereg_conf=malloc(sizeof(*rtereg_conf))) == NULL) {
-	    TRACE_DEBUG(INFO, "malloc failured");
-	    return 1;
+		LOG_E("[rt_ereg] malloc failured");
+		return 1;
 	}
 	rtereg_conf_size = 1;
 	memset(rtereg_conf, 0, sizeof(*rtereg_conf));
@@ -366,19 +365,27 @@
 /* Unload */
 static void rtereg_fini(void)
 {
-	TRACE_ENTRY();
-
 	/* Unregister the cb */
 	CHECK_FCT_DO( fd_rt_out_unregister ( rtereg_hdl, NULL ), /* continue */ );
 
+#ifndef HAVE_REG_STARTEND
+	free(buf);
+	buf = NULL;
+#endif /* HAVE_REG_STARTEND */
+
+	if (pthread_rwlock_wrlock(&rte_lock) != 0) {
+		fd_log_error("%s: write-locking failed in fini, giving up", MODULE_NAME);
+		return;
+	}
 	/* Destroy the data */
 	rtereg_conf_free(rtereg_conf, rtereg_conf_size);
 	rtereg_conf = NULL;
 	rtereg_conf_size = 0;
-#ifndef HAVE_REG_STARTEND
-	free(buf);
-	buf = NULL;
-#endif /* HAVE_REG_STARTEND */
+
+	if (pthread_rwlock_unlock(&rte_lock) != 0) {
+		fd_log_error("%s: write-unlocking failed in fini", MODULE_NAME);
+		return;
+	}
 
 	/* Done */
 	return ;
diff -r 6e4737d332e7 -r d70f5f6cb306 extensions/rt_ereg/rtereg_conf.l
--- a/extensions/rt_ereg/rtereg_conf.l	Fri Aug 02 20:46:18 2019 +0200
+++ b/extensions/rt_ereg/rtereg_conf.l	Tue Oct 15 16:25:47 2019 +0200
@@ -80,7 +80,7 @@
 				/* Match a quoted string. */
 				CHECK_MALLOC_DO( yylval->string = strdup(yytext+1), 
 				{
-					TRACE_DEBUG(INFO, "Unable to copy the string '%s': %s", yytext, strerror(errno));
+					LOG_E("[rt_ereg] unable to copy the string '%s': %s", yytext, strerror(errno));
 					return LEX_ERROR; /* trig an error in yacc parser */
 				} );
 				yylval->string[strlen(yytext) - 2] = '\0';
diff -r 6e4737d332e7 -r d70f5f6cb306 extensions/rt_ereg/rtereg_conf.y
--- a/extensions/rt_ereg/rtereg_conf.y	Fri Aug 02 20:46:18 2019 +0200
+++ b/extensions/rt_ereg/rtereg_conf.y	Tue Oct 15 16:25:47 2019 +0200
@@ -61,15 +61,13 @@
 	extern FILE * rtereg_confin;
 	int ret;
 
-	TRACE_ENTRY("%p", conffile);
-
-	TRACE_DEBUG (FULL, "Parsing configuration file: %s...", conffile);
+	LOG_D("[rt_ereg] parsing configuration file '%s'", conffile);
 
 	rtereg_confin = fopen(conffile, "r");
 	if (rtereg_confin == NULL) {
 		ret = errno;
 		fd_log_debug("Unable to open extension configuration file %s for reading: %s", conffile, strerror(ret));
-		TRACE_DEBUG (INFO, "rt_ereg: error occurred, message logged -- configuration file.");
+		LOG_E("[rt_ereg] error occurred, message logged -- configuration file.");
 		return ret;
 	}
 
@@ -79,19 +77,19 @@
 	fclose(rtereg_confin);
 
 	if (rtereg_conf[rtereg_conf_size-1].finished == 0) {
-		TRACE_DEBUG(INFO, "rt_ereg: configuration invalid, AVP ended without OCTETSTRING AVP");
+		LOG_E("[rt_ereg] configuration invalid, AVP ended without OCTETSTRING AVP");
 		return EINVAL;
 	}
 
 	if (ret != 0) {
-		TRACE_DEBUG(INFO, "rt_ereg: unable to parse the configuration file.");
+		LOG_E("[rt_ereg] unable to parse the configuration file.");
 		return EINVAL;
 	} else {
 		int i, sum = 0;
 		for (i=0; i<rtereg_conf_size; i++) {
 			sum += rtereg_conf[i].rules_nb;
 		}
-		TRACE_DEBUG(FULL, "[rt-ereg] Added %d rules successfully.", sum);
+		LOG_D("[rt-ereg] Added %d rules successfully.", sum);
 	}
 
 	return 0;
@@ -104,25 +102,25 @@
 
 	if (rtereg_conf[rtereg_conf_size-1].finished) {
 		if ((ret = realloc(rtereg_conf, sizeof(*rtereg_conf)*(rtereg_conf_size+1))) == NULL) {
-			TRACE_DEBUG(INFO, "rt_ereg: realloc failed");
+			LOG_E("[rt_ereg] realloc failed");
 			return -1;
 		}
 		rtereg_conf_size++;
 		rtereg_conf = ret;
 		memset(&rtereg_conf[rtereg_conf_size-1], 0, sizeof(*rtereg_conf));
-		TRACE_DEBUG(INFO, "rt_ereg: New AVP group found starting with %s", name);
+		LOG_D("[rt_ereg] New AVP group found starting with %s", name);
 	}
 	level = rtereg_conf[rtereg_conf_size-1].level + 1;
 
 	if ((ret = realloc(rtereg_conf[rtereg_conf_size-1].avps, sizeof(*rtereg_conf[rtereg_conf_size-1].avps)*level)) == NULL) {
-		TRACE_DEBUG(INFO, "rt_ereg: realloc failed");
+		LOG_E("[rt_ereg] realloc failed");
 		return -1;
 	}
 	rtereg_conf[rtereg_conf_size-1].avps = ret;
 
 	CHECK_FCT_DO( fd_dict_search ( fd_g_config->cnf_dict, DICT_AVP, AVP_BY_NAME_ALL_VENDORS, name, &rtereg_conf[rtereg_conf_size-1].avps[level-1], ENOENT ),
 		      {
-			      TRACE_DEBUG(INFO, "rt_ereg: Unable to find '%s' AVP in the loaded dictionaries.", name);
+			      LOG_E("[rt_ereg] Unable to find '%s' AVP in the loaded dictionaries.", name);
 			      return -1;
 		      } );
 
@@ -133,7 +131,7 @@
 		if (data.avp_basetype == AVP_TYPE_OCTETSTRING) {
 			rtereg_conf[rtereg_conf_size-1].finished = 1;
 		} else if (data.avp_basetype != AVP_TYPE_GROUPED) {
-			TRACE_DEBUG(INFO, "rt_ereg: '%s' AVP is not an OCTETSTRING nor GROUPED AVP (%d).", name, data.avp_basetype);
+			LOG_E("[rt_ereg] '%s' AVP is not an OCTETSTRING nor GROUPED AVP (%d).", name, data.avp_basetype);
 			return -1;
 		}
 	}
@@ -147,7 +145,7 @@
 /* Function to report the errors */
 void yyerror (YYLTYPE *ploc, char * conffile, char const *s)
 {
-	TRACE_DEBUG(INFO, "rt_ereg: error in configuration parsing");
+	LOG_E("[rt_ereg] error in configuration parsing");
 
 	if (ploc->first_line != ploc->last_line)
 		fd_log_debug("%s:%d.%d-%d.%d : %s", conffile, ploc->first_line, ploc->first_column, ploc->last_line, ploc->last_column, s);
@@ -222,7 +220,7 @@
 						size_t bl;
 
 						/* Error while compiling the regex */
-						TRACE_DEBUG(INFO, "rt_ereg: error while compiling the regular expression '%s':", new->pattern);
+						LOG_E("[rt_ereg] error while compiling the regular expression '%s':", new->pattern);
 
 						/* Get the error message size */
 						bl = regerror(err, &new->preg, NULL, 0);
@@ -232,7 +230,7 @@
 
 						/* Get the error message content */
 						regerror(err, &new->preg, buf, bl);
-						TRACE_DEBUG(INFO, "\t%s", buf);
+						LOG_E("\t%s", buf);
 
 						/* Free the buffer, return the error */
 						free(buf);