replace debug() with our custom logger

mostly we want trace() and log(). trace() can be enabled whenever
we want by flipping a flag and restarting box
This commit is contained in:
Girish Ramakrishnan
2026-03-12 22:55:28 +05:30
parent d57554a48c
commit 01d0c738bc
104 changed files with 1187 additions and 1174 deletions

View File

@@ -2,7 +2,7 @@ import assert from 'node:assert';
import backupSites from '../backupsites.js';
import BoxError from '../boxerror.js';
import DataLayout from '../datalayout.js';
import debugModule from 'debug';
import logger from '../logger.js';
import hush from '../hush.js';
const { DecryptStream, EncryptStream } = hush;
import fs from 'node:fs';
@@ -17,7 +17,7 @@ import tar from 'tar-stream';
import util from 'node:util';
import zlib from 'node:zlib';
const debug = debugModule('box:backupformat/tgz');
const { log, trace } = logger('backupformat/tgz');
// In tar, the entry header contains the file size. If we don't provide it those many bytes, the tar will become corrupt
// Linux provides no guarantee of how many bytes can be read from a file. This is the case with sqlite and log files
@@ -31,12 +31,12 @@ class EnsureFileSizeStream extends Transform {
_transform(chunk, encoding, callback) {
if (this._remaining <= 0) {
debug(`EnsureFileSizeStream: ${this._name} dropping ${chunk.length} bytes`);
log(`EnsureFileSizeStream: ${this._name} dropping ${chunk.length} bytes`);
return callback(null);
}
if (this._remaining - chunk.length < 0) {
debug(`EnsureFileSizeStream: ${this._name} dropping extra ${chunk.length - this._remaining} bytes`);
log(`EnsureFileSizeStream: ${this._name} dropping extra ${chunk.length - this._remaining} bytes`);
chunk = chunk.subarray(0, this._remaining);
this._remaining = 0;
} else {
@@ -48,7 +48,7 @@ class EnsureFileSizeStream extends Transform {
_flush(callback) {
if (this._remaining > 0) {
debug(`EnsureFileSizeStream: ${this._name} injecting ${this._remaining} bytes`);
log(`EnsureFileSizeStream: ${this._name} injecting ${this._remaining} bytes`);
this.push(Buffer.alloc(this._remaining, 0));
}
callback();
@@ -63,7 +63,7 @@ function addEntryToPack(pack, header, options) {
return new Promise((resolve, reject) => {
const packEntry = safe(() => pack.entry(header, function (error) {
if (error) {
debug(`addToPack: error adding ${header.name} ${header.type} ${error.message}`);
log(`addToPack: error adding ${header.name} ${header.type} ${error.message}`);
reject(new BoxError(BoxError.FS_ERROR, error.message));
} else {
resolve();
@@ -74,7 +74,7 @@ function addEntryToPack(pack, header, options) {
if (options?.input) {
const ensureFileSizeStream = new EnsureFileSizeStream({ name: header.name, size: header.size });
safe(stream.pipeline(options.input, ensureFileSizeStream, packEntry), { debug }); // background. rely on pack.entry callback for promise completion
safe(stream.pipeline(options.input, ensureFileSizeStream, packEntry), { debug: log }); // background. rely on pack.entry callback for promise completion
}
});
}
@@ -92,7 +92,7 @@ async function addPathToPack(pack, localPath, dataLayout) {
const dir = queue.shift();
const [readdirError, entries] = await safe(fs.promises.readdir(dir, { withFileTypes: true }));
if (!entries) {
debug(`tarPack: skipping directory ${dir}: ${readdirError.message}`);
log(`tarPack: skipping directory ${dir}: ${readdirError.message}`);
continue;
}
const subdirs = [];
@@ -101,9 +101,9 @@ async function addPathToPack(pack, localPath, dataLayout) {
const headerName = dataLayout.toRemotePath(abspath);
if (entry.isFile()) {
const [openError, handle] = await safe(fs.promises.open(abspath, 'r'));
if (!handle) { debug(`tarPack: skipping file, could not open ${abspath}: ${openError.message}`); continue; }
if (!handle) { log(`tarPack: skipping file, could not open ${abspath}: ${openError.message}`); continue; }
const [statError, stat] = await safe(handle.stat());
if (!stat) { debug(`tarPack: skipping file, could not stat ${abspath}: ${statError.message}`); continue; }
if (!stat) { log(`tarPack: skipping file, could not stat ${abspath}: ${statError.message}`); continue; }
const header = { name: headerName, type: 'file', mode: stat.mode, size: stat.size, uid: process.getuid(), gid: process.getgid() };
if (stat.size > 8589934590 || entry.name.length > 99) header.pax = { size: stat.size };
const input = handle.createReadStream({ autoClose: true });
@@ -116,12 +116,12 @@ async function addPathToPack(pack, localPath, dataLayout) {
++stats.dirCount;
} else if (entry.isSymbolicLink()) {
const [readlinkError, site] = await safe(fs.promises.readlink(abspath));
if (!site) { debug(`tarPack: skipping link, could not readlink ${abspath}: ${readlinkError.message}`); continue; }
if (!site) { log(`tarPack: skipping link, could not readlink ${abspath}: ${readlinkError.message}`); continue; }
const header = { name: headerName, type: 'symlink', linkname: site, uid: process.getuid(), gid: process.getgid() };
await addEntryToPack(pack, header, { /* options */ });
++stats.linkCount;
} else {
debug(`tarPack: ignoring unknown type ${entry.name} ${entry.type}`);
log(`tarPack: ignoring unknown type ${entry.name} ${entry.type}`);
}
}
@@ -163,11 +163,11 @@ async function tarPack(dataLayout, encryption, uploader, progressCallback) {
let fileCount = 0;
for (const localPath of dataLayout.localPaths()) {
const [error, stats] = await safe(addPathToPack(pack, localPath, dataLayout), { debug });
const [error, stats] = await safe(addPathToPack(pack, localPath, dataLayout), { debug: log });
if (error) break; // the pipeline will error and we will retry the whole packing all over
fileCount += stats.fileCount;
}
debug(`tarPack: packed ${fileCount} files`);
log(`tarPack: packed ${fileCount} files`);
pack.finalize(); // harmless to call if already in error state
@@ -175,7 +175,7 @@ async function tarPack(dataLayout, encryption, uploader, progressCallback) {
if (error) throw new BoxError(BoxError.EXTERNAL_ERROR, `tarPack pipeline error: ${error.message}`);
const stats = ps.stats(); // { startTime, totalMsecs, transferred }
debug(`tarPack: pipeline finished: ${JSON.stringify(stats)}`);
log(`tarPack: pipeline finished: ${JSON.stringify(stats)}`);
await uploader.finish();
return {
@@ -195,7 +195,7 @@ async function tarExtract(inStream, dataLayout, encryption, progressCallback) {
let entryCount = 0;
extract.on('entry', async function (header, entryStream, next) {
if (path.isAbsolute(header.name)) {
debug(`tarExtract: ignoring absolute path ${header.name}`);
log(`tarExtract: ignoring absolute path ${header.name}`);
return next();
}
++entryCount;
@@ -211,7 +211,7 @@ async function tarExtract(inStream, dataLayout, encryption, progressCallback) {
await safe(fs.promises.unlink(abspath)); // remove any link created from previous failed extract
[error] = await safe(fs.promises.symlink(header.linkname, abspath));
} else {
debug(`tarExtract: ignoring unknown entry: ${header.name} ${header.type}`);
log(`tarExtract: ignoring unknown entry: ${header.name} ${header.type}`);
entryStream.resume(); // drain
}
@@ -220,7 +220,7 @@ async function tarExtract(inStream, dataLayout, encryption, progressCallback) {
[error] = await safe(fs.promises.lutimes(abspath, now /* atime */, header.mtime)); // for dirs, mtime will get overwritten
next(error);
});
extract.on('finish', () => debug(`tarExtract: extracted ${entryCount} entries`));
extract.on('finish', () => log(`tarExtract: extracted ${entryCount} entries`));
const gunzip = zlib.createGunzip({});
const ps = new ProgressStream({ interval: 10000 });
@@ -242,7 +242,7 @@ async function tarExtract(inStream, dataLayout, encryption, progressCallback) {
if (error) throw new BoxError(BoxError.EXTERNAL_ERROR, `tarExtract pipeline error: ${error.message}`);
}
debug(`tarExtract: pipeline finished: ${JSON.stringify(ps.stats())}`);
log(`tarExtract: pipeline finished: ${JSON.stringify(ps.stats())}`);
}
async function download(backupSite, remotePath, dataLayout, progressCallback) {
@@ -251,9 +251,9 @@ async function download(backupSite, remotePath, dataLayout, progressCallback) {
assert(dataLayout instanceof DataLayout, 'dataLayout must be a DataLayout');
assert.strictEqual(typeof progressCallback, 'function');
debug(`download: Downloading ${remotePath} to ${dataLayout.toString()}`);
log(`download: Downloading ${remotePath} to ${dataLayout.toString()}`);
await promiseRetry({ times: 3, interval: 20000, debug }, async () => {
await promiseRetry({ times: 3, interval: 20000, debug: log }, async () => {
progressCallback({ message: `Downloading backup ${remotePath}` });
const sourceStream = await backupSites.storageApi(backupSite).download(backupSite.config, remotePath);
@@ -267,9 +267,9 @@ async function upload(backupSite, remotePath, dataLayout, progressCallback) {
assert.strictEqual(typeof dataLayout, 'object');
assert.strictEqual(typeof progressCallback, 'function');
debug(`upload: uploading to site ${backupSite.id} path ${remotePath} (encrypted: ${!!backupSite.encryption}) dataLayout ${dataLayout.toString()}`);
log(`upload: uploading to site ${backupSite.id} path ${remotePath} (encrypted: ${!!backupSite.encryption}) dataLayout ${dataLayout.toString()}`);
return await promiseRetry({ times: 5, interval: 20000, debug }, async () => {
return await promiseRetry({ times: 5, interval: 20000, debug: log }, async () => {
progressCallback({ message: `Uploading backup ${remotePath}` });
const uploader = await backupSites.storageApi(backupSite).upload(backupSite.config, backupSite.limits, remotePath);
@@ -296,7 +296,7 @@ async function verify(backupSite, remotePath, integrityMap, progressCallback) {
assert(util.types.isMap(integrityMap), 'integrityMap should be a Map');
assert.strictEqual(typeof progressCallback, 'function');
debug(`verify: Verifying ${remotePath}`);
log(`verify: Verifying ${remotePath}`);
const inStream = await backupSites.storageApi(backupSite).download(backupSite.config, remotePath);
@@ -305,17 +305,17 @@ async function verify(backupSite, remotePath, integrityMap, progressCallback) {
const extract = tar.extract();
extract.on('entry', async function (header, entryStream, next) {
if (path.isAbsolute(header.name)) {
debug(`verify: ignoring absolute path ${header.name}`);
log(`verify: ignoring absolute path ${header.name}`);
return next();
}
debug(`verify: ${header.name} ${header.size} ${header.type}`);
log(`verify: ${header.name} ${header.size} ${header.type}`);
if (header.type === 'file') {
++fileCount;
}
entryStream.resume(); // drain
next();
});
extract.on('finish', () => debug('verify: extract finished'));
extract.on('finish', () => log('verify: extract finished'));
const hash = new HashStream();
const gunzip = zlib.createGunzip({});
@@ -336,7 +336,7 @@ async function verify(backupSite, remotePath, integrityMap, progressCallback) {
}
const integrity = integrityMap.get('.');
debug(`verify: Expecting: ${JSON.stringify(integrity)} Actual: size:${ps.stats().transferred} filecount:${fileCount} digest:${hash.digest()}`);
log(`verify: Expecting: ${JSON.stringify(integrity)} Actual: size:${ps.stats().transferred} filecount:${fileCount} digest:${hash.digest()}`);
const messages = [];
if (integrity.size !== ps.stats().transferred) messages.push(`Size mismatch. Expected: ${integrity.size} Actual: ${ps.stats().transferred}`);