Files
Multi-Debrid-Downloader/src/main/conversion-trace.ts
T
Sucukdeluxe 5309f8dd69 Diagnose: Vollstaendiges Conversion-Trace-Logging (conversion.log) fuer haengende/langsame Link-Umwandlung
Bewusst NUR Diagnose, KEINE Verhaltensaenderung — damit das naechste
Support-Bundle das echte aktuelle Verhalten zeigt und der naechste Fix
die Ursache trifft statt zu raten (live belegt: "Unrestrict Timeout nach
60s" R53/R64, API-"Token error, please log-in" kuehlt beide Accounts ab).

Neues Modul conversion-trace.ts: AsyncLocalStorage-Trace, der einen
unrestrict-Versuch ueber alle Schichten begleitet und EINEN strukturierten
Block pro Versuch nach conversion.log schreibt (Datei-Infra wie
account-rotation-log: Rotation bei 5 MB, 14 Tage Retention; im Support-
Bundle). tracePhase ist no-op ohne aktiven Trace — additiv, null Risiko.

Instrumentiert wird die Kern-Blindstelle der bisherigen Logs:
- download-manager Boundary: runWithConversionTrace + Slot-Belegung
  (conv/dl/active/max) + Caller-Timeout-Attribution (was lief, als die 60s
  feuerten).
- Provider-Kette (debrid): chain-try/ok/failed/aborted — zeigt, ob der
  Web->API-Failover ueberhaupt feuert oder vom globalen Abbruch gekappt wird.
- Mega-Rotation: mega-account mit workMs + outcome (ok/failed/fatal/aborted)
  + Cooldown je Account.
- API-Token-Lifecycle: token cached/pending-join/fresh-login + connectMs,
  getLink response_code/text — klaert die Herkunft von "Token error".
- Mega-Web runExclusive: web-queue mit queueWaitMs UND workMs getrennt —
  klaert, ob die 60s Warten in der Queue oder echte langsame Arbeit sind.

Test conversion-trace.test.ts (Formatter + ALS-Kontext-Propagation).
838/838 gruen, tsc unveraendert (6 Baseline), Build ok.
2026-06-17 02:52:44 +02:00

191 lines
5.6 KiB
TypeScript

import fs from "node:fs";
import path from "node:path";
import { AsyncLocalStorage } from "node:async_hooks";
import { logTimestamp } from "./log-timestamp";
export interface ConversionPhase {
atMs: number;
phase: string;
provider?: string;
account?: string;
tokenState?: string;
queueWaitMs?: number;
workMs?: number;
outcome?: string;
detail?: string;
}
export interface ConversionTrace {
startedAt: number;
itemId: string;
itemName: string;
link: string;
providerOrder: string;
notes: Record<string, string | number>;
phases: ConversionPhase[];
}
const conversionContext = new AsyncLocalStorage<ConversionTrace>();
function shortLink(link: string): string {
const raw = String(link || "").trim();
return raw.length > 90 ? `${raw.slice(0, 90)}…` : raw;
}
export function traceConversionPhase(phase: Omit<ConversionPhase, "atMs">): void {
const trace = conversionContext.getStore();
if (!trace) {
return;
}
trace.phases.push({ ...phase, atMs: Date.now() - trace.startedAt });
}
export function traceConversionNote(key: string, value: string | number): void {
const trace = conversionContext.getStore();
if (!trace) {
return;
}
trace.notes[key] = value;
}
export function hasActiveConversionTrace(): boolean {
return conversionContext.getStore() !== undefined;
}
export function formatConversionBlock(
trace: ConversionTrace,
outcome: string,
detail: string,
totalMs: number
): string {
const noteParts = Object.entries(trace.notes)
.map(([key, value]) => `${key}=${value}`)
.join(" ");
const header = `${logTimestamp()} [CONV] item=${trace.itemName || trace.itemId} | order=${trace.providerOrder || "?"}`
+ ` | result=${outcome}${detail ? ` (${detail})` : ""} | total=${totalMs}ms${noteParts ? ` | ${noteParts}` : ""}`
+ ` | link=${shortLink(trace.link)}`;
const lines = trace.phases.map((p) => {
const parts: string[] = [];
if (p.provider) parts.push(`provider=${p.provider}`);
if (p.account) parts.push(`account=${p.account}`);
if (p.tokenState) parts.push(`token=${p.tokenState}`);
if (typeof p.queueWaitMs === "number") parts.push(`queueWaitMs=${p.queueWaitMs}`);
if (typeof p.workMs === "number") parts.push(`workMs=${p.workMs}`);
if (p.outcome) parts.push(`outcome=${p.outcome}`);
if (p.detail) parts.push(`detail=${String(p.detail).replace(/\r?\n/g, "\\n")}`);
return ` +${p.atMs}ms ${p.phase}${parts.length ? ` | ${parts.join(" | ")}` : ""}`;
});
return [header, ...lines].join("\n");
}
const CONVERSION_LOG_MAX_FILE_BYTES = Number(process.env.RD_CONVERSION_LOG_MAX_BYTES || 5 * 1024 * 1024);
const CONVERSION_LOG_RETENTION_DAYS = Number(process.env.RD_CONVERSION_LOG_RETENTION_DAYS || 14);
let conversionLogPath: string | null = null;
function rotateIfNeeded(filePath: string): void {
try {
const stat = fs.statSync(filePath);
if (stat.size < CONVERSION_LOG_MAX_FILE_BYTES) {
return;
}
const backup = `${filePath}.old`;
try {
fs.rmSync(backup, { force: true });
} catch {
}
fs.renameSync(filePath, backup);
} catch {
}
}
function cleanupOldBackup(filePath: string): void {
const backup = `${filePath}.old`;
try {
const stat = fs.statSync(backup);
const cutoff = Date.now() - CONVERSION_LOG_RETENTION_DAYS * 24 * 60 * 60 * 1000;
if (stat.mtimeMs < cutoff) {
fs.rmSync(backup, { force: true });
}
} catch {
}
}
export function initConversionLog(baseDir: string): void {
conversionLogPath = path.join(baseDir, "conversion.log");
try {
fs.mkdirSync(path.dirname(conversionLogPath), { recursive: true });
cleanupOldBackup(conversionLogPath);
if (!fs.existsSync(conversionLogPath)) {
fs.writeFileSync(conversionLogPath, "", "utf8");
}
rotateIfNeeded(conversionLogPath);
if (!fs.existsSync(conversionLogPath)) {
fs.writeFileSync(conversionLogPath, "", "utf8");
}
fs.appendFileSync(conversionLogPath, `=== Conversion Log Start: ${logTimestamp()} ===\n`, "utf8");
} catch {
conversionLogPath = null;
}
}
export function getConversionLogPath(): string | null {
if (!conversionLogPath) {
return null;
}
return fs.existsSync(conversionLogPath) ? conversionLogPath : null;
}
export function shutdownConversionLog(): void {
if (!conversionLogPath) {
return;
}
try {
fs.appendFileSync(conversionLogPath, `=== Conversion Log Ende: ${logTimestamp()} ===\n`, "utf8");
} catch {
}
conversionLogPath = null;
}
function writeConversionBlock(block: string): void {
if (!conversionLogPath) {
return;
}
try {
rotateIfNeeded(conversionLogPath);
if (!fs.existsSync(conversionLogPath)) {
fs.writeFileSync(conversionLogPath, "", "utf8");
}
fs.appendFileSync(conversionLogPath, `${block}\n`, "utf8");
} catch {
}
}
export async function runWithConversionTrace<T>(
meta: { itemId: string; itemName: string; link: string; providerOrder: string },
fn: () => Promise<T>
): Promise<T> {
const trace: ConversionTrace = {
startedAt: Date.now(),
itemId: meta.itemId,
itemName: meta.itemName,
link: meta.link,
providerOrder: meta.providerOrder,
notes: {},
phases: []
};
let outcome = "OK";
let detail = "";
try {
const result = await conversionContext.run(trace, fn);
return result;
} catch (error) {
outcome = "FAIL";
detail = String((error as { message?: string })?.message || error || "").replace(/^Error:\s*/i, "").slice(0, 160);
throw error;
} finally {
const totalMs = Date.now() - trace.startedAt;
writeConversionBlock(formatConversionBlock(trace, outcome, detail, totalMs));
}
}