Quieten Rhizome advertisement debug logging

Introduce DEBUG_RHIZOME_ADS and sqlite_set_debugmask(), use in
rhizome_packetformats.c advertisement mustering and processing code.
This commit is contained in:
Andrew Bettison 2012-10-10 13:22:30 +10:30
parent 04d50e0057
commit 2a8cfb0404
5 changed files with 69 additions and 16 deletions

1
log.c
View File

@ -314,6 +314,7 @@ debugflags_t debugFlagMask(const char *flagname)
else if (!strcasecmp(flagname,"rhizome")) return DEBUG_RHIZOME;
else if (!strcasecmp(flagname,"rhizometx")) return DEBUG_RHIZOME_TX;
else if (!strcasecmp(flagname,"rhizomerx")) return DEBUG_RHIZOME_RX;
else if (!strcasecmp(flagname,"rhizomerx")) return DEBUG_RHIZOME_RX;
else if (!strcasecmp(flagname,"monitorroutes")) return DEBUG_OVERLAYROUTEMONITOR;
else if (!strcasecmp(flagname,"queues")) return DEBUG_QUEUES;
else if (!strcasecmp(flagname,"broadcasts")) return DEBUG_BROADCASTS;

1
log.h
View File

@ -55,6 +55,7 @@ extern debugflags_t debug;
#define DEBUG_MANIFESTS (1 << 24)
#define DEBUG_MDPREQUESTS (1 << 25)
#define DEBUG_TIMING (1 << 26)
#define DEBUG_RHIZOME_ADS (1 << 27)
#define LOG_LEVEL_SILENT (-1)
#define LOG_LEVEL_DEBUG (0)

View File

@ -246,6 +246,8 @@ __RHIZOME_INLINE int sqlite_code_busy(int code)
return code == SQLITE_BUSY || code == SQLITE_LOCKED;
}
debugflags_t sqlite_set_debugmask(debugflags_t newmask);
sqlite3_stmt *_sqlite_prepare(struct __sourceloc where, sqlite_retry_state *retry, const char *sqlformat, ...);
sqlite3_stmt *_sqlite_prepare_loglevel(struct __sourceloc where, int log_level, sqlite_retry_state *retry, strbuf stmt);
int _sqlite_retry(struct __sourceloc where, sqlite_retry_state *retry, const char *action);

View File

