[PATCH 3/3] add SQL tracing debug facility

This is merely a historical archive of years 2008-2021, before the migration to mailman3.

A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/OpenBSC@lists.osmocom.org/.

Max max.suraev at fairwaves.co
Wed Jul 29 18:20:30 UTC 2015


Signed-off-by: Max <max.suraev at fairwaves.co>
---
 openbsc/include/openbsc/debug.h |  1 +
 openbsc/src/libcommon/debug.c   |  5 +++
 openbsc/src/libmsc/db.c         | 97 ++++++++++++++++++++++-------------------
 3 files changed, 58 insertions(+), 45 deletions(-)

diff --git a/openbsc/include/openbsc/debug.h b/openbsc/include/openbsc/debug.h
index 19d8fc2..658483a 100644
--- a/openbsc/include/openbsc/debug.h
+++ b/openbsc/include/openbsc/debug.h
@@ -23,6 +23,7 @@ enum {
 	DMGCP,
 	DHO,
 	DDB,
+	DSQL,
 	DREF,
 	DGPRS,
 	DNS,
diff --git a/openbsc/src/libcommon/debug.c b/openbsc/src/libcommon/debug.c
index 7fb3ecb..00a9476 100644
--- a/openbsc/src/libcommon/debug.c
+++ b/openbsc/src/libcommon/debug.c
@@ -115,6 +115,11 @@ static const struct log_info_cat default_categories[] = {
 		.description = "Database Layer",
 		.enabled = 1, .loglevel = LOGL_NOTICE,
 	},
+	[DSQL] = {
+		.name = "DSQL",
+		.description = "SQL Queries Tracing",
+		.enabled = 0, .loglevel = LOGL_DEBUG,
+	},
 	[DREF] = {
 		.name = "DREF",
 		.description = "Reference Counting",
diff --git a/openbsc/src/libmsc/db.c b/openbsc/src/libmsc/db.c
index 9b0ce43..d544ec4 100644
--- a/openbsc/src/libmsc/db.c
+++ b/openbsc/src/libmsc/db.c
@@ -185,6 +185,13 @@ void db_error_func(dbi_conn conn, void *data)
 	osmo_log_backtrace(DDB, LOGL_ERROR);
 }
 
+/* Use macro instead of vararg function because recursive vararg use is impossible.
+   ##__VA_ARGS__ extension is not used in order to catch useless calls to dbi_conn_queryf()
+   instead of dbi_conn_query()
+*/
+#define trace_dbi_conn_queryf(c, f, ...) \
+    dbi_conn_queryf(c, f, __VA_ARGS__); do { LOGP(DSQL, LOGL_DEBUG, f "\n", __VA_ARGS__); } while(0)
+
 static int update_db_revision_2(void)
 {
 	dbi_result result;
@@ -507,7 +514,7 @@ struct gsm_subscriber *db_create_subscriber(const char *imsi)
 	/* Is this subscriber known in the db? */
 	subscr = db_get_subscriber(GSM_SUBSCRIBER_IMSI, imsi);
 	if (subscr) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
                          "UPDATE Subscriber set updated = datetime('now') "
                          "WHERE imsi = %s " , imsi);
 		if (!result)
@@ -521,7 +528,7 @@ struct gsm_subscriber *db_create_subscriber(const char *imsi)
 	if (!subscr)
 		return NULL;
 	subscr->flags |= GSM_SUBSCRIBER_FIRST_CONTACT;
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT INTO Subscriber "
 		"(imsi, created, updated) "
 		"VALUES "
@@ -548,7 +555,7 @@ static int get_equipment_by_subscr(struct gsm_subscriber *subscr)
 	const unsigned char *cm2, *cm3;
 	struct gsm_equipment *equip = &subscr->equipment;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"SELECT Equipment.* "
 			"FROM Equipment JOIN EquipmentWatch ON "
 				"EquipmentWatch.equipment_id=Equipment.id "
@@ -597,7 +604,7 @@ int db_get_authinfo_for_subscr(struct gsm_auth_info *ainfo,
 	dbi_result result;
 	const unsigned char *a3a8_ki;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"SELECT * FROM AuthKeys WHERE subscriber_id=%llu",
 			 subscr->id);
 	if (!result)
@@ -630,7 +637,7 @@ int db_sync_authinfo_for_subscr(struct gsm_auth_info *ainfo,
 
 	/* Deletion ? */
 	if (ainfo == NULL) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM AuthKeys WHERE subscriber_id=%llu",
 			subscr->id);
 
@@ -653,13 +660,13 @@ int db_sync_authinfo_for_subscr(struct gsm_auth_info *ainfo,
 		ainfo->a3a8_ki, ainfo->a3a8_ki_len, &ki_str);
 
 	if (!upd) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 				"INSERT INTO AuthKeys "
 				"(subscriber_id, algorithm_id, a3a8_ki) "
 				"VALUES (%llu, %u, %s)",
 				subscr->id, ainfo->auth_algo, ki_str);
 	} else {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 				"UPDATE AuthKeys "
 				"SET algorithm_id=%u, a3a8_ki=%s "
 				"WHERE subscriber_id=%llu",
@@ -683,7 +690,7 @@ int db_get_lastauthtuple_for_subscr(struct gsm_auth_tuple *atuple,
 	int len;
 	const unsigned char *blob;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"SELECT * FROM AuthLastTuples WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result)
@@ -739,7 +746,7 @@ int db_sync_lastauthtuple_for_subscr(struct gsm_auth_tuple *atuple,
 
 	/* Deletion ? */
 	if (atuple == NULL) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM AuthLastTuples WHERE subscriber_id=%llu",
 			subscr->id);
 
@@ -766,7 +773,7 @@ int db_sync_lastauthtuple_for_subscr(struct gsm_auth_tuple *atuple,
 		atuple->kc, sizeof(atuple->kc), &kc_str);
 
 	if (!upd) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 				"INSERT INTO AuthLastTuples "
 				"(subscriber_id, issued, use_count, "
 				 "key_seq, rand, sres, kc) "
@@ -777,7 +784,7 @@ int db_sync_lastauthtuple_for_subscr(struct gsm_auth_tuple *atuple,
 	} else {
 		char *issued = atuple->key_seq == atuple_old.key_seq ?
 					"issued" : "datetime('now')";
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 				"UPDATE AuthLastTuples "
 				"SET issued=%s, use_count=%u, "
 				 "key_seq=%u, rand=%s, sres=%s, kc=%s "
@@ -839,7 +846,7 @@ struct gsm_subscriber *db_get_subscriber(enum gsm_subscriber_field field,
 	switch (field) {
 	case GSM_SUBSCRIBER_IMSI:
 		dbi_conn_quote_string_copy(conn, id, &quoted);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			BASE_QUERY
 			"WHERE imsi = %s ",
 			quoted
@@ -848,7 +855,7 @@ struct gsm_subscriber *db_get_subscriber(enum gsm_subscriber_field field,
 		break;
 	case GSM_SUBSCRIBER_TMSI:
 		dbi_conn_quote_string_copy(conn, id, &quoted);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			BASE_QUERY
 			"WHERE tmsi = %s ",
 			quoted
@@ -857,7 +864,7 @@ struct gsm_subscriber *db_get_subscriber(enum gsm_subscriber_field field,
 		break;
 	case GSM_SUBSCRIBER_EXTENSION:
 		dbi_conn_quote_string_copy(conn, id, &quoted);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			BASE_QUERY
 			"WHERE extension = %s ",
 			quoted
@@ -866,7 +873,7 @@ struct gsm_subscriber *db_get_subscriber(enum gsm_subscriber_field field,
 		break;
 	case GSM_SUBSCRIBER_ID:
 		dbi_conn_quote_string_copy(conn, id, &quoted);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			BASE_QUERY
 			"WHERE id = %s ", quoted);
 		free(quoted);
@@ -907,7 +914,7 @@ int db_subscriber_update(struct gsm_subscriber *subscr)
 
 	/* Copy the id to a string as queryf with %llu is failing */
 	sprintf(buf, "%llu", subscr->id);
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			BASE_QUERY
 			"WHERE id = %s", buf);
 
@@ -949,7 +956,7 @@ int db_sync_subscriber(struct gsm_subscriber *subscriber)
 		q_tmsi = strdup("NULL");
 
 	if (subscriber->expire_lu == GSM_SUBSCRIBER_NO_EXPIRATION) {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"UPDATE Subscriber "
 			"SET updated = datetime('now'), "
 			"name = %s, "
@@ -966,7 +973,7 @@ int db_sync_subscriber(struct gsm_subscriber *subscriber)
 			subscriber->lac,
 			subscriber->imsi);
 	} else {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"UPDATE Subscriber "
 			"SET updated = datetime('now'), "
 			"name = %s, "
@@ -1003,7 +1010,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 {
 	dbi_result result;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM AuthKeys WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1013,7 +1020,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM AuthLastTuples WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1023,7 +1030,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM AuthToken WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1033,7 +1040,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM EquipmentWatch WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1043,7 +1050,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM SMS WHERE src_addr=%s OR dest_addr=%s",
 			subscr->extension, subscr->extension);
 	if (!result) {
@@ -1053,7 +1060,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM VLR WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1063,7 +1070,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM ApduBlobs WHERE subscriber_id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1073,7 +1080,7 @@ int db_subscriber_delete(struct gsm_subscriber *subscr)
 	}
 	dbi_result_free(result);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 			"DELETE FROM Subscriber WHERE id=%llu",
 			subscr->id);
 	if (!result) {
@@ -1143,7 +1150,7 @@ int db_sync_equipment(struct gsm_equipment *equip)
 				   equip->classmark3_len, &cm3);
 	dbi_conn_quote_string_copy(conn, equip->imei, &q_imei);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"UPDATE Equipment SET "
 			"updated = datetime('now'), "
 			"classmark1 = %u, "
@@ -1201,7 +1208,7 @@ int db_subscriber_alloc_tmsi(struct gsm_subscriber *subscriber)
 
 		sprintf(tmsi, "%u", subscriber->tmsi);
 		dbi_conn_quote_string_copy(conn, tmsi, &tmsi_quoted);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"SELECT * FROM Subscriber "
 			"WHERE tmsi = %s ",
 			tmsi_quoted);
@@ -1235,7 +1242,7 @@ int db_subscriber_alloc_exten(struct gsm_subscriber *subscriber)
 
 	for (;;) {
 		try = (rand()%(GSM_MAX_EXTEN-GSM_MIN_EXTEN+1)+GSM_MIN_EXTEN);
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"SELECT * FROM Subscriber "
 			"WHERE extension = %i",
 			try
@@ -1274,7 +1281,7 @@ int db_subscriber_alloc_token(struct gsm_subscriber *subscriber, uint32_t *token
 		try = rand();
 		if (!try) /* 0 is an invalid token */
 			continue;
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"SELECT * FROM AuthToken "
 			"WHERE subscriber_id = %llu OR token = \"%08X\" ",
 			subscriber->id, try);
@@ -1293,7 +1300,7 @@ int db_subscriber_alloc_token(struct gsm_subscriber *subscriber, uint32_t *token
 		}
 		dbi_result_free(result);
 	}
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT INTO AuthToken "
 		"(subscriber_id, created, token) "
 		"VALUES "
@@ -1319,7 +1326,7 @@ int db_subscriber_assoc_imei(struct gsm_subscriber *subscriber, char imei[GSM_IM
 	strncpy(subscriber->equipment.imei, imei,
 		sizeof(subscriber->equipment.imei)-1);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT OR IGNORE INTO Equipment "
 		"(imei, created, updated) "
 		"VALUES "
@@ -1339,7 +1346,7 @@ int db_subscriber_assoc_imei(struct gsm_subscriber *subscriber, char imei[GSM_IM
 	if (equipment_id)
 		DEBUGP(DDB, "New Equipment: ID %llu, IMEI %s\n", equipment_id, imei);
 	else {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"SELECT id FROM Equipment "
 			"WHERE imei = %s ",
 			imei
@@ -1357,7 +1364,7 @@ int db_subscriber_assoc_imei(struct gsm_subscriber *subscriber, char imei[GSM_IM
 		dbi_result_free(result);
 	}
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT OR IGNORE INTO EquipmentWatch "
 		"(subscriber_id, equipment_id, created, updated) "
 		"VALUES "
@@ -1377,7 +1384,7 @@ int db_subscriber_assoc_imei(struct gsm_subscriber *subscriber, char imei[GSM_IM
 		DEBUGP(DDB, "New EquipmentWatch: ID %llu, IMSI %s, IMEI %s\n",
 			equipment_id, subscriber->imsi, imei);
 	else {
-		result = dbi_conn_queryf(conn,
+		result = trace_dbi_conn_queryf(conn,
 			"UPDATE EquipmentWatch "
 			"SET updated = datetime('now') "
 			"WHERE subscriber_id = %llu AND equipment_id = %llu ",
@@ -1411,7 +1418,7 @@ int db_sms_store(struct gsm_sms *sms)
 				   &q_udata);
 
 	/* FIXME: correct validity period */
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT INTO SMS "
 		"(created, valid_until, "
 		 "reply_path_req, status_rep_req, protocol_id, "
@@ -1500,7 +1507,7 @@ struct gsm_sms *db_sms_get(struct gsm_network *net, unsigned long long id)
 	dbi_result result;
 	struct gsm_sms *sms;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"SELECT * FROM SMS WHERE SMS.id = %llu", id);
 	if (!result)
 		return NULL;
@@ -1523,7 +1530,7 @@ struct gsm_sms *db_sms_get_unsent(struct gsm_network *net, unsigned long long mi
 	dbi_result result;
 	struct gsm_sms *sms;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"SELECT SMS.* "
 			"FROM SMS JOIN Subscriber ON "
 				"SMS.dest_addr = Subscriber.extension "
@@ -1553,7 +1560,7 @@ struct gsm_sms *db_sms_get_unsent_by_subscr(struct gsm_network *net,
 	dbi_result result;
 	struct gsm_sms *sms;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"SELECT SMS.* "
 			"FROM SMS JOIN Subscriber ON "
 				"SMS.dest_addr = Subscriber.extension "
@@ -1582,7 +1589,7 @@ struct gsm_sms *db_sms_get_unsent_for_subscr(struct gsm_subscriber *subscr)
 	dbi_result result;
 	struct gsm_sms *sms;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"SELECT SMS.* "
 			"FROM SMS JOIN Subscriber ON "
 				"SMS.dest_addr = Subscriber.extension "
@@ -1610,7 +1617,7 @@ int db_sms_mark_delivered(struct gsm_sms *sms)
 {
 	dbi_result result;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"UPDATE SMS "
 		"SET sent = datetime('now') "
 		"WHERE id = %llu", sms->id);
@@ -1628,7 +1635,7 @@ int db_sms_inc_deliver_attempts(struct gsm_sms *sms)
 {
 	dbi_result result;
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"UPDATE SMS "
 		"SET deliver_attempts = deliver_attempts + 1 "
 		"WHERE id = %llu", sms->id);
@@ -1651,7 +1658,7 @@ int db_apdu_blob_store(struct gsm_subscriber *subscr,
 
 	dbi_conn_quote_binary_copy(conn, apdu, len, &q_apdu);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT INTO ApduBlobs "
 		"(created,subscriber_id,apdu_id_flags,apdu) VALUES "
 		"(datetime('now'),%llu,%u,%s)",
@@ -1673,7 +1680,7 @@ int db_store_counter(struct osmo_counter *ctr)
 
 	dbi_conn_quote_string_copy(conn, ctr->name, &q_name);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"INSERT INTO Counters "
 		"(timestamp,name,value) VALUES "
 		"(datetime('now'),%s,%lu)", q_name, ctr->value);
@@ -1696,7 +1703,7 @@ static int db_store_rate_ctr(struct rate_ctr_group *ctrg, unsigned int num,
 	dbi_conn_quote_string_copy(conn, ctrg->desc->ctr_desc[num].name,
 				   &q_name);
 
-	result = dbi_conn_queryf(conn,
+	result = trace_dbi_conn_queryf(conn,
 		"Insert INTO RateCounters "
 		"(timestamp,name,idx,value) VALUES "
 		"(datetime('now'),%s.%s,%u,%"PRIu64")",
-- 
2.1.4




More information about the OpenBSC mailing list