diff --git a/doc/debug-sections.txt b/doc/debug-sections.txt index 4ef6627bc98..892042ae2c7 100644 --- a/doc/debug-sections.txt +++ b/doc/debug-sections.txt @@ -130,6 +130,7 @@ section 80 WCCP Support section 81 Store HEAP Removal Policies section 81 aio_xxx() POSIX emulation on Windows section 82 External ACL +section 82 External ACL Helpers section 83 SSL accelerator support section 83 SSL-Bump Server/Peer negotiation section 83 TLS I/O diff --git a/src/Makefile.am b/src/Makefile.am index 3dca80df761..3058e6f5f08 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -16,7 +16,8 @@ LOADABLE_MODULES_SOURCES = \ LoadableModules.cc \ LoadableModules.h -SUBDIRS = mem time debug base anyp helper dns html ftp parser comm error eui acl format clients sbuf servers fs repl store DiskIO proxyp +# subdir Y that requires a file built in subdir X must appear after X +SUBDIRS = mem time debug base anyp helper dns html ftp parser comm error eui sbuf acl format clients servers fs repl store DiskIO proxyp if ENABLE_AUTH SUBDIRS += auth diff --git a/src/acl/external/time_quota/Makefile.am b/src/acl/external/time_quota/Makefile.am index 21cec6a5ce4..26eddb573cf 100644 --- a/src/acl/external/time_quota/Makefile.am +++ b/src/acl/external/time_quota/Makefile.am @@ -14,7 +14,15 @@ DEFS += -DDEFAULT_QUOTA_DB=\"$(localstatedir)/ext_time_quota.db\" ext_time_quota_acl_SOURCES = \ ext_time_quota_acl.cc + ext_time_quota_acl_LDADD = \ + $(top_builddir)/src/sbuf/libsbuf.la \ + $(top_builddir)/src/debug/libdebug.la \ + $(top_builddir)/src/error/liberror.la \ + $(top_builddir)/src/comm/libminimal.la \ + $(top_builddir)/src/mem/libminimal.la \ + $(top_builddir)/src/base/libbase.la \ + $(top_builddir)/src/time/libtime.la \ $(COMPAT_LIB) \ $(LIBTDB_LIBS) diff --git a/src/acl/external/time_quota/ext_time_quota_acl.cc b/src/acl/external/time_quota/ext_time_quota_acl.cc index 5158e8f4584..6a8796a18cb 100644 --- a/src/acl/external/time_quota/ext_time_quota_acl.cc +++ b/src/acl/external/time_quota/ext_time_quota_acl.cc @@ -26,18 +26,14 @@ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. */ +/* DEBUG: section 82 External ACL Helpers */ + #include "squid.h" +#include "debug/Stream.h" #include "helper/protocol_defines.h" +#include "sbuf/Stream.h" -#include -#include #include -#include -#include -#include -#if HAVE_UNISTD_H -#include -#endif #if HAVE_GETOPT_H #include #endif @@ -49,19 +45,20 @@ #error "Please define DEFAULT_QUOTA_DB preprocessor constant." #endif +static const auto MY_DEBUG_SECTION = 82; const char *db_path = DEFAULT_QUOTA_DB; const char *program_name; TDB_CONTEXT *db = nullptr; -#define KEY_LAST_ACTIVITY "last-activity" -#define KEY_PERIOD_START "period-start" -#define KEY_PERIOD_LENGTH_CONFIGURED "period-length-configured" -#define KEY_TIME_BUDGET_LEFT "time-budget-left" -#define KEY_TIME_BUDGET_CONFIGURED "time-budget-configured" +static const auto KeyLastActivity = "last-activity"; +static const auto KeyPeriodStart = "period-start"; +static const auto KeyPeriodLengthConfigured = "period-length-configured"; +static const auto KeyTimeBudgetLeft = "time-budget-left"; +static const auto KeyTimeBudgetConfigured = "time-budget-configured"; /** Maximum size of buffers used to read or display lines. */ -#define TQ_BUFFERSIZE 1024 +static const size_t TQ_BUFFERSIZE = 1024; /** If there is more than this given number of seconds between two * successive requests, than the second request will be treated as a @@ -73,65 +70,17 @@ TDB_CONTEXT *db = nullptr; */ static int pauseLength = 300; -static FILE *logfile = stderr; -static int tq_debug_enabled = false; - -static void vlog(const char *level, const char *format, va_list args) -{ - time_t now = time(NULL); - - fprintf(logfile, "%ld %s| %s: ", static_cast(now), - program_name, level); - vfprintf (logfile, format, args); - fflush(logfile); -} - -static void log_debug(const char *format, ...) -{ - va_list args; - - if ( tq_debug_enabled ) { - va_start (args, format); - vlog("DEBUG", format, args); - va_end (args); - } -} - -static void log_info(const char *format, ...) -{ - va_list args; - - va_start (args, format); - vlog("INFO", format, args); - va_end (args); -} - -static void log_error(const char *format, ...) -{ - va_list args; - - va_start (args, format); - vlog("ERROR", format, args); - va_end (args); -} - -static void log_fatal(const char *format, ...) -{ - va_list args; - - va_start (args, format); - vlog("FATAL", format, args); - va_end (args); -} - static void init_db(void) { - log_info("opening time quota database \"%s\".\n", db_path); + debugs(MY_DEBUG_SECTION, 2, "opening time quota database \"" << db_path << "\"."); + db = tdb_open(db_path, 0, TDB_CLEAR_IF_FIRST, O_CREAT | O_RDWR, 0666); if (!db) { - log_fatal("Failed to open time_quota db '%s'\n", db_path); + debugs(MY_DEBUG_SECTION, DBG_CRITICAL, "FATAL: Failed to open time_quota db '" << db_path << '\''); exit(EXIT_FAILURE); } + // count the number of entries in the database, only used for debugging + debugs(MY_DEBUG_SECTION, 2, "Database contains " << tdb_traverse(db, nullptr, nullptr) << " entries"); } static void shutdown_db(void) @@ -139,65 +88,53 @@ static void shutdown_db(void) tdb_close(db); } -static char *KeyString(int &len, const char *user_key, const char *sub_key) +static SBuf KeyString(const char *user_key, const char *sub_key) { - static char keybuffer[TQ_BUFFERSIZE]; - *keybuffer = 0; - - len = snprintf(keybuffer, sizeof(keybuffer), "%s-%s", user_key, sub_key); - if (len < 0) { - log_error("Cannot add entry: %s-%s", user_key, sub_key); - len = 0; - - } else if (static_cast(len) >= sizeof(keybuffer)) { - log_error("key too long (%s,%s)\n", user_key, sub_key); - len = 0; - } - - return keybuffer; + return ToSBuf(user_key, "-", sub_key); } static void writeTime(const char *user_key, const char *sub_key, time_t t) { - int len = 0; - if (/* const */ char *keybuffer = KeyString(len, user_key, sub_key)) { - - TDB_DATA key, data; - - key.dptr = reinterpret_cast(keybuffer); - key.dsize = len; - - data.dptr = reinterpret_cast(&t); - data.dsize = sizeof(t); - - tdb_store(db, key, data, TDB_REPLACE); - log_debug("writeTime(\"%s\", %d)\n", keybuffer, t); - } + auto ks = KeyString(user_key, sub_key); + const TDB_DATA key { + reinterpret_cast(const_cast(ks.rawContent())), + ks.length() + }; + const TDB_DATA data { + reinterpret_cast(&t), + sizeof(t) + }; + + tdb_store(db, key, data, TDB_REPLACE); + debugs(MY_DEBUG_SECTION, 3, "writeTime(\"" << ks << "\", " << t << ')'); } static time_t readTime(const char *user_key, const char *sub_key) { - int len = 0; - if (/* const */ char *keybuffer = KeyString(len, user_key, sub_key)) { - - TDB_DATA key; - key.dptr = reinterpret_cast(keybuffer); - key.dsize = len; - - auto data = tdb_fetch(db, key); - - time_t t = 0; - if (data.dsize != sizeof(t)) { - log_error("CORRUPTED DATABASE (%s)\n", keybuffer); - } else { - memcpy(&t, data.dptr, sizeof(t)); - } + auto ks = KeyString(user_key, sub_key); + const TDB_DATA key { + reinterpret_cast(const_cast(ks.rawContent())), + ks.length() + }; + auto data = tdb_fetch(db, key); + + if (!data.dptr) { + debugs(MY_DEBUG_SECTION, 3, "no data found for key \"" << ks << "\"."); + return 0; + } - log_debug("readTime(\"%s\")=%d\n", keybuffer, t); - return t; + time_t t = 0; + if (data.dsize == sizeof(t)) { + memcpy(&t, data.dptr, sizeof(t)); + } else { + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "ERROR: Incompatible or corrupted database. " << + "key: '" << ks << + "', expected time value size: " << sizeof(t) << + ", actual time value size: " << data.dsize); } - return 0; + debugs(MY_DEBUG_SECTION, 3, "readTime(\"" << ks << "\")=" << t); + return t; } static void parseTime(const char *s, time_t *secs, time_t *start) @@ -235,7 +172,7 @@ static void parseTime(const char *s, time_t *secs, time_t *start) *start += 24 * 3600; // in europe, the week starts monday break; default: - log_error("Wrong time unit \"%c\". Only \"m\", \"h\", \"d\", or \"w\" allowed.\n", unit); + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "ERROR: Wrong time unit \"" << unit << "\". Only \"m\", \"h\", \"d\", or \"w\" allowed"); break; } @@ -259,7 +196,7 @@ static void readConfig(const char *filename) time_t budgetSecs, periodSecs; time_t start; - log_info("reading config file \"%s\".\n", filename); + debugs(MY_DEBUG_SECTION, 2, "reading config file \"" << filename << "\"."); FH = fopen(filename, "r"); if ( FH ) { @@ -274,30 +211,30 @@ static void readConfig(const char *filename) /* chop \n characters */ *cp = '\0'; } - log_debug("read config line %u: \"%s\".\n", lineCount, line); + debugs(MY_DEBUG_SECTION, 3, "read config line " << lineCount << ": \"" << line << '\"'); if ((username = strtok(line, "\t ")) != NULL) { /* get the time budget */ if ((budget = strtok(nullptr, "/")) == NULL) { - fprintf(stderr, "ERROR: missing 'budget' field on line %u of '%s'.\n", lineCount, filename); + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "ERROR: missing 'budget' field on line " << lineCount << " of '" << filename << '\''); continue; } if ((period = strtok(nullptr, "/")) == NULL) { - fprintf(stderr, "ERROR: missing 'period' field on line %u of '%s'.\n", lineCount, filename); + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "ERROR: missing 'period' field on line " << lineCount << " of '" << filename << '\''); continue; } parseTime(budget, &budgetSecs, &start); parseTime(period, &periodSecs, &start); - log_debug("read time quota for user \"%s\": %lds / %lds starting %lds\n", - username, budgetSecs, periodSecs, start); + debugs(MY_DEBUG_SECTION, 3, "read time quota for user \"" << username << "\": " << + budgetSecs << "s / " << periodSecs << "s starting " << start); - writeTime(username, KEY_PERIOD_START, start); - writeTime(username, KEY_PERIOD_LENGTH_CONFIGURED, periodSecs); - writeTime(username, KEY_TIME_BUDGET_CONFIGURED, budgetSecs); - t = readTime(username, KEY_TIME_BUDGET_CONFIGURED); - writeTime(username, KEY_TIME_BUDGET_LEFT, t); + writeTime(username, KeyPeriodStart, start); + writeTime(username, KeyPeriodLengthConfigured, periodSecs); + writeTime(username, KeyTimeBudgetConfigured, budgetSecs); + t = readTime(username, KeyTimeBudgetConfigured); + writeTime(username, KeyTimeBudgetLeft, t); } } fclose(FH); @@ -316,85 +253,89 @@ static void processActivity(const char *user_key) time_t userPeriodLength; time_t timeBudgetCurrent; time_t timeBudgetConfigured; - char message[TQ_BUFFERSIZE]; - log_debug("processActivity(\"%s\")\n", user_key); + debugs(MY_DEBUG_SECTION, 3, "processActivity(\"" << user_key << "\")"); // [1] Reset period if over - periodStart = readTime(user_key, KEY_PERIOD_START); + periodStart = readTime(user_key, KeyPeriodStart); if ( periodStart == 0 ) { // This is the first period ever. periodStart = now; - writeTime(user_key, KEY_PERIOD_START, periodStart); + writeTime(user_key, KeyPeriodStart, periodStart); } periodLength = now - periodStart; - userPeriodLength = readTime(user_key, KEY_PERIOD_LENGTH_CONFIGURED); + userPeriodLength = readTime(user_key, KeyPeriodLengthConfigured); if ( userPeriodLength == 0 ) { // This user is not configured. Allow anything. - log_debug("No period length found for user \"%s\". Quota for this user disabled.\n", user_key); - writeTime(user_key, KEY_TIME_BUDGET_LEFT, pauseLength); + debugs(MY_DEBUG_SECTION, 3, "disabling user quota for user '" << + user_key << "': no period length found"); + writeTime(user_key, KeyTimeBudgetLeft, pauseLength); } else { if ( periodLength >= userPeriodLength ) { // a new period has started. - log_debug("New time period started for user \"%s\".\n", user_key); + debugs(MY_DEBUG_SECTION, 3, "New time period started for user \"" << user_key << '\"'); while ( periodStart < now ) { periodStart += periodLength; } - writeTime(user_key, KEY_PERIOD_START, periodStart); - timeBudgetConfigured = readTime(user_key, KEY_TIME_BUDGET_CONFIGURED); + writeTime(user_key, KeyPeriodStart, periodStart); + timeBudgetConfigured = readTime(user_key, KeyTimeBudgetConfigured); if ( timeBudgetConfigured == 0 ) { - log_debug("No time budget configured for user \"%s\". Quota for this user disabled.\n", user_key); - writeTime(user_key, KEY_TIME_BUDGET_LEFT, pauseLength); + debugs(MY_DEBUG_SECTION, 3, "No time budget configured for user \"" << user_key << + "\". Quota for this user disabled."); + writeTime(user_key, KeyTimeBudgetLeft, pauseLength); } else { - writeTime(user_key, KEY_TIME_BUDGET_LEFT, timeBudgetConfigured); + writeTime(user_key, KeyTimeBudgetLeft, timeBudgetConfigured); } } } // [2] Decrease time budget iff activity - lastActivity = readTime(user_key, KEY_LAST_ACTIVITY); + lastActivity = readTime(user_key, KeyLastActivity); if ( lastActivity == 0 ) { // This is the first request ever - writeTime(user_key, KEY_LAST_ACTIVITY, now); + writeTime(user_key, KeyLastActivity, now); } else { activityLength = now - lastActivity; if ( activityLength >= pauseLength ) { // This is an activity pause. - log_debug("Activity pause detected for user \"%s\".\n", user_key); - writeTime(user_key, KEY_LAST_ACTIVITY, now); + debugs(MY_DEBUG_SECTION, 3, "Activity pause detected for user \"" << user_key << "\"."); + writeTime(user_key, KeyLastActivity, now); } else { // This is real usage. - writeTime(user_key, KEY_LAST_ACTIVITY, now); + writeTime(user_key, KeyLastActivity, now); - log_debug("Time budget reduced by %ld for user \"%s\".\n", - activityLength, user_key); - timeBudgetCurrent = readTime(user_key, KEY_TIME_BUDGET_LEFT); + debugs(MY_DEBUG_SECTION, 3, "Time budget reduced by " << activityLength << + " for user \"" << user_key << "\"."); + timeBudgetCurrent = readTime(user_key, KeyTimeBudgetLeft); timeBudgetCurrent -= activityLength; - writeTime(user_key, KEY_TIME_BUDGET_LEFT, timeBudgetCurrent); + writeTime(user_key, KeyTimeBudgetLeft, timeBudgetCurrent); } } - timeBudgetCurrent = readTime(user_key, KEY_TIME_BUDGET_LEFT); - snprintf(message, TQ_BUFFERSIZE, "message=\"Remaining quota for '%s' is %d seconds.\"", user_key, (int)timeBudgetCurrent); + timeBudgetCurrent = readTime(user_key, KeyTimeBudgetLeft); + + const auto message = ToSBuf(HLP_MSG("Remaining quota for '"), user_key, "' is ", timeBudgetCurrent, " seconds."); if ( timeBudgetCurrent > 0 ) { - log_debug("OK %s.\n", message); SEND_OK(message); } else { - log_debug("ERR %s\n", message); SEND_ERR("Time budget exceeded."); } } static void usage(void) { - fprintf(stderr, "Usage: %s [-d] [-b dbpath] [-p pauselen] [-h] configfile\n", program_name); - fprintf(stderr, " -d enable debugging output\n"); - fprintf(stderr, " -b dbpath Path where persistent session database will be kept\n"); - fprintf(stderr, " If option is not used, then " DEFAULT_QUOTA_DB " will be used.\n"); - fprintf(stderr, " -p pauselen length in seconds to describe a pause between 2 requests.\n"); - fprintf(stderr, " -h show show command line help.\n"); - fprintf(stderr, "configfile is a file containing time quota definitions.\n"); + debugs(MY_DEBUG_SECTION, DBG_CRITICAL, "Wrong usage. Please reconfigure in squid.conf."); + + std::cerr << + "Usage: " << program_name << " [-d] [-b dbpath] [-p pauselen] [-h] configfile\n" + " -d enable debugging output\n" + " -l logfile log messages to logfile\n" + " -b dbpath Path where persistent session database will be kept\n" + " If option is not used, then " DEFAULT_QUOTA_DB " will be used.\n" + " -p pauselen length in seconds to describe a pause between 2 requests.\n" + " -h show show command line help.\n" + "configfile is a file containing time quota definitions.\n"; } int main(int argc, char **argv) @@ -403,11 +344,12 @@ int main(int argc, char **argv) int opt; program_name = argv[0]; + Debug::NameThisHelper("ext_time_quota_acl"); while ((opt = getopt(argc, argv, "dp:b:h")) != -1) { switch (opt) { case 'd': - tq_debug_enabled = true; + Debug::Levels[MY_DEBUG_SECTION] = DBG_DATA; break; case 'b': db_path = optarg; @@ -427,7 +369,7 @@ int main(int argc, char **argv) } } - log_info("Starting %s\n", __FILE__); + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "Starting " << program_name); setbuf(stdout, nullptr); init_db(); @@ -439,7 +381,7 @@ int main(int argc, char **argv) readConfig(argv[optind]); } - log_info("Waiting for requests...\n"); + debugs(MY_DEBUG_SECTION, 2, "Waiting for requests..."); while (fgets(request, HELPER_INPUT_BUFFER, stdin)) { // we expect the following line syntax: %LOGIN const char *user_key = strtok(request, " \n"); @@ -449,7 +391,7 @@ int main(int argc, char **argv) } processActivity(user_key); } - log_info("Ending %s\n", __FILE__); + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "Ending " << program_name); shutdown_db(); return EXIT_SUCCESS; }