From 2c41ae7b738fafb6e32c8f7cffa1e291af91ca11 Mon Sep 17 00:00:00 2001 From: DL6ER Date: Wed, 16 Jan 2019 09:14:35 +0100 Subject: [PATCH] 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 --- FTL.h | 13 ++++- config.c | 126 +++++++++++++++++++++++++++++++++++++++----- database.c | 12 ++--- dnsmasq_interface.c | 37 ++++++++----- gc.c | 6 +-- grep.c | 2 +- networktable.c | 10 ++-- regex.c | 10 ++-- routines.h | 1 + shmem.c | 17 +++--- socket.c | 6 +-- 11 files changed, 184 insertions(+), 56 deletions(-) diff --git a/FTL.h b/FTL.h index eda21af6..eee6e6ec 100644 --- a/FTL.h +++ b/FTL.h @@ -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 diff --git a/config.c b/config.c index 95bf42fb..e072d842 100644 --- a/config.c +++ b/config.c @@ -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(); + } +} diff --git a/database.c b/database.c index 8de6983c..5240d0da 100644 --- a/database.c +++ b/database.c @@ -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; } diff --git a/dnsmasq_interface.c b/dnsmasq_interface.c index b9c8c65e..96aa7fc5 100644 --- a/dnsmasq_interface.c +++ b/dnsmasq_interface.c @@ -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; } diff --git a/gc.c b/gc.c index b5d3f915..342e4846 100644 --- a/gc.c +++ b/gc.c @@ -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(); diff --git a/grep.c b/grep.c index 95551e5b..a640f906 100644 --- a/grep.c +++ b/grep.c @@ -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); } diff --git a/networktable.c b/networktable.c index 09624164..67f564cb 100644 --- a/networktable.c +++ b/networktable.c @@ -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; } diff --git a/regex.c b/regex.c index 5b62385e..93988740 100644 --- a/regex.c +++ b/regex.c @@ -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(®ex[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 diff --git a/routines.h b/routines.h index 109b92c7..9bbdd627 100644 --- a/routines.h +++ b/routines.h @@ -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); diff --git a/shmem.c b/shmem.c index 924dc0ca..dd94ae8f 100644 --- a/shmem.c +++ b/shmem.c @@ -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) diff --git a/socket.c b/socket.c index 74470c5e..a7354156 100644 --- a/socket.c +++ b/socket.c @@ -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]); }