[PATCH 3/3] add SQL tracing debug facility

Signed-off-by: Max <max.suraev(a)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