feat(oneshot): add ONESHOT_DEBUG verbose logging mode

Adds a debug flag (ONESHOT_DEBUG=true / --debug / npm run oneshot-debug) that surfaces the engine's internal decision process at every key step. Debug output tags ───────────────── [DBG:FEED] — Market discovery: every slug probed, API response status, token IDs extracted, tick size fetched. Throttled poll summary every 10 ticks per market showing bid/ask/spread/mid/depth for both UP and DOWN sides. [DBG:GATE] — Hard gate result every 5 evaluations per market: TTE range, spread width, depth thinness, stale flag. Shows exact gate fail reason or PASS confirmation. [DBG:FEAT] — Feature breakdown for each side every 5 evals: slope, imbalance, spread, retrace raw values plus per-component scores and weighted total. [DBG:SCORE] — Per-side qualify check: score vs threshold, trend confirm flag, and QUALIFY / skip verdict. [DBG:SIGNAL] — Always logged (no throttle) when an ENTER signal fires. [DBG:HEART] — 5-second heartbeat: active markets, per-market SM state, dailyPnl, consecLosses, cooldownLeft, halted flag. New script ────────── npm run oneshot-debug → DRY_RUN=true ONESHOT_DEBUG=true node src/oneshot.js Co-Authored-By: direkturcrypto <direkturcrypto.x@mail3.me>
2026-02-24 13:29:26 +07:00
parent f074ca9ecb
commit 202bf98fe7
6 changed files with 179 additions and 18 deletions
@@ -166,3 +166,8 @@ ONESHOT_DAILY_LOSS_CAP=20

 # Maximum milliseconds to wait for a FOK fill ack (timeout → cancel → IDLE)
 ONESHOT_FILL_TIMEOUT_MS=800
+
+# Enable verbose debug logging (discovery probes, gate results, feature scores, heartbeat)
+# Can also be enabled with: npm run oneshot-debug
+# Or on the command line: ONESHOT_DEBUG=true npm run oneshot
+ONESHOT_DEBUG=false
@@ -15,7 +15,8 @@
    "sniper-dev": "DRY_RUN=true nodemon --ignore 'data/*.json' src/sniper.js",
    "oneshot": "DRY_RUN=false node src/oneshot.js",
    "oneshot-sim": "DRY_RUN=true node src/oneshot.js",
