chore(logging): add logging quality audit

docs/logging-quality-audit.md

@@ -0,0 +1,77 @@
+# Logging Quality Audit
+
+## Scope
+
+This audit covers backend/API logging quality only:
+
+- `thinx-core.js`
+- `thinx.js`
+- `lib/**/*.js`
+- selected service entrypoints:
+  - `services/worker/worker.js`
+  - `services/transformer/index.js`
+  - `services/transformer/app.js`
+  - `services/transformer/transformer.js`
+
+The audit intentionally does not mass-convert every remaining `console.*` call,
+and does not scan bundled console frontend vendor assets.
+
+## Current Audit Counts
+
+Latest command:
+
+```sh
+npm run --silent logging-audit -- --json
+```
+
+Current report summary:
+
+- Files scanned: 80
+- `console.*` calls: 897
+- `logger.*` calls: 20
+- Tracked event occurrences: 26
+- Sensitive findings: 21
+- High-risk sensitive findings: 0
+- Severity-string mismatches: 607
+- Tracked event quality gaps: 0
+
+## Fixed High-Risk Findings
+
+- Raw websocket cookie headers in `thinx-core.js` are redacted with
+  `Util.redactCookieHeader()`, preserving cookie names only.
+- OAuth handoff/access token logs in `lib/router.github.js`,
+  `lib/router.google.js`, `lib/router.gdpr.js`, and `lib/router.auth.js` now
+  redact tokens or avoid logging them.
+- Full OAuth `userWrapper` and GitHub `hdata` payload logging was removed.
+- Invalid local-login failures no longer log the submitted username.
+- `LOGIN_INVALID`, `BUILD_FAILED`, `BUILD_STARTED`, `BUILD_SUCCESS`,
+  `DEVICE_CHECKIN`, and `DEVICE_NEW` now have warn-level logger coverage while
+  preserving existing `InfluxConnector.statsLog` calls.
+
+## Build Event Decision
+
+`BUILD_COMPLETED` remains an operational line. It is not part of
+`statistics.js` `owner_template`, which tracks `BUILD_SUCCESS`. Successful local
+build exits now emit `BUILD_SUCCESS` via the logger/metrics helper so local
+build success can be counted consistently with the existing statistics model.
+
+## Remaining Backlog
+
+The remaining findings are lower-risk and intentionally left for follow-up:
+
+- Convert broad backend `console.*` usage to the shared logger.
+- Resolve severity-string mismatches where messages tagged `[error]`,
+  `[warning]`, `[info]`, or `[debug]` still go through `console.log`.
+- Review medium-risk payload logs, especially API-key and device response
+  payload logging, and replace them with redacted structured context.
+- Consider standardizing non-template event markers such as `NEW_SESSION`,
+  `DEVICE_ATTACH`, `MESH_ATTACH`, and transfer events.
+
+## Verification
+
+Focused verification commands:
+
+```sh
+npm run --silent logging-audit -- --json
+npx jasmine spec/jasmine/LoggingQualityAuditSpec.js spec/jasmine/UtilSpec.js spec/jasmine/LoggerSpec.js spec/jasmine/MetricsCoverageSpec.js
+```

lib/router.auth.js

@@ -3,6 +3,7 @@
 const Globals = require("./thinx/globals");
 
 const Util = require("./thinx/util");
+const logger = require("./thinx/logger");
 
 const Sanitka = require("./thinx/sanitka"); let sanitka = new Sanitka();
 const AuditLog = require("./thinx/audit"); let alog = new AuditLog();
