Output VALUE_PAIRs being merged into control: and reply: by rlm_sql

src/include/radiusd.h

@@ -532,7 +532,8 @@ int		session_zap(REQUEST *request, uint32_t nasaddr,
 #undef debug_pair
 void		debug_pair(VALUE_PAIR *);
 void		debug_pair_list(VALUE_PAIR *);
-void 		rdebug_pair_list(int, REQUEST *, VALUE_PAIR *);
+void		rdebug_pair(int level, REQUEST *, VALUE_PAIR *);
+void 		rdebug_pair_list(int level, REQUEST *, VALUE_PAIR *);
 int		log_err (char *);
 
 /* util.c */

src/main/valuepair.c

@@ -696,6 +696,23 @@ void debug_pair_list(VALUE_PAIR *vp)
 	fflush(fr_log_fp);
 }
 
+/** Print a single valuepair to stderr or error log.
+ *
+ * @param[in] level Debug level (1-4).
+ * @param[in] request to read logging params from.
+ * @param[in] vp to print.
+ */
+void rdebug_pair(int level, REQUEST *request, VALUE_PAIR *vp)
+{
+	char buffer[256];
+	if (!vp || !request || !request->log.func) return;
+
+	if (!radlog_debug_enabled(L_DBG, level, request)) return;
+
+	vp_prints(buffer, sizeof(buffer), vp);
+	RDEBUGX(level, "%s", buffer);
+}
+
 /** Print a list of valuepairs to the request list.
  *
  * @param[in] level Debug level (1-4).
@@ -713,18 +730,10 @@ void rdebug_pair_list(int level, REQUEST *request, VALUE_PAIR *vp)
 	for (vp = fr_cursor_init(&cursor, &vp);
 	     vp;
 	     vp = fr_cursor_next(&cursor)) {
-		/*
-		 *	Take this opportunity to verify all the VALUE_PAIRs are still valid.
-		 */
-		if (!talloc_get_type(vp, VALUE_PAIR)) {
-			REDEBUG("Expected VALUE_PAIR pointer got \"%s\"", talloc_get_name(vp));
-
-			fr_log_talloc_report(vp);
-			rad_assert(0);
-		}
+		VERIFY_VP(vp);
 
 		vp_prints(buffer, sizeof(buffer), vp);
-		RDEBUGX(level, "\t%s", buffer);
+		RDEBUGX(level, "%s", buffer);
 	}
 }
 

src/modules/rlm_cache/rlm_cache.c

@@ -149,22 +149,31 @@ static void CC_HINT(nonnull) cache_merge(rlm_cache_t *inst, REQUEST *request, rl
 
 	if (c->control) {
 		RDEBUG2("Merging cached control list:");
+
+		RINDENT();
 		rdebug_pair_list(2, request, c->control);
+		REXDENT();
 
 		pairadd(&request->config_items, paircopy(request, c->control));
 	}
 
 	if (c->packet && request->packet) {
 		RDEBUG2("Merging cached request list:");
+
+		RINDENT();
 		rdebug_pair_list(2, request, c->packet);
+		REXDENT();
 
 		pairadd(&request->packet->vps,
 			paircopy(request->packet, c->packet));
 	}
 
 	if (c->reply && request->reply) {
 		RDEBUG2("Merging cached reply list:");
+
+		RINDENT();
 		rdebug_pair_list(2, request, c->reply);
+		REXDENT();
 
 		pairadd(&request->reply->vps,
 			paircopy(request->reply, c->reply));

src/modules/rlm_sql/rlm_sql.c

@@ -636,6 +636,9 @@ static rlm_rcode_t rlm_sql_process_groups(rlm_sql_t *inst, REQUEST *request, rlm
 		}
 
 		if (inst->config->authorize_group_check_query && (*inst->config->authorize_group_check_query != '\0')) {
+			vp_cursor_t cursor;
+			VALUE_PAIR *vp;
+
 			/*
 			 *	Expand the group query
 			 */
@@ -665,9 +668,19 @@ static rlm_rcode_t rlm_sql_process_groups(rlm_sql_t *inst, REQUEST *request, rlm
 				continue;
 			}
 
-			RDEBUG2("Group \"%s\" check items matched", entry->name);
+			RDEBUG2("Group \"%s\": Conditional check items matched", entry->name);
 			rcode = RLM_MODULE_OK;
 
+			RDEBUG2("Group \"%s\": Merging assignment check items", entry->name);
+			RINDENT();
+			for (vp = fr_cursor_init(&cursor, &check_tmp);
+			     vp;
+			     vp = fr_cursor_next(&cursor)) {
+			 	if (!fr_assignment_op[vp->op]) continue;
+
+			 	rdebug_pair(2, request, vp);
+			}
+			REXDENT();
 			radius_pairmove(request, &request->config_items, check_tmp, true);
 			check_tmp = NULL;
 		}
@@ -690,12 +703,15 @@ static rlm_rcode_t rlm_sql_process_groups(rlm_sql_t *inst, REQUEST *request, rlm
 				rcode = RLM_MODULE_FAIL;
 				goto finish;
 			}
-
 			*do_fall_through = fall_through(reply_tmp);
 
-			RDEBUG2("Group \"%s\" reply items processed", entry->name);
+			RDEBUG2("Group \"%s\": Merging reply items", entry->name);
 			rcode = RLM_MODULE_OK;
 
+			RINDENT();
+			rdebug_pair_list(2, request, reply_tmp);
+			REXDENT();
+
 			radius_pairmove(request, &request->reply->vps, reply_tmp, true);
 			reply_tmp = NULL;
 		}
@@ -966,6 +982,9 @@ static rlm_rcode_t CC_HINT(nonnull) mod_authorize(void *instance, REQUEST *reque
 	 *	Query the check table to find any conditions associated with this user/realm/whatever...
 	 */
 	if (inst->config->authorize_check_query) {
+		vp_cursor_t cursor;
+		VALUE_PAIR *vp;
+
 		if (radius_axlat(&expanded, request, inst->config->authorize_check_query,
 				 sql_escape_func, inst) < 0) {
 			REDEBUG("Error generating query");
@@ -994,8 +1013,18 @@ static rlm_rcode_t CC_HINT(nonnull) mod_authorize(void *instance, REQUEST *reque
 			goto skipreply;
 		}
 
-		RDEBUG2("Check items matched");
+		RDEBUG2("Conditional check items matched, merging assignment check items");
+		RINDENT();
+		for (vp = fr_cursor_init(&cursor, &check_tmp);
+		     vp;
+		     vp = fr_cursor_next(&cursor)) {
+			if (!fr_assignment_op[vp->op]) continue;
+
+			rdebug_pair(2, request, vp);
+		}
+		REXDENT();
 		radius_pairmove(request, &request->config_items, check_tmp, true);
+
 		rcode = RLM_MODULE_OK;
 		check_tmp = NULL;
 	}
@@ -1023,9 +1052,15 @@ static rlm_rcode_t CC_HINT(nonnull) mod_authorize(void *instance, REQUEST *reque
 
 		do_fall_through = fall_through(reply_tmp);
 
-		RDEBUG2("User found in radreply table");
+		RDEBUG2("User found in radreply table, merging reply items");
 		user_found = true;
+
+		RINDENT();
+		rdebug_pair_list(2, request, reply_tmp);
+		REXDENT();
+
 		radius_pairmove(request, &request->reply->vps, reply_tmp, true);
+
 		rcode = RLM_MODULE_OK;
 		reply_tmp = NULL;
 	}