-    "oneshot-dev": "DRY_RUN=true nodemon --ignore 'data/*.json' src/oneshot.js"
+    "oneshot-dev": "DRY_RUN=true nodemon --ignore 'data/*.json' src/oneshot.js",
+    "oneshot-debug": "DRY_RUN=true ONESHOT_DEBUG=true node src/oneshot.js"
  },
  "keywords": [
    "polymarket",
@@ -33,6 +33,7 @@ import { RiskEngine }       from './oneshot/RiskEngine.js';
 import { PositionEngine }   from './oneshot/PositionEngine.js';
 import { Telemetry }        from './oneshot/Telemetry.js';
 import { State, Signal, ReasonCode } from './oneshot/constants.js';
+import { DEBUG, dbg } from './oneshot/debug.js';

 // ── Configuration ──────────────────────────────────────────────────────────────
 // All values read from .env.  Sensible defaults are provided for optional fields.
@@ -108,6 +109,24 @@ async function main() {
    await feedService.start();
    logger.success('OneShot Engine running — waiting for market signals...');

+    if (DEBUG) {
+        logger.info('[DBG] Debug mode active. Tags: FEED=discovery/poll, GATE=hard gates, FEAT=features, SCORE=scores, SIGNAL=entry trigger, SM=state changes');
+        // Heartbeat: every 5s log the overall engine status
+        setInterval(() => {
+            const markets = feedService.activeMarkets;
+            const states  = markets.map((slug) => {
+                const sm = stateMachines.get(slug);
+                return `${slug.split('-')[0]}:${sm?.state ?? 'none'}`;
+            }).join(' | ') || '(none)';
+            const risk = riskEngine.stats();
+            dbg('HEART',
+                `active=${markets.length} | states=[${states}] | ` +
+                `dailyPnl=$${risk.dailyPnl.toFixed(4)} | consec=${risk.consecLosses} | ` +
+                `cooldown=${risk.cooldownLeft} | halted=${risk.halted}`,
+            );
+        }, 5_000);
+    }
+
    process.on('SIGINT',  shutdown);
    process.on('SIGTERM', shutdown);
 }
@@ -17,11 +17,13 @@
 */

 import logger from '../utils/logger.js';
+import { dbg, DEBUG } from './debug.js';

-const GAMMA_HOST        = 'https://gamma-api.polymarket.com';
+const GAMMA_HOST         = 'https://gamma-api.polymarket.com';
 const STALE_THRESHOLD_MS = 1500;
-const TOP_N_LEVELS       = 5;   // Levels counted for depth calculation
+const TOP_N_LEVELS       = 5;    // Levels counted for depth calculation
 const DISCOVER_INTERVAL  = 30_000; // Re-scan for new markets every 30s
+const DEBUG_POLL_EVERY   = 10;   // Log a poll summary every N ticks per market (debug only)

 export class MarketFeedService {
    /**
@@ -43,8 +45,11 @@ export class MarketFeedService {
        /** @type {Map<string, MarketRecord>} slug → market record */
        this._markets      = new Map();

-        this._pollTimer    = null;
+        this._pollTimer     = null;
        this._discoverTimer = null;
+
+        /** Per-market tick counter for throttled debug logs */
+        this._pollCount    = new Map();
    }

    // ── Lifecycle ─────────────────────────────────────────────────────────────
@@ -54,6 +59,7 @@ export class MarketFeedService {
        this._pollTimer     = setInterval(() => this._tick().catch(() => {}), this._pollMs);
        this._discoverTimer = setInterval(() => this._discoverMarkets().catch(() => {}), DISCOVER_INTERVAL);
        logger.info(`MarketFeedService: started | assets=[${this._assets}] interval=${this._pollMs}ms`);
+        if (DEBUG) logger.info('[DBG:FEED] Debug mode ON — verbose feed logging enabled');
    }

    stop() {
@@ -78,21 +84,41 @@ export class MarketFeedService {
            this._slotTs() + durationMin * 60,
        ];

+        dbg('FEED', `--- discovery cycle | probing ${this._assets.length * slots.length} slug(s) ---`);
+
        for (const asset of this._assets) {
            for (const slotTs of slots) {
                const slug = `${asset}-updown-${this._duration}-${slotTs}`;
-                if (this._markets.has(slug)) continue;
+
+                if (this._markets.has(slug)) {
+                    dbg('FEED', `  ${slug} → already tracked, skip`);
+                    continue;
+                }
+
+                dbg('FEED', `  probing ${slug} ...`);

                try {
                    const market = await this._fetchMarketBySlug(slug);
-                    if (!market) continue;
+
+                    if (!market) {
+                        dbg('FEED', `  ${slug} → not found on Gamma API`);
+                        continue;
+                    }

                    const endTs = this._parseEndTs(market);
-                    if (!endTs || Date.now() >= endTs) continue;
+                    if (!endTs) {
+                        dbg('FEED', `  ${slug} → found but endTs unparseable`);
+                        continue;
+                    }
+                    if (Date.now() >= endTs) {
+                        dbg('FEED', `  ${slug} → found but already expired`);
+                        continue;
+                    }

                    const { upTokenId, downTokenId } = this._extractTokenIds(market);
                    if (!upTokenId || !downTokenId) {
                        logger.warn(`MarketFeedService: could not extract token IDs for ${slug}`);
+                        dbg('FEED', `  tokens shape: ${JSON.stringify(Object.keys(market).slice(0, 10))}`);
                        continue;
                    }

@@ -110,20 +136,29 @@ export class MarketFeedService {

                    const secLeft = Math.floor((endTs - Date.now()) / 1000);
                    logger.success(`MarketFeedService: tracking ${slug} (closes in ${secLeft}s)`);
+                    dbg('FEED', `  upToken=${upTokenId.slice(0, 12)}... downToken=${downTokenId.slice(0, 12)}... tick=${tickSize}`);

-                } catch {
+                } catch (err) {
+                    dbg('FEED', `  ${slug} → discovery error: ${err.message}`);
                    // Network blip — will retry on next discovery cycle
                }
            }
        }

-        // Prune expired markets (add a 5s grace period for final snapshots)
+        // Prune expired markets (5s grace period for final snapshots)
        for (const [slug, mkt] of this._markets) {
            if (Date.now() > mkt.endTs + 5_000) {
                this._markets.delete(slug);
+                this._pollCount.delete(slug);
                logger.info(`MarketFeedService: pruned expired market ${slug}`);
            }
        }
+
+        if (this._markets.size === 0) {
+            dbg('FEED', 'No active markets found — will retry in 30s');
+        } else {
+            dbg('FEED', `Active markets: [${[...this._markets.keys()].join(', ')}]`);
+        }
    }

    /** Deterministic UTC slot boundary timestamp (seconds) */
@@ -185,6 +220,8 @@ export class MarketFeedService {
    // ── Book polling ──────────────────────────────────────────────────────────

    async _tick() {
+        if (this._markets.size === 0) return;
+
        for (const [, mkt] of this._markets) {
            const tteSec = Math.floor((mkt.endTs - Date.now()) / 1000);
            if (tteSec <= 0) continue;
@@ -203,8 +240,29 @@ export class MarketFeedService {
                const snapshot = this._buildSnapshot(mkt, upBook, downBook, tteSec, stale);
                this._eventBus.emit('snapshot', snapshot);

-            } catch {
-                // Silent — stale snapshot will suppress entry via gate check
+                // ── Debug: throttled poll summary (every N ticks) ─────────────
+                if (DEBUG) {
+                    const count = (this._pollCount.get(mkt.slug) ?? 0) + 1;
+                    this._pollCount.set(mkt.slug, count);
+
+                    if (count % DEBUG_POLL_EVERY === 1) {
+                        const u = snapshot.up;
+                        const d = snapshot.down;
+                        const staleFlag = stale ? ' [STALE]' : '';
+                        dbg('POLL',
+                            `${mkt.slug} | tte=${tteSec}s | fetchMs=${fetchMs}ms${staleFlag}\n` +
+                            `         UP   bid=${u.bestBid.toFixed(4)}/ask=${u.bestAsk.toFixed(4)} ` +
+                                `spread=${u.spread.toFixed(4)} mid=${u.mid.toFixed(4)} ` +
+                                `depthBid=${u.depthBid.toFixed(1)} depthAsk=${u.depthAsk.toFixed(1)}\n` +
+                            `         DOWN bid=${d.bestBid.toFixed(4)}/ask=${d.bestAsk.toFixed(4)} ` +
+                                `spread=${d.spread.toFixed(4)} mid=${d.mid.toFixed(4)} ` +
+                                `depthBid=${d.depthBid.toFixed(1)} depthAsk=${d.depthAsk.toFixed(1)}`,
+                        );
+                    }
+                }
+
+            } catch (err) {
+                dbg('POLL', `${mkt.slug} → poll error: ${err.message}`);
            }
        }
    }
@@ -240,7 +298,7 @@ export class MarketFeedService {
            : (bestBid || bestAsk || 0.5);
        const spread   = Math.max(0, bestAsk - bestBid);

-        const topN    = Math.min(TOP_N_LEVELS, Math.max(bids.length, asks.length));
+        const topN     = Math.min(TOP_N_LEVELS, Math.max(bids.length, asks.length));
        const depthBid = bids.slice(0, topN).reduce((s, l) => s + l.size, 0);
        const depthAsk = asks.slice(0, topN).reduce((s, l) => s + l.size, 0);

@@ -14,6 +14,7 @@
 */

 import { Signal, ReasonCode } from './constants.js';
+import { dbg, DEBUG } from './debug.js';

 // ── Score weights ──────────────────────────────────────────────────────────────
 const W_IMBALANCE = 0.35;
@@ -33,6 +34,9 @@ const RETRACE_MID   = 0.35;    // Moderate retrace
 const CONFIRM_SLOPE = 0.0001;  // Minimum positive slope for trend confirmation
 const CONFIRM_RTRC  = 0.30;    // Maximum retrace for trend confirmation

+/** Throttle debug output: log gate+score detail every N evaluations per market */
+const DEBUG_EVERY = 5;
+
 export class SignalEngine {
    /**
     * @param {Object} opts
@@ -49,6 +53,9 @@ export class SignalEngine {
        this._tteMin         = tteMin;
        this._tteMax         = tteMax;

+        /** Per-market evaluation counter for throttled debug logs */
+        this._evalCount = new Map();
+
        this._eventBus.on('features', (feat) => this._onFeatures(feat));
    }

@@ -57,9 +64,30 @@ export class SignalEngine {
    _onFeatures(feat) {
        const { ts, marketSlug, tteSec, up, down, snapshot } = feat;

+        // Track evaluation count for throttled debug output
+        const evalN = (this._evalCount.get(marketSlug) ?? 0) + 1;
+        this._evalCount.set(marketSlug, evalN);
+        const logThis = DEBUG && (evalN % DEBUG_EVERY === 1);
+
        // ── Step C: hard gate check ─────────────────────────────────────────

        const gate = this._hardGates(snapshot, tteSec);
+
+        if (logThis) {
+            if (!gate.pass) {
+                dbg('GATE',
+                    `${marketSlug} | tte=${tteSec}s | FAIL → ${gate.reason} | ` +
+                    `upSprd=${snapshot.up.spread.toFixed(4)} dnSprd=${snapshot.down.spread.toFixed(4)} ` +
+                    `upBidSz=${snapshot.up.bestBidSize.toFixed(1)} upAskSz=${snapshot.up.bestAskSize.toFixed(1)}`,
+                );
+            } else {
+                dbg('GATE',
+                    `${marketSlug} | tte=${tteSec}s | PASS | ` +
+                    `upSprd=${snapshot.up.spread.toFixed(4)} dnSprd=${snapshot.down.spread.toFixed(4)}`,
+                );
+            }
+        }
+
        if (!gate.pass) {
            this._emit(marketSlug, Signal.NO_TRADE, null, 0, gate.reason, ts, snapshot, feat);
            return;
@@ -67,15 +95,22 @@ export class SignalEngine {

        // ── Step D: evaluate each side, pick best qualifying signal ─────────

-        const upResult   = this._evaluateSide(up,   snapshot.up);
-        const downResult = this._evaluateSide(down, snapshot.down);
+        const upResult   = this._evaluateSide(up,   snapshot.up,   marketSlug, 'UP',   logThis);
+        const downResult = this._evaluateSide(down, snapshot.down, marketSlug, 'DOWN', logThis);

        // Determine which side (if any) qualifies
        const upQual   = upResult.score   >= this._scoreThreshold && upResult.confirmed;
        const downQual = downResult.score >= this._scoreThreshold && downResult.confirmed;

+        if (logThis) {
+            dbg('SCORE',
+                `${marketSlug} | threshold=${this._scoreThreshold} | ` +
+                `UP  score=${upResult.score.toFixed(3)} confirmed=${upResult.confirmed} → ${upQual ? 'QUALIFY' : 'skip'} | ` +
+                `DOWN score=${downResult.score.toFixed(3)} confirmed=${downResult.confirmed} → ${downQual ? 'QUALIFY' : 'skip'}`,
+            );
+        }
+
        if (!upQual && !downQual) {
-            // Emit the reason from whichever side had the higher score
            const dominant = upResult.score >= downResult.score ? upResult : downResult;
            const reason   = dominant.confirmed ? ReasonCode.SIG_SCORE_LOW : ReasonCode.SIG_NO_CONFIRM;
            this._emit(marketSlug, Signal.NO_TRADE, null, dominant.score, reason, ts, snapshot, feat);
@@ -97,6 +132,9 @@ export class SignalEngine {
            score  = downResult.score;
        }

+        // Always log qualifying entries regardless of throttle
+        dbg('SIGNAL', `>>> ${signal} | ${marketSlug} | score=${score.toFixed(3)} | tte=${tteSec}s`);
+
        this._emit(marketSlug, signal, side, score, null, ts, snapshot, feat);
    }

@@ -129,12 +167,14 @@ export class SignalEngine {
     * Score and confirm one side.
     * @param {Object} sideFeatures  - From FeatureEngine (midSlope6s, imbalance, ...)
     * @param {Object} sideBook      - Current BookSide from snapshot
+     * @param {string} marketSlug    - For debug logs
+     * @param {string} label         - 'UP' or 'DOWN' for debug logs
+     * @param {boolean} logThis      - Whether to emit debug output this tick
     * @returns {{ score: number, confirmed: boolean }}
     */
-    _evaluateSide(sideFeatures, sideBook) {
+    _evaluateSide(sideFeatures, sideBook, marketSlug, label, logThis) {
        const { midSlope6s, retrace3s, imbalance, spread } = sideFeatures;

-        // Score components (each 0–1, then weighted)
        const slopeScore     = this._scoreSlope(midSlope6s);
        const imbalanceScore = this._scoreImbalance(imbalance);
        const spreadScore    = this._scoreSpread(spread);
@@ -146,9 +186,19 @@ export class SignalEngine {
            W_SPREAD    * spreadScore    +
            W_RETRACE   * retraceScore;

-        // Trend confirmation: positive momentum + low retrace
        const confirmed = midSlope6s > CONFIRM_SLOPE && retrace3s < CONFIRM_RTRC;

+        if (logThis) {
+            dbg('FEAT',
+                `${marketSlug} ${label} | ` +
+                `slope=${midSlope6s.toFixed(6)}(s=${slopeScore.toFixed(2)}) ` +
+                `imb=${imbalance.toFixed(3)}(s=${imbalanceScore.toFixed(2)}) ` +
+                `sprd=${spread.toFixed(4)}(s=${spreadScore.toFixed(2)}) ` +
+                `rtrc=${retrace3s.toFixed(3)}(s=${retraceScore.toFixed(2)}) ` +
+                `→ total=${score.toFixed(3)} confirm=${confirmed}`,
+            );
+        }
+
        return { score, confirmed };
    }

@@ -0,0 +1,28 @@
+/**
+ * debug.js
+ * Lightweight debug helper for the OneShot engine.
+ *
+ * Enable by setting ONESHOT_DEBUG=true in your .env or environment,
+ * or by passing --debug on the command line:
+ *
+ *   ONESHOT_DEBUG=true npm run oneshot
+ *   npm run oneshot -- --debug
+ *   npm run oneshot-debug            (shorthand script)
+ */
+
+import logger from '../utils/logger.js';
+
+export const DEBUG = process.env.ONESHOT_DEBUG === 'true'
+    || process.argv.includes('--debug');
+
+/**
+ * Log a debug message — no-op when DEBUG is false.
+ * Prefixes every line with a [DBG <tag>] marker so you can grep by component.
+ *
+ * @param {string} tag   - Component name, e.g. 'FEED', 'GATE', 'SCORE'
+ * @param {string} msg   - Message string
+ */
+export function dbg(tag, msg) {
+    if (!DEBUG) return;
+    logger.info(`[DBG:${tag}] ${msg}`);
+}