@@ -36,6 +37,7 @@ module.exports = function (app) {
 
     function auditLogError(owner, data) {
         if (!Util.isDefined(owner)) owner = "0";
+        logger.warn(`[OID:${owner}] [LOGIN_INVALID] ${data}`);
         InfluxConnector.statsLog(owner, "LOGIN_INVALID", data);
     }
 
@@ -45,8 +47,8 @@ module.exports = function (app) {
         redis.get(oauth, (error, userWrapper) => {
 
                 if ((typeof(userWrapper) === "undefined") || (userWrapper === null)) {
-                    console.log("Login failed, wrapper not found for token", oauth);
-                    auditLogError(oauth, "wrapper_error_1");
+                    console.log("Login failed, wrapper not found for token", Util.redactToken(oauth));
+                    auditLogError(null, "wrapper_error_1");
                     return Util.failureResponse(res, 403, "wrapper error");
                 }
 
@@ -213,12 +215,10 @@ module.exports = function (app) {
         if (password.indexOf(user_data.password) === -1) {
             let p = user_data.password;
             if (typeof (p) === "undefined" || p === null) {
-                console.log(`[OID:${user_data.owner}] [LOGIN_INVALID] not activated/no password.`);
                 auditLogError(user_data.owner, "not_activated");
                 alog.log(req.session.owner, "Password missing");
                 Util.responder(stored_response, false, "password_missing");
             } else {
-                console.log(`[OID:${user_data.owner}] [LOGIN_INVALID] Password mismatch.`);
                 auditLogError(user_data.owner, "password_mismatch");
                 alog.log(req.session.owner, "Password mismatch.");
                 stored_response.status(401);
@@ -290,7 +290,7 @@ module.exports = function (app) {
 
         let username = sanitka.username(req.body.username);
         let password = sha256(prefix + req.body.password);
-        console.log(`🔨 [debug] [auth] Username/password login attempt for: ${username}`);
+        console.log("🔨 [debug] [auth] Username/password login attempt");
 
         // Search the user in DB, should search by key and return one only
         user.validate(username, (db_body) => {
@@ -300,12 +300,12 @@ module.exports = function (app) {
             // `db_body.rows` throws a TypeError -> unhandled -> HTTP 500 with
             // an HTML error page, which the JSON-expecting console cannot parse.
             if (db_body === false) {
-                console.log(`[OID:0] [LOGIN_ERROR] user directory unavailable for ${username}`);
+                console.log("[OID:0] [LOGIN_ERROR] user directory unavailable");
                 return Util.failureResponse(res, 503, "service_unavailable");
             }
 
             if ((typeof (db_body.rows) === "undefined") || (db_body.rows.length == 0)) {
-                console.log(`[OID:0] [LOGIN_INVALID] with username ${username}`);
+                auditLogError(null, "unknown_username");
                 return Util.failureResponse(res, 403, "invalid_credentials");
             }
 
@@ -371,4 +371,4 @@ module.exports = function (app) {
         logoutAction(req, res);
     });
 
-};
+};

lib/router.gdpr.js

@@ -100,7 +100,7 @@ module.exports = function (app) {
 
             var wrapper = JSON.parse(userWrapper);
             if (typeof (wrapper) === "undefined" || wrapper === null) {
-                console.log("Not found wrapper", userWrapper, "for token", token);
+                console.log("Not found GDPR wrapper for token", Util.redactToken(token));
                 return Util.responder(res, false, "handover_failed");
             }
 
@@ -166,4 +166,4 @@ module.exports = function (app) {
         revokeGDPR(req, res);
     });
 
-};
+};

lib/router.github.js

@@ -100,7 +100,7 @@ module.exports = function (app) {
                     // shows the GDPR consent gate before logging in.
                     const courl = oauthReturn.returnURLFor(response.thx_return_origin, token, false);
 
-                    console.log("Redirecting to login (2)", courl);
+                    console.log("Redirecting to login (2) with token", Util.redactToken(token));
                     response.redirect(courl); // for successful login, this must be a response to /oauth/<idp>/callback
                 });
                 return;
@@ -109,7 +109,10 @@ module.exports = function (app) {
             console.log(`ℹ️ [info] Calling trackUserLogin on GtHub Auth Callback...`);
             user.trackUserLogin(owner_id);
 
-            console.log("validateGithubUser", { token }, { userWrapper });
+            console.log("validateGithubUser", {
+                token: Util.redactToken(token),
+                owner: userWrapper.owner
+            });
             app.redis_client.set(token, JSON.stringify(userWrapper));
             app.redis_client.expire(token, 3600);
 
@@ -139,14 +142,14 @@ module.exports = function (app) {
         } else {
             family_name = hdata.login;
             given_name = hdata.login;
-            console.log("🔨 [debug] [github] [token] Warning: no name in GitHub access token response, using login: ", { hdata }); // logs personal data in case the user has no name!
+            console.log("🔨 [debug] [github] [token] Warning: no name in GitHub access token response, using login fallback.");
         }
         email = hdata.email || hdata.login;
 
         try {
             owner_id = sha256(prefix + email);
         } catch (e) {
-            console.log("☣️ [error] [github] [token] error parsing e-mail: " + e + " email: " + email);
+            console.log("☣️ [error] [github] [token] error parsing e-mail: " + e + " email: " + Util.redactEmail(email));
             return res.redirect(app_config.public_url + '/error.html?success=failed&title=Sorry&reason=Missing%20e-mail.');
         }
         validateGithubUser(original_response, token, {

lib/router.google.js

@@ -13,6 +13,7 @@ var alog = new AuditLog();
 const https = require('https');
 const sha256 = require("sha256");
 const oauthReturn = require("./thinx/oauth_return");
+const Util = require("./thinx/util");
 
 const app_config = Globals.app_config(); // public_url and public_url but it is the same now
 
@@ -71,8 +72,7 @@ module.exports = function (app) {
       // New account: consent not yet given -> g=false so the console shows the
       // GDPR consent gate before logging in.
       const ourl = oauthReturn.returnURLFor(oauthReturn.takeReturnOrigin(req, ores), token, false);
-      console.log("OURL", ourl);
-      console.log("Redirecting to:", ourl);
+      console.log("Redirecting Google OAuth user with token", Util.redactToken(token));
       ores.redirect(ourl);
     });
   }

lib/thinx/builder.js

@@ -38,6 +38,14 @@ const Sources = require("./sources");
 
 const InfluxConnector = require('./influx');
 const Util = require("./util.js");
+const logger = require("./logger.js");
+
+function recordStatsEvent(owner, event, data) {
+	const safeOwner = Util.isDefined(owner) ? owner : "0";
+	const detail = Util.isDefined(data) ? " " + data : "";
+	logger.warn(`[OID:${safeOwner}] [${event}]${detail}`);
+	InfluxConnector.statsLog(safeOwner, event, data);
+}
 
 module.exports = class Builder {
 
@@ -237,8 +245,8 @@ module.exports = class Builder {
 		};
 
 		if (typeof (worker.socket) === "undefined") {
-			console.log(`[OID:${owner}] [BUILD_FAILED] REMOTE execution failed; no socket.`);
-			return InfluxConnector.statsLog(owner, "BUILD_FAILED", build_id);
+			recordStatsEvent(owner, "BUILD_FAILED", build_id);
+			return;
 		}
 
 		worker.socket.on('log', (data) => {
@@ -253,8 +261,7 @@ module.exports = class Builder {
 				this.cleanupDeviceRepositories(owner, udid, build_id);
 			}
 		});
-		console.log(`[OID:${owner}] [BUILD_STARTED]`);
-		InfluxConnector.statsLog(owner, "BUILD_STARTED", build_id);
+		recordStatsEvent(owner, "BUILD_STARTED", build_id);
 	}
 
 	getDirectories(source) {
@@ -347,9 +354,11 @@ module.exports = class Builder {
 			notifiers: notifiers
 		};
 		console.log("[builder] Executing LOCAL build:", shellEscape([command, ...args]));
+		recordStatsEvent(owner, "BUILD_STARTED", build_id);
 		let shell = exec.spawn(command, args, { cwd: ROOT, shell: false });
 		shell.on("error", (error) => {
 			console.log("[builder] local build spawn failed:", error);
+			recordStatsEvent(owner, "BUILD_FAILED", build_id);
 			this.processExitData(owner, build_id, udid, notifiers, error.message);
 			this.cleanupSecrets(XBUILD_PATH);
 		});
@@ -360,9 +369,12 @@ module.exports = class Builder {
 			this.processShellError(owner, build_id, udid, data);
 		});
 		shell.on("exit", (code) => {
-			console.log(`[OID:${owner}] [BUILD_COMPLETED] LOCAL [builder] with code ${code}`);
+			console.log(`[OID:${owner}] Build completed LOCAL [builder] with code ${code}`);
 			// success error code is processed using job-status parser
-			if (code !== 0) {
+			if (code === 0) {
+				recordStatsEvent(owner, "BUILD_SUCCESS", build_id);
+			} else {
+				recordStatsEvent(owner, "BUILD_FAILED", build_id);
 				this.processExitData(owner, build_id, udid, notifiers, code);
 			}
 			this.cleanupSecrets(XBUILD_PATH);
@@ -580,7 +592,7 @@ module.exports = class Builder {
 
 		let start_timestamp = new Date().getTime();
 
-		console.log("[builder] [BUILD_STARTED] at", start_timestamp);
+		console.log("[builder] Build preparation started at", start_timestamp);
 
 		let build_id = br.build_id;
 		let owner = br.owner;
@@ -590,14 +602,14 @@ module.exports = class Builder {
 		let source_id = br.source_id;
 
 		if ((typeof (br.worker) === "undefined") || (typeof (br.worker.socket) === "undefined")) {
-			InfluxConnector.statsLog(br.owner, "BUILD_FAILED", br.build_id);
+			recordStatsEvent(br.owner, "BUILD_FAILED", br.build_id);
 			if (process.env.ENVIRONMENT !== "test") {
 				return callback(false, "workers_not_ready");
 			}
 		}
 
 		if (!this.buildGuards(callback, owner, git, branch)) {
-			InfluxConnector.statsLog(owner, "BUILD_FAILED", build_id);
+			recordStatsEvent(owner, "BUILD_FAILED", build_id);
 		}
 
 		blog.log(build_id, owner, udid, "started"); // may take time to save, initial record to be edited using blog.state

lib/thinx/device.js

@@ -36,6 +36,15 @@ const ACL = require('./acl');
 
 const InfluxConnector = require('./influx');
 const Util = require("./util.js");
+const logger = require("./logger.js");
+
+function recordStatsEvent(owner, event, data) {
+	const safeOwner = Util.isDefined(owner) ? owner : "0";
+	const detail = Util.isDefined(data) ? " " + data : "";
+	logger.warn(`[OID:${safeOwner}] [${event}]${detail}`);
+	InfluxConnector.statsLog(safeOwner, event, data);
+}
+
 module.exports = class Device {
 
 	constructor(redis) {
@@ -410,8 +419,7 @@ module.exports = class Device {
 				console.log("WARNING! Failed to fetch device owner profile in device checkin! Transformers will not work.");
 			}
 
-			console.log("[OID:" + reg.owner + "] [DEVICE_CHECKIN] Checkin Existing device: " + JSON.stringify(reg.udid, null, 4));
-			InfluxConnector.statsLog(reg.owner, "DEVICE_CHECKIN", reg.udid);
+			recordStatsEvent(reg.owner, "DEVICE_CHECKIN", sanitka.udid(reg.udid));
 			// Override/update last checkin timestamp
 			device.lastupdate = new Date();
 
@@ -987,9 +995,7 @@ module.exports = class Device {
 							// New device
 							//
 
-							console.log(`[OID:${registration_owner}] [DEVICE_NEW]`);
-
-							InfluxConnector.statsLog(registration_owner, "DEVICE_NEW", reg.udid);
+							recordStatsEvent(registration_owner, "DEVICE_NEW", udid);
 
 							// COPY B
 							// in case there is no status, this is an downlink request and should provide

lib/thinx/util.js

@@ -136,4 +136,40 @@ module.exports = class Util {
     return s.substring(0, n) + "…";
   }
 
-};
+  static redactHeaderValue(value, prefix) {
+    if (typeof value === "undefined") return "<undefined>";
+    if (value === null) return "<null>";
+
+    let s = String(value).trim();
+    if (s === "") return "<empty>";
+
+    let bearer = s.match(/^Bearer\s+(.+)$/i);
+    if (bearer) return "Bearer " + Util.redactToken(bearer[1], prefix);
+
+    return Util.redactToken(s, prefix);
+  }
+
+  static redactCookieHeader(header) {
+    if (typeof header === "undefined") return "<undefined>";
+    if (header === null) return "<null>";
+
+    let s = String(header).trim();
+    if (s === "") return "<empty>";
+
+    return s.split(";").map((cookie) => {
+      let trimmed = cookie.trim();
+      if (trimmed === "") return "<empty>";
+
+      let eq = trimmed.indexOf("=");
+      if (eq === -1) {
+        return trimmed.replace(/[^A-Za-z0-9_.:-]/g, "_") + "=<malformed>";
+      }
+
+      let name = trimmed.substring(0, eq).trim();
+      if (name === "") return "<malformed>=<redacted>";
+
+      return name + "=<redacted>";
+    }).join("; ");
+  }
+
+};

package.json

@@ -19,6 +19,7 @@
     "test": "mkdir -p coverage; jasmine; [ -n \"$COVERALLS_REPO_TOKEN\" ] && nyc report --reporter=text-lcov > coverage/lcov.info && coveralls < coverage/lcov.info || true",
     "dev": "source ./.env && echo $ENVIRONMENT && nyc jasmine; nyc report --reporter=text-lcov > coverage/lcov.info; coveralls < coverage/lcov.info",
     "metrics-coverage": "node scripts/metrics-coverage.js",
+    "logging-audit": "node scripts/logging-quality-audit.js",
     "lint": "eslint ./",
     "lint:commit": "commitlint --from HEAD~1 --to HEAD --verbose",
     "setup:hooks": "git config core.hooksPath .githooks",