diff --git a/lib/auto-trade.ts b/lib/auto-trade.ts index 232fcbf..368aa02 100644 --- a/lib/auto-trade.ts +++ b/lib/auto-trade.ts @@ -18,10 +18,12 @@ import { isNoTradeTime, isPastSessionClose, BIG_DAY_THRESHOLD, LEG_COMPLETION_EPSILON, MAX_LEGS_PER_DAY, FALLBACK_COMMISSION_PER_CONTRACT, MAX_COMMISSION_PER_CONTRACT, DLL_MIN_STOP, + CME_EVENING_OPEN_MIN, foldReason, type DayPlan, } from './trading-logic'; import { getSetting, setSetting } from './db'; -import { POINT_VALUES, housekeepingRoot } from './instrument-specs'; +import type { LaneTick, TickReason } from './master-protocol'; +import { POINT_VALUES, housekeepingRoot, MAX_HOLD_HOURS } from './instrument-specs'; import { firmInstruments, drawFuturesInstrument, spreadBlock, type LegShape } from './instruments'; import { errorMessage, isClientReady, isOrderNotPlaced, type PlatformClient, type PlatformContract, type PickContext } from './platform-client'; @@ -69,6 +71,9 @@ interface TradeRuntime { lastTickOutcome: TickOutcome; /** The last tick's outcome per lane. */ laneOutcomes?: Map; + /** The last tick per lane as the master sees it: what happened and why + * accounts sat it out (getSchedulerStatus). */ + laneTicks?: Map; lastFireAt: number; holding: string[]; quarantined: string[]; @@ -780,14 +785,50 @@ export async function runTrade(action: 'Buy' | 'Sell' | 'Auto', symbol: string): return results; } +/** What a lane's batch decided: its outcome, what it traded, and for the + * master a line on what happened and why accounts sat it out. */ +type BatchOutcome = { outcome: TradeOutcome; results: FirmTradeResults[]; detail?: string; reasons?: TickReason[] }; + +/** Accounts that sat a batch out, by reason. Dollar amounts are folded so + * like reasons group ("day done ($12 left of $300)" and "($40 left of $500)"). */ +type ReasonTally = Map; + +function tally(reasons: ReasonTally, reason: string, who: string): void { + const key = foldReason(reason); + const entry = reasons.get(key) ?? { count: 0, accounts: [] }; + entry.count++; + if (entry.accounts.length < 3) entry.accounts.push(who); + reasons.set(key, entry); +} + +function reasonList(reasons: ReasonTally): TickReason[] { + return [...reasons.entries()] + .map(([reason, { count, accounts }]) => ({ reason, count, accounts })) + .sort((a, b) => b.count - a.count) + .slice(0, 8); +} + +const fmtCentralMinutes = (m: number): string => { + const h = Math.floor(m / 60) % 24; + return `${h % 12 || 12}:${String(m % 60).padStart(2, '0')} ${h < 12 ? 'AM' : 'PM'} CT`; +}; + +/** Why a lane is closed, for the master: when today's session opens. */ +function closedDetail(lane: string): string { + if (lane !== FUTURES_LANE) return 'standing down around the daily roll'; + const delay = todaysSessionOpenDelay(); + const open = getSetting('trading_hours') === 'equity_hours' ? 8 * 60 + 35 + delay : CME_EVENING_OPEN_MIN + delay; + return `outside trading hours — today's open is ${fmtCentralMinutes(open)}`; +} + /** One lane's batch plus what it decided, which the tick records for getSchedulerHealth. */ async function runTradeBatch( action: 'Buy' | 'Sell' | 'Auto', symbol: string, lane: string, -): Promise<{ outcome: TradeOutcome; results: FirmTradeResults[] }> { +): Promise { const lease = acquireTradeMutex('[auto-trade]', lane); - if (lease === null) return { outcome: 'skipped-in-flight', results: [] }; + if (lease === null) return { outcome: 'skipped-in-flight', results: [], detail: 'another batch is still in flight' }; try { return await runTradeLocked(action, symbol, lease, lane); } finally { @@ -822,11 +863,11 @@ async function runTradeLocked( symbol: string, lease: number, lane: string, -): Promise<{ outcome: TradeOutcome; results: FirmTradeResults[] }> { +): Promise { const laneFirms = getTradableFirms().filter((f) => laneOf(f) === lane); if (laneFirms.every((f) => isInNoTradeWindow(f))) { console.log(`[auto-trade] ${laneName(lane)}: market closed — skipping`); - return { outcome: 'closed', results: [] }; + return { outcome: 'closed', results: [], detail: closedDetail(lane) }; } // Block if any account in the lane still has an open position (same gate @@ -836,7 +877,7 @@ async function runTradeLocked( const openPositions = countOpenPositions(laneReady); if (openPositions > 0) { console.log(`[auto-trade] ${laneName(lane)}: ${openPositions} position(s) still open — skipping`); - return { outcome: 'positions-open', results: [] }; + return { outcome: 'positions-open', results: [], detail: `${openPositions} position(s) still open` }; } const open = laneReady.filter(({ firm }) => !isInNoTradeWindow(firm)); @@ -858,16 +899,22 @@ async function runTradeLocked( type Candidate = SizingItem & { daysTraded: number; isExtraDay: boolean }; type EligibleItem = LegItem & { daysTraded: number; isExtraDay: boolean }; const allEligible: Candidate[] = []; + // Why accounts sat this batch out (accounts with no type aren't ours), + // and what stopped the batch itself — for the master. + const reasons: ReasonTally = new Map(); + const notes = new Set(); for (const { firm, client } of open) { if (client.accountList.length === 0) continue; const listed = firmInstruments(firm); if (listed.length === 0) { console.log(`[auto-trade] ${firm.name}: no instruments listed — skipping firm`); + tally(reasons, 'its firm lists no instruments', firm.name); continue; } if (explicit && !listed.includes(explicit)) { console.log(`[auto-trade] ${firm.name}: ${explicit} isn't on its instrument list — skipping firm`); + tally(reasons, `${explicit} isn't on its firm's list`, firm.name); continue; } // One firm's trouble (a malformed snapshot) skips that firm, never @@ -875,7 +922,11 @@ async function runTradeLocked( try { for (const acc of client.accountList) { const ev = evaluateAccountForTrade(client, acc, tradeDate); - if (!ev || !ev.eligible || !ev.plan) continue; + if (!ev) continue; + if (!ev.eligible || !ev.plan) { + tally(reasons, ev.reason || 'no day plan', acc.name); + continue; + } allEligible.push({ firmName: firm.name, firm, client, acc, cash: ev.cash, dailyPnL: ev.dailyPnL, daysTraded: ev.daysTraded, @@ -886,12 +937,13 @@ async function runTradeLocked( } } catch (err) { console.error(`[auto-trade] ${firm.name}: skipped — ${errorMessage(err)}`); + tally(reasons, `firm skipped — ${errorMessage(err)}`, firm.name); } } if (allEligible.length === 0) { console.log(`[auto-trade] ${laneName(lane)}: no eligible accounts found`); - return { outcome: 'no-eligible', results: [] }; + return { outcome: 'no-eligible', results: [], detail: 'no eligible accounts', reasons: reasonList(reasons) }; } // Take only the first batch — all fired simultaneously, no rolling pool. @@ -932,7 +984,10 @@ async function runTradeLocked( const tried: string[] = []; for (let attempt = 0; attempt < 3 && batch.length === 0; attempt++) { const root = explicit ?? await drawFuturesInstrument(allowed.filter((r) => !tried.includes(r)), shape); - if (!root) break; + if (!root) { + notes.add(`nothing on ${prefix || 'its'} list fits right now (spread or ${MAX_HOLD_HOURS}h hold cap)`); + break; + } tried.push(root); // Paying more than the master's limit to cross the book: // not this tick (the draw left it out already; an explicit @@ -940,6 +995,7 @@ async function runTradeLocked( const wide = spreadBlock(root); if (wide) { console.log(`[auto-trade] ${wide} — not trading it this tick`); + notes.add(wide); if (explicit) break; continue; } @@ -950,11 +1006,13 @@ async function runTradeLocked( const pv = contract?.pointValue ?? POINT_VALUES[root]; if (!contract || !pv) { console.log(`[auto-trade] ${firm.name}: no ${root} contract — leaving its accounts out`); + notes.add(`${firm.name}: no ${root} contract`); continue; } resolved.push(...pool.filter((it) => it.firm.id === firm.id).map((it) => ({ ...it, contract, pv }))); } catch (err) { console.error(`[auto-trade] ${firm.name}: ${root} contract lookup failed — ${errorMessage(err)}`); + notes.add(`${firm.name}: ${root} contract lookup failed`); } } if (resolved.length > 0) { @@ -974,9 +1032,11 @@ async function runTradeLocked( resolvedSymbol = String(contract.id); } else { console.log(`[auto-trade] ${firm.name}: nothing on its list can trade right now`); + notes.add(`${firm.name}: nothing on its list can trade right now`); } } catch (err) { console.error(`[auto-trade] ${firm.name}: instrument pick failed — ${errorMessage(err)}`); + notes.add(`${firm.name}: instrument pick failed — ${errorMessage(err)}`); } } if (batch.length > 0) { @@ -987,7 +1047,11 @@ async function runTradeLocked( if (batch.length === 0) { console.log(`[auto-trade] ${laneName(lane)}: nothing tradable for any eligible group`); - return { outcome: 'no-eligible', results: [] }; + return { + outcome: 'no-eligible', results: [], + detail: `${allEligible.length} eligible, nothing tradable${notes.size ? ` — ${[...notes].join('; ')}` : ''}`, + reasons: reasonList(reasons), + }; } // Choosing took so long that another batch presumed this one wedged and @@ -995,7 +1059,7 @@ async function runTradeLocked( // firing now could trade an account twice. if (!holdsTradeMutex(lease, lane)) { console.warn('[auto-trade] superseded while collecting accounts — abandoning this batch'); - return { outcome: 'skipped-in-flight', results: [] }; + return { outcome: 'skipped-in-flight', results: [], detail: 'superseded by another batch while choosing' }; } console.log(`[auto-trade] ${laneName(lane)}: ${allEligible.length} eligible account(s) across ${groups.size} prefix group(s) — firing batch of ${batch.length} ${batchPrefix || '(no prefix)'} on ${resolvedSymbol}`); @@ -1057,9 +1121,19 @@ async function runTradeLocked( ); } + const all = [...firmResultsMap.values()].flat(); + const filledCount = all.filter((r) => r.status === 'filled').length; + const failed = all.filter((r) => r.status === 'error'); + // Accounts left for a later batch aren't benched: the next tick fires them. + for (const item of allEligible) { + if (!batch.some((b) => b.acc.id === item.acc.id)) tally(reasons, 'eligible — waits for a later batch', item.acc.name); + } return { outcome: 'fired', results: Array.from(firmResultsMap.entries()).map(([firm, results]) => ({ firm, results })), + detail: `fired ${batch.length} × ${batchPrefix || '(no prefix)'} on ${resolvedSymbol}: ${filledCount} filled` + + (failed.length ? `, ${failed.length} failed (${String(failed[0].reason ?? '').slice(0, 120)})` : ''), + reasons: reasonList(reasons), }; } @@ -1770,13 +1844,25 @@ export function startScheduler(action: 'Buy' | 'Sell' | 'Auto', symbol: string, } const outcomes = new Map(); + const ticks = new Map(); + const record = (lane: string, outcome: TickOutcome, detail: string, reasons?: TickReason[]) => { + outcomes.set(lane, outcome); + ticks.set(lane, { + lane: laneName(lane), + at: new Date(now).toISOString(), + outcome, + detail: detail.slice(0, 300), + ...(reasons && reasons.length > 0 ? { reasons } : {}), + }); + }; let filled = 0; for (const lane of tradableLanes()) { try { const laneHolding = holding.filter((f) => laneOf(f) === lane); if (laneHolding.length > 0) { - outcomes.set(lane, 'holding-for-sync'); - console.log(`[scheduler] ${laneName(lane)}: waiting for sync: ${laneHolding.map((f) => f.name).join(', ')}`); + const names = laneHolding.map((f) => f.name).join(', '); + record(lane, 'holding-for-sync', `waiting for sync: ${names}`); + console.log(`[scheduler] ${laneName(lane)}: waiting for sync: ${names}`); continue; } // Skip this lane if any of its accounts still has an open @@ -1784,19 +1870,20 @@ export function startScheduler(action: 'Buy' | 'Sell' | 'Auto', symbol: string, // when every (ready) account in the lane is flat. const openPositions = countOpenPositions(inLane(ready, lane)); if (openPositions > 0) { - outcomes.set(lane, 'positions-open'); + record(lane, 'positions-open', `${openPositions} position(s) still open`); console.log(`[scheduler] ${laneName(lane)}: ${openPositions} position(s) still open — skipping tick`); continue; } - const { outcome, results } = await runTradeBatch(state.action, state.symbol, lane); - outcomes.set(lane, outcome); + const { outcome, results, detail, reasons } = await runTradeBatch(state.action, state.symbol, lane); + record(lane, outcome, detail ?? outcome, reasons); filled += results.flatMap((r) => r.results).filter((r) => r.status === 'filled').length; } catch (err) { - outcomes.set(lane, `error: ${errorMessage(err)}`); + record(lane, `error: ${errorMessage(err)}`, errorMessage(err)); console.error(`[scheduler] ${laneName(lane)}: tick error: ${errorMessage(err)}`); } } rt.laneOutcomes = outcomes; + rt.laneTicks = ticks; rt.lastTickOutcome = overallOutcome([...outcomes.values()]); if (filled > 0) console.log(`[scheduler] tick: ${filled} account(s) filled`); @@ -1880,6 +1967,8 @@ export function getSchedulerStatus() { intervalSeconds: parseInt(getSetting('tick_interval_seconds') ?? '60', 10), stopAfterAll: state.stopAfterAll, sessionOpenDelayMin: todaysSessionOpenDelay(), + // A stopped scheduler keeps its last ticks, each with its time. + lastTicks: [...(runtime().laneTicks?.values() ?? [])], }; } diff --git a/lib/master-link.ts b/lib/master-link.ts index 3044c04..db6f997 100644 --- a/lib/master-link.ts +++ b/lib/master-link.ts @@ -23,6 +23,7 @@ import { futuresRootsHere } from './instruments'; import { queueRun } from './queue-run'; import { pushBackup } from './backup-sync'; import { getBuildVersion } from './version'; +import { updaterStatus } from './updater-status'; import type { Command, InstanceCapabilities, @@ -185,6 +186,7 @@ export function pushReport(firms: unknown[], scheduler: unknown): boolean { scheduler: scheduler as never, capabilities: collectCapabilities(), version: getBuildVersion() ?? undefined, + updater: updaterStatus(), }); } diff --git a/lib/master-protocol.ts b/lib/master-protocol.ts index 5453137..998f2ae 100644 --- a/lib/master-protocol.ts +++ b/lib/master-protocol.ts @@ -191,9 +191,54 @@ export interface SchedulerState { lastRun: string | null; intervalSeconds: number; stopAfterAll?: boolean; - /** Today's random session-open delay in minutes (1–20), drawn once per - * Central-time day. Optional so an older master simply ignores it. */ + /** Today's random session-open delay in minutes (0–180, after 5:45 PM + * CT), drawn once per Central-time day. Optional so an older master + * simply ignores it. */ sessionOpenDelayMin?: number; + /** What the last tick did in each lane, and why accounts sat it out. + * Optional so an older master simply ignores it. */ + lastTicks?: LaneTick[]; +} + +/** Accounts that sat a tick out for one reason (dollar amounts folded, so + * like reasons group), with a few of their names. */ +export interface TickReason { + reason: string; + count: number; + accounts: string[]; +} + +/** What the scheduler's last tick did in one lane. */ +export interface LaneTick { + /** "futures", or the every-day firm's name. */ + lane: string; + /** ISO time of the tick. */ + at: string; + /** fired, no-eligible, positions-open, closed, holding-for-sync, + * skipped-in-flight, or "error: …". */ + outcome: string; + /** One line on what happened: what fired, or what stopped it. */ + detail: string; + /** Why the lane's accounts weren't in the batch, most common first. */ + reasons?: TickReason[]; +} + +/** The auto-updater on this machine (scripts/update-check.mjs), read from + * the files it keeps and from git. */ +export interface UpdaterStatus { + /** Its last check (it runs every minute under PM2); null = never ran here. */ + lastCheckAt: string | null; + /** What that check found, e.g. "up to date at 1a2b3c4d" or "ERROR: …". */ + lastCheck: string | null; + /** An update that failed and waits to retry: at which step, how often. */ + failed: { target: string; step: string; at: string; attempts: number } | null; + /** The commit the running build was made from. */ + builtCommit: string | null; + /** Commits on origin this checkout doesn't have, as of the updater's + * last fetch; null when git can't say. */ + behind: number | null; + /** Tracked files edited on this machine — they can block the pull. */ + localChanges: string[]; } /** The build this instance is running — its checkout's HEAD commit. The @@ -381,5 +426,5 @@ export type MasterMessage = export type InstanceMessage = | { type: 'hello'; instance: string; id?: string; capabilities: InstanceCapabilities; version?: BuildVersion } - | { type: 'report'; firms: FirmStats[]; scheduler: SchedulerState; capabilities?: InstanceCapabilities; version?: BuildVersion } + | { type: 'report'; firms: FirmStats[]; scheduler: SchedulerState; capabilities?: InstanceCapabilities; version?: BuildVersion; updater?: UpdaterStatus } | { type: 'ack'; id: string; ok: boolean; result?: unknown; error?: string }; diff --git a/lib/reporter.ts b/lib/reporter.ts index 1215d0f..e03e0fc 100644 --- a/lib/reporter.ts +++ b/lib/reporter.ts @@ -14,6 +14,7 @@ import { getSetting, loadEndedCycleStart } from './db'; import { pushReport } from './master-link'; import { getBuildVersion } from './version'; +import { updaterStatus } from './updater-status'; import { getClients } from './clients'; import { getTradableFirms } from './firm-catalog'; import { getAccountConfig } from './account-type-resolver'; @@ -505,6 +506,7 @@ export async function sendReport(): Promise { firms, scheduler, version: getBuildVersion() ?? undefined, + updater: updaterStatus(), }), }); } catch { diff --git a/lib/trading-logic.ts b/lib/trading-logic.ts index 4aadabe..373e58d 100644 --- a/lib/trading-logic.ts +++ b/lib/trading-logic.ts @@ -1563,6 +1563,13 @@ function centralClock(now: Date): { day: string; minutes: number; resetMinutes: * waiting for them to go flat, and skips the open's widest spreads. */ export const CME_EVENING_OPEN_MIN = 17 * 60 + 45; +/** An account's reason for sitting a tick out, with its dollar amounts and + * "=number" values folded, so like reasons count together on the master: + * "day done ($12 left of $300)" and "day done ($40 left of $500)" are one. */ +export function foldReason(reason: string): string { + return reason.replace(/\$-?[\d,]+(?:\.\d+)?/g, '$…').replace(/=-?\d+(?:\.\d+)?/g, '=…'); +} + /** Every-day firms' roll guard ends here (plus the day's delay): they have * no Tradovate roll to wait for. */ const EVERY_DAY_OPEN_MIN = 17 * 60 + 5; diff --git a/lib/updater-status.ts b/lib/updater-status.ts new file mode 100644 index 0000000..6abd8e7 --- /dev/null +++ b/lib/updater-status.ts @@ -0,0 +1,78 @@ +/** + * The auto-updater's state on this machine (scripts/update-check.mjs), for + * the master: its last check, an update that failed and waits to retry, how + * far the checkout is behind origin, and tracked files edited by hand — which + * stop the fast-forward pull. Read from the files the updater keeps and from + * git, and cached: the reporter asks every 30 seconds. + */ + +import { execFileSync } from 'node:child_process'; +import { readFileSync } from 'node:fs'; +import path from 'node:path'; +import type { UpdaterStatus } from './master-protocol'; + +const CACHE_MS = 2 * 60_000; +const BRANCH = process.env.AUTOFIRMER_BRANCH ?? 'master'; + +// Per process: instrumentation.ts and the route handlers each load this module. +const g = globalThis as typeof globalThis & { __updaterStatus?: { at: number; status: UpdaterStatus } }; + +function readScript(file: string): string | null { + try { + return readFileSync(path.join(process.cwd(), 'scripts', file), 'utf8'); + } catch { + return null; + } +} + +function git(args: string[]): string | null { + try { + return execFileSync('git', args, { + cwd: process.cwd(), + encoding: 'utf8', + stdio: ['ignore', 'pipe', 'ignore'], + timeout: 5_000, + }).trimEnd(); + } catch { + return null; + } +} + +function readFailure(): UpdaterStatus['failed'] { + try { + const f = JSON.parse(readScript('.update-failed') ?? 'null') as Record | null; + if (!f || typeof f.target !== 'string') return null; + const at = Number(f.at); + return { + target: f.target.slice(0, 12), + step: String(f.step ?? '').slice(0, 40), + at: Number.isFinite(at) ? new Date(at).toISOString() : '', + attempts: Number(f.count) || 1, + }; + } catch { + return null; + } +} + +export function updaterStatus(now = Date.now()): UpdaterStatus { + const cached = g.__updaterStatus; + if (cached && now - cached.at < CACHE_MS) return cached.status; + + // " ", rewritten on every check. + const last = /^(\S+)\s+(.*)$/.exec(readScript('.last-check')?.trim() ?? ''); + const behind = git(['rev-list', '--count', `HEAD..origin/${BRANCH}`]); + const changed = git(['status', '--porcelain', '--untracked-files=no']); + const status: UpdaterStatus = { + lastCheckAt: last ? last[1] : null, + lastCheck: last ? last[2].slice(0, 200) : null, + failed: readFailure(), + builtCommit: readScript('.built-commit')?.trim().slice(0, 12) || null, + behind: behind !== null && /^\d+$/.test(behind) ? Number(behind) : null, + // "XY path" per line; the status column can start with a space. + localChanges: changed + ? changed.split('\n').map((line) => line.slice(3).trim()).filter(Boolean).slice(0, 10) + : [], + }; + g.__updaterStatus = { at: now, status }; + return status; +} diff --git a/scripts/check-trading-logic.mjs b/scripts/check-trading-logic.mjs index 97e8baf..787cccc 100644 --- a/scripts/check-trading-logic.mjs +++ b/scripts/check-trading-logic.mjs @@ -13,7 +13,7 @@ import { botStopsActive, sizeNotional, isNoTradeTime, isPastSessionClose, nextTradingDate, effectiveCombine, DEFAULT_TARGET_HOLD_HOURS, projectPerfectPath, cycleCompletion, DLL_RESERVE_FRACTION, DLL_MIN_STOP, notionalCap, expectedSwapToWin, MARGIN_HEADROOM, dllReserve, DLL_SLIPPAGE_FRACTION, maxLossRoom, lastStand, breachDistance, LAST_STAND_FRACTION, planLegSize, rankForTarget, - currentTradeDateCT, + currentTradeDateCT, foldReason, } from '../lib/trading-logic.ts'; // Deterministic PRNG so a failure reproduces. @@ -729,3 +729,12 @@ test('l2Book best bid/ask', () => { assert.equal(empty.bid, undefined); assert.equal(empty.ask, undefined); }); + +test('tick reasons fold their amounts, so like reasons count together', () => { + assert.equal(foldReason('day done ($12.5 left of $300)'), 'day done ($… left of $…)'); + assert.equal(foldReason('day done ($40 left of $1,500)'), 'day done ($… left of $…)'); + assert.equal(foldReason('already traded today (realizedPnL=-123.45)'), 'already traded today (realizedPnL=…)'); + assert.equal(foldReason('daily loss limit: $294.7 of $3000 left — day booked'), 'daily loss limit: $… of $… left — day booked'); + assert.equal(foldReason("waiting for the broker to roll the account's day"), "waiting for the broker to roll the account's day"); + assert.equal(foldReason('leg cap reached (5 today)'), 'leg cap reached (5 today)'); +});