diff --git a/src/config/configManager.ts b/src/config/configManager.ts index b238705e..e6f0fe28 100644 --- a/src/config/configManager.ts +++ b/src/config/configManager.ts @@ -14,6 +14,8 @@ import { normalizeReceiveBetaUpdates } from "@domain/appUpdate/betaUpdates" import { DEFAULT_COMPRESSION_LEVEL, DEFAULT_CONFIG_BASE } from "@domain/config/defaults" import { normalizeServerBookmarks } from "@domain/servers/bookmarks" +const LOG_PREFIX = "[back] [config] [config/configManager.ts]" + const defaultConfig: ConfigType = { ...DEFAULT_CONFIG_BASE, schemaVersion: CURRENT_CONFIG_SCHEMA, @@ -90,8 +92,8 @@ export async function saveConfig(config: ConfigType): Promise { configReady = true return true } catch (err) { - logMessage("error", "[back] [config] [config/configManager.ts] [saveConfig] Error saving configuration.") - logMessage("debug", `[back] [config] [config/configManager.ts] [saveConfig] ${err}`) + logMessage("error", `${LOG_PREFIX} [saveConfig] Error saving configuration.`) + logMessage("debug", `${LOG_PREFIX} [saveConfig] ${err}`) return false } } @@ -118,8 +120,8 @@ export async function getConfig(): Promise { if (mustSave) await saveConfig(ensuredConfig) return ensuredConfig } catch (err) { - logMessage("error", `[back] [config] [config/configManager.ts] [getConfig] Error getting config at [PATH]. Using default config.`) - logMessage("debug", `[back] [config] [config/configManager.ts] [getConfig] Error getting config at [PATH]: ${err}`) + logMessage("error", `${LOG_PREFIX} [getConfig] Error getting config at [PATH]. Using default config.`) + logMessage("debug", `${LOG_PREFIX} [getConfig] Error getting config at [PATH]: ${err}`) await saveConfig(defaultConfig) return defaultConfig } @@ -130,22 +132,22 @@ export async function ensureConfig(): Promise { configPath = join(app.getPath("userData"), "config.json") try { if (!(await fse.pathExists(configPath))) { - logMessage("info", `[back] [config] [config/configManager.ts] [ensureConfig] Config not found. Creating default config.`) + logMessage("info", `${LOG_PREFIX} [ensureConfig] Config not found. Creating default config.`) return await saveConfig(defaultConfig) } configReady = true - logMessage("info", `[back] [config] [config/configManager.ts] [ensureConfig] Config found at [PATH].`) + logMessage("info", `${LOG_PREFIX} [ensureConfig] Config found at [PATH].`) return true } catch (err) { - logMessage("error", `[back] [config] [config/configManager.ts] [ensureConfig] Error ensuring config.`) - logMessage("error", `[back] [config] [config/configManager.ts] [ensureConfig] Error ensuring config at [PATH]: ${err}`) + logMessage("error", `${LOG_PREFIX} [ensureConfig] Error ensuring config.`) + logMessage("error", `${LOG_PREFIX} [ensureConfig] Error ensuring config at [PATH]: ${err}`) return false } } /** Says what the schema pipeline did with the stored document, and at what level it deserves saying. */ function logConfigMigration(migration: ReturnType): void { - const prefix = "[back] [config] [config/configManager.ts] [getConfig]" + const prefix = `${LOG_PREFIX} [getConfig]` const steps = migration.applied.map((step) => `${step.fromSchema}->${step.toSchema}`).join(", ") switch (migration.outcome) { @@ -189,10 +191,10 @@ async function migrateLegacyAccount(config: unknown): Promise { try { await saveAccountSecrets(legacyAccount.publicAccount.playerUid, legacyAccount.secrets) } catch { - logMessage("warn", "[back] [config] [configManager.ts] Legacy account credentials were not migrated to secure storage.") + logMessage("warn", `${LOG_PREFIX} Legacy account credentials were not migrated to secure storage.`) } } else { - logMessage("warn", "[back] [config] [configManager.ts] Legacy account credentials were invalid and were discarded.") + logMessage("warn", `${LOG_PREFIX} Legacy account credentials were invalid and were discarded.`) } return true @@ -235,7 +237,7 @@ async function migrateAccountStore(legacyDocument: unknown, config: ConfigType): try { return await adoptLegacySingleAccountSecrets(uid) } catch { - logMessage("warn", "[back] [config] [configManager.ts] The stored account session was not carried into the multi-account store. Retrying on the next launch.") + logMessage("warn", `${LOG_PREFIX} The stored account session was not carried into the multi-account store. Retrying on the next launch.`) return false } } @@ -299,8 +301,8 @@ async function reconcileConfigBackup(migrationRan: boolean): Promise { stripLegacyAccountSecrets(document) await writeJsonAtomic(backupPath, document, { mode: 0o600, spaces: 2 }) } catch (err) { - logMessage("warn", "[back] [config] [configManager.ts] Could not reconcile the pre-migration config backup.") - logMessage("debug", `[back] [config] [configManager.ts] ${err}`) + logMessage("warn", `${LOG_PREFIX} Could not reconcile the pre-migration config backup.`) + logMessage("debug", `${LOG_PREFIX} ${err}`) } } diff --git a/src/ipc/adapters/modScan.ts b/src/ipc/adapters/modScan.ts index c843d092..375cf342 100644 --- a/src/ipc/adapters/modScan.ts +++ b/src/ipc/adapters/modScan.ts @@ -13,6 +13,8 @@ import { sweepCacheFolder } from "@src/ipc/cacheSweep" import { assertSafeFileName } from "@src/ipc/validation" import { logMessage } from "@src/utils/logManager" +const LOG_PREFIX = "[back] [mods] [ipc/adapters/modScan.ts]" + /** Entry inside a mod archive carrying its metadata. */ const MODINFO_ENTRY = "modinfo.json" @@ -45,7 +47,7 @@ function readModArchive(archivePath: string): Promise { return new Promise((resolve) => { yauzl.open(archivePath, { lazyEntries: true }, (openErr, zip) => { if (openErr || !zip) { - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [readModArchive] Could not open a mod archive.`) + logMessage("debug", `${LOG_PREFIX} [readModArchive] Could not open a mod archive.`) return resolve({ ok: false, problem: "unreadable-archive" }) } @@ -79,7 +81,7 @@ function readModArchive(archivePath: string): Promise { const collect = (entry: yauzl.Entry, limit: number, onDone: (bytes: Buffer) => void, onOversize: () => void, onUnreadable: () => void): void => { zip.openReadStream(entry, (streamErr, stream) => { if (streamErr || !stream) { - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [readModArchive] Could not read a mod archive entry.`) + logMessage("debug", `${LOG_PREFIX} [readModArchive] Could not read a mod archive entry.`) return onUnreadable() } @@ -97,7 +99,7 @@ function readModArchive(archivePath: string): Promise { }) stream.on("end", () => onDone(Buffer.concat(chunks))) stream.on("error", () => { - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [readModArchive] Error reading a mod archive entry.`) + logMessage("debug", `${LOG_PREFIX} [readModArchive] Error reading a mod archive entry.`) onUnreadable() }) }) @@ -146,7 +148,7 @@ function readModArchive(archivePath: string): Promise { zip.on("end", () => settle({ ok: true, content })) zip.on("error", () => { - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [readModArchive] Error walking a mod archive.`) + logMessage("debug", `${LOG_PREFIX} [readModArchive] Error walking a mod archive.`) settle({ ok: false, problem: "unreadable-archive" }) }) @@ -194,8 +196,8 @@ export function createIconStorePort(): IconStore { } return imageName } catch (err) { - logMessage("error", `[back] [mods] [ipc/adapters/modScan.ts] [createIconStorePort] Error saving a mod's icon.`) - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [createIconStorePort] Error saving a mod's icon: ${err}`) + logMessage("error", `${LOG_PREFIX} [createIconStorePort] Error saving a mod's icon.`) + logMessage("debug", `${LOG_PREFIX} [createIconStorePort] Error saving a mod's icon: ${err}`) return undefined } } @@ -265,8 +267,8 @@ export function createModImageStorePort(): ModImageCache { await writeFileAtomic(target, bytes) return name } catch (err) { - logMessage("error", `[back] [mods] [ipc/adapters/modScan.ts] [createModImageStorePort] Error saving a ModDB logo.`) - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [createModImageStorePort] Error saving a ModDB logo: ${err}`) + logMessage("error", `${LOG_PREFIX} [createModImageStorePort] Error saving a ModDB logo.`) + logMessage("debug", `${LOG_PREFIX} [createModImageStorePort] Error saving a ModDB logo: ${err}`) return undefined } } @@ -319,7 +321,7 @@ export async function pruneModIconCache(maxBytes: number = MOD_ICON_CACHE_MAX_BY async function doPruneModIconCache(maxBytes: number): Promise { await sweepCacheFolder({ folder: modImagesFolder(), - origin: "[back] [mods] [ipc/adapters/modScan.ts] [pruneModIconCache]", + origin: `${LOG_PREFIX} [pruneModIconCache]`, subject: "the icon cache", accepts: (name) => { // Throws its own reason rather than returning false, and the sweep logs it. @@ -363,7 +365,7 @@ export function createModsDirectoryReaderPort(): DirectoryReader { try { assertSafeFileName(entry) if ((await fse.lstat(join(path, entry))).isSymbolicLink()) { - logMessage("debug", `[back] [mods] [ipc/adapters/modScan.ts] [listFileNames] Skipping a symbolic link inside the Mods folder.`) + logMessage("debug", `${LOG_PREFIX} [listFileNames] Skipping a symbolic link inside the Mods folder.`) continue } names.push(entry) diff --git a/src/ipc/handlers/accountHandlers.ts b/src/ipc/handlers/accountHandlers.ts index 103d3201..b3ba330d 100644 --- a/src/ipc/handlers/accountHandlers.ts +++ b/src/ipc/handlers/accountHandlers.ts @@ -13,6 +13,8 @@ import { AccountStoreUnreadableError, removeAccountSecrets, saveAccountSecrets } import type { AccountSaveOutcome } from "@src/ipc/accountStore" import { getErrorMessage, logMessage } from "@src/utils/logManager" +const LOG_PREFIX = "[back] [ipc] [ipc/handlers/accountHandlers.ts]" + const LOGIN_URL = new URL("https://auth3.vintagestory.at/v2/gamelogin") /** @@ -71,19 +73,18 @@ async function settle(verdict: LoginVerdict): Promise { // socket: `ENOSPC` from a keyring write and `ENOSPC` from a socket look identical // by then, and this call site is the only one that knows which it was. if (!(error instanceof AccountStoreUnreadableError)) throw new AccountStorageFailure(error) - logMessage("error", "[back] [ipc] [accountHandlers.ts] [LOGIN] The account store is unreadable and could not be copied aside, so it was left untouched. The session was not saved.") - logMessage("debug", `[back] [ipc] [accountHandlers.ts] [LOGIN] ${getErrorMessage(error)}`) + logMessage("error", `${LOG_PREFIX} [LOGIN] The account store is unreadable and could not be copied aside, so it was left untouched. The session was not saved.`) + logMessage("debug", `${LOG_PREFIX} [LOGIN] ${getErrorMessage(error)}`) return sessionStoreUnreadableResult() } if (outcome === "saved-after-rebuild") - logMessage("warn", "[back] [ipc] [accountHandlers.ts] [LOGIN] The account store could not be read; it was copied aside and rebuilt around this login. Other saved accounts must log in again.") + logMessage("warn", `${LOG_PREFIX} [LOGIN] The account store could not be read; it was copied aside and rebuilt around this login. Other saved accounts must log in again.`) // No keyring on this machine, so nothing was written and the session lives in this process // only (#481). The login itself stands: the service accepted these credentials, and refusing // to report that left the player unable to play at all over a missing wallet. - if (outcome === "saved-in-memory") - logMessage("warn", "[back] [ipc] [accountHandlers.ts] [LOGIN] No system keyring is available, so this session is held in memory for this run and was not written to disk.") + if (outcome === "saved-in-memory") logMessage("warn", `${LOG_PREFIX} [LOGIN] No system keyring is available, so this session is held in memory for this run and was not written to disk.`) return { status: "success", @@ -100,11 +101,11 @@ async function settle(verdict: LoginVerdict): Promise { // The toast collapses every refusal into "invalid email or password"; the // service's own reason string is the only way to tell a real credential // mismatch from anything else it may refuse for. Server enum, never user data. - logMessage("debug", `[back] [ipc] [accountHandlers.ts] [LOGIN] Service refused the login, reason: "${verdict.serverReason}".`) + logMessage("debug", `${LOG_PREFIX} [LOGIN] Service refused the login, reason: "${verdict.serverReason}".`) return badCredentialsResult() case "unreadable-response": { const outcome = unexpectedResponseOutcome(verdict) - logMessage("error", `[back] [ipc] [accountHandlers.ts] [LOGIN] ${outcome.logMessage}`) + logMessage("error", `${LOG_PREFIX} [LOGIN] ${outcome.logMessage}`) return outcome.result } } @@ -140,8 +141,8 @@ ipcMain.handle(IPC_CHANNELS.ACCOUNT_MANAGER.LOGIN, async (event, email: unknown, // instead, which still tells a network failure from an HTTP status from a // keyring that is not there from a disk with no room left on it. const reason = loginFailureReason(error) - logMessage("error", "[back] [ipc] [accountHandlers.ts] [LOGIN] Login failed.") - logMessage("debug", `[back] [ipc] [accountHandlers.ts] [LOGIN] Login failure reason: ${reason}.`) + logMessage("error", `${LOG_PREFIX} [LOGIN] Login failed.`) + logMessage("debug", `${LOG_PREFIX} [LOGIN] Login failure reason: ${reason}.`) // A reason `loginFailureFamily` can place resolves instead of throwing, so the // renderer can say which of DNS/refused/timeout, a certificate, an HTTP error the diff --git a/src/ipc/handlers/gameHandlers.ts b/src/ipc/handlers/gameHandlers.ts index 25bac33b..e89fe281 100644 --- a/src/ipc/handlers/gameHandlers.ts +++ b/src/ipc/handlers/gameHandlers.ts @@ -47,6 +47,8 @@ import type { ProcessProbeRequest } from "@domain/ports" +const LOG_PREFIX = "[back] [ipc] [ipc/handlers/gameHandlers.ts]" + async function assertExecutable(pathValue: string): Promise { const stats = await fse.lstat(pathValue) if (!stats.isFile() || stats.isSymbolicLink()) throw new Error("Invalid game executable") @@ -158,14 +160,11 @@ async function adoptRefreshedSession(accountId: string, secrets: AccountSecrets) try { const outcome = await saveAccountSecrets(accountId, secrets) if (outcome === "saved-after-rebuild") - logMessage( - "warn", - `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] The account store could not be read; it was copied aside and rebuilt around this adoption. Other saved accounts must log in again.` - ) - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] The game had already refreshed this account's session. Adopted it instead of overwriting it.`) + logMessage("warn", `${LOG_PREFIX} [EXECUTE_GAME] The account store could not be read; it was copied aside and rebuilt around this adoption. Other saved accounts must log in again.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] The game had already refreshed this account's session. Adopted it instead of overwriting it.`) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Could not store the session the game refreshed. Launching anyway.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Could not store the session the game refreshed. Launching anyway.`) + logMessage("debug", `${LOG_PREFIX} [EXECUTE_GAME] ${getErrorMessage(err)}`) } } @@ -208,8 +207,8 @@ function realGameProcess(): GameProcess { // UNKNOWN, so a truncated or quarantined Vintagestory.exe lands here rather // than on the event below; without this the whole handler rejects and the // launch stops being a reason the player is told. - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error running Vintage Story.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error running Vintage Story.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] ${getErrorMessage(err)}`) settle({ started: false, error: getErrorMessage(err) }) return } @@ -226,15 +225,15 @@ function realGameProcess(): GameProcess { externalApp.stderr.on("data", (data) => { const text = data.toString() stderrScan = appendStderrScan(stderrScan, text) - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Vintage Story threw an error! Check verbose logs for more info.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${text.slice(0, 2_048)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Vintage Story threw an error! Check verbose logs for more info.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] ${text.slice(0, 2_048)}`) }) externalApp.on("close", (code) => settle({ started: true, exitCode: code, missingRuntime: hasMissingDotnetSentinel(stderrScan) })) externalApp.on("error", (error) => { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error running Vintage Story.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${error}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error running Vintage Story.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] ${error}`) settle({ started: false, error: getErrorMessage(error) }) }) }) @@ -272,28 +271,28 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un const config = await getConfig() const account = config.accounts.find((candidate) => candidate.playerUid === config.activeAccountId) ?? null const accountSecrets = account ? await getAccountSecrets(account.playerUid) : null - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Trying to run Vintage Story ${safeVersion.version}.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Trying to run Vintage Story ${safeVersion.version}.`) let connectTarget: string | undefined if (serverId !== undefined) { const safeServerId = assertString(serverId, "server bookmark id", 128) const bookmark = safeInstallation.id ? resolveServerBookmark(config.installations, safeInstallation.id, safeServerId) : null if (!bookmark) { - logMessage("warn", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused a server that is not one this installation has saved.`) + logMessage("warn", `${LOG_PREFIX} [EXECUTE_GAME] Refused a server that is not one this installation has saved.`) return invalidRequestResult() } connectTarget = joinTargetUrl(bookmark) // One fixed line, and nothing of the server in it. A server address is somebody's machine, // often somebody's home, and redactSensitiveText strips paths rather than host names. - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Joining a saved server.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Joining a saved server.`) } let processEnv: Record try { processEnv = parseSafeEnvironment(safeInstallation.envVars) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused invalid environment variables for this installation.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Refused invalid environment variables for this installation.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] ${getErrorMessage(err)}`) return invalidRequestResult() } @@ -301,7 +300,7 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un if (os.platform() === "linux" && safeInstallation.launchWrapper) { const resolvedWrapper = await resolveLaunchWrapper(safeInstallation.launchWrapper) if (!resolvedWrapper) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused an unavailable or non-executable launch wrapper.`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Refused an unavailable or non-executable launch wrapper.`) return invalidExecutableResult() } launchWrapper = resolvedWrapper @@ -311,8 +310,8 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un try { fileNames = await fse.readdir(safeVersion.path) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error detecting how to run Vintage Story.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error detecting how to run Vintage Story: ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error detecting how to run Vintage Story.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] Error detecting how to run Vintage Story: ${getErrorMessage(err)}`) return noExecutableResult() } @@ -331,7 +330,7 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un ) if (!planned.ok) { - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Couldn't find a way to run Vintage Story on ${os.platform()} (${planned.reason}), aborting...`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Couldn't find a way to run Vintage Story on ${os.platform()} (${planned.reason}), aborting...`) return launchPlanFailureResult(planned.reason) } @@ -340,20 +339,20 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un try { await assertExecutable(plan.executablePath) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused to run an invalid game executable.`) - logMessage("verbose", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Refused to run an invalid game executable.`) + logMessage("verbose", `${LOG_PREFIX} [EXECUTE_GAME] ${getErrorMessage(err)}`) return invalidExecutableResult() } if (account && accountSecrets) { - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Logged in. Setting session keys.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Logged in. Setting session keys.`) let settingsPath: string try { settingsPath = await assertManagedPath(join(safeInstallation.path, CLIENT_SETTINGS_FILE_NAME), "client settings", { allowMissing: true }) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error setting login session keys.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused the client settings path: ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error setting login session keys.`) + logMessage("debug", `${LOG_PREFIX} [EXECUTE_GAME] Refused the client settings path: ${getErrorMessage(err)}`) return sessionWriteFailedResult() } @@ -380,14 +379,10 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un // Never logs what the file held: the path this installation was copied out of is untrusted // input and stays out of the log. The path we put there is our own and may be named. const modPathsNotice = "modPaths" in written ? written.modPaths : undefined - if (modPathsNotice === "repointed") logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Repointed this installation's mod folder list at [PATH].`) + if (modPathsNotice === "repointed") logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Repointed this installation's mod folder list at [PATH].`) else if (modPathsNotice === "repoint-write-failed") - logMessage( - "warn", - `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] This installation's mod folder list needed repointing but the settings file could not be written; the game's own session was kept.` - ) - else if (modPathsNotice === "left-as-found") - logMessage("warn", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] This installation's mod folder list is not the game's default one and was left as found.`) + logMessage("warn", `${LOG_PREFIX} [EXECUTE_GAME] This installation's mod folder list needed repointing but the settings file could not be written; the game's own session was kept.`) + else if (modPathsNotice === "left-as-found") logMessage("warn", `${LOG_PREFIX} [EXECUTE_GAME] This installation's mod folder list is not the game's default one and was left as found.`) switch (written.outcome) { case "written": @@ -397,8 +392,8 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un break case "unreadable-settings": case "write-failed": - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error setting login session keys.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error setting login session keys: ${written.outcome}.`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error setting login session keys.`) + logMessage("debug", `${LOG_PREFIX} [EXECUTE_GAME] Error setting login session keys: ${written.outcome}.`) return sessionWriteFailedResult() } } else if (account && !accountSecrets) { @@ -414,8 +409,8 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un try { settingsPath = await assertManagedPath(join(safeInstallation.path, CLIENT_SETTINGS_FILE_NAME), "client settings", { allowMissing: true }) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Error checking for another player's session keys.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Refused the client settings path: ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Error checking for another player's session keys.`) + logMessage("debug", `${LOG_PREFIX} [EXECUTE_GAME] Refused the client settings path: ${getErrorMessage(err)}`) return sessionWriteFailedResult() } @@ -423,19 +418,19 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un switch (cleared.outcome) { case "cleared": - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Cleared another player's session before launching without one of our own.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Cleared another player's session before launching without one of our own.`) break case "not-foreign": break case "unreadable-settings": case "write-failed": - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Could not confirm this installation is not still signed in as another player.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] ${cleared.outcome}.`) + logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Could not confirm this installation is not still signed in as another player.`) + logMessage("debug", `${LOG_PREFIX} [EXECUTE_GAME] ${cleared.outcome}.`) return sessionWriteFailedResult() } } - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Running Vintagestory with a validated executable${launchWrapper ? ` through ${launchWrapper}` : ""}.`) + logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Running Vintagestory with a validated executable${launchWrapper ? ` through ${launchWrapper}` : ""}.`) // The id comes from the config the launcher wrote, never from the renderer's own object, so the // file name a session lands under cannot be chosen by whatever sent the launch. @@ -460,16 +455,12 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.EXECUTE_GAME, async (event, version: un if (session && installationId) { const stored = await recordPlaySession(installationId, session) const shape = session.partial ? "partial" : "complete" - if (stored) logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Recorded a ${shape} play session of ${session.samples.length} readings.`) - else logMessage("warn", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Could not record this play session; the sessions file was left as it was.`) + if (stored) logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Recorded a ${shape} play session of ${session.samples.length} readings.`) + else logMessage("warn", `${LOG_PREFIX} [EXECUTE_GAME] Could not record this play session; the sessions file was left as it was.`) } - if (!outcome.started) - logMessage( - "error", - `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Failed to run Vintage Story${launchWrapper ? ` through ${launchWrapper}` : ""}: ${outcome.error ?? "unknown error"}.` - ) - else logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [EXECUTE_GAME] Vintage Story closed: ${outcome.exitCode}`) + if (!outcome.started) logMessage("error", `${LOG_PREFIX} [EXECUTE_GAME] Failed to run Vintage Story${launchWrapper ? ` through ${launchWrapper}` : ""}: ${outcome.error ?? "unknown error"}.`) + else logMessage("info", `${LOG_PREFIX} [EXECUTE_GAME] Vintage Story closed: ${outcome.exitCode}`) return gameProcessOutcomeToResult(outcome) }) @@ -488,8 +479,8 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.GET_PLAY_SESSIONS, async (event, instal assertTrustedIpcSender(event) const read = await readPlaySessions(installationId) - if (!read.ok) logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_PLAY_SESSIONS] Refused: ${read.reason}.`) - else logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_PLAY_SESSIONS] Read ${read.sessions.length} play sessions.`) + if (!read.ok) logMessage("info", `${LOG_PREFIX} [GET_PLAY_SESSIONS] Refused: ${read.reason}.`) + else logMessage("info", `${LOG_PREFIX} [GET_PLAY_SESSIONS] Read ${read.sessions.length} play sessions.`) return read }) @@ -497,7 +488,7 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.FORGET_PLAY_SESSIONS, async (event, ins assertTrustedIpcSender(event) const ok = await forgetPlaySessions(installationId) - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [FORGET_PLAY_SESSIONS] Cleared the play sessions: ${ok}.`) + logMessage("info", `${LOG_PREFIX} [FORGET_PLAY_SESSIONS] Cleared the play sessions: ${ok}.`) return { ok } }) @@ -530,13 +521,13 @@ function realProcessProbe(): ProcessProbe { try { await assertExecutable(request.command === "mono" ? (request.args[0] ?? "") : request.command) } catch (err) { - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Refused to probe an invalid executable.`) - logMessage("verbose", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Refused to probe an invalid executable.`) + logMessage("verbose", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) return { ok: false, stdout: "", error: getErrorMessage(err) } } return new Promise((resolve) => { - logMessage("info", "[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Checking Vintage Story with a validated executable.") + logMessage("info", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Checking Vintage Story with a validated executable.`) let stdout = "" let settled = false @@ -558,14 +549,14 @@ function realProcessProbe(): ProcessProbe { } catch (err) { // Same throw-instead-of-emit split as EXECUTE_GAME's spawn above, settled // the way the "error" event below settles it. - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Error looking for the Vintage Story version.`) - logMessage("verbose", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Error looking for the Vintage Story version.`) + logMessage("verbose", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) settle({ ok: false, stdout, error: getErrorMessage(err) }) return } timer = setTimeout(() => { - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Timed out waiting for Vintage Story to report its version.`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Timed out waiting for Vintage Story to report its version.`) externalApp.kill() settle({ ok: false, stdout, error: "Timed out waiting for a response." }) }, LOOK_FOR_A_GAME_VERSION_PROBE_TIMEOUT_MS) @@ -575,18 +566,18 @@ function realProcessProbe(): ProcessProbe { }) externalApp.stderr.on("data", (data) => { - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Vintage Story threw an error! Check verbose logs for more info.`) - logMessage("verbose", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] ${data}`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Vintage Story threw an error! Check verbose logs for more info.`) + logMessage("verbose", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] ${data}`) }) externalApp.on("close", (code) => { - logMessage("info", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Vintage Story closed: ${code}`) + logMessage("info", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Vintage Story closed: ${code}`) settle({ ok: true, stdout }) }) externalApp.on("error", (error) => { - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Error looking for the Vintage Story version.`) - logMessage("verbose", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] ${error}`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Error looking for the Vintage Story version.`) + logMessage("verbose", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] ${error}`) settle({ ok: false, stdout, error: getErrorMessage(error) }) }) }) @@ -625,25 +616,25 @@ function tasklistProbe(): ProcessProbe { ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.LOOK_FOR_A_GAME_VERSION, async (event, path: unknown): Promise => { assertTrustedIpcSender(event) const safePath = await assertManagedPath(path, "game version path", { allowMissing: true }) - logMessage("info", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Looking for the game at [PATH]`) + logMessage("info", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Looking for the game at [PATH]`) let fileNames: string[] try { fileNames = await fse.readdir(safePath) } catch (err) { - logMessage("error", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Error reading the folder.`) - logMessage("verbose", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Error reading the folder.`) + logMessage("verbose", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] ${getErrorMessage(err)}`) return NOT_FOUND } const result = await detectInstalledGameVersion({ paths, processProbe: realProcessProbe() }, { platform: os.platform(), folder: safePath, fileNames }) if (!result.ok) { - logMessage("info", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] No version found: ${result.reason}.`) + logMessage("info", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] No version found: ${result.reason}.`) return NOT_FOUND } - logMessage("info", `[back] [ipc] [gameHandlers.ts] [LOOK_FOR_A_GAME_VERSION] Found Vintage Story ${result.version}.`) + logMessage("info", `${LOG_PREFIX} [LOOK_FOR_A_GAME_VERSION] Found Vintage Story ${result.version}.`) const variant = toWireBuildVariant(result.variant) return variant ? { exists: true, installedGameVersion: result.version, variant } : { exists: true, installedGameVersion: result.version } }) @@ -737,7 +728,7 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.GET_GAME_LOG_REPORT, async (event, inst try { installation = await assertConfiguredInstallationPath(installationPath) } catch { - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_GAME_LOG_REPORT] Refused: not a configured Installation.`) + logMessage("info", `${LOG_PREFIX} [GET_GAME_LOG_REPORT] Refused: not a configured Installation.`) return { ok: false, reason: "refused" } } @@ -751,13 +742,13 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.GET_GAME_LOG_REPORT, async (event, inst mainLog = await readBoundedText(mainLogPath, WHOLE_LOG_BYTES, LOG_HEAD_BYTES, LOG_TAIL_BYTES) crashFile = await readBoundedText(crashPath, CRASH_FILE_BYTES, CRASH_FILE_BYTES, 0) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_GAME_LOG_REPORT] Could not read this Installation's logs.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_GAME_LOG_REPORT] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [GET_GAME_LOG_REPORT] Could not read this Installation's logs.`) + logMessage("debug", `${LOG_PREFIX} [GET_GAME_LOG_REPORT] ${getErrorMessage(err)}`) return { ok: false, reason: "unreadable" } } if (!mainLog && !crashFile) { - logMessage("info", `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_GAME_LOG_REPORT] No session logs to read yet.`) + logMessage("info", `${LOG_PREFIX} [GET_GAME_LOG_REPORT] No session logs to read yet.`) return { ok: false, reason: "no-logs" } } @@ -772,7 +763,7 @@ ipcMain.handle(IPC_CHANNELS.GAME_MANAGER.GET_GAME_LOG_REPORT, async (event, inst logMessage( "info", - `[back] [ipc] [ipc/handlers/gameHandlers.ts] [GET_GAME_LOG_REPORT] Built a session report: ${report.mods.length} groups, ${report.unattributed.length} other lines, crash ${report.crash ? 1 : 0}, truncated ${report.source.truncated ? 1 : 0}.` + `${LOG_PREFIX} [GET_GAME_LOG_REPORT] Built a session report: ${report.mods.length} groups, ${report.unattributed.length} other lines, crash ${report.crash ? 1 : 0}, truncated ${report.source.truncated ? 1 : 0}.` ) return { ok: true, report } }) diff --git a/src/ipc/handlers/modsHandlers.ts b/src/ipc/handlers/modsHandlers.ts index d7d7a628..fdb866f8 100644 --- a/src/ipc/handlers/modsHandlers.ts +++ b/src/ipc/handlers/modsHandlers.ts @@ -17,6 +17,8 @@ import { MAX_MODPACK_MOD_NAME_LENGTH } from "@domain/mods/importModpack" import { emptyModProfilesDocument, MAX_MOD_PROFILES_FILE_BYTES, MOD_PROFILES_FILE_NAME, normalizeModProfilesDocument } from "@domain/mods/profiles" import { normalizeServerBookmarks } from "@domain/servers/bookmarks" +const LOG_PREFIX = "[back] [mods] [ipc/handlers/modsHandlers.ts]" + const MAX_MODPACK_ENTRIES = 2_000 // Narrows DOWNLOAD_URL_RULES, which already lists this host for archive downloads, to the one host @@ -50,7 +52,7 @@ async function cacheModImage(urlValue: unknown): Promise { if (!isPngBytes(bytes) && !isJpegBytes(bytes)) throw new TypeError("Downloaded ModDB image is not a PNG or JPEG") return (await images.store(key, bytes)) ?? staleName } catch (err) { - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [CACHE_MOD_IMAGE] Could not cache ModDB image: ${getErrorMessage(err)}`) + logMessage("debug", `${LOG_PREFIX} [CACHE_MOD_IMAGE] Could not cache ModDB image: ${getErrorMessage(err)}`) return staleName } } @@ -100,31 +102,30 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.GET_INSTALLED_MODS, async (event, path: // policy as before. path = await assertManagedPath(path, "mods path", { allowMissing: true, allowSymlinks: true }) try { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] Looking for mods at [PATH].`) + logMessage("info", `${LOG_PREFIX} [GET_INSTALLED_MODS] Looking for mods at [PATH].`) if (!(await fse.pathExists(path))) { // pathExists follows a link, so a linked Mods folder whose disk is not mounted lands here too. // That folder is not empty, it is out of reach, and a caller that records the folder must know. if (await fse.lstat(path).catch(() => false)) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] That path is a link to nothing. Its mods can't be read.`) + logMessage("info", `${LOG_PREFIX} [GET_INSTALLED_MODS] That path is a link to nothing. Its mods can't be read.`) return { mods: [], errors: [], unreadable: true } } - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] That path does not exists. 0 mods detected.`) + logMessage("info", `${LOG_PREFIX} [GET_INSTALLED_MODS] That path does not exists. 0 mods detected.`) return { mods: [], errors: [] } } const scan = await scanInstalledMods(createScanInstalledModsPorts(), { folder: path }) - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] Found ${scan.mods.length} mods and ${scan.errors.length} mods with errors.`) - if (scan.errors.length > 0) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] Found ${scan.errors.length} mods with errors: ${scan.errors.map((archive) => archive.problem).join(", ")}`) + logMessage("info", `${LOG_PREFIX} [GET_INSTALLED_MODS] Found ${scan.mods.length} mods and ${scan.errors.length} mods with errors.`) + if (scan.errors.length > 0) logMessage("debug", `${LOG_PREFIX} [GET_INSTALLED_MODS] Found ${scan.errors.length} mods with errors: ${scan.errors.map((archive) => archive.problem).join(", ")}`) void pruneModIconCache() return { mods: scan.mods.map(toWireMod), errors: scan.errors.map((archive) => ({ zipname: archive.zipname, path: archive.path })) } } catch (err) { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] Error getting installed mods.`) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_INSTALLED_MODS] Error getting installed mods: ${err}`) + logMessage("error", `${LOG_PREFIX} [GET_INSTALLED_MODS] Error getting installed mods.`) + logMessage("debug", `${LOG_PREFIX} [GET_INSTALLED_MODS] Error getting installed mods: ${err}`) return { mods: [], errors: [], unreadable: true } } }) @@ -148,14 +149,14 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.GET_SERVER_MODS, async (event, installa const folder = await assertManagedPath(join(installation, MODS_BY_SERVER_FOLDER_NAME), "server mods path", { allowMissing: true, allowSymlinks: true }) if (!(await fse.pathExists(folder))) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_SERVER_MODS] This installation has no server mods folder.`) + logMessage("info", `${LOG_PREFIX} [GET_SERVER_MODS] This installation has no server mods folder.`) return { groups: [] } } const scan = await scanServerMods(createScanInstalledModsPorts(), { folder }) const scanned = scan.groups.reduce((total, group) => total + group.mods.length, 0) - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_SERVER_MODS] Found ${scan.groups.length} server folders and ${scanned} mods.`) + logMessage("info", `${LOG_PREFIX} [GET_SERVER_MODS] Found ${scan.groups.length} server folders and ${scanned} mods.`) const groups = scan.groups.map((group) => { const wire = { server: group.server, path: group.path, mods: group.mods.map(toWireMod), unreadable: group.unreadable, ...(group.truncated ? { truncated: true as const } : {}) } @@ -163,8 +164,8 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.GET_SERVER_MODS, async (event, installa }) return scan.truncated ? { groups, truncated: true } : { groups } } catch (err) { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_SERVER_MODS] Error getting server mods.`) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_SERVER_MODS] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [GET_SERVER_MODS] Error getting server mods.`) + logMessage("debug", `${LOG_PREFIX} [GET_SERVER_MODS] ${getErrorMessage(err)}`) return { groups: [], unreadable: true } } }) @@ -198,7 +199,7 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.SET_MOD_ENABLED, async (event, pathValu const rename = renameModArchiveTo(assertSafeFileName(basename(safePath), "mod archive name"), wanted) if (!rename.ok) { - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SET_MOD_ENABLED] Nothing to rename: ${rename.reason}.`) + logMessage("debug", `${LOG_PREFIX} [SET_MOD_ENABLED] Nothing to rename: ${rename.reason}.`) return rename.reason === "already-in-state" ? { ok: false, reason: "already-in-state" } : { ok: false, reason: "refused" } } @@ -208,19 +209,19 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.SET_MOD_ENABLED, async (event, pathValu await assertManagedPath(target, "mod archive path", { allowMissing: true, allowSymlinks: true }) if (await fse.pathExists(target)) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SET_MOD_ENABLED] The other name is already taken, leaving both archives alone.`) + logMessage("info", `${LOG_PREFIX} [SET_MOD_ENABLED] The other name is already taken, leaving both archives alone.`) return { ok: false, reason: "name-taken" } } - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SET_MOD_ENABLED] Renaming a mod archive to turn it ${wanted ? "on" : "off"}.`) + logMessage("info", `${LOG_PREFIX} [SET_MOD_ENABLED] Renaming a mod archive to turn it ${wanted ? "on" : "off"}.`) // move rather than rename: it refuses an existing destination on every platform, so the check // above losing a race cannot end with one archive written over the other. await fse.move(safePath, target) return { ok: true, path: target } } catch (err) { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SET_MOD_ENABLED] Error renaming a mod archive.`) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SET_MOD_ENABLED] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [SET_MOD_ENABLED] Error renaming a mod archive.`) + logMessage("debug", `${LOG_PREFIX} [SET_MOD_ENABLED] ${getErrorMessage(err)}`) return { ok: false, reason: "refused" } } }) @@ -229,7 +230,7 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.EXPORT_MODPACK, async (event, manifest: assertTrustedIpcSender(event) try { const safeManifest = parseModpackManifest(manifest) - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [EXPORT_MODPACK] Exporting a modpack with ${safeManifest.mods.length} mods and ${safeManifest.servers?.length ?? 0} servers.`) + logMessage("info", `${LOG_PREFIX} [EXPORT_MODPACK] Exporting a modpack with ${safeManifest.mods.length} mods and ${safeManifest.servers?.length ?? 0} servers.`) const result = await dialog.showSaveDialog({ title: "Export Modpack", @@ -238,7 +239,7 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.EXPORT_MODPACK, async (event, manifest: }) if (result.canceled || !result.filePath) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [EXPORT_MODPACK] Export cancelled.`) + logMessage("info", `${LOG_PREFIX} [EXPORT_MODPACK] Export cancelled.`) return { success: false } } @@ -246,11 +247,11 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.EXPORT_MODPACK, async (event, manifest: const safeOutputPath = await assertManagedPath(result.filePath, "modpack path", { allowMissing: true }) await writeJsonAtomic(safeOutputPath, safeManifest, { spaces: 2 }) - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [EXPORT_MODPACK] Modpack exported to [PATH].`) + logMessage("info", `${LOG_PREFIX} [EXPORT_MODPACK] Modpack exported to [PATH].`) return { success: true, path: result.filePath } } catch (err) { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [EXPORT_MODPACK] Error exporting modpack.`) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [EXPORT_MODPACK] Error exporting modpack: ${err}`) + logMessage("error", `${LOG_PREFIX} [EXPORT_MODPACK] Error exporting modpack.`) + logMessage("debug", `${LOG_PREFIX} [EXPORT_MODPACK] Error exporting modpack: ${err}`) return { success: false } } }) @@ -258,7 +259,7 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.EXPORT_MODPACK, async (event, manifest: ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.IMPORT_MODPACK, async (event): Promise<{ success: boolean; manifest?: ModpackManifestType; error?: string }> => { assertTrustedIpcSender(event) try { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] Opening file dialog for modpack import.`) + logMessage("info", `${LOG_PREFIX} [IMPORT_MODPACK] Opening file dialog for modpack import.`) const result = await dialog.showOpenDialog({ title: "Import Modpack", @@ -267,13 +268,13 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.IMPORT_MODPACK, async (event): Promise< }) if (result.canceled || result.filePaths.length === 0) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] Import cancelled.`) + logMessage("info", `${LOG_PREFIX} [IMPORT_MODPACK] Import cancelled.`) return { success: false } } const filePath = result.filePaths[0] if (!filePath) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] Import cancelled.`) + logMessage("info", `${LOG_PREFIX} [IMPORT_MODPACK] Import cancelled.`) return { success: false } } registerUserSelectedPaths([filePath]) @@ -284,11 +285,11 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.IMPORT_MODPACK, async (event): Promise< const manifest = parseModpackManifest(parsedManifest) - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] A modpack loaded with ${manifest.mods.length} mods and ${manifest.servers?.length ?? 0} servers.`) + logMessage("info", `${LOG_PREFIX} [IMPORT_MODPACK] A modpack loaded with ${manifest.mods.length} mods and ${manifest.servers?.length ?? 0} servers.`) return { success: true, manifest } } catch (err) { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] Error importing modpack.`) - logMessage("debug", `[back] [mods] [ipc/handlers/modsHandlers.ts] [IMPORT_MODPACK] Error importing modpack: ${err}`) + logMessage("error", `${LOG_PREFIX} [IMPORT_MODPACK] Error importing modpack.`) + logMessage("debug", `${LOG_PREFIX} [IMPORT_MODPACK] Error importing modpack: ${err}`) return { success: false, error: "Error reading modpack file." } } }) @@ -345,11 +346,11 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.GET_MOD_PROFILES, async (event, install const location = await locateModProfiles(installationPath) const read = location.ok ? await readModProfilesFile(location.path) : location if (!read.ok) { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_MOD_PROFILES] Refused: ${read.reason}.`) + logMessage("info", `${LOG_PREFIX} [GET_MOD_PROFILES] Refused: ${read.reason}.`) return read } - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [GET_MOD_PROFILES] Read ${read.document.profiles.length} profiles.`) + logMessage("info", `${LOG_PREFIX} [GET_MOD_PROFILES] Read ${read.document.profiles.length} profiles.`) return read }) @@ -357,7 +358,7 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.SAVE_MOD_PROFILES, async (event, instal assertTrustedIpcSender(event) function refuse(reason: "newer-format" | "unreadable" | "invalid" | "refused"): ModProfilesSaveResult { - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SAVE_MOD_PROFILES] Refused: ${reason}.`) + logMessage("info", `${LOG_PREFIX} [SAVE_MOD_PROFILES] Refused: ${reason}.`) return { ok: false, reason } } @@ -381,10 +382,10 @@ ipcMain.handle(IPC_CHANNELS.MODS_MANAGER.SAVE_MOD_PROFILES, async (event, instal try { await writeJsonAtomic(location.path, cleaned.document, { spaces: 2 }) } catch { - logMessage("error", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SAVE_MOD_PROFILES] Could not write the profiles file.`) + logMessage("error", `${LOG_PREFIX} [SAVE_MOD_PROFILES] Could not write the profiles file.`) return { ok: false, reason: "refused" } } - logMessage("info", `[back] [mods] [ipc/handlers/modsHandlers.ts] [SAVE_MOD_PROFILES] Saved ${cleaned.document.profiles.length} profiles.`) + logMessage("info", `${LOG_PREFIX} [SAVE_MOD_PROFILES] Saved ${cleaned.document.profiles.length} profiles.`) return { ok: true } }) diff --git a/src/ipc/handlers/netHandlers.ts b/src/ipc/handlers/netHandlers.ts index cc49e79b..f2bd75cf 100644 --- a/src/ipc/handlers/netHandlers.ts +++ b/src/ipc/handlers/netHandlers.ts @@ -21,6 +21,8 @@ import { import { getConfig, saveConfig } from "@src/config/configManager" import { getErrorMessage, logMessage } from "@src/utils/logManager" +const LOG_PREFIX = "[back] [ipc] [ipc/handlers/netHandlers.ts]" + const MOD_CATALOG_HOSTNAME = "mods.vintagestory.at" const MOD_CATALOG_PATHNAME = "/api/mods" @@ -76,7 +78,7 @@ export async function queryUrl(url: unknown): Promise { const text = await queryConcurrency.run(() => requestBoundedText(safeUrl, { maxBytes })) if (isCatalog) { await writeCatalogCache(safeUrl, text).catch((cacheErr: unknown) => { - logMessage("debug", `[back] [ipc] [ipc/handlers/netHandlers.ts] [QUERY_URL] Failed to write mod catalog cache: ${getErrorMessage(cacheErr)}`) + logMessage("debug", `${LOG_PREFIX} [QUERY_URL] Failed to write mod catalog cache: ${getErrorMessage(cacheErr)}`) }) } return text @@ -84,8 +86,8 @@ export async function queryUrl(url: unknown): Promise { if (isCatalog) { const cached = await readCatalogCache(safeUrl) if (cached !== null) { - logMessage("warn", "[back] [ipc] [ipc/handlers/netHandlers.ts] [QUERY_URL] Mod catalog fetch failed, serving last good cached response.") - logMessage("debug", `[back] [ipc] [ipc/handlers/netHandlers.ts] [QUERY_URL] ${getErrorMessage(err)}`) + logMessage("warn", `${LOG_PREFIX} [QUERY_URL] Mod catalog fetch failed, serving last good cached response.`) + logMessage("debug", `${LOG_PREFIX} [QUERY_URL] ${getErrorMessage(err)}`) return cached } } @@ -125,7 +127,7 @@ export async function fetchModDbListingArchive(listingVersion: string): Promise< if (!detail.ok) return "unreachable" fileId = releaseFileIdForVersion(detail.payload, listingVersion) } catch (err) { - logMessage("debug", `[back] [ipc] [ipc/handlers/netHandlers.ts] [COUNT_MODDB_DOWNLOAD] ${getErrorMessage(err)}`) + logMessage("debug", `${LOG_PREFIX} [COUNT_MODDB_DOWNLOAD] ${getErrorMessage(err)}`) return "unreachable" } @@ -143,14 +145,11 @@ export async function fetchModDbListingArchive(listingVersion: string): Promise< // ever rewords it the request still behaves exactly the same and only this line falls back // to the branch below. if (message.toLowerCase().includes("redirect")) { - logMessage( - "debug", - "[back] [ipc] [ipc/handlers/netHandlers.ts] [COUNT_MODDB_DOWNLOAD] The listing download endpoint answered with its redirect, which is the counted outcome. Not followed on purpose." - ) + logMessage("debug", `${LOG_PREFIX} [COUNT_MODDB_DOWNLOAD] The listing download endpoint answered with its redirect, which is the counted outcome. Not followed on purpose.`) return "counted" } - logMessage("debug", `[back] [ipc] [ipc/handlers/netHandlers.ts] [COUNT_MODDB_DOWNLOAD] ${message}`) + logMessage("debug", `${LOG_PREFIX} [COUNT_MODDB_DOWNLOAD] ${message}`) return "unreachable" } } @@ -226,7 +225,7 @@ ipcMain.handle(IPC_CHANNELS.NET_MANAGER.COUNT_MODDB_DOWNLOAD, async (event, cons // Fixed text and the outcome's own token only, never a URL or a response body: the provenance // rule tests/log-provenance.test.ts holds every network log in this file to. - logMessage("info", `[back] [ipc] [ipc/handlers/netHandlers.ts] [COUNT_MODDB_DOWNLOAD] ModDB listing count for this version: ${result.reason}.`) + logMessage("info", `${LOG_PREFIX} [COUNT_MODDB_DOWNLOAD] ModDB listing count for this version: ${result.reason}.`) return result }) @@ -237,8 +236,8 @@ ipcMain.handle(IPC_CHANNELS.NET_MANAGER.QUERY_URL, async (event, url: unknown): try { return await queryUrl(url) } catch (err) { - logMessage("error", "[back] [ipc] [ipc/handlers/netHandlers.ts] [QUERY_URL] Network request failed.") - logMessage("debug", `[back] [ipc] [ipc/handlers/netHandlers.ts] [QUERY_URL] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [QUERY_URL] Network request failed.`) + logMessage("debug", `${LOG_PREFIX} [QUERY_URL] ${getErrorMessage(err)}`) throw err } }) @@ -371,7 +370,7 @@ ipcMain.handle(IPC_CHANNELS.NET_MANAGER.FETCH_RELEASE_NOTES, async (event): Prom // Fixed text and the failure's own reason token only: never the response body, a release name // or the URL, the same provenance rule every other network log in this file already follows. - if (!result.ok) logMessage("info", `[back] [ipc] [ipc/handlers/netHandlers.ts] [FETCH_RELEASE_NOTES] Release notes fetch failed: ${result.reason}.`) + if (!result.ok) logMessage("info", `${LOG_PREFIX} [FETCH_RELEASE_NOTES] Release notes fetch failed: ${result.reason}.`) return result }) diff --git a/src/ipc/handlers/pathsHandlers.ts b/src/ipc/handlers/pathsHandlers.ts index a60e627c..e7e420e8 100644 --- a/src/ipc/handlers/pathsHandlers.ts +++ b/src/ipc/handlers/pathsHandlers.ts @@ -28,6 +28,8 @@ import innoExtractWorker from "@src/ipc/workers/innoExtractWorker?modulePath" import changePermsWorker from "@src/ipc/workers/changePermsWorker?modulePath" import downloadWorkerPath from "@src/ipc/workers/downloadWorker?modulePath" +const LOG_PREFIX = "[back] [ipc] [ipc/handlers/pathsHandlers.ts]" + const WORKER_TIMEOUTS_MS: Record = { DOWNLOAD_ON_PATH: 45 * 60 * 1_000, EXTRACT_ON_PATH: 30 * 60 * 1_000, @@ -248,8 +250,8 @@ function runTrackedWorker( } const onError = (error: Error): void => { - logMessage("error", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [${operation}] Worker error.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [${operation}] ${getErrorMessage(error)}`) + logMessage("error", `${LOG_PREFIX} [${operation}] Worker error.`) + logMessage("debug", `${LOG_PREFIX} [${operation}] ${getErrorMessage(error)}`) rejectOnce(error) } @@ -277,12 +279,12 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.DELETE_PATH, async (event, pathValue: try { const safePath = await assertManagedDeletionPath(pathValue) - logMessage("info", "[back] [ipc] [ipc/handlers/pathsHandlers.ts] [DELETE_PATH] Deleting an approved path.") + logMessage("info", `${LOG_PREFIX} [DELETE_PATH] Deleting an approved path.`) await fse.remove(safePath) return true } catch (err) { - logMessage("error", "[back] [ipc] [ipc/handlers/pathsHandlers.ts] [DELETE_PATH] Error deleting path.") - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [DELETE_PATH] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [DELETE_PATH] Error deleting path.`) + logMessage("debug", `${LOG_PREFIX} [DELETE_PATH] ${getErrorMessage(err)}`) return false } }) @@ -298,12 +300,12 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.MOVE_PATH, async (event, fromPath: str if (safeFromPath === safeToPath) throw new TypeError("Source and destination paths must differ") if (await fse.pathExists(safeToPath)) throw new TypeError("Destination path already exists") - logMessage("info", "[back] [ipc] [ipc/handlers/pathsHandlers.ts] [MOVE_PATH] Moving an approved path.") + logMessage("info", `${LOG_PREFIX} [MOVE_PATH] Moving an approved path.`) await fse.move(safeFromPath, safeToPath) return true } catch (err) { - logMessage("error", "[back] [ipc] [ipc/handlers/pathsHandlers.ts] [MOVE_PATH] Error moving path.") - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [MOVE_PATH] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [MOVE_PATH] Error moving path.`) + logMessage("debug", `${LOG_PREFIX} [MOVE_PATH] ${getErrorMessage(err)}`) return false } }) @@ -364,8 +366,8 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.ENSURE_PATH_EXISTS, async (event, path await fse.ensureDir(await assertManagedPath(pathValue, "path", { allowMissing: true })) return true } catch (err) { - logMessage("error", "[back] [ipc] [ipc/handlers/pathsHandlers.ts] [ENSURE_PATH_EXISTS] Error ensuring path.") - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [ENSURE_PATH_EXISTS] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [ENSURE_PATH_EXISTS] Error ensuring path.`) + logMessage("debug", `${LOG_PREFIX} [ENSURE_PATH_EXISTS] ${getErrorMessage(err)}`) return false } }) @@ -390,7 +392,7 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.DOWNLOAD_ON_PATH, async (event, id: st const optimumManifest = expectedSha256 ? await getCachedOptimumManifest() : undefined const maxBytes = optimumManifest?.archive.size - logMessage("info", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [DOWNLOAD_ON_PATH] [${safeId}] Starting a bounded download.`) + logMessage("info", `${LOG_PREFIX} [DOWNLOAD_ON_PATH] [${safeId}] Starting a bounded download.`) const downloadedPath = await downloadConcurrency.run(() => { sendProgress(event, IPC_CHANNELS.PATHS_MANAGER.DOWNLOAD_PROGRESS, safeId, 0) return runTrackedWorker( @@ -457,7 +459,7 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.EXTRACT_ON_PATH, async (event, id: str const isBackupArchive = await isLauncherBackupArchive(safeFilePath) - logMessage("info", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [EXTRACT_ON_PATH] [${safeId}] Starting a bounded extraction.`) + logMessage("info", `${LOG_PREFIX} [EXTRACT_ON_PATH] [${safeId}] Starting a bounded extraction.`) await archiveConcurrency.run(() => { sendProgress(event, IPC_CHANNELS.PATHS_MANAGER.EXTRACT_PROGRESS, safeId, 0) return runTrackedWorker( @@ -524,7 +526,7 @@ async function extractInstallerPayload( safeOutputPath: string, shouldDeleteInstaller: boolean ): Promise<"extracted" | "failed" | "format-refused"> { - logMessage("info", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Extracting the installer payload instead of running it.`) + logMessage("info", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Extracting the installer payload instead of running it.`) try { return await archiveConcurrency.run(() => { @@ -543,18 +545,18 @@ async function extractInstallerPayload( (message) => { if (message.verdict === "format-refused") { const reason = typeof message.reason === "string" ? message.reason : "no reason given" - logMessage("warn", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] The installer format was refused, falling back to running it. reason=${reason}`) + logMessage("warn", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] The installer format was refused, falling back to running it. reason=${reason}`) return "format-refused" } if (message.verdict !== "extracted") throw new Error("Installer payload extraction returned an unknown verdict") - logMessage("info", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Extracted ${message.filesWritten} files, ${message.bytesWritten} bytes.`) + logMessage("info", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Extracted ${message.filesWritten} files, ${message.bytesWritten} bytes.`) return "extracted" } ) }) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Installer payload extraction failed.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Installer payload extraction failed.`) + logMessage("debug", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] ${getErrorMessage(err)}`) return "failed" } } @@ -587,15 +589,12 @@ function spawnInstaller(event: IpcMainInvokeEvent, safeId: string, safeFilePath: const installer = spawn(exePath, ["/VERYSILENT", "/SUPPRESSMSGBOXES", "/NORESTART", "/CURRENTUSER", "/NOICONS", `/DIR=${safeOutputPath}`], { shell: false, windowsHide: true }) const timeoutHandle = setTimeout(() => { - logMessage( - "error", - `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Timed out after ${RUN_INSTALLER_TIMEOUT_MS}ms waiting on the installer; killing its process tree. reason=installer-timed-out` - ) + logMessage("error", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Timed out after ${RUN_INSTALLER_TIMEOUT_MS}ms waiting on the installer; killing its process tree. reason=installer-timed-out`) attemptInstallerTreeKill( installer.pid, process.platform, (command, args) => spawn(command, args, { shell: false, windowsHide: true }), - (level, message) => logMessage(level, `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] ${message}`) + (level, message) => logMessage(level, `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] ${message}`) ) finish("timed-out") }, RUN_INSTALLER_TIMEOUT_MS) @@ -610,14 +609,14 @@ function spawnInstaller(event: IpcMainInvokeEvent, safeId: string, safeFilePath: } installer.on("error", (error) => { - logMessage("error", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Error launching installer.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] ${getErrorMessage(error)}`) + logMessage("error", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Error launching installer.`) + logMessage("debug", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] ${getErrorMessage(error)}`) finish("failed") }) installer.on("close", (code) => finish(code === 0 ? "installed" : "failed")) } catch (err) { - logMessage("error", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] Installer setup failed.`) - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [RUN_INSTALLER] [${safeId}] ${getErrorMessage(err)}`) + logMessage("error", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] Installer setup failed.`) + logMessage("debug", `${LOG_PREFIX} [RUN_INSTALLER] [${safeId}] ${getErrorMessage(err)}`) resolvePromise(spawnInstallerOutcomeToResult("failed")) } }) @@ -633,7 +632,7 @@ ipcMain.handle( const safeOutputFileName = assertSafeFileName(outputFileName, "output file name") const safeCompressionLevel = assertInteger(compressionLevel, "compression level", 0, 9) - logMessage("info", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [COMPRESS_ON_PATH] [${safeId}] Starting bounded compression.`) + logMessage("info", `${LOG_PREFIX} [COMPRESS_ON_PATH] [${safeId}] Starting bounded compression.`) await archiveConcurrency.run(() => { sendProgress(event, IPC_CHANNELS.PATHS_MANAGER.COMPRESS_PROGRESS, safeId, 0) return runTrackedWorker( @@ -668,7 +667,7 @@ ipcMain.handle(IPC_CHANNELS.PATHS_MANAGER.CHANGE_PERMS, async (event, paths: str * the log afterwards needs, and it is the half that was missing entirely. */ function refuseIconCopy(reason: CustomIconCopyFailureReason, cause: unknown): { status: false; reason: CustomIconCopyFailureReason } { - logMessage("debug", `[back] [ipc] [ipc/handlers/pathsHandlers.ts] [COPY_TO_ICONS] Refused an icon (${reason}): ${cause instanceof Error ? cause.message : String(cause)}.`) + logMessage("debug", `${LOG_PREFIX} [COPY_TO_ICONS] Refused an icon (${reason}): ${cause instanceof Error ? cause.message : String(cause)}.`) return { status: false, reason } } diff --git a/src/ipc/handlers/utilsHandlers.ts b/src/ipc/handlers/utilsHandlers.ts index 717b9532..9e7532ec 100644 --- a/src/ipc/handlers/utilsHandlers.ts +++ b/src/ipc/handlers/utilsHandlers.ts @@ -8,6 +8,8 @@ import { logMessage } from "@src/utils/logManager" import { setShouldPreventClose } from "@src/utils/shouldPreventClose" import { registerUserSelectedPaths } from "@src/ipc/pathPolicy" +const LOG_PREFIX = "[back] [ipc] [ipc/handlers/utilsHandlers.ts]" + ipcMain.handle(IPC_CHANNELS.UTILS.GET_APP_VERSION, (event) => { assertTrustedIpcSender(event) return app.getVersion() @@ -25,7 +27,7 @@ ipcMain.on(IPC_CHANNELS.UTILS.LOG_MESSAGE, (event, mode: ErrorTypes, message: st try { logMessage(mode, assertString(message, "log message", 16_384)) } catch { - logMessage("warn", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [LOG_MESSAGE] Rejected an invalid log message.") + logMessage("warn", `${LOG_PREFIX} [LOG_MESSAGE] Rejected an invalid log message.`) } }) @@ -36,7 +38,7 @@ ipcMain.on(IPC_CHANNELS.UTILS.SET_PREVENT_APP_CLOSE, (event, action: "add" | "re try { setShouldPreventClose(action, assertSafeTaskId(id), assertString(desc, "task description", 256)) } catch { - logMessage("warn", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [SET_PREVENT_APP_CLOSE] Rejected invalid task state.") + logMessage("warn", `${LOG_PREFIX} [SET_PREVENT_APP_CLOSE] Rejected invalid task state.`) } }) @@ -45,12 +47,12 @@ ipcMain.on(IPC_CHANNELS.UTILS.OPEN_ON_BROWSER, (event, url: string): void => { try { const safeUrl = assertAllowedBrowserUrl(url) - logMessage("info", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [OPEN_ON_BROWSER] Opening an approved URL on the default browser.") + logMessage("info", `${LOG_PREFIX} [OPEN_ON_BROWSER] Opening an approved URL on the default browser.`) void shell.openExternal(safeUrl.toString()).catch(() => { - logMessage("warn", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [OPEN_ON_BROWSER] The default browser rejected the URL.") + logMessage("warn", `${LOG_PREFIX} [OPEN_ON_BROWSER] The default browser rejected the URL.`) }) } catch { - logMessage("warn", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [OPEN_ON_BROWSER] Rejected an unsafe URL.") + logMessage("warn", `${LOG_PREFIX} [OPEN_ON_BROWSER] Rejected an unsafe URL.`) } }) @@ -67,14 +69,14 @@ ipcMain.handle(IPC_CHANNELS.UTILS.COPY_TO_CLIPBOARD, (event, text: string): bool clipboard.writeText(assertString(text, "clipboard text", 2_048)) return true } catch { - logMessage("warn", "[back] [ipc] [ipc/handlers/utilsHandlers.ts] [COPY_TO_CLIPBOARD] The clipboard refused the write.") + logMessage("warn", `${LOG_PREFIX} [COPY_TO_CLIPBOARD] The clipboard refused the write.`) return false } }) ipcMain.handle(IPC_CHANNELS.UTILS.SELECT_FOLDER_DIALOG, async (event, options?: { type?: "file" | "folder"; mode?: "single" | "multi"; extensions?: string[] }): Promise => { assertTrustedIpcSender(event) - logMessage("info", `[back] [ipc] [ipc/handlers/utilsHandlers.ts] [SELECT_FOLDER_DIALOG] Opening folder selection.`) + logMessage("info", `${LOG_PREFIX} [SELECT_FOLDER_DIALOG] Opening folder selection.`) if (options !== undefined) { if (!isRecord(options)) throw new TypeError("Invalid dialog options") @@ -101,11 +103,11 @@ ipcMain.handle(IPC_CHANNELS.UTILS.SELECT_FOLDER_DIALOG, async (event, options?: }) if (result.canceled) { - logMessage("warn", `[back] [ipc] [ipc/handlers/utilsHandlers.ts] [SELECT_FOLDER_DIALOG] Operation cancelled.`) + logMessage("warn", `${LOG_PREFIX} [SELECT_FOLDER_DIALOG] Operation cancelled.`) return [] } - logMessage("info", `[back] [ipc] [ipc/handlers/utilsHandlers.ts] [SELECT_FOLDER_DIALOG] Selection completed with ${result.filePaths.length} path(s).`) + logMessage("info", `${LOG_PREFIX} [SELECT_FOLDER_DIALOG] Selection completed with ${result.filePaths.length} path(s).`) registerUserSelectedPaths(result.filePaths) return result.filePaths diff --git a/src/main/index.ts b/src/main/index.ts index 40825d6d..063deab5 100644 --- a/src/main/index.ts +++ b/src/main/index.ts @@ -33,6 +33,8 @@ import fse from "fs-extra" import "@src/ipc" import { clearTimeout, setTimeout } from "node:timers" +const LOG_PREFIX = "[back] [index] [main/index.ts]" + // #247: when the terminal that started the launcher exits, the next console write fails, and // Node reports that failure as an "error" event on process.stdout with no listener, i.e. an // uncaught exception Electron shows as "A JavaScript error occurred in the main process". @@ -53,7 +55,7 @@ Logger.transports.file.resolvePathFn = (variables, message): string => { return join(logsPath, `${message.level}.log`) } -logMessage("info", `[back] [index] [main/index.ts] [setUpUserDataFolder] ${describeUserDataSetup(userDataSetup)}`) +logMessage("info", `${LOG_PREFIX} [setUpUserDataFolder] ${describeUserDataSetup(userDataSetup)}`) /** * The one setting that has to be answered before Electron starts. @@ -77,7 +79,7 @@ function storedAllowBasicSessionStore(): boolean { const passwordStore = basicPasswordStoreSwitch(process.platform, storedAllowBasicSessionStore()) if (passwordStore) { app.commandLine.appendSwitch("password-store", passwordStore) - logMessage("info", "[back] [index] [main/index.ts] [passwordStore] Starting with the basic password store, as this launcher's session storage setting asks.") + logMessage("info", `${LOG_PREFIX} [passwordStore] Starting with the basic password store, as this launcher's session storage setting asks.`) } let mainWindow: BrowserWindow @@ -124,7 +126,7 @@ protocol.registerSchemesAsPrivileged(privilegedSchemes) // in Electron's other child processes (GPU, utility, and sandbox helpers) without // collecting crash reports or sending telemetry anywhere. app.on("child-process-gone", (_event, details) => { - logMessage("error", `[back] [index] [main/index.ts] [child-process-gone] ${details.type} process exited: ${details.reason} (exit code ${details.exitCode}).`) + logMessage("error", `${LOG_PREFIX} [child-process-gone] ${details.type} process exited: ${details.reason} (exit code ${details.exitCode}).`) }) function createWindow(): void { @@ -162,19 +164,19 @@ function createWindow(): void { const isAllowedMainFrameUrl = (url: string): boolean => isAllowedRendererUrl(url, is.dev ? process.env["ELECTRON_RENDERER_URL"] : undefined, packagedRendererPath) mainWindow.webContents.on("render-process-gone", (_event, details) => { - logMessage("error", `[back] [index] [main/index.ts] [createWindow] Renderer process exited: ${details.reason}.`) + logMessage("error", `${LOG_PREFIX} [createWindow] Renderer process exited: ${details.reason}.`) }) mainWindow.webContents.on("unresponsive", () => { - logMessage("warn", "[back] [index] [main/index.ts] [createWindow] Renderer became unresponsive.") + logMessage("warn", `${LOG_PREFIX} [createWindow] Renderer became unresponsive.`) }) mainWindow.webContents.on("responsive", () => { - logMessage("info", "[back] [index] [main/index.ts] [createWindow] Renderer became responsive again.") + logMessage("info", `${LOG_PREFIX} [createWindow] Renderer became responsive again.`) }) mainWindow.on("ready-to-show", async () => { - logMessage("info", "[back] [index] [main/index.ts] [createWindow] Main window ready to show. Opening.") + logMessage("info", `${LOG_PREFIX} [createWindow] Main window ready to show. Opening.`) const config = await getConfig() const oldWindowsState = config.window @@ -191,7 +193,7 @@ function createWindow(): void { if (!hasSweptOrphanedTempFiles) { hasSweptOrphanedTempFiles = true void sweepOrphanedTempFiles(getOrphanedTempFileSweepTargets(app.getPath("userData"), config)).catch((error: unknown) => { - logMessage("debug", `[back] [index] [main/index.ts] [ready-to-show] Could not sweep orphaned temporary files: ${error}`) + logMessage("debug", `${LOG_PREFIX} [ready-to-show] Could not sweep orphaned temporary files: ${error}`) }) } }) @@ -201,7 +203,7 @@ function createWindow(): void { const safeUrl = assertAllowedBrowserUrl(details.url) void shell.openExternal(safeUrl.toString()) } catch { - logMessage("warn", "[back] [index] [main/index.ts] [createWindow] Blocked an unsafe external window URL.") + logMessage("warn", `${LOG_PREFIX} [createWindow] Blocked an unsafe external window URL.`) } return { action: "deny" } }) @@ -240,10 +242,10 @@ function createWindow(): void { if (getShouldPreventClose()) { e.preventDefault() if (!mainWindow.isDestroyed()) mainWindow.webContents.send(IPC_CHANNELS.UTILS.PREVENTED_APP_CLOSE) - logMessage("info", "[back] [index] [main/index.ts] [createWindow] Main window prevented from closing.") + logMessage("info", `${LOG_PREFIX} [createWindow] Main window prevented from closing.`) return false } - logMessage("info", "[back] [index] [main/index.ts] [createWindow] Main window closing.") + logMessage("info", `${LOG_PREFIX} [createWindow] Main window closing.`) return true }) @@ -276,7 +278,7 @@ function readLinuxPackageType(): string | undefined { // This method will be called when Electron has finished initialization and is ready to create browser windows. Some APIs can only be used after this event occurs. app.whenReady().then(async () => { - logMessage("info", "[back] [index] [main/index.ts] [whenReady] Electron ready.") + logMessage("info", `${LOG_PREFIX} [whenReady] Electron ready.`) session.defaultSession.setPermissionCheckHandler(() => false) session.defaultSession.setPermissionRequestHandler((_webContents, _permission, callback) => callback(false)) @@ -395,10 +397,10 @@ app.whenReady().then(async () => { // A packaged build missing its own updater is a broken package, not a reason to refuse to // launch: everything else in the app works without it, and this is the only line that // would otherwise have gone unreported now that the import is no longer at module scope. - logMessage("error", `[back] [index] [main/index.ts] [whenReady] Could not load the auto-updater: ${getErrorMessage(error)}.`) + logMessage("error", `${LOG_PREFIX} [whenReady] Could not load the auto-updater: ${getErrorMessage(error)}.`) }) } else { - logMessage("info", `[back] [index] [main/index.ts] [whenReady] Auto-update disabled: ${updateDecision.reason}.`) + logMessage("info", `${LOG_PREFIX} [whenReady] Auto-update disabled: ${updateDecision.reason}.`) } app.on("activate", function () { @@ -411,10 +413,10 @@ app.whenReady().then(async () => { app.on("window-all-closed", () => { if (getShouldPreventClose() && mainWindow && !mainWindow.isDestroyed()) { mainWindow.webContents.send(IPC_CHANNELS.UTILS.PREVENTED_APP_CLOSE) - return logMessage("info", "[back] [index] [main/index.ts] [window-all-closed] Main window prevented from closing.") + return logMessage("info", `${LOG_PREFIX} [window-all-closed] Main window prevented from closing.`) } - logMessage("info", "[back] [index] [main/index.ts] [window-all-closed] All windows closed.") + logMessage("info", `${LOG_PREFIX} [window-all-closed] All windows closed.`) clearModIconMemoryCache(modIconMemoryCache) if (process.platform !== "darwin") { app.quit() diff --git a/src/main/orphanedTempFiles.ts b/src/main/orphanedTempFiles.ts index 167275c7..74a81145 100644 --- a/src/main/orphanedTempFiles.ts +++ b/src/main/orphanedTempFiles.ts @@ -5,6 +5,8 @@ import { isRestoreStagingWorkspaceName } from "@src/ipc/validation" import { DOWNLOAD_TEMP_FILE_NAMESPACE } from "@src/ipc/workers/download" import { logMessage } from "@src/utils/logManager" +const LOG_PREFIX = "[back] [maintenance] [main/orphanedTempFiles.ts]" + /** A week leaves plenty of time for a slow or interrupted download to be resumed manually. */ export const ORPHANED_TEMP_FILE_MAX_AGE_MS = 7 * 24 * 60 * 60 * 1_000 @@ -79,7 +81,7 @@ async function sweepDirectory(target: TemporaryFileSweepTarget, options: Require try { entries = await fse.readdir(folder, { withFileTypes: true }) } catch (error) { - if (!isMissing(error)) options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Could not inspect ${folder}: ${error}`) + if (!isMissing(error)) options.log("debug", `${LOG_PREFIX} Could not inspect ${folder}: ${error}`) return 0 } @@ -101,7 +103,7 @@ async function sweepDirectory(target: TemporaryFileSweepTarget, options: Require try { stats = await fse.lstat(entryPath) } catch (error) { - if (!isMissing(error)) options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Could not inspect ${entryPath}: ${error}`) + if (!isMissing(error)) options.log("debug", `${LOG_PREFIX} Could not inspect ${entryPath}: ${error}`) continue } if (stats.isSymbolicLink() || options.nowMs - stats.mtimeMs <= options.maxAgeMs) continue @@ -109,9 +111,9 @@ async function sweepDirectory(target: TemporaryFileSweepTarget, options: Require try { await fse.remove(entryPath) removed += 1 - options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Removed ${label} ${entryPath}.`) + options.log("debug", `${LOG_PREFIX} Removed ${label} ${entryPath}.`) } catch (error) { - if (!isMissing(error)) options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Could not remove ${entryPath}: ${error}`) + if (!isMissing(error)) options.log("debug", `${LOG_PREFIX} Could not remove ${entryPath}: ${error}`) } continue } @@ -129,7 +131,7 @@ async function sweepDirectory(target: TemporaryFileSweepTarget, options: Require // between readdir and this check. stats = await fse.lstat(entryPath) } catch (error) { - if (!isMissing(error)) options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Could not inspect ${entryPath}: ${error}`) + if (!isMissing(error)) options.log("debug", `${LOG_PREFIX} Could not inspect ${entryPath}: ${error}`) continue } @@ -138,9 +140,9 @@ async function sweepDirectory(target: TemporaryFileSweepTarget, options: Require try { await fse.unlink(entryPath) removed += 1 - options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Removed orphaned temporary file ${entryPath}.`) + options.log("debug", `${LOG_PREFIX} Removed orphaned temporary file ${entryPath}.`) } catch (error) { - if (!isMissing(error)) options.log("debug", `[back] [maintenance] [orphanedTempFiles.ts] Could not remove ${entryPath}: ${error}`) + if (!isMissing(error)) options.log("debug", `${LOG_PREFIX} Could not remove ${entryPath}: ${error}`) } }