Fix codex
This commit is contained in:
14
open-sse/utils/debugLog.js
Normal file
14
open-sse/utils/debugLog.js
Normal file
@@ -0,0 +1,14 @@
|
||||
// Debug logging utility — only active in dev mode (NODE_ENV !== "production")
|
||||
// Outputs are tagged with [DBG:tag] for easy grep/filter
|
||||
const isDev = process.env.NODE_ENV !== "production";
|
||||
|
||||
function ts() {
|
||||
return new Date().toLocaleTimeString("en-US", { hour12: false, hour: "2-digit", minute: "2-digit", second: "2-digit" });
|
||||
}
|
||||
|
||||
export function dbg(tag, msg) {
|
||||
if (!isDev) return;
|
||||
console.log(`[${ts()}] 🐛 [DBG:${tag}] ${msg}`);
|
||||
}
|
||||
|
||||
export const isDebugEnabled = isDev;
|
||||
@@ -1,9 +1,101 @@
|
||||
import { Readable } from "stream";
|
||||
import { MEMORY_CONFIG } from "../config/runtimeConfig.js";
|
||||
import { dbg } from "./debugLog.js";
|
||||
|
||||
const originalFetch = globalThis.fetch;
|
||||
const proxyDispatchers = new Map();
|
||||
|
||||
// ─── TLS fingerprinting via got-scraping (browser-like JA3) ───────────────
|
||||
// Lazy-loaded once; if import fails (missing optional native deps in some
|
||||
// envs) we silently fall back to native fetch — no behavioral change.
|
||||
let _gotScraping = null;
|
||||
let _gotScrapingChecked = false;
|
||||
const _gotScrapingLoggedHosts = new Set();
|
||||
|
||||
async function getGotScraping() {
|
||||
if (_gotScrapingChecked) return _gotScraping;
|
||||
_gotScrapingChecked = true;
|
||||
try {
|
||||
const mod = await import("got-scraping");
|
||||
_gotScraping = typeof mod.gotScraping === "function" ? mod.gotScraping : null;
|
||||
if (_gotScraping) dbg("TLS", "got-scraping loaded (browser-like JA3 enabled)");
|
||||
} catch (e) {
|
||||
console.warn(`[ProxyFetch] got-scraping unavailable, falling back to native fetch: ${e.message}`);
|
||||
_gotScraping = null;
|
||||
}
|
||||
return _gotScraping;
|
||||
}
|
||||
|
||||
// Run a request through got-scraping streaming, return a fetch-compatible Response
|
||||
async function gotScrapingFetch(url, options) {
|
||||
const gs = await getGotScraping();
|
||||
if (!gs) return null;
|
||||
|
||||
const method = (options.method || "GET").toUpperCase();
|
||||
const headersInit = options.headers || {};
|
||||
const headers = headersInit instanceof Headers
|
||||
? Object.fromEntries(headersInit.entries())
|
||||
: { ...headersInit };
|
||||
|
||||
return new Promise((resolve, reject) => {
|
||||
let settled = false;
|
||||
const stream = gs.stream({
|
||||
url,
|
||||
method,
|
||||
headers,
|
||||
body: method === "GET" || method === "HEAD" ? undefined : options.body,
|
||||
throwHttpErrors: false,
|
||||
retry: { limit: 0 },
|
||||
timeout: { request: undefined }, // streaming → no overall timeout
|
||||
followRedirect: false,
|
||||
decompress: true,
|
||||
});
|
||||
|
||||
if (options.signal) {
|
||||
const onAbort = () => { try { stream.destroy(new Error("aborted")); } catch { /* noop */ } };
|
||||
if (options.signal.aborted) onAbort();
|
||||
else options.signal.addEventListener("abort", onAbort, { once: true });
|
||||
}
|
||||
|
||||
stream.once("response", (res) => {
|
||||
if (settled) return;
|
||||
settled = true;
|
||||
const resHeaders = new Headers();
|
||||
for (const [k, v] of Object.entries(res.headers || {})) {
|
||||
if (Array.isArray(v)) v.forEach((x) => resHeaders.append(k, String(x)));
|
||||
else if (v != null) resHeaders.set(k, String(v));
|
||||
}
|
||||
const body = Readable.toWeb(stream);
|
||||
resolve(new Response(body, { status: res.statusCode, statusText: res.statusMessage || "", headers: resHeaders }));
|
||||
});
|
||||
|
||||
stream.once("error", (err) => {
|
||||
if (settled) return;
|
||||
settled = true;
|
||||
reject(err);
|
||||
});
|
||||
});
|
||||
}
|
||||
|
||||
async function tryGotScrapingFetch(url, options) {
|
||||
try {
|
||||
const res = await gotScrapingFetch(url, options);
|
||||
if (res) {
|
||||
try {
|
||||
const host = new URL(typeof url === "string" ? url : url.toString()).hostname;
|
||||
if (!_gotScrapingLoggedHosts.has(host)) {
|
||||
_gotScrapingLoggedHosts.add(host);
|
||||
dbg("TLS", `using got-scraping for ${host}`);
|
||||
}
|
||||
} catch { /* noop */ }
|
||||
}
|
||||
return res;
|
||||
} catch (e) {
|
||||
console.warn(`[ProxyFetch] got-scraping request failed, fallback to native fetch: ${e.message}`);
|
||||
return null;
|
||||
}
|
||||
}
|
||||
|
||||
// DNS cache — use Map to avoid prototype pollution via malformed hostnames
|
||||
const DNS_CACHE = new Map();
|
||||
const MITM_BYPASS_HOSTS = [
|
||||
@@ -255,6 +347,8 @@ export async function proxyAwareFetch(url, options = {}, proxyOptions = null) {
|
||||
}
|
||||
}
|
||||
|
||||
// got-scraping disabled — use native fetch directly
|
||||
// (Re-enable per-host by wrapping with tryGotScrapingFetch when needed)
|
||||
return originalFetch(url, options);
|
||||
}
|
||||
|
||||
|
||||
@@ -3,6 +3,7 @@ import { FORMATS } from "../translator/formats.js";
|
||||
import { trackPendingRequest, appendRequestLog } from "@/lib/usageDb.js";
|
||||
import { extractUsage, hasValidUsage, estimateUsage, logUsage, addBufferToUsage, filterUsageForFormat, COLORS } from "./usageTracking.js";
|
||||
import { parseSSELine, hasValuableContent, fixInvalidId, formatSSE } from "./streamHelpers.js";
|
||||
import { dbg, isDebugEnabled } from "./debugLog.js";
|
||||
|
||||
export { COLORS, formatSSE };
|
||||
|
||||
@@ -58,11 +59,15 @@ export function createSSEStream(options = {}) {
|
||||
let accumulatedContent = "";
|
||||
let accumulatedThinking = "";
|
||||
let ttftAt = null;
|
||||
let sseLineCount = 0;
|
||||
let sseEmittedCount = 0;
|
||||
const eventTypeCounts = {};
|
||||
|
||||
return new TransformStream({
|
||||
transform(chunk, controller) {
|
||||
if (!ttftAt) {
|
||||
ttftAt = Date.now();
|
||||
dbg("SSE", `${provider}/${model} | first chunk received | size=${chunk?.byteLength || 0}B`);
|
||||
}
|
||||
const text = decoder.decode(chunk, { stream: true });
|
||||
buffer += text;
|
||||
@@ -73,6 +78,14 @@ export function createSSEStream(options = {}) {
|
||||
|
||||
for (const line of lines) {
|
||||
const trimmed = line.trim();
|
||||
if (isDebugEnabled && trimmed) {
|
||||
sseLineCount++;
|
||||
if (trimmed.startsWith("event:")) {
|
||||
const evt = trimmed.slice(6).trim();
|
||||
eventTypeCounts[evt] = (eventTypeCounts[evt] || 0) + 1;
|
||||
if (eventTypeCounts[evt] <= 2) dbg("SSE", `recv event: ${evt} (#${eventTypeCounts[evt]})`);
|
||||
}
|
||||
}
|
||||
|
||||
// Passthrough mode: normalize and forward
|
||||
if (mode === STREAM_MODE.PASSTHROUGH) {
|
||||
@@ -248,12 +261,15 @@ export function createSSEStream(options = {}) {
|
||||
const output = formatSSE(item, sourceFormat);
|
||||
reqLogger?.appendConvertedChunk?.(output);
|
||||
controller.enqueue(sharedEncoder.encode(output));
|
||||
sseEmittedCount++;
|
||||
}
|
||||
}
|
||||
}
|
||||
},
|
||||
|
||||
flush(controller) {
|
||||
const evtSummary = Object.entries(eventTypeCounts).map(([k, v]) => `${k}=${v}`).join(",") || "none";
|
||||
dbg("SSE", `flush | provider=${provider} | model=${model} | recvLines=${sseLineCount} | emitted=${sseEmittedCount} | events=[${evtSummary}]`);
|
||||
trackPendingRequest(model, provider, connectionId, false);
|
||||
try {
|
||||
const remaining = decoder.decode();
|
||||
|
||||
@@ -1,5 +1,6 @@
|
||||
// Stream handler with disconnect detection - shared for all providers
|
||||
import { STREAM_STALL_TIMEOUT_MS } from "../config/runtimeConfig.js";
|
||||
import { dbg, isDebugEnabled } from "./debugLog.js";
|
||||
|
||||
// Get HH:MM:SS timestamp
|
||||
function getTimeString() {
|
||||
@@ -38,6 +39,7 @@ export function createStreamController({ onDisconnect, onError, log, provider, m
|
||||
disconnected = true;
|
||||
|
||||
logStream(`disconnect: ${reason}`);
|
||||
dbg("CTRL", `${provider}/${model} | disconnect=${reason} | dur=${Date.now() - startTime}ms`);
|
||||
|
||||
// Delay abort to allow cleanup
|
||||
abortTimeout = setTimeout(() => {
|
||||
@@ -117,8 +119,23 @@ export function createDisconnectAwareStream(transformStream, streamController) {
|
||||
streamController.handleError(error);
|
||||
reader.cancel().catch(() => {});
|
||||
writer.abort().catch(() => {});
|
||||
|
||||
if (!wasConnected || error.name === "AbortError" || error.message?.includes("aborted")) {
|
||||
|
||||
// Treat network resets / socket hang up / abort as graceful close
|
||||
const msg = error?.message || "";
|
||||
const code = error?.code || error?.cause?.code || "";
|
||||
const isNetworkClose =
|
||||
error.name === "AbortError" ||
|
||||
msg.includes("aborted") ||
|
||||
msg.includes("socket hang up") ||
|
||||
msg.includes("ECONNRESET") ||
|
||||
msg.includes("ETIMEDOUT") ||
|
||||
msg.includes("EPIPE") ||
|
||||
code === "ECONNRESET" ||
|
||||
code === "ETIMEDOUT" ||
|
||||
code === "EPIPE" ||
|
||||
code === "UND_ERR_SOCKET";
|
||||
|
||||
if (!wasConnected || isNetworkClose) {
|
||||
try {
|
||||
controller.close();
|
||||
} catch (e) {
|
||||
@@ -158,6 +175,11 @@ export function createDisconnectAwareStream(transformStream, streamController) {
|
||||
*/
|
||||
export function pipeWithDisconnect(providerResponse, transformStream, streamController) {
|
||||
let stallTimer = null;
|
||||
let chunkCount = 0;
|
||||
let totalBytes = 0;
|
||||
let lastChunkAt = Date.now();
|
||||
const t0 = Date.now();
|
||||
const tag = "STREAM";
|
||||
const clearStall = () => {
|
||||
if (stallTimer) { clearTimeout(stallTimer); stallTimer = null; }
|
||||
};
|
||||
@@ -165,6 +187,7 @@ export function pipeWithDisconnect(providerResponse, transformStream, streamCont
|
||||
clearStall();
|
||||
stallTimer = setTimeout(() => {
|
||||
stallTimer = null;
|
||||
dbg(tag, `STALL TIMEOUT ${STREAM_STALL_TIMEOUT_MS}ms | chunks=${chunkCount} | bytes=${totalBytes} | sinceLast=${Date.now() - lastChunkAt}ms`);
|
||||
streamController.handleError?.(new Error("stream stall timeout"));
|
||||
streamController.abort?.();
|
||||
}, STREAM_STALL_TIMEOUT_MS);
|
||||
@@ -177,20 +200,30 @@ export function pipeWithDisconnect(providerResponse, transformStream, streamCont
|
||||
signal: streamController.signal,
|
||||
startTime: streamController.startTime,
|
||||
isConnected: () => streamController.isConnected(),
|
||||
handleComplete: () => { clearStall(); streamController.handleComplete(); },
|
||||
handleError: (e) => { clearStall(); streamController.handleError(e); },
|
||||
handleDisconnect: (r) => { clearStall(); streamController.handleDisconnect(r); },
|
||||
handleComplete: () => { dbg(tag, `complete | chunks=${chunkCount} | bytes=${totalBytes} | dur=${Date.now() - t0}ms`); clearStall(); streamController.handleComplete(); },
|
||||
handleError: (e) => { dbg(tag, `error: ${e?.message} | chunks=${chunkCount} | bytes=${totalBytes} | dur=${Date.now() - t0}ms`); clearStall(); streamController.handleError(e); },
|
||||
handleDisconnect: (r) => { dbg(tag, `disconnect: ${r} | chunks=${chunkCount} | bytes=${totalBytes} | dur=${Date.now() - t0}ms`); clearStall(); streamController.handleDisconnect(r); },
|
||||
abort: () => { clearStall(); streamController.abort(); }
|
||||
};
|
||||
|
||||
armStall();
|
||||
dbg(tag, `pipe start | stallTimeout=${STREAM_STALL_TIMEOUT_MS}ms`);
|
||||
|
||||
const upstreamTap = new TransformStream({
|
||||
transform(chunk, controller) {
|
||||
chunkCount++;
|
||||
const sz = chunk?.byteLength || chunk?.length || 0;
|
||||
totalBytes += sz;
|
||||
const now = Date.now();
|
||||
const gap = now - lastChunkAt;
|
||||
lastChunkAt = now;
|
||||
if (isDebugEnabled && (chunkCount <= 5 || chunkCount % 20 === 0 || gap > 5000)) {
|
||||
dbg(tag, `chunk #${chunkCount} | size=${sz}B | gap=${gap}ms | total=${totalBytes}B`);
|
||||
}
|
||||
armStall();
|
||||
controller.enqueue(chunk);
|
||||
},
|
||||
flush() { clearStall(); }
|
||||
flush() { dbg(tag, `upstream EOF | chunks=${chunkCount} | bytes=${totalBytes} | dur=${Date.now() - t0}ms`); clearStall(); }
|
||||
});
|
||||
|
||||
const transformedBody = providerResponse.body
|
||||
|
||||
Reference in New Issue
Block a user