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.
This commit is contained in:
Sucukdeluxe
2026-06-17 02:52:44 +02:00
parent e91e66a5f3
commit 5309f8dd69
8 changed files with 395 additions and 285 deletions
+3
View File
@@ -43,6 +43,7 @@ import { encryptBackup, decryptBackup } from "./backup-crypto";
import { buildBackupPayload, planBackupImport } from "./backup-payload";
import { getAuditLogPath, initAuditLog, logAuditEvent, shutdownAuditLog } from "./audit-log";
import { initAccountRotationLog, shutdownAccountRotationLog } from "./account-rotation-log";
import { initConversionLog, shutdownConversionLog } from "./conversion-trace";
import { runStartupHealthCheck } from "./startup-health-check";
import { getDebugSetupCheck } from "./debug-setup";
import { buildLinkExportSelection, serializeLinkExportText } from "./link-export";
@@ -94,6 +95,7 @@ export class AppController {
initItemLogs(this.storagePaths.baseDir);
initAuditLog(this.storagePaths.baseDir);
initAccountRotationLog(this.storagePaths.baseDir);
initConversionLog(this.storagePaths.baseDir);
initRenameLog(this.storagePaths.baseDir);
let desktopDir: string | null = null;
try {
@@ -800,6 +802,7 @@ public async checkDebridAccounts(): Promise<DebridAccountStatus[]> {
this.audit("INFO", "App beendet");
shutdownTraceLog();
shutdownAccountRotationLog();
shutdownConversionLog();
shutdownAuditLog();
if (this.settings.historyRetentionMode === "session") {
clearHistory(this.storagePaths);
+190
View File
@@ -0,0 +1,190 @@
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));
}
}
+43 -1
View File
@@ -6,6 +6,7 @@ import { isMegaDebridResolveFailure, germanMegaDebridResolveReason } from "../sh
import { APP_VERSION, REQUEST_RETRIES } from "./constants";
import { logger } from "./logger";
import { logAccountRotation } from "./account-rotation-log";
import { traceConversionPhase } from "./conversion-trace";
import { RealDebridClient, UnrestrictedLink } from "./realdebrid";
import { MEGA_DEBRID_NO_SERVER_RE } from "./mega-web-fallback";
import { isMegaFileUrl, resolveMegaFilename } from "./mega-public-api";
@@ -1742,11 +1743,13 @@ class MegaDebridClient {
const key = this.cacheKey;
const cached = MegaDebridClient.cachedApiTokens.get(key);
if (cached && cached.token && Date.now() - cached.at < 20 * 60 * 1000) {
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: `cached(${Math.floor((Date.now() - cached.at) / 1000)}s)`, outcome: "ok" });
return cached.token;
}
const pending = MegaDebridClient.pendingConnects.get(key);
if (pending) {
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: "pending-join", outcome: "ok" });
return pending;
}
@@ -1762,6 +1765,7 @@ class MegaDebridClient {
}
private async doConnectApi(signal?: AbortSignal): Promise<string | null> {
const connectStartedAt = Date.now();
const url = `${MEGA_DEBRID_API_BASE}?action=connectUser&login=${encodeURIComponent(this.login)}&password=${encodeURIComponent(this.password)}`;
const response = await fetch(url, {
headers: { "User-Agent": DEBRID_USER_AGENT },
@@ -1772,6 +1776,7 @@ class MegaDebridClient {
if (response.status === 401 || response.status === 403) {
this.clearTokenCache();
}
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: "fresh-login", workMs: Date.now() - connectStartedAt, outcome: "error", detail: `HTTP ${response.status}` });
return null;
}
const payload = parseJsonSafe(text);
@@ -1779,13 +1784,16 @@ class MegaDebridClient {
if (payload && String(payload.response_code || "").toLowerCase().includes("token")) {
this.clearTokenCache();
}
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: "fresh-login", workMs: Date.now() - connectStartedAt, outcome: "error", detail: `response_code=${payload?.response_code || "?"} ${String(payload?.response_text || "").slice(0, 80)}`.trim() });
return null;
}
const token = String(payload.token || "").trim();
if (!token) {
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: "fresh-login", workMs: Date.now() - connectStartedAt, outcome: "error", detail: "leeres Token" });
return null;
}
MegaDebridClient.cachedApiTokens.set(this.cacheKey, { token, at: Date.now() });
traceConversionPhase({ phase: "token", provider: "megadebrid-api", tokenState: "fresh-login", workMs: Date.now() - connectStartedAt, outcome: "ok" });
return token;
}
@@ -1795,6 +1803,7 @@ class MegaDebridClient {
return null;
}
const getLinkStartedAt = Date.now();
const url = `${MEGA_DEBRID_API_BASE}?action=getLink&token=${encodeURIComponent(token)}`;
const response = await fetch(url, {
method: "POST",
@@ -1810,14 +1819,17 @@ class MegaDebridClient {
if (response.status === 401 || response.status === 403) {
this.clearTokenCache();
}
traceConversionPhase({ phase: "api-getlink", provider: "megadebrid-api", workMs: Date.now() - getLinkStartedAt, outcome: "error", detail: `HTTP ${response.status}` });
return null;
}
const payload = parseJsonSafe(text);
if (!payload || payload.response_code !== "ok") {
if (payload && String(payload.response_code || "").includes("token")) {
const tokenInvalidated = Boolean(payload && String(payload.response_code || "").includes("token"));
if (tokenInvalidated) {
this.clearTokenCache();
}
const errorText = String(payload?.response_text || "").trim();
traceConversionPhase({ phase: "api-getlink", provider: "megadebrid-api", workMs: Date.now() - getLinkStartedAt, outcome: "error", detail: `response_code=${payload?.response_code || "?"}${tokenInvalidated ? " (token-cache-geleert)" : ""} ${errorText}`.trim() });
if (errorText) {
throw new Error(`Mega-Debrid API: ${errorText}`);
}
@@ -1826,8 +1838,10 @@ class MegaDebridClient {
const directUrl = String(payload.debridLink || "").trim();
if (!directUrl) {
traceConversionPhase({ phase: "api-getlink", provider: "megadebrid-api", workMs: Date.now() - getLinkStartedAt, outcome: "error", detail: "kein debridLink" });
return null;
}
traceConversionPhase({ phase: "api-getlink", provider: "megadebrid-api", workMs: Date.now() - getLinkStartedAt, outcome: "ok" });
const fileName = String(payload.filename || "").trim() || filenameFromUrl(directUrl) || filenameFromUrl(link);
return {
directUrl,
@@ -2004,6 +2018,7 @@ class MegaDebridClient {
clearMegaDebridAccountCooldownState(cooldownKey);
clearMegaDebridEmptyResponseStreak(cooldownKey);
const elapsedMs = Date.now() - testStartedAt;
traceConversionPhase({ phase: "mega-account", provider: providerName.includes("API") ? "megadebrid-api" : "megadebrid-web", account: rotationLabel, workMs: elapsedMs, outcome: "ok" });
megaDebridStickyCount += 1;
if (megaDebridStickyCount >= MEGA_DEBRID_STICKY_LINKS) {
megaDebridRotationCursor = idx + 1;
@@ -2037,6 +2052,14 @@ class MegaDebridClient {
if (ranLongEnough) {
setMegaDebridAccountCooldownState(cooldownKey, MEGA_DEBRID_ACCOUNT_COOLDOWN_MS, `Abbruch/Timeout nach ${Math.ceil(elapsedMs / 1000)}s`, "temporary");
}
traceConversionPhase({
phase: "mega-account",
provider: providerName.includes("API") ? "megadebrid-api" : "megadebrid-web",
account: rotationLabel,
workMs: elapsedMs,
outcome: "aborted",
detail: `${abortText}${ranLongEnough ? ` cd=${Math.ceil(MEGA_DEBRID_ACCOUNT_COOLDOWN_MS / 1000)}s` : ""}`
});
failures.push(`Mega-Debrid${accountLabel}: ${abortText}`);
logAccountRotation("WARN", providerName, rotationLabel, "TIMEOUT_COOLDOWN", {
elapsedMs,
@@ -2047,6 +2070,14 @@ class MegaDebridClient {
throw new Error(`Mega-Debrid${accountLabel}: ${abortText}`);
}
const failure = MegaDebridClient.classifyAccountFailure(error);
traceConversionPhase({
phase: "mega-account",
provider: providerName.includes("API") ? "megadebrid-api" : "megadebrid-web",
account: rotationLabel,
workMs: Date.now() - testStartedAt,
outcome: failure.fatal ? "fatal" : "failed",
detail: `${failure.message}${failure.cooldownMs > 0 ? ` cd=${Math.ceil(failure.cooldownMs / 1000)}s` : ""}`
});
failures.push(`Mega-Debrid${accountLabel}: ${failure.message}`);
let parkUntilRestart = false;
@@ -3780,9 +3811,12 @@ export class DebridService {
continue;
}
const providerStartedAt = Date.now();
try {
logger.info(`Provider-Kette: versuche ${PROVIDER_LABELS[provider]}`);
traceConversionPhase({ phase: "chain-try", provider });
const result = await this.unrestrictViaProvider(settings, provider, link, signal);
traceConversionPhase({ phase: "chain-ok", provider, workMs: Date.now() - providerStartedAt, outcome: "ok" });
let fileName = result.fileName;
if (isRapidgatorLink(link) && looksLikeOpaqueFilename(fileName || filenameFromUrl(link))) {
const fromPage = await resolveRapidgatorFilename(link, signal);
@@ -3799,9 +3833,17 @@ export class DebridService {
} catch (error) {
const errorText = compactErrorText(error);
if (signal?.aborted || (/aborted/i.test(errorText) && !/timeout/i.test(errorText))) {
traceConversionPhase({ phase: "chain-aborted", provider, workMs: Date.now() - providerStartedAt, outcome: "aborted", detail: errorText.slice(0, 120) });
throw error;
}
const nextProvider = order.slice(order.indexOf(provider) + 1).find((candidate) => this.isProviderSelectableFor(settings, candidate));
traceConversionPhase({
phase: "chain-failed",
provider,
workMs: Date.now() - providerStartedAt,
outcome: nextProvider ? "failover" : "exhausted",
detail: `${errorText.slice(0, 120)}${nextProvider ? `${nextProvider}` : ""}`
});
if (nextProvider) {
logger.warn(`Provider-Kette: ${PROVIDER_LABELS[provider]} fehlgeschlagen (${errorText}), Fallback auf ${PROVIDER_LABELS[nextProvider]}`);
} else {
+42 -1
View File
@@ -60,6 +60,7 @@ import { processVideoFile, resolveVideoTooling, stripDualLangMarker, hasDualLang
import { sendNotification } from "./notify";
import { logger } from "./logger";
import { getRecentRotationEvents, runWithRotationItemSink, setRotationEventListener } from "./account-rotation-log";
import { runWithConversionTrace, traceConversionPhase, traceConversionNote } from "./conversion-trace";
import type { RotationEvent } from "../shared/types";
import { ensureItemLog, getItemLogPath as getPersistedItemLogPath, logItemEvent as writeItemLogEvent } from "./item-log";
import { ensurePackageLog, getPackageLogPath as getPersistedPackageLogPath, logPackageEvent as writePackageLogEvent } from "./package-log";
@@ -7979,6 +7980,23 @@ export class DownloadManager extends EventEmitter {
return count;
}
private describeSlotOccupancy(): string {
let converting = 0;
let downloading = 0;
for (const active of this.activeTasks.values()) {
const activeItem = this.session.items[active.itemId];
if (!activeItem) {
continue;
}
if (activeItem.status === "validating") {
converting += 1;
} else if (activeItem.status === "downloading") {
downloading += 1;
}
}
return `conv${converting}/dl${downloading}/active${this.activeTasks.size}/max${this.settings.maxParallel}`;
}
private getSerializedValidatingLimit(provider: DebridProvider | null): number {
if (provider === "megadebrid-web") {
const usableAccounts = getAvailableMegaDebridAccounts(this.settings)
@@ -8760,7 +8778,30 @@ export class DownloadManager extends EventEmitter {
const unrestrictedSignal = AbortSignal.any([active.abortController.signal, unrestrictTimeoutSignal]);
let unrestricted;
try {
unrestricted = await this.debridService.unrestrictLink(item.url, unrestrictedSignal);
unrestricted = await runWithConversionTrace(
{
itemId: item.id,
itemName: item.fileName || item.id,
link: item.url,
providerOrder: (this.settings.providerOrder || []).join(",") || String(this.getExpectedProviderForItem(item) || "?")
},
async () => {
traceConversionNote("slots", this.describeSlotOccupancy());
traceConversionNote("retry", Number(active.unrestrictRetries || 0));
try {
return await this.debridService.unrestrictLink(item.url, unrestrictedSignal);
} catch (innerError) {
if (!active.abortController.signal.aborted && unrestrictTimeoutSignal.aborted) {
traceConversionPhase({
phase: "caller-timeout",
outcome: "timeout",
detail: `Caller-Budget ${Math.ceil(getUnrestrictTimeoutMs() / 1000)}s erschoepft (siehe letzte Phase fuer in-flight Provider/Account)`
});
}
throw innerError;
}
}
);
} catch (unrestrictError) {
if (!active.abortController.signal.aborted && unrestrictTimeoutSignal.aborted) {
this.recordProviderFailure(cooldownProvider);
+11 -1
View File
@@ -1,5 +1,6 @@
import { UnrestrictedLink } from "./realdebrid";
import { compactErrorText, filenameFromUrl, sleep } from "./utils";
import { traceConversionPhase } from "./conversion-trace";
type MegaCredentials = {
login: string;
@@ -287,9 +288,18 @@ export class MegaWebFallback {
throwIfAborted(signal);
const waited = Date.now() - queuedAt;
if (waited > QUEUE_WAIT_TIMEOUT_MS) {
traceConversionPhase({ phase: "web-queue", provider: "megadebrid-web", queueWaitMs: waited, outcome: "queue-timeout", detail: `${Math.floor(waited / 1000)}s in Web-Queue gewartet` });
throw new Error(`Mega-Web Queue-Timeout (${Math.floor(waited / 1000)}s gewartet)`);
}
return job();
const workStartedAt = Date.now();
try {
const result = await job();
traceConversionPhase({ phase: "web-queue", provider: "megadebrid-web", queueWaitMs: waited, workMs: Date.now() - workStartedAt, outcome: "ok" });
return result;
} catch (jobError) {
traceConversionPhase({ phase: "web-queue", provider: "megadebrid-web", queueWaitMs: waited, workMs: Date.now() - workStartedAt, outcome: "error", detail: compactErrorText(jobError).slice(0, 100) });
throw jobError;
}
};
const prev = this.queues.get(key) ?? Promise.resolve();
const run = prev.then(guardedJob, guardedJob);
+3
View File
@@ -3,6 +3,7 @@ import path from "node:path";
import AdmZip from "adm-zip";
import { APP_VERSION } from "./constants";
import { getAccountRotationLogPath } from "./account-rotation-log";
import { getConversionLogPath } from "./conversion-trace";
import { getAuditLogPath } from "./audit-log";
import { getDebugSetupCheck } from "./debug-setup";
import { getLogFilePath } from "./logger";
@@ -191,6 +192,8 @@ export function buildSupportBundle(manager: DownloadManager, baseDir: string, op
addFileIfExists(zip, getTraceLogPath() ? `${getTraceLogPath()}.old` : null, "logs/trace.log.old");
addFileIfExists(zip, getAccountRotationLogPath(), "logs/account-rotation.log");
addFileIfExists(zip, getAccountRotationLogPath() ? `${getAccountRotationLogPath()}.old` : null, "logs/account-rotation.log.old");
addFileIfExists(zip, getConversionLogPath(), "logs/conversion.log");
addFileIfExists(zip, getConversionLogPath() ? `${getConversionLogPath()}.old` : null, "logs/conversion.log.old");
const SUPPORT_BUNDLE_LOG_WINDOW_MS = 8 * 60 * 60 * 1000;
addDirectoryIfExists(zip, path.join(baseDir, "session-logs"), "logs/session-logs");