diff --git a/docs/logging-quality-audit.md b/docs/logging-quality-audit.md new file mode 100644 index 000000000..557d6e089 --- /dev/null +++ b/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 +``` diff --git a/lib/router.auth.js b/lib/router.auth.js index 1e52dde96..dde32df0e 100644 --- a/lib/router.auth.js +++ b/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); }); -}; \ No newline at end of file +}; diff --git a/lib/router.gdpr.js b/lib/router.gdpr.js index 9e0f77cee..148c7f524 100644 --- a/lib/router.gdpr.js +++ b/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); }); -}; \ No newline at end of file +}; diff --git a/lib/router.github.js b/lib/router.github.js index 283e2b318..45cbefcdf 100644 --- a/lib/router.github.js +++ b/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//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, { diff --git a/lib/router.google.js b/lib/router.google.js index 6582a567a..23e8d1735 100644 --- a/lib/router.google.js +++ b/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); }); } diff --git a/lib/thinx/builder.js b/lib/thinx/builder.js index a07b82e43..af4418d94 100644 --- a/lib/thinx/builder.js +++ b/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 diff --git a/lib/thinx/device.js b/lib/thinx/device.js index 630a7beae..70616656b 100644 --- a/lib/thinx/device.js +++ b/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 diff --git a/lib/thinx/util.js b/lib/thinx/util.js index 3d4f6d8fb..df32e8625 100644 --- a/lib/thinx/util.js +++ b/lib/thinx/util.js @@ -136,4 +136,40 @@ module.exports = class Util { return s.substring(0, n) + "…"; } -}; \ No newline at end of file + static redactHeaderValue(value, prefix) { + if (typeof value === "undefined") return ""; + if (value === null) return ""; + + let s = String(value).trim(); + if (s === "") return ""; + + 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 ""; + if (header === null) return ""; + + let s = String(header).trim(); + if (s === "") return ""; + + return s.split(";").map((cookie) => { + let trimmed = cookie.trim(); + if (trimmed === "") return ""; + + let eq = trimmed.indexOf("="); + if (eq === -1) { + return trimmed.replace(/[^A-Za-z0-9_.:-]/g, "_") + "="; + } + + let name = trimmed.substring(0, eq).trim(); + if (name === "") return "="; + + return name + "="; + }).join("; "); + } + +}; diff --git a/package.json b/package.json index 416657e63..4063e1edf 100644 --- a/package.json +++ b/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", diff --git a/scripts/logging-quality-audit.js b/scripts/logging-quality-audit.js new file mode 100644 index 000000000..5876501c8 --- /dev/null +++ b/scripts/logging-quality-audit.js @@ -0,0 +1,412 @@ +#!/usr/bin/env node +/** + * Logging Quality Auditor + * + * Scans backend/API logging for structured logger adoption, tracked statistics + * events, sensitive logging patterns, severity-string mismatches, and useful + * operational context. + * + * Usage: + * node scripts/logging-quality-audit.js [--json] + */ + +'use strict'; + +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.resolve(__dirname, '..'); +const ROOT_FILES = ['thinx-core.js', 'thinx.js']; +const SERVICE_ENTRYPOINTS = [ + 'services/worker/worker.js', + 'services/transformer/index.js', + 'services/transformer/app.js', + 'services/transformer/transformer.js', +]; + +const CONSOLE_CALL_RE = /\bconsole\.(log|warn|error|info|debug)\s*\(/g; +const LOGGER_CALL_RE = /\blogger\.(warn|error|info|debug)\s*\(/g; +const OID_EVENT_RE = /\[OID:[^\]]+\]\s*\[([A-Z_]+)\]/g; +const STATS_LOG_RE = /(?:InfluxConnector\.)?statsLog\s*\([^,]+,\s*["']([A-Z_]+)["']/g; +const STATS_EVENT_WRAPPER_RE = /recordStatsEvent\s*\([^,]+,\s*["']([A-Z_]+)["']/g; +const COMMENT_RE = /^\s*(?:\/\/|\/\*|\*)/; + +const SEVERITY_TAGS = [ + { name: 'critical', re: /\[(?:critical|CRITICAL)\]|critical/i, expected: ['error'] }, + { name: 'error', re: /\[(?:error|ERROR)\]|error/i, expected: ['error'] }, + { name: 'warning', re: /\[(?:warning|WARN|warn)\]|warning/i, expected: ['warn', 'error'] }, + { name: 'info', re: /\[(?:info|INFO)\]|info/i, expected: ['info', 'warn', 'error'] }, + { name: 'debug', re: /\[(?:debug|DEBUG)\]|debug/i, expected: ['debug', 'info', 'warn', 'error'] }, +]; + +const SENSITIVE_PATTERNS = [ + { + id: 'raw_cookie_header', + severity: 'high', + description: 'Raw Cookie header or cookie string is logged without redaction.', + test: line => ( + isLogLine(line) && + /(?:headers\.cookie|JSON\.stringify\s*\(\s*cookies\s*\)|,\s*cookies\s*\)|\+\s*cookies\b)/.test(line) && + !/redactCookieHeader/.test(line) + ), + }, + { + id: 'oauth_access_token', + severity: 'high', + description: 'OAuth access token variable is logged without redaction.', + test: line => ( + isLogLine(line) && + /\b(?:access_token|accessToken)\b/.test(line) && + !/redactToken/.test(line) && + !/Signing JWT access\+refresh tokens/.test(line) + ), + }, + { + id: 'oauth_handoff_token', + severity: 'high', + description: 'One-shot OAuth/GDPR handoff token or redirect URL is logged without redaction.', + test: line => ( + isLogLine(line) && + /(?:\{\s*token\s*\}|for token",?\s*token|for token',?\s*token|\b(?:courl|ourl|redirectURL)\b|auth\.html\?t=)/.test(line) && + !/redactToken/.test(line) + ), + }, + { + id: 'full_user_wrapper', + severity: 'high', + description: 'Full OAuth userWrapper payload is logged.', + test: line => ( + isLogLine(line) && + /(?:\{\s*userWrapper\s*\}|JSON\.stringify\s*\(\s*userWrapper\s*\)|,\s*userWrapper\b|\buserWrapper\s*\))/.test(line) && + !/redact/.test(line) + ), + }, + { + id: 'full_hdata', + severity: 'high', + description: 'Full GitHub hdata payload is logged.', + test: line => ( + isLogLine(line) && + /(?:\{\s*hdata\s*\}|JSON\.stringify\s*\(\s*hdata\s*\)|,\s*hdata\b|\bhdata\s*\))/.test(line) && + !/redact/.test(line) + ), + }, + { + id: 'invalid_login_username', + severity: 'high', + description: 'Invalid login event logs the submitted username.', + test: line => ( + isLogLine(line) && + /LOGIN_INVALID/.test(line) && + /\busername\b/.test(line) + ), + }, + { + id: 'possible_secret_payload', + severity: 'medium', + description: 'Log line includes likely secret-bearing request or response payload.', + test: line => ( + isLogLine(line) && + /(?:JSON\.stringify\s*\(\s*(?:req\.body|reg|device|doc|response)\s*\)|\{\s*(?:req|reg|device|doc|response)\s*\})/.test(line) && + !/redact|mask|delete/.test(line) + ), + }, +]; + +function isLogLine(line) { + return /\b(?:console|logger)\.(?:log|warn|error|info|debug)\s*\(/.test(line); +} + +function rel(filePath) { + return path.relative(ROOT, filePath); +} + +function walk(dir, files = []) { + if (!fs.existsSync(dir)) return files; + for (const entry of fs.readdirSync(dir, { withFileTypes: true })) { + const full = path.join(dir, entry.name); + if (entry.isDirectory()) { + walk(full, files); + } else if (entry.isFile() && entry.name.endsWith('.js')) { + files.push(full); + } + } + return files; +} + +function collectFiles() { + const files = []; + for (const f of ROOT_FILES) { + const full = path.join(ROOT, f); + if (fs.existsSync(full)) files.push(full); + } + files.push(...walk(path.join(ROOT, 'lib'))); + for (const f of SERVICE_ENTRYPOINTS) { + const full = path.join(ROOT, f); + if (fs.existsSync(full)) files.push(full); + } + return [...new Set(files)].sort(); +} + +function loadStatisticsEvents() { + const statisticsPath = path.join(ROOT, 'lib/thinx/statistics.js'); + if (!fs.existsSync(statisticsPath)) return []; + + const content = fs.readFileSync(statisticsPath, 'utf8'); + const templateMatch = content.match(/const\s+owner_template\s*=\s*\{([\s\S]*?)\};/); + if (!templateMatch) return []; + + const events = []; + const keyRe = /^\s*([A-Z_]+)\s*:/gm; + let match; + while ((match = keyRe.exec(templateMatch[1])) !== null) { + events.push(match[1]); + } + return [...new Set(events)].sort(); +} + +function emptyCounts() { + return { + log: 0, + warn: 0, + error: 0, + info: 0, + debug: 0, + total: 0, + }; +} + +function increment(counts, key) { + counts[key] += 1; + counts.total += 1; +} + +function logCallLevel(line) { + let match = line.match(/\blogger\.(warn|error|info|debug)\s*\(/); + if (match) return { sink: 'logger', level: match[1] }; + + match = line.match(/\bconsole\.(log|warn|error|info|debug)\s*\(/); + if (match) return { sink: 'console', level: match[1] }; + + return { sink: 'unknown', level: 'unknown' }; +} + +function normalizedLevel(sink, level) { + if (sink === 'logger') return level; + if (sink === 'console' && level === 'warn') return 'warn'; + if (sink === 'console' && level === 'error') return 'error'; + if (sink === 'console' && level === 'info') return 'info'; + if (sink === 'console' && level === 'debug') return 'debug'; + return 'log'; +} + +function excerpt(line) { + return line.trim().replace(/\s+/g, ' ').slice(0, 240); +} + +function detectSeverityMismatch(line, lineNumber) { + if (!isLogLine(line)) return null; + + const call = logCallLevel(line); + const actual = normalizedLevel(call.sink, call.level); + + for (const tag of SEVERITY_TAGS) { + if (!tag.re.test(line)) continue; + if (tag.expected.includes(actual)) return null; + return { + line: lineNumber, + sink: call.sink, + level: call.level, + message_severity: tag.name, + excerpt: excerpt(line), + }; + } + + return null; +} + +function analyzeFile(filePath, statisticsEvents) { + const content = fs.readFileSync(filePath, 'utf8'); + const lines = content.split(/\r?\n/); + const consoleCounts = emptyCounts(); + const loggerCounts = emptyCounts(); + const trackedEvents = []; + const suspiciousSensitive = []; + const severityMismatches = []; + + lines.forEach((line, index) => { + const lineNumber = index + 1; + const trimmed = line.trim(); + if (COMMENT_RE.test(trimmed)) return; + + let match; + const consoleRe = new RegExp(CONSOLE_CALL_RE.source, 'g'); + while ((match = consoleRe.exec(line)) !== null) { + increment(consoleCounts, match[1]); + } + + const loggerRe = new RegExp(LOGGER_CALL_RE.source, 'g'); + while ((match = loggerRe.exec(line)) !== null) { + increment(loggerCounts, match[1]); + } + + const oidRe = new RegExp(OID_EVENT_RE.source, 'g'); + while ((match = oidRe.exec(line)) !== null) { + const call = logCallLevel(line); + const event = match[1]; + const trackedByStatistics = statisticsEvents.includes(event); + const compliant = !trackedByStatistics || (call.sink === 'logger' && call.level === 'warn'); + trackedEvents.push({ + event, + line: lineNumber, + sink: call.sink, + level: call.level, + source: 'oid_log', + tracked_by_statistics: trackedByStatistics, + compliant, + excerpt: excerpt(line), + }); + } + + const statsRe = new RegExp(STATS_LOG_RE.source, 'g'); + while ((match = statsRe.exec(line)) !== null) { + const event = match[1]; + trackedEvents.push({ + event, + line: lineNumber, + sink: 'metrics', + level: 'statsLog', + source: 'InfluxConnector.statsLog', + tracked_by_statistics: statisticsEvents.includes(event), + compliant: true, + excerpt: excerpt(line), + }); + } + + const wrapperRe = new RegExp(STATS_EVENT_WRAPPER_RE.source, 'g'); + while ((match = wrapperRe.exec(line)) !== null) { + const event = match[1]; + trackedEvents.push({ + event, + line: lineNumber, + sink: 'logger', + level: 'warn', + source: 'recordStatsEvent', + tracked_by_statistics: statisticsEvents.includes(event), + compliant: true, + excerpt: excerpt(line), + }); + } + + for (const pattern of SENSITIVE_PATTERNS) { + if (!pattern.test(line)) continue; + suspiciousSensitive.push({ + id: pattern.id, + severity: pattern.severity, + description: pattern.description, + line: lineNumber, + excerpt: excerpt(line), + }); + } + + const mismatch = detectSeverityMismatch(line, lineNumber); + if (mismatch) severityMismatches.push(mismatch); + }); + + return { + file: rel(filePath), + console: consoleCounts, + logger: loggerCounts, + tracked_events: trackedEvents, + suspicious_sensitive: suspiciousSensitive, + severity_mismatches: severityMismatches, + }; +} + +function sum(files, selector) { + return files.reduce((acc, f) => acc + selector(f), 0); +} + +function buildReport(files, statisticsEvents) { + const trackedEvents = files.flatMap(f => f.tracked_events.map(e => ({ file: f.file, ...e }))); + const sensitiveFindings = files.flatMap(f => f.suspicious_sensitive.map(e => ({ file: f.file, ...e }))); + const severityMismatches = files.flatMap(f => f.severity_mismatches.map(e => ({ file: f.file, ...e }))); + const trackedEventQualityGaps = trackedEvents.filter(e => e.tracked_by_statistics && !e.compliant); + const eventNames = [...new Set(trackedEvents.map(e => e.event))].sort(); + + return { + scope: { + root_files: ROOT_FILES, + lib_glob: 'lib/**/*.js', + service_entrypoints: SERVICE_ENTRYPOINTS, + statistics_events: statisticsEvents, + }, + summary: { + files_scanned: files.length, + console_calls: sum(files, f => f.console.total), + logger_calls: sum(files, f => f.logger.total), + tracked_event_occurrences: trackedEvents.length, + tracked_events: eventNames, + sensitive_findings: sensitiveFindings.length, + high_risk_sensitive_findings: sensitiveFindings.filter(f => f.severity === 'high').length, + severity_mismatches: severityMismatches.length, + tracked_event_quality_gaps: trackedEventQualityGaps.length, + }, + files, + tracked_events: trackedEvents, + suspicious_sensitive: sensitiveFindings, + severity_mismatches: severityMismatches, + tracked_event_quality_gaps: trackedEventQualityGaps, + }; +} + +function printReport(report) { + const s = report.summary; + + console.log('\n=== Logging Quality Audit ===\n'); + console.log(`Files scanned : ${s.files_scanned}`); + console.log(`console.* calls : ${s.console_calls}`); + console.log(`logger.* calls : ${s.logger_calls}`); + console.log(`Tracked event occurrences : ${s.tracked_event_occurrences}`); + console.log(`Sensitive findings : ${s.sensitive_findings} (${s.high_risk_sensitive_findings} high risk)`); + console.log(`Severity-string mismatches : ${s.severity_mismatches}`); + console.log(`Tracked event quality gaps : ${s.tracked_event_quality_gaps}`); + console.log(`Tracked events : ${s.tracked_events.join(', ') || '(none)'}`); + + console.log('\n--- Files With Logging Calls ---'); + for (const file of report.files.filter(f => f.console.total > 0 || f.logger.total > 0)) { + console.log(`${file.file}: console=${file.console.total}, logger=${file.logger.total}, events=${file.tracked_events.length}`); + } + + if (report.suspicious_sensitive.length > 0) { + console.log('\n--- Sensitive Findings ---'); + for (const finding of report.suspicious_sensitive) { + console.log(`${finding.severity.toUpperCase()} ${finding.id} ${finding.file}:${finding.line} ${finding.excerpt}`); + } + } + + if (report.tracked_event_quality_gaps.length > 0) { + console.log('\n--- Tracked Event Quality Gaps ---'); + for (const gap of report.tracked_event_quality_gaps) { + console.log(`${gap.file}:${gap.line} ${gap.event} via ${gap.sink}.${gap.level}`); + } + } + + console.log(''); +} + +function main() { + const args = process.argv.slice(2); + const jsonMode = args.includes('--json'); + const statisticsEvents = loadStatisticsEvents(); + const files = collectFiles().map(file => analyzeFile(file, statisticsEvents)); + const report = buildReport(files, statisticsEvents); + + if (jsonMode) { + console.log(JSON.stringify(report, null, 2)); + } else { + printReport(report); + } +} + +main(); diff --git a/scripts/metrics-coverage.js b/scripts/metrics-coverage.js index f2f53df0e..87b244cc1 100644 --- a/scripts/metrics-coverage.js +++ b/scripts/metrics-coverage.js @@ -34,10 +34,14 @@ const INSTRUMENTATION_PATTERNS = [ /InfluxConnector\.statsLog\s*\(/, /statsLog\s*\(/, /influx\.statsLog\s*\(/, + /recordStatsEvent\s*\(/, ]; // Patterns for metrics events to extract -const EVENT_PATTERN = /statsLog\s*\([^,]+,\s*["']([A-Z_]+)["']/g; +const EVENT_PATTERNS = [ + /statsLog\s*\([^,]+,\s*["']([A-Z_]+)["']/g, + /recordStatsEvent\s*\([^,]+,\s*["']([A-Z_]+)["']/g, +]; /** * Collect all .js files recursively under a directory. @@ -71,11 +75,13 @@ function analyzeFile(filePath) { const events = []; if (hasInstrumentation) { - let match; - const re = new RegExp(EVENT_PATTERN.source, 'g'); - while ((match = re.exec(content)) !== null) { - if (!events.includes(match[1])) { - events.push(match[1]); + for (const pattern of EVENT_PATTERNS) { + let match; + const re = new RegExp(pattern.source, 'g'); + while ((match = re.exec(content)) !== null) { + if (!events.includes(match[1])) { + events.push(match[1]); + } } } } diff --git a/spec/jasmine/LoggingQualityAuditSpec.js b/spec/jasmine/LoggingQualityAuditSpec.js new file mode 100644 index 000000000..1e3965d58 --- /dev/null +++ b/spec/jasmine/LoggingQualityAuditSpec.js @@ -0,0 +1,107 @@ +const path = require('path'); +const { execFileSync } = require('child_process'); + +const SCRIPT = path.resolve(__dirname, '../../scripts/logging-quality-audit.js'); +const ROOT = path.resolve(__dirname, '../..'); + +describe("Logging Quality Auditor", function () { + + let report; + + beforeAll(function () { + const out = execFileSync(process.execPath, [SCRIPT, '--json'], { + cwd: ROOT, + encoding: 'utf8' + }); + report = JSON.parse(out); + }); + + function fileReport(file) { + return report.files.find(f => f.file === file); + } + + function hasCompliantEvent(file, event) { + return report.tracked_events.some(e => + e.file === file && + e.event === event && + (e.sink === 'metrics' || (e.sink === 'logger' && e.level === 'warn')) && + e.compliant === true + ); + } + + it("should return a valid report structure", function () { + expect(report).toBeDefined(); + expect(report.scope).toBeDefined(); + expect(report.summary).toBeDefined(); + expect(Array.isArray(report.files)).toBeTrue(); + expect(Array.isArray(report.tracked_events)).toBeTrue(); + expect(Array.isArray(report.suspicious_sensitive)).toBeTrue(); + expect(Array.isArray(report.severity_mismatches)).toBeTrue(); + expect(Array.isArray(report.tracked_event_quality_gaps)).toBeTrue(); + }); + + it("should scan the backend/API logging scope", function () { + expect(report.scope.root_files).toContain('thinx-core.js'); + expect(report.scope.root_files).toContain('thinx.js'); + expect(report.scope.lib_glob).toEqual('lib/**/*.js'); + expect(report.scope.service_entrypoints).toContain('services/worker/worker.js'); + expect(report.scope.service_entrypoints).toContain('services/transformer/app.js'); + expect(fileReport('thinx-core.js')).toBeDefined(); + expect(fileReport('lib/router.auth.js')).toBeDefined(); + expect(fileReport('lib/thinx/device.js')).toBeDefined(); + }); + + it("should report the current lower-risk logging backlog", function () { + expect(report.summary.files_scanned).toBeGreaterThan(0); + expect(report.summary.console_calls).toBeGreaterThan(0); + expect(report.summary.severity_mismatches).toBeGreaterThan(0); + expect(report.summary.sensitive_findings).toBeGreaterThanOrEqual(report.summary.high_risk_sensitive_findings); + }); + + it("should identify statistics events from the statistics owner template", function () { + const events = report.scope.statistics_events; + expect(events).toContain('LOGIN_INVALID'); + expect(events).toContain('DEVICE_NEW'); + expect(events).toContain('DEVICE_CHECKIN'); + expect(events).toContain('BUILD_STARTED'); + expect(events).toContain('BUILD_SUCCESS'); + expect(events).toContain('BUILD_FAILED'); + }); + + it("should gate high-risk sensitive logging regressions", function () { + const blockedIds = [ + 'raw_cookie_header', + 'oauth_access_token', + 'oauth_handoff_token', + 'full_user_wrapper', + 'full_hdata', + 'invalid_login_username' + ]; + const highRisk = report.suspicious_sensitive.filter(f => blockedIds.includes(f.id)); + expect(highRisk).toEqual([]); + expect(report.summary.high_risk_sensitive_findings).toEqual(0); + }); + + it("should gate tracked statistics events that bypass logger.warn or metrics", function () { + expect(report.tracked_event_quality_gaps).toEqual([]); + expect(report.summary.tracked_event_quality_gaps).toEqual(0); + }); + + it("should show fixed high-value events as logger.warn or metrics backed", function () { + expect(hasCompliantEvent('lib/router.auth.js', 'LOGIN_INVALID')).toBeTrue(); + expect(hasCompliantEvent('lib/thinx/builder.js', 'BUILD_STARTED')).toBeTrue(); + expect(hasCompliantEvent('lib/thinx/builder.js', 'BUILD_FAILED')).toBeTrue(); + expect(hasCompliantEvent('lib/thinx/builder.js', 'BUILD_SUCCESS')).toBeTrue(); + expect(hasCompliantEvent('lib/thinx/device.js', 'DEVICE_CHECKIN')).toBeTrue(); + expect(hasCompliantEvent('lib/thinx/device.js', 'DEVICE_NEW')).toBeTrue(); + }); + + it("should support the npm logging-audit -- --json entrypoint", function () { + const out = execFileSync('npm', ['run', '--silent', 'logging-audit', '--', '--json'], { + cwd: ROOT, + encoding: 'utf8' + }); + const npmReport = JSON.parse(out); + expect(npmReport.summary.files_scanned).toEqual(report.summary.files_scanned); + }); +}); diff --git a/spec/jasmine/UtilSpec.js b/spec/jasmine/UtilSpec.js index 156aa591f..55022ab40 100644 --- a/spec/jasmine/UtilSpec.js +++ b/spec/jasmine/UtilSpec.js @@ -206,4 +206,34 @@ describe("Util", function () { let tok = "deadbeefcafebabe1234567890abcdef"; expect(Util.redactToken(tok)).to.equal(Util.redactToken(tok)); }); -}); \ No newline at end of file + + it("should redact bearer-style header values while preserving the scheme", function () { + expect(Util.redactHeaderValue("Bearer abcdef123456", 4)).to.equal("Bearer abcd…"); + }); + + it("should handle empty/null/undefined header values defensively", function () { + expect(Util.redactHeaderValue("")).to.equal(""); + expect(Util.redactHeaderValue(null)).to.equal(""); + expect(Util.redactHeaderValue(undefined)).to.equal(""); + }); + + it("should redact a single cookie header value while preserving the cookie name", function () { + expect(Util.redactCookieHeader("x-thx-core=s%3Asecretvalue")).to.equal("x-thx-core="); + }); + + it("should redact multi-cookie headers without exposing raw values", function () { + expect(Util.redactCookieHeader("x-thx-core=s%3Asecret; XSRF-TOKEN=csrf-value; theme=dark")) + .to.equal("x-thx-core=; XSRF-TOKEN=; theme="); + }); + + it("should handle empty/null/undefined cookie headers defensively", function () { + expect(Util.redactCookieHeader("")).to.equal(""); + expect(Util.redactCookieHeader(null)).to.equal(""); + expect(Util.redactCookieHeader(undefined)).to.equal(""); + }); + + it("should mark malformed cookie header parts without throwing", function () { + expect(Util.redactCookieHeader("malformed-cookie")).to.equal("malformed-cookie="); + expect(Util.redactCookieHeader("=missingName")).to.equal("="); + }); +}); diff --git a/thinx-core.js b/thinx-core.js index 5ea825158..b29da73cb 100644 --- a/thinx-core.js +++ b/thinx-core.js @@ -498,7 +498,7 @@ module.exports = class THiNX extends EventEmitter { if (Util.isDefined(cookies)) { // other x-thx cookies are now deprecated and can be removed if (cookies.indexOf("x-thx-core") === -1) { - console.log("Should destroy socket, access unauthorized."); + console.log("Should destroy socket, access unauthorized.", Util.redactCookieHeader(cookies)); socket.write('HTTP/1.1 401 Unauthorized\r\n\r\n'); socket.destroy(); return; @@ -652,7 +652,7 @@ module.exports = class THiNX extends EventEmitter { if (typeof (cookies) !== "undefined") { if (cookies.indexOf("x-thx") === -1) { - console.log(`🚫 [critical] No thx-session found in WS: ${JSON.stringify(cookies)}`); + console.log(`🚫 [critical] No thx-session found in WS: ${Util.redactCookieHeader(cookies)}`); return; } } else {