From 48605ae156d3c8493222d237687bb405da3776da Mon Sep 17 00:00:00 2001 From: onefang Date: Wed, 18 Mar 2020 11:31:21 +1000 Subject: New logging levels - stuff only the developer needs to know during development. --- src/sledjchisl/sledjchisl.c | 156 +++++++++++++++++++++++--------------------- 1 file changed, 80 insertions(+), 76 deletions(-) (limited to 'src') diff --git a/src/sledjchisl/sledjchisl.c b/src/sledjchisl/sledjchisl.c index 8b9d567..393376e 100644 --- a/src/sledjchisl/sledjchisl.c +++ b/src/sledjchisl/sledjchisl.c @@ -476,6 +476,8 @@ char *logTypes[] = "36", "TIMEOUT", // cyan "97;40", "INFO", // white "90", "DEBUG", // grey + "35", "debug", // magenta + "34", "timeout", // blue }; #define DATE_TIME_LEN 42 @@ -513,6 +515,8 @@ void logMe(int v, char *format, ...) #define T(...) logMe(3, __VA_ARGS__) #define I(...) logMe(4, __VA_ARGS__) #define D(...) logMe(5, __VA_ARGS__) +#define d(...) logMe(6, __VA_ARGS__) +#define t(...) logMe(7, __VA_ARGS__) static void addStrL(qlist_t *list, char *s) @@ -643,7 +647,7 @@ float waitLoadAverage(float la, float extra, int timeout) l = info.loads[0]/65536.0; clock_gettime(CLOCK_MONOTONIC, &timeOut); timeout -= 5; - T("Tick, load average is %.02f, countdown %d seconds.", l, timeout); + t("Tick, load average is %.02f, countdown %d seconds.", l, timeout); } while (((la + extra) < l) && (timeOut.tv_sec < to)); return l; @@ -788,7 +792,7 @@ int checkSimIsRunning(char *sim) { free(path); path = xmprintf("rm -f %s/caches/%s.pid", scRoot, sim); - D("%s", path); + d("%s", path); i = system(path); } } @@ -818,7 +822,7 @@ static void PrintEnv(qgrow_t *reply, char *label, char **envp) static void printEnv(char **envp) { for ( ; *envp != NULL; envp++) - D("%s", *envp); + d("%s", *envp); } @@ -836,7 +840,7 @@ static void dumpHash(qhashtbl_t *tbl) memset((void*)&obj, 0, sizeof(obj)); tbl->lock(tbl); while(tbl->getnext(tbl, &obj, true) == true) - D("%s = %s", obj.name, (char *) obj.data); + d("%s = %s", obj.name, (char *) obj.data); tbl->unlock(tbl); } @@ -846,7 +850,7 @@ static void dumpArray(int d, char **ar) while (ar[i] != NULL) { - D("%d %d %s", d, i, ar[i]); + d("%d %d %s", d, i, ar[i]); i++; } } @@ -902,7 +906,7 @@ qlisttbl_t *dbGetFields(MYSQL *db, char *table) // Chicken, meet egg, sorry you had to cross the road for this. char *sql = xmprintf("SELECT * FROM %s LIMIT 0", table); -D("Getting field metadata for %s", table); +d("Getting field metadata for %s", table); if (mysql_query(db, sql)) E("Query failed: %s\n%s", mysql_error(db), sql); else @@ -1026,7 +1030,7 @@ void dbDoSomething(dbRequest *req, boolean count, ...) req->sql = t; } -D("New SQL statement - %s", req->sql); +d("New SQL statement - %s", req->sql); // prepare statement with the other fields req->prep = mysql_stmt_init(req->db); if (NULL == req->prep) @@ -1214,53 +1218,53 @@ I("count!!!!!!!!!!!!!!!!"); { case MYSQL_TYPE_TINY: { -//D("TINY %d %s %d", i, fld->name, req->outBind[i].buffer_length); +//d("TINY %d %s %d", i, fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_SHORT: { -//D("SHORT %s %d", fld->name, req->outBind[i].buffer_length); +//d("SHORT %s %d", fld->name, req->outBind[i].buffer_length); req->outBind[i].is_unsigned = FALSE; break; } case MYSQL_TYPE_INT24: { -//D("INT24 %s %d", fld->name, req->outBind[i].buffer_length); +//d("INT24 %s %d", fld->name, req->outBind[i].buffer_length); req->outBind[i].is_unsigned = FALSE; break; } case MYSQL_TYPE_LONG: { -//D("LONG %d %s %d", i, fld->name, req->outBind[i].buffer_length); +//d("LONG %d %s %d", i, fld->name, req->outBind[i].buffer_length); req->outBind[i].is_unsigned = FALSE; break; } case MYSQL_TYPE_LONGLONG: { -//D("LONG LONG %s %d", fld->name, req->outBind[i].buffer_length); +//d("LONG LONG %s %d", fld->name, req->outBind[i].buffer_length); req->outBind[i].is_unsigned = FALSE; break; } case MYSQL_TYPE_FLOAT: { -//D("FLOAT %s %d", fld->name, req->outBind[i].buffer_length); +//d("FLOAT %s %d", fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_DOUBLE: { -//D("DOUBLE %s %d", fld->name, req->outBind[i].buffer_length); +//d("DOUBLE %s %d", fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_NEWDECIMAL: { -//D("NEWDECIMAL %s %d", fld->name, req->outBind[i].buffer_length); +//d("NEWDECIMAL %s %d", fld->name, req->outBind[i].buffer_length); break; } @@ -1269,14 +1273,14 @@ I("count!!!!!!!!!!!!!!!!"); case MYSQL_TYPE_DATETIME: case MYSQL_TYPE_TIMESTAMP: { -//D("DATETIME %s %d", fld->name, req->outBind[i].buffer_length); +//d("DATETIME %s %d", fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_STRING: case MYSQL_TYPE_VAR_STRING: { -//D("STRING %s %d", fld->name, req->outBind[i].buffer_length); +//d("STRING %s %d", fld->name, req->outBind[i].buffer_length); req->outBind[i].length = xzalloc(sizeof(unsigned long)); break; } @@ -1286,19 +1290,19 @@ I("count!!!!!!!!!!!!!!!!"); case MYSQL_TYPE_MEDIUM_BLOB: case MYSQL_TYPE_LONG_BLOB: { -//D("BLOB %s %d", fld->name, req->outBind[i].buffer_length); +//d("BLOB %s %d", fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_BIT: { -//D("BIT %s %d", fld->name, req->outBind[i].buffer_length); +//d("BIT %s %d", fld->name, req->outBind[i].buffer_length); break; } case MYSQL_TYPE_NULL: { -//D("NULL %s %d", fld->name, req->outBind[i].buffer_length); +//d("NULL %s %d", fld->name, req->outBind[i].buffer_length); break; } } @@ -1313,7 +1317,7 @@ I("count!!!!!!!!!!!!!!!!"); } -//D("input bind for %s", req->sql); +//d("input bind for %s", req->sql); for (i = 0; i < req->inCount; i++) { dbField *fld = req->flds->get(req->flds, req->inParams[i], NULL, false); @@ -1443,7 +1447,7 @@ I("count!!!!!!!!!!!!!!!!"); } -D("Execute %s", req->sql); +d("Execute %s", req->sql); // do the prepared statement req->prep. if (mysql_stmt_execute(req->prep)) @@ -1481,7 +1485,7 @@ D("Execute %s", req->sql); req->rows->fieldNames[i] = fld->name; if (!*(req->outBind[i].is_null)) { -//D("2.8 %s", req->rows->fieldNames[i]); +//d("2.8 %s", req->rows->fieldNames[i]); flds->put(flds, req->rows->fieldNames[i], req->outBind[i].buffer, req->outBind[i].buffer_length); switch(fld->type) @@ -1513,7 +1517,7 @@ D("Execute %s", req->sql); goto freeIt; } char *t = xmprintf("%d", (int) *((int *) (req->outBind[i].buffer))); -//D("Setting %i %s %s", i, fld->name, t); +//d("Setting %i %s %s", i, fld->name, t); flds->putstr(flds, req->rows->fieldNames[i], t); break; } @@ -1952,14 +1956,14 @@ qhashtbl_t *toknize(char *text, char *delims) else if (delims[1] == dlm) { ret->putstr(ret, qstrtrim_head(key), token); -D(" %s = %s", qstrtrim_head(key), val); +d(" %s = %s", qstrtrim_head(key), val); val = NULL; } } if (NULL != val) { ret->putstr(ret, qstrtrim_head(key), val); -D(" %s = %s", qstrtrim_head(key), val); +d(" %s = %s", qstrtrim_head(key), val); } free(txt); return ret; @@ -2951,14 +2955,14 @@ W("New sesh"); else { qstrcpy(ret->salt, sizeof(ret->salt), qhex_encode(buf, sizeof(buf))); -//D("salt %s", ret->salt); +//d("salt %s", ret->salt); numBytes = getrandom((void *)buf, sizeof(buf), GRND_NONBLOCK); if (-1 == numBytes) perror_msg("Unable to generate a suitable random number."); else { qstrcpy(ret->seshID, sizeof(ret->seshID), qhex_encode(buf, sizeof(buf))); -//D("seshID %s", ret->seshID); +//d("seshID %s", ret->seshID); ret->timeStamp[0].tv_nsec = UTIME_OMIT; ret->timeStamp[0].tv_sec = UTIME_OMIT; @@ -2969,24 +2973,24 @@ W("New sesh"); // tv_sec is a time_t, tv_nsec is a long, but the actual type of time_t isn't well defined, it's some sort of integer. t0 = xmprintf("%s%ld.%ld", ret->seshID, (long) ret->timeStamp[1].tv_sec, ret->timeStamp[1].tv_nsec); qstrcpy(ret->sesh, sizeof(ret->sesh), t0); -//D("sesh %s", ret->sesh); +//d("sesh %s", ret->sesh); t1 = myHMAC(t0, FALSE); free(t0); munchie = xmprintf("%s%ld.%ld", t1, (long) ret->timeStamp[1].tv_sec, ret->timeStamp[1].tv_nsec); free(t1); qstrcpy(ret->munchie, sizeof(ret->munchie), munchie); -//D("munchie %s", ret->munchie); +//d("munchie %s", ret->munchie); t0 = xmprintf("%s%s", getStrH(Rd->stuff, "UUID"), munchie); toke_n_munchie = myHMAC(t0, FALSE); free(t0); qstrcpy(ret->toke_n_munchie, sizeof(ret->toke_n_munchie), toke_n_munchie); -//D("toke_n_munchie %s", ret->toke_n_munchie); +//d("toke_n_munchie %s", ret->toke_n_munchie); hashish = myHMACkey(ret->salt, toke_n_munchie, FALSE); qstrcpy(ret->hashish, sizeof(ret->hashish), hashish); -//D("hashish %s", ret->hashish); +//d("hashish %s", ret->hashish); t0 = myHMACkey(getStrH(Rd->configs, "pepper"), hashish, TRUE); qstrcpy(ret->leaf, sizeof(ret->leaf), t0); -//D("leaf %s", ret->leaf); +//d("leaf %s", ret->leaf); free(t0); ret->isLinky = linky; setToken_n_munchie(Rd, linky); @@ -3105,7 +3109,7 @@ int LuaToHash(reqData *Rd, char *file, char *var, qhashtbl_t *tnm, int ret, stru if (lua_isstring(Rd->L, -1)) { tnm->putstr(tnm, n, (char *) lua_tostring(Rd->L, -1)); -//D("Reading %s %s", n, getStrH(tnm, n)); +//d("Reading %s %s", n, getStrH(tnm, n)); } else { @@ -3146,7 +3150,7 @@ static int validateSesh(reqData *Rd, qhashtbl_t *data) // In this case the session stuff has to come from specific places. hashish = getStrH(Rd->queries, "hashish"); -//D("O hashish %s", hashish); +//d("O hashish %s", hashish); if ('\0' != hashish[0]) linky = TRUE; else @@ -3161,16 +3165,16 @@ static int validateSesh(reqData *Rd, qhashtbl_t *data) } } -//D("O hashish %s", hashish); -//D("O toke_n_munchie %s", toke_n_munchie); -//D("O munchie %s", munchie); +//d("O hashish %s", hashish); +//d("O toke_n_munchie %s", toke_n_munchie); +//d("O munchie %s", munchie); if (0 == ret) { struct stat st; struct timespec now; leaf = myHMACkey(getStrH(Rd->configs, "pepper"), hashish, TRUE); -//D("leaf %s", leaf); +//d("leaf %s", leaf); if (linky) t0 = xmprintf("%s/sessions/%s.linky", scCache, leaf); else @@ -3197,12 +3201,12 @@ static int validateSesh(reqData *Rd, qhashtbl_t *data) else { timeStamp = xmprintf("%ld.%ld", (long) st.st_mtim.tv_sec, st.st_mtim.tv_nsec); -//D("timeStamp %s", timeStamp); +//d("timeStamp %s", timeStamp); seshion = xmprintf("%s%s", tnm->getstr(tnm, "seshID", false), timeStamp); -//D("sesh %s", seshion); +//d("sesh %s", seshion); t0 = myHMAC(seshion, FALSE); munchie = xmprintf("%s%s", t0, timeStamp); -//D("munchie %s", munchie); +//d("munchie %s", munchie); free(t0); t1 = getStrH(Rd->body, "munchie"); if ('\0' != t1[0]) @@ -3218,7 +3222,7 @@ static int validateSesh(reqData *Rd, qhashtbl_t *data) t1 = myHMAC(t0, FALSE); free(t0); -//D("toke_n_munchie %s", t1); +//d("toke_n_munchie %s", t1); if (strcmp(t1, toke_n_munchie) != 0) { bitchSession(Rd, "Wrong toke_n_munchie for session.", "HMAC(UUID + munchie) != toke_n_munchie"); @@ -3236,10 +3240,10 @@ static int validateSesh(reqData *Rd, qhashtbl_t *data) t1 = myHMAC(t0, FALSE); free(t0); toke_n_munchie = t1; -//D("toke_n_munchie %s", t1); +//d("toke_n_munchie %s", t1); } t1 = myHMACkey(getStrH(tnm, "salt"), toke_n_munchie, FALSE); -//D("hashish %s", t1); +//d("hashish %s", t1); if (strcmp(t1, hashish) != 0) { bitchSession(Rd, "Wrong hashish for session.", "HMAC(toke_n_munchie + salt) != hashish"); @@ -3856,7 +3860,7 @@ static int validateUUID(reqData *Rd, qhashtbl_t *data) uuid_generate_random(binuuid); uuid_unparse_lower(binuuid, uuid); - D("Trying new UUID %s.", uuid); + d("Trying new UUID %s.", uuid); // TODO - check the Lua user files as well. dbDoSomething(uuids, FALSE, uuid); rows = uuids->rows; @@ -4270,12 +4274,12 @@ void account_html(char *file, reqData *Rd, HTMLfile *thisFile) if (Rd->vegOut) { - T("vegOut"); + t("vegOut"); freeSesh(Rd, FALSE, TRUE); } else if (Rd->chillOut) { - T("chillOut"); + t("chillOut"); freeSesh(Rd, FALSE, FALSE); newSesh(Rd, FALSE); } @@ -4334,14 +4338,14 @@ void sledjchisl_main(void) } else { - if (S_ISREG (statbuf.st_mode)) D("STDIN is a regular file."); - else if (S_ISDIR (statbuf.st_mode)) D("STDIN is a directory."); - else if (S_ISCHR (statbuf.st_mode)) D("STDIN is a character device."); - else if (S_ISBLK (statbuf.st_mode)) D("STDIN is a block device."); - else if (S_ISFIFO(statbuf.st_mode)) D("STDIN is a FIFO (named pipe)."); - else if (S_ISLNK (statbuf.st_mode)) D("STDIN is a symbolic link."); - else if (S_ISSOCK(statbuf.st_mode)) D("STDIN is a socket."); - else D("STDIN is a unknown file descriptor type."); + if (S_ISREG (statbuf.st_mode)) d("STDIN is a regular file."); + else if (S_ISDIR (statbuf.st_mode)) d("STDIN is a directory."); + else if (S_ISCHR (statbuf.st_mode)) d("STDIN is a character device."); + else if (S_ISBLK (statbuf.st_mode)) d("STDIN is a block device."); + else if (S_ISFIFO(statbuf.st_mode)) d("STDIN is a FIFO (named pipe)."); + else if (S_ISLNK (statbuf.st_mode)) d("STDIN is a symbolic link."); + else if (S_ISSOCK(statbuf.st_mode)) d("STDIN is a socket."); + else d("STDIN is a unknown file descriptor type."); if (!S_ISCHR(statbuf.st_mode)) isWeb = TRUE; } @@ -4438,19 +4442,19 @@ jit library is loaded or the JIT compiler will not be activated. } } } - if ((vd = configs->get (configs, "loadAverageInc", NULL, false)) != NULL) {loadAverageInc = *((float *) vd); D("Setting loadAverageInc = %f", loadAverageInc);} - if ((vd = configs->get (configs, "simTimeOut", NULL, false)) != NULL) {simTimeOut = (int) *((float *) vd); D("Setting simTimeOut = %d", simTimeOut);} - if ((tmp = configs->getstr(configs, "scRoot", false)) != NULL) {scRoot = tmp; D("Setting scRoot = %s", scRoot);} - if ((tmp = configs->getstr(configs, "scUser", false)) != NULL) {scUser = tmp; D("Setting scUser = %s", scUser);} - if ((tmp = configs->getstr(configs, "Tconsole", false)) != NULL) {Tconsole = tmp; D("Setting Tconsole = %s", Tconsole);} - if ((tmp = configs->getstr(configs, "Tsocket", false)) != NULL) {Tsocket = tmp; D("Setting Tsocket = %s", Tsocket);} - if ((tmp = configs->getstr(configs, "Ttab", false)) != NULL) {Ttab = tmp; D("Setting Ttab = %s", Ttab);} - if ((tmp = configs->getstr(configs, "webRoot", false)) != NULL) {webRoot = tmp; D("Setting webRoot = %s", webRoot);} - if ((tmp = configs->getstr(configs, "URL", false)) != NULL) {URL = tmp; D("Setting URL = %s", URL);} - if ((vd = configs->get (configs, "seshTimeOut", NULL, false)) != NULL) {seshTimeOut = (int) *((float *) vd); D("Setting seshTimeOut = %d", seshTimeOut);} - if ((vd = configs->get (configs, "idleTimeOut", NULL, false)) != NULL) {idleTimeOut = (int) *((float *) vd); D("Setting idleTimeOut = %d", idleTimeOut);} - if ((vd = configs->get (configs, "newbieTimeOut", NULL, false)) != NULL) {newbieTimeOut = (int) *((float *) vd); D("Setting newbieTimeOut = %d", newbieTimeOut);} - if ((tmp = configs->getstr(configs, "ToS", false)) != NULL) {ToS = tmp; D("Setting ToS = %s", ToS);} + if ((vd = configs->get (configs, "loadAverageInc", NULL, false)) != NULL) {loadAverageInc = *((float *) vd); d("Setting loadAverageInc = %f", loadAverageInc);} + if ((vd = configs->get (configs, "simTimeOut", NULL, false)) != NULL) {simTimeOut = (int) *((float *) vd); d("Setting simTimeOut = %d", simTimeOut);} + if ((tmp = configs->getstr(configs, "scRoot", false)) != NULL) {scRoot = tmp; d("Setting scRoot = %s", scRoot);} + if ((tmp = configs->getstr(configs, "scUser", false)) != NULL) {scUser = tmp; d("Setting scUser = %s", scUser);} + if ((tmp = configs->getstr(configs, "Tconsole", false)) != NULL) {Tconsole = tmp; d("Setting Tconsole = %s", Tconsole);} + if ((tmp = configs->getstr(configs, "Tsocket", false)) != NULL) {Tsocket = tmp; d("Setting Tsocket = %s", Tsocket);} + if ((tmp = configs->getstr(configs, "Ttab", false)) != NULL) {Ttab = tmp; d("Setting Ttab = %s", Ttab);} + if ((tmp = configs->getstr(configs, "webRoot", false)) != NULL) {webRoot = tmp; d("Setting webRoot = %s", webRoot);} + if ((tmp = configs->getstr(configs, "URL", false)) != NULL) {URL = tmp; d("Setting URL = %s", URL);} + if ((vd = configs->get (configs, "seshTimeOut", NULL, false)) != NULL) {seshTimeOut = (int) *((float *) vd); d("Setting seshTimeOut = %d", seshTimeOut);} + if ((vd = configs->get (configs, "idleTimeOut", NULL, false)) != NULL) {idleTimeOut = (int) *((float *) vd); d("Setting idleTimeOut = %d", idleTimeOut);} + if ((vd = configs->get (configs, "newbieTimeOut", NULL, false)) != NULL) {newbieTimeOut = (int) *((float *) vd); d("Setting newbieTimeOut = %d", newbieTimeOut);} + if ((tmp = configs->getstr(configs, "ToS", false)) != NULL) {ToS = tmp; d("Setting ToS = %s", ToS);} // Use a FHS compatible setup - @@ -4667,11 +4671,11 @@ jit library is loaded or the JIT compiler will not be activated. I("Running SledjChisl inside a web server, pid %d.", getpid()); if (0 == toys.optc) - D("no args"); + d("no args"); else { for (entries = 0, bytes = -1; entries < toys.optc; entries++) - D("ARG %s\n", toys.optargs[entries]); + d("ARG %s\n", toys.optargs[entries]); } printEnv(environ); @@ -4710,7 +4714,7 @@ jit library is loaded or the JIT compiler will not be activated. // So far I'm seeing these as all caps, but I don't think they are defined that way. Case insensitive per the spec. // So convert them now, also "-" -> "_". -T("HEADERS"); +t("HEADERS"); char **envp = environ; for ( ; *envp != NULL; envp++) { @@ -4722,7 +4726,7 @@ T("HEADERS"); char *ky = qstrreplace("tr", qstrupper(k), "-", "_"); Rd->headers->putstr(Rd->headers, ky, v + 1); if ((strcmp("HTTP_COOKIE", ky) == 0) || (strcmp("CONTENT_LENGTH", ky) == 0) || (strcmp("QUERY_STRING", ky) == 0)) - D(" %s = %s", ky, v + 1); + d(" %s = %s", ky, v + 1); } } @@ -4761,10 +4765,10 @@ if ((strcmp("HTTP_COOKIE", ky) == 0) || (strcmp("CONTENT_LENGTH", ky) == 0) || ( */ -T("COOKIES"); +t("COOKIES"); Rd->cookies = toknize(Rd->headers->getstr(Rd->headers, "HTTP_COOKIE", false), "=;"); santize(Rd->cookies, TRUE); -T("QUERY"); +t("QUERY"); Rd->queries = toknize(Rd->headers->getstr(Rd->headers, "QUERY_STRING", false), "=&"); santize(Rd->queries, TRUE); char *Body = NULL; @@ -4779,7 +4783,7 @@ T("QUERY"); } Body[len] = '\0'; } -T("BODY"); +t("BODY"); Rd->body = toknize(Body, "=&"); santize(Rd->body, TRUE); -- cgit v1.1