Offer fine grained debugging options through independentally configurable debug flags. The debugging output of FTL gre considerable over the last year and became overwhelming for users that are not used to it. With this addition, users will be able to switch on only what they want to see.

Signed-off-by: DL6ER <dl6er@dl6er.de>
This commit is contained in:
DL6ER
2019-01-16 09:14:35 +01:00
parent 4d97dd8dd4
commit 2c41ae7b73
11 changed files with 184 additions and 56 deletions
+12 -1
View File
@@ -79,6 +79,17 @@ enum { PRIVACY_SHOW_ALL = 0, PRIVACY_HIDE_DOMAINS, PRIVACY_HIDE_DOMAINS_CLIENTS,
enum { MODE_IP, MODE_NX, MODE_NULL, MODE_IP_NODATA_AAAA, MODE_NODATA };
enum { REGEX_UNKNOWN, REGEX_BLOCKED, REGEX_NOTBLOCKED };
enum { BLOCKING_DISABLED, BLOCKING_ENABLED, BLOCKING_UNKNOWN };
enum {
DEBUG_DATABASE = (1 << 0), /* 00000000 00000001 */
DEBUG_NETWORKING = (1 << 1), /* 00000000 00000010 */
DEBUG_LOCKS = (1 << 2), /* 00000000 00000100 */
DEBUG_QUERIES = (1 << 3), /* 00000000 00001000 */
DEBUG_FLAGS = (1 << 4), /* 00000000 00010000 */
DEBUG_SHMEM = (1 << 5), /* 00000000 00100000 */
DEBUG_GC = (1 << 6), /* 00000000 01000000 */
DEBUG_ARP = (1 << 7), /* 00000000 10000000 */
DEBUG_REGEX = (1 << 8), /* 00000001 00000000 */
};
// Database table "ftl"
enum { DB_VERSION, DB_LASTTIMESTAMP, DB_FIRSTCOUNTERTIMESTAMP };
@@ -147,10 +158,10 @@ typedef struct {
unsigned char privacylevel;
bool ignore_localhost;
unsigned char blockingmode;
bool regex_debugmode;
bool analyze_only_A_AAAA;
bool DBimport;
bool parse_arp_cache;
int16_t debug;
} ConfigStruct;
// Dynamic structs
+113 -13
View File
@@ -255,19 +255,6 @@ void read_FTLconf(void)
break;
}
// REGEX_DEBUGMODE
// defaults to: No
config.regex_debugmode = false;
buffer = parse_FTLconf(fp, "REGEX_DEBUGMODE");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.regex_debugmode = true;
if(config.regex_debugmode)
logg(" REGEX_DEBUGMODE: Active. May increase log file size!");
else
logg(" REGEX_DEBUGMODE: Inactive");
// ANALYZE_ONLY_A_AND_AAAA
// defaults to: No
config.analyze_only_A_AAAA = false;
@@ -335,6 +322,9 @@ void read_FTLconf(void)
else
logg(" PARSE_ARP_CACHE: Inactive");
// Read DEBUG_... setting from pihole-FTL.conf
read_debuging_settings(fp);
logg("Finished config file parsing");
// Release memory
@@ -509,3 +499,113 @@ void get_blocking_mode(FILE *fp)
if(opened)
fclose(fp);
}
void read_debuging_settings(FILE *fp)
{
// Set default (no debug instructions set)
config.debug = 0;
// See if we got a file handle, if not we have to open
// the config file ourselves
bool opened = false;
if(fp == NULL)
{
if((fp = fopen(FTLfiles.conf, "r")) == NULL)
// Return silently if there is no config file available
return;
opened = true;
}
// DEBUG_DATABASE
// defaults to: false
char* buffer = parse_FTLconf(fp, "DEBUG_DATABASE");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_DATABASE;
// DEBUG_NETWORKING
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_NETWORKING");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_NETWORKING;
// DEBUG_LOCKS
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_LOCKS");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_LOCKS;
// DEBUG_QUERIES
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_QUERIES");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_QUERIES;
// DEBUG_FLAGS
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_FLAGS");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_FLAGS;
// DEBUG_SHMEM
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_SHMEM");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_SHMEM;
// DEBUG_GC
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_GC");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_GC;
// DEBUG_ARP
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_ARP");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_ARP;
// DEBUG_REGEX or REGEX_DEBUGMODE (legacy config option)
// defaults to: false
buffer = parse_FTLconf(fp, "DEBUG_REGEX");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_REGEX;
buffer = parse_FTLconf(fp, "REGEX_DEBUGMODE");
if(buffer != NULL && strcasecmp(buffer, "true") == 0)
config.debug |= DEBUG_REGEX;
if(config.debug)
{
logg("*********************");
logg("* Debugging enabled *");
if(config.debug & DEBUG_DATABASE)
logg("* DEBUG_DATABASE *");
if(config.debug & DEBUG_NETWORKING)
logg("* DEBUG_NETWORKING *");
if(config.debug & DEBUG_LOCKS)
logg("* DEBUG_LOCKS *");
if(config.debug & DEBUG_QUERIES)
logg("* DEBUG_QUERIES *");
if(config.debug & DEBUG_FLAGS)
logg("* DEBUG_FLAGS *");
if(config.debug & DEBUG_SHMEM)
logg("* DEBUG_SHMEM *");
if(config.debug & DEBUG_GC)
logg("* DEBUG_GC *");
if(config.debug & DEBUG_ARP)
logg("* DEBUG_ARP *");
if(config.debug & DEBUG_REGEX)
logg("* DEBUG_REGEX *");
logg("*********************");
}
// Have to close the config file if we opened it
if(opened)
{
fclose(fp);
// Release memory only when we opened the file
// Otherwise, it may still be needed outside of
// this function (initial config parsing)
release_config_memory();
}
}
+6 -6
View File
@@ -88,7 +88,7 @@ bool dbquery(const char *format, ...)
return false;
}
if(debug) logg("dbquery: %s", query);
if(config.debug & DEBUG_DATABASE) logg("dbquery: %s", query);
int rc = sqlite3_exec(db, query, NULL, NULL, &zErrMsg);
@@ -403,7 +403,7 @@ void save_to_DB(void)
return;
// Start database timer
if(debug) timer_start(DATABASE_WRITE_TIMER);
if(config.debug & DEBUG_DATABASE) timer_start(DATABASE_WRITE_TIMER);
// Open database
if(!dbopen())
@@ -554,7 +554,7 @@ void save_to_DB(void)
// Close database
dbclose();
if(debug)
if(config.debug & DEBUG_DATABASE)
{
logg("Notice: Queries stored in DB: %u (took %.1f ms, last SQLite ID %llu)", saved, timer_elapsed_msec(DATABASE_WRITE_TIMER), lastID);
if(saved_error > 0)
@@ -585,7 +585,7 @@ void delete_old_queries_in_DB(void)
int affected = sqlite3_changes(db);
// Print final message only if there is a difference
if(debug || affected)
if((config.debug & DEBUG_DATABASE) || affected)
logg("Notice: Database size is %.2f MB, deleted %i rows", get_db_filesize(), affected);
// Close database
@@ -666,7 +666,7 @@ void read_data_from_DB(void)
return;
}
// Log DB query string in debug mode
if(debug) logg(rstr);
if(config.debug & DEBUG_DATABASE) logg(rstr);
// Prepare SQLite3 statement
sqlite3_stmt* stmt;
@@ -691,7 +691,7 @@ void read_data_from_DB(void)
}
if(queryTimeStamp > now)
{
if(debug) logg("DB warn: Skipping query logged in the future (%i)", queryTimeStamp);
if(config.debug & DEBUG_DATABASE) logg("DB warn: Skipping query logged in the future (%i)", queryTimeStamp);
continue;
}
+24 -13
View File
@@ -61,7 +61,7 @@ void _FTL_new_query(unsigned int flags, char *name, struct all_addr *addr, char
else
{
// Return early to avoid accessing querytypedata out of bounds
if(debug) logg("Notice: Skipping unknown query type: %s (%i)", types, id);
if(config.debug & DEBUG_QUERIES) logg("Notice: Skipping unknown query type: %s (%i)", types, id);
unlock_shm();
return;
}
@@ -69,7 +69,7 @@ void _FTL_new_query(unsigned int flags, char *name, struct all_addr *addr, char
// Skip AAAA queries if user doesn't want to have them analyzed
if(!config.analyze_AAAA && querytype == TYPE_AAAA)
{
if(debug) logg("Not analyzing AAAA query");
if(config.debug & DEBUG_QUERIES) logg("Not analyzing AAAA query");
unlock_shm();
return;
}
@@ -112,7 +112,7 @@ void _FTL_new_query(unsigned int flags, char *name, struct all_addr *addr, char
// Log new query if in debug mode
char *proto = (type == UDP) ? "UDP" : "TCP";
if(debug) logg("**** new %s %s \"%s\" from %s (ID %i, %s:%i)", proto, types, domain, client, id, file, line);
if(config.debug & DEBUG_QUERIES) logg("**** new %s %s \"%s\" from %s (ID %i, %s:%i)", proto, types, domain, client, id, file, line);
// Update counters
int timeidx = findOverTimeID(overTimetimestamp);
@@ -125,7 +125,7 @@ void _FTL_new_query(unsigned int flags, char *name, struct all_addr *addr, char
if(config.analyze_only_A_AAAA && querytype != TYPE_A && querytype != TYPE_AAAA)
{
// Don't process this query further here, we already counted it
if(debug) logg("Notice: Skipping new query: %s (%i)", types, id);
if(config.debug & DEBUG_QUERIES) logg("Notice: Skipping new query: %s (%i)", types, id);
free(domain);
free(domainbuffer);
free(client);
@@ -261,7 +261,7 @@ void _FTL_forwarded(unsigned int flags, char *name, struct all_addr *addr, int i
strtolower(forward);
// Debug logging
if(debug) logg("**** forwarded %s to %s (ID %i, %s:%i)", name, forward, id, file, line);
if(config.debug & DEBUG_QUERIES) logg("**** forwarded %s to %s (ID %i, %s:%i)", name, forward, id, file, line);
// Save status and forwardID in corresponding query identified by dnsmasq's ID
int i = findQueryID(id);
@@ -374,6 +374,9 @@ void FTL_dnsmasq_reload(void)
// Reread regex.list
free_regex();
read_regex_from_file();
// Reread pihole-FTL.conf to see which debugging flags are set
read_debuging_settings(NULL);
}
void _FTL_reply(unsigned short flags, char *name, struct all_addr *addr, int id, const char* file, const int line)
@@ -401,7 +404,7 @@ void _FTL_reply(unsigned short flags, char *name, struct all_addr *addr, int id,
else if(flags & F_NEG)
answer = "(NODATA)";
if(debug)
if(config.debug & DEBUG_QUERIES)
{
logg("**** got reply %s is %s (ID %i, %s:%i)", name, answer, id, file, line);
print_flags(flags);
@@ -416,7 +419,7 @@ void _FTL_reply(unsigned short flags, char *name, struct all_addr *addr, int id,
if(i < 0)
{
// This may happen e.g. if the original query was "pi.hole"
if(debug) logg("FTL_reply(): Query %i has not been found", id);
if(config.debug & DEBUG_QUERIES) logg("FTL_reply(): Query %i has not been found", id);
unlock_shm();
return;
}
@@ -617,8 +620,11 @@ void _FTL_cache(unsigned int flags, char *name, struct all_addr *addr, char *arg
free(domain);
// Debug logging
if(debug) logg("**** got cache answer for %s / %s / %s (ID %i, %s:%i)", name, dest, arg, id, file, line);
if(debug) print_flags(flags);
if(config.debug & DEBUG_QUERIES)
{
logg("**** got cache answer for %s / %s / %s (ID %i, %s:%i)", name, dest, arg, id, file, line);
print_flags(flags);
}
// Get response time
struct timeval response;
@@ -752,7 +758,7 @@ void _FTL_dnssec(int status, int id, const char* file, const int line)
}
// Debug logging
if(debug)
if(config.debug & DEBUG_QUERIES)
{
int domainID = queries[i].domainID;
validate_access("domains", domainID, true, __LINE__, __FUNCTION__, __FILE__);
@@ -793,7 +799,7 @@ void _FTL_header_ADbit(unsigned char header4, unsigned int rcode, int id, const
return;
}
if(debug)
if(config.debug & DEBUG_QUERIES)
{
int domainID = queries[i].domainID;
validate_access("domains", domainID, true, __LINE__, __FUNCTION__, __FILE__);
@@ -829,6 +835,11 @@ void print_flags(unsigned int flags)
{
// Debug function, listing resolver flags in clear text
// e.g. "Flags: F_FORWARD F_NEG F_IPV6"
// Only print flags if corresponding debugging flag is set
if(!(config.debug & DEBUG_FLAGS))
return;
unsigned int i;
char *flagstr = calloc(256,sizeof(char));
for(i = 0; i < sizeof(flags)*8; i++)
@@ -1000,7 +1011,7 @@ void _FTL_forwarding_failed(struct server *server, const char* file, const int l
strtolower(forward);
int forwardID = findForwardID(forward, false);
if(debug) logg("**** forwarding to %s (ID %i, %s:%i) failed", dest, forwardID, file, line);
if(config.debug & DEBUG_QUERIES) logg("**** forwarding to %s (ID %i, %s:%i) failed", dest, forwardID, file, line);
forwarded[forwardID].failed++;
@@ -1123,7 +1134,7 @@ static void block_single_domain(char *domain)
regexlistname = files.regexlist;
add_blocked_domain_cache(&addr4, &addr6, has_IPv4, has_IPv6, domain, NULL, 0, SRC_REGEX);
if(debug) logg("Added %s to cache", domain);
if(config.debug & DEBUG_QUERIES) logg("Added %s to cache", domain);
return;
}
+3 -3
View File
@@ -37,11 +37,11 @@ void *GC_thread(void *val)
// Get minimum time stamp to keep
time_t mintime = time(NULL) - config.maxlogage;
if(debug) timer_start(GC_TIMER);
if(config.debug & DEBUG_GC) timer_start(GC_TIMER);
long int i;
int removed = 0;
if(debug) logg("GC starting, mintime: %u %s", mintime, ctime(&mintime));
if(config.debug & DEBUG_GC) logg("GC starting, mintime: %u %s", mintime, ctime(&mintime));
// Process all queries
for(i=0; i < counters->queries; i++)
@@ -159,7 +159,7 @@ void *GC_thread(void *val)
// Zero out remaining memory (marked as "F" in the above example)
memset(&queries[counters->queries], 0, (counters->queries_MAX - counters->queries)*sizeof(*queries));
if(debug) logg("Notice: GC removed %i queries (took %.2f ms)", removed, timer_elapsed_msec(GC_TIMER));
if(config.debug & DEBUG_GC) logg("Notice: GC removed %i queries (took %.2f ms)", removed, timer_elapsed_msec(GC_TIMER));
// Release thread lock
unlock_shm();
+1 -1
View File
@@ -142,5 +142,5 @@ void check_blocking_status(void)
message = "disabled";
}
if(debug) logg("Blocking status is %s", message);
logg("Blocking status is %s", message);
}
+5 -5
View File
@@ -58,7 +58,7 @@ void parse_arp_cache(void)
}
// Start ARP timer
if(debug) timer_start(ARP_TIMER);
if(config.debug & DEBUG_ARP) timer_start(ARP_TIMER);
// Prepare buffers
char * linebuffer = NULL;
@@ -184,7 +184,7 @@ void parse_arp_cache(void)
dbquery("COMMIT");
// Debug logging
if(debug) logg("ARP table processing (%i entries) took %.1f ms", entries, timer_elapsed_msec(ARP_TIMER));
if(config.debug & DEBUG_ARP) logg("ARP table processing (%i entries) took %.1f ms", entries, timer_elapsed_msec(ARP_TIMER));
// Close file handle
fclose(arpfp);
@@ -199,13 +199,13 @@ static char* getMACVendor(const char* hwaddr)
if(stat(FTLfiles.macvendordb, &st) != 0)
{
// File does not exist
if(debug) logg("getMACVenor(%s): %s does not exist", hwaddr, FTLfiles.macvendordb);
if(config.debug & DEBUG_ARP) logg("getMACVenor(%s): %s does not exist", hwaddr, FTLfiles.macvendordb);
return strdup("");
}
else if(strlen(hwaddr) != 17)
{
// MAC address is incomplete
if(debug) logg("getMACVenor(%s): MAC invalid (length %lu)", hwaddr, strlen(hwaddr));
if(config.debug & DEBUG_ARP) logg("getMACVenor(%s): MAC invalid (length %lu)", hwaddr, strlen(hwaddr));
return strdup("");
}
@@ -269,7 +269,7 @@ void updateMACVendorRecords()
if(stat(FTLfiles.macvendordb, &st) != 0)
{
// File does not exist
if(debug) logg("updateMACVendorRecords(): %s does not exist", FTLfiles.macvendordb);
if(config.debug & DEBUG_ARP) logg("updateMACVendorRecords(): %s does not exist", FTLfiles.macvendordb);
return;
}
+5 -5
View File
@@ -40,7 +40,7 @@ static bool init_regex(const char *regexin, int index)
}
// Store compiled regex string in buffer if in regex debug mode
if(config.regex_debugmode)
if(config.debug & DEBUG_REGEX)
{
regexbuffer[index] = strdup(regexin);
}
@@ -98,8 +98,8 @@ bool match_regex(char *input)
matched = true;
// Print match message when in regex debug mode
if(config.regex_debugmode)
logg("DEBUG: Regex in line %i \"%s\" matches \"%s\"", index+1, regexbuffer[index], input);
if(config.debug & DEBUG_REGEX)
logg("Regex in line %i \"%s\" matches \"%s\"", index+1, regexbuffer[index], input);
break;
}
else if (errcode != REG_NOMATCH)
@@ -134,7 +134,7 @@ void free_regex(void)
regfree(&regex[index]);
// Also free buffered regex strings if in regex debug mode
if(config.regex_debugmode)
if(config.debug & DEBUG_REGEX)
{
free(regexbuffer[index]);
regexbuffer[index] = NULL;
@@ -245,7 +245,7 @@ void read_regex_from_file(void)
regexconfigured = calloc(num_regex, sizeof(bool));
// Buffer strings if in regex debug mode
if(config.regex_debugmode)
if(config.debug & DEBUG_REGEX)
regexbuffer = calloc(num_regex, sizeof(char*));
// Search through file
+1
View File
@@ -73,6 +73,7 @@ void getLogFilePath(void);
void read_FTLconf(void);
void get_privacy_level(FILE *fp);
void get_blocking_mode(FILE *fp);
void read_debuging_settings(FILE *fp);
// gc.c
void *GC_thread(void *val);
+11 -6
View File
@@ -60,7 +60,7 @@ unsigned long long addstr(const char *str)
return 0;
}
if(debug) logg("Adding \"%s\" (len %i) to buffer. next_pos is %i", str, len, next_pos);
if(config.debug & DEBUG_SHMEM) logg("Adding \"%s\" (len %i) to buffer. next_pos is %i", str, len, next_pos);
// Reserve additional memory if necessary
size_t required_size = next_pos + len + 1;
@@ -164,11 +164,13 @@ void _lock_shm(const char* function, const int line, const char * file) {
// Signal that FTL is waiting for a lock
shmLock->waitingForLock = true;
if(debug) logg("Waiting for lock in %s() (%s:%i)", function, file, line);
if(config.debug & DEBUG_LOCKS)
logg("Waiting for lock in %s() (%s:%i)", function, file, line);
int result = pthread_mutex_lock(&shmLock->lock);
if(debug) logg("Obtained lock for %s() (%s:%i)", function, file, line);
if(config.debug & DEBUG_LOCKS)
logg("Obtained lock for %s() (%s:%i)", function, file, line);
// Turn off the waiting for lock signal to notify everyone who was
// deferring to FTL that they can jump in the lock queue.
@@ -187,7 +189,8 @@ void _lock_shm(const char* function, const int line, const char * file) {
void _unlock_shm(const char* function, const int line, const char * file) {
int result = pthread_mutex_unlock(&shmLock->lock);
if(debug) logg("Removed lock in %s() (%s:%i)", function, file, line);
if(config.debug & DEBUG_LOCKS)
logg("Removed lock in %s() (%s:%i)", function, file, line);
if(result != 0)
logg("Failed to unlock SHM lock: %s", strerror(result));
@@ -289,7 +292,8 @@ void destroy_shmem(void)
SharedMemory create_shm(char *name, size_t size)
{
if(debug) logg("Creating shared memory with name \"%s\" and size %zu", name, size);
if(config.debug & DEBUG_SHMEM)
logg("Creating shared memory with name \"%s\" and size %zu", name, size);
SharedMemory sharedMemory = {
.name = name,
@@ -397,7 +401,8 @@ void *enlarge_shmem_struct(char type)
}
bool realloc_shm(SharedMemory *sharedMemory, size_t size) {
logg("Resizing \"%s\" from %zu to %zu", sharedMemory->name, sharedMemory->size, size);
if(config.debug & DEBUG_SHMEM)
logg("Resizing \"%s\" from %zu to %zu", sharedMemory->name, sharedMemory->size, size);
int result = munmap(sharedMemory->ptr, sharedMemory->size);
if(result != 0)
+3 -3
View File
@@ -552,14 +552,14 @@ bool ipv6_available(void)
{
iface[addr->sa_family == AF_INET6 ? 1 : 0]++;
// For now unused debug statement
// logg("Interface %s is %s", interface->ifa_name, addr->sa_family == AF_INET6 ? "IPv6" : "IPv4");
if(config.debug & DEBUG_NETWORKING)
logg("Interface %s is %s", interface->ifa_name, addr->sa_family == AF_INET6 ? "IPv6" : "IPv4");
}
}
freeifaddrs(allInterfaces);
}
if(debug)
if(config.debug & DEBUG_NETWORKING)
{
logg("Found %i IPv4 and %i IPv6 capable interfaces", iface[0], iface[1]);
}