@ -120,10 +120,36 @@ int rhizome_manifest_priority(sqlite_retry_state *retry, const char *id)
return (int) result;
}
debugflags_t sqlite_trace_debug = DEBUG_RHIZOME;
const struct __sourceloc *sqlite_trace_where = NULL;
static void sqlite_trace_callback(void *context, const char *rendered_sql)
{
if (debug & DEBUG_RHIZOME)
DEBUG(rendered_sql);
if (debug & sqlite_trace_debug)
logMessage(LOG_LEVEL_DEBUG, sqlite_trace_where ? *sqlite_trace_where : __HERE__, "%s", rendered_sql);
}
/* This function allows code like:
*
* debugflags_t oldmask = sqlite_set_debugmask(DEBUG_SOMETHING_ELSE);
* ...
* sqlite3_stmt *statement = sqlite_prepare(&retry, "select blah blah blah");
* while (sqlite_step_retry(&retry, statement) == SQLITE_ROW) {
* // do blah blah blah
* }
* ...
* sqlite_set_debugmask(oldmask);
* return result;
*
* so that code can choose which DEBUG_ flags control the logging of rendered SQL queries.
*
* @author Andrew Bettison <andrew@servalproject.com>
*/
debugflags_t sqlite_set_debugmask(debugflags_t newmask)
{
debugflags_t oldmask = sqlite_trace_debug;
sqlite_trace_debug = newmask;
return oldmask;
}
int rhizome_opendb()
@ -315,9 +341,9 @@ sqlite3_stmt *_sqlite_prepare_loglevel(struct __sourceloc where, int log_level,
int _sqlite_step_retry(struct __sourceloc where, int log_level, sqlite_retry_state *retry, sqlite3_stmt *statement)
{
if (!statement)
return -1;
while (1) {
int ret = -1;
sqlite_trace_where = &where;
while (statement) {
int stepcode = sqlite3_step(statement);
switch (stepcode) {
case SQLITE_OK:
@ -325,7 +351,9 @@ int _sqlite_step_retry(struct __sourceloc where, int log_level, sqlite_retry_sta
case SQLITE_ROW:
if (retry)
_sqlite_retry_done(where, retry, sqlite3_sql(statement));
return stepcode;
ret = stepcode;
statement = NULL;
break;
case SQLITE_BUSY:
case SQLITE_LOCKED:
if (retry && _sqlite_retry(where, retry, sqlite3_sql(statement))) {
@ -335,9 +363,13 @@ int _sqlite_step_retry(struct __sourceloc where, int log_level, sqlite_retry_sta
// fall through...
default:
logMessage(log_level, where, "query failed, %s: %s", sqlite3_errmsg(rhizome_db), sqlite3_sql(statement));
return -1;
ret = -1;
statement = NULL;
break;
}
}
sqlite_trace_where = NULL;
return ret;
}
/*

View File

@ -208,18 +208,21 @@ int overlay_rhizome_add_advertisements(int interface_number, struct overlay_buff
// TODO Group handling not completely thought out here yet.
debugflags_t oldmask = sqlite_set_debugmask(DEBUG_RHIZOME_ADS);
sqlite_retry_state retry = SQLITE_RETRY_STATE_DEFAULT;
/* Get number of bundles available if required */
long long tmp = 0;
if (sqlite_exec_int64_retry(&retry, &tmp, "SELECT COUNT(BAR) FROM MANIFESTS;") != 1)
{ RETURN(WHY("Could not count BARs for advertisement")); }
if (sqlite_exec_int64_retry(&retry, &tmp, "SELECT COUNT(BAR) FROM MANIFESTS;") != 1) {
sqlite_set_debugmask(oldmask);
RETURN(WHY("Could not count BARs for advertisement"));
}
bundles_available = (int) tmp;
if (bundles_available==-1||(bundle_offset[0]>=bundles_available))
bundle_offset[0]=0;
if (bundles_available==-1||(bundle_offset[1]>=bundles_available))
bundle_offset[1]=0;
if(0)
if (debug & DEBUG_RHIZOME_ADS)
DEBUGF("%d bundles in database (%d %d), slots=%d.",bundles_available,
bundle_offset[0],bundle_offset[1],slots);
@ -236,8 +239,10 @@ int overlay_rhizome_add_advertisements(int interface_number, struct overlay_buff
statement = sqlite_prepare(&retry, "SELECT BAR,ROWID FROM MANIFESTS LIMIT %d,%d", bundle_offset[pass], slots);
break;
}
if (!statement)
if (!statement) {
sqlite_set_debugmask(oldmask);
RETURN(WHY("Could not prepare sql statement for fetching BARs for advertisement"));
}
while( sqlite_step_retry(&retry, statement) == SQLITE_ROW
&& e->position+RHIZOME_BAR_BYTES<=e->sizeLimit
) {
@ -259,7 +264,7 @@ int overlay_rhizome_add_advertisements(int interface_number, struct overlay_buff
int blob_bytes=sqlite3_blob_bytes(blob);
if (pass&&(blob_bytes!=RHIZOME_BAR_BYTES)) {
if (debug&DEBUG_RHIZOME)
if (debug&DEBUG_RHIZOME_ADS)
DEBUG("Found a BAR that is the wrong size - ignoring");
sqlite3_blob_close(blob);
blob=NULL;
@ -328,6 +333,7 @@ int overlay_rhizome_add_advertisements(int interface_number, struct overlay_buff
ob_patch_rfs(e, COMPUTE_RFS_LENGTH);
sqlite_set_debugmask(oldmask);
RETURN(0);
}
@ -342,6 +348,8 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
rhizome_manifest *m=NULL;
char httpaddrtxt[INET_ADDRSTRLEN];
debugflags_t oldmask = sqlite_set_debugmask(DEBUG_RHIZOME_ADS);
switch (ad_frame_type) {
case 3:
/* The same as type=1, but includes the source HTTP port number */
@ -376,12 +384,14 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
m = rhizome_new_manifest();
if (!m) {
WHY("Out of manifests");
sqlite_set_debugmask(oldmask);
RETURN(0);
}
if (rhizome_read_manifest_file(m, (char *)data, manifest_length) == -1) {
WHY("Error importing manifest body");
rhizome_manifest_free(m);
sqlite_set_debugmask(oldmask);
RETURN(0);
}
@ -389,13 +399,15 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
if (rhizome_manifest_get(m, "id", manifest_id_prefix, sizeof manifest_id_prefix) == NULL) {
WHY("Manifest does not contain 'id' field");
rhizome_manifest_free(m);
sqlite_set_debugmask(oldmask);
RETURN(0);
}
/* trim manifest ID to a prefix for ease of debugging
(that is the only use of this */
manifest_id_prefix[8]=0;
long long version = rhizome_manifest_get_ll(m, "version");
if (debug & DEBUG_RHIZOME_RX) DEBUGF("manifest id=%s* version=%lld", manifest_id_prefix, version);
if (debug & DEBUG_RHIZOME_ADS)
DEBUGF("manifest id=%s* version=%lld", manifest_id_prefix, version);
/* Crude signature presence test */
for(i=m->manifest_all_bytes-1;i>0;i--)
@ -408,6 +420,7 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
offering the same manifest */
WARN("Ignoring manifest announcment with no signature");
rhizome_manifest_free(m);
sqlite_set_debugmask(oldmask);
RETURN(0);
}
@ -421,9 +434,11 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
/* Manifest is okay, so see if it is worth storing */
if (rhizome_manifest_version_cache_lookup(m)) {
/* We already have this version or newer */
if (debug & DEBUG_RHIZOME_RX) DEBUG("We already have that manifest or newer.");
if (debug & DEBUG_RHIZOME_ADS)
DEBUG("We already have that manifest or newer.");
} else {
if (debug & DEBUG_RHIZOME_RX) DEBUG("Not seen before.");
if (debug & DEBUG_RHIZOME_ADS)
DEBUG("Not seen before.");
rhizome_suggest_queue_manifest_import(m, &httpaddr);
// the above function will free the manifest structure, make sure we don't free it again
m=NULL;
@ -431,7 +446,8 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
}
else
{
if (debug & DEBUG_RHIZOME) DEBUG("Unverified manifest has errors - so not processing any further.");
if (debug & DEBUG_RHIZOME_ADS)
DEBUG("Unverified manifest has errors - so not processing any further.");
/* Don't waste any time on this manifest in future attempts for at least
a minute. */
rhizome_queue_ignore_manifest(m, &httpaddr, 60000);
@ -443,5 +459,6 @@ int overlay_rhizome_saw_advertisements(int i, struct overlay_frame *f, long long
}
break;
}
sqlite_set_debugmask(oldmask);
RETURN(0);
}