diff --git a/src/alpaca.test.ts b/src/alpaca.test.ts index 9c3fbf4..ce566dc 100644 --- a/src/alpaca.test.ts +++ b/src/alpaca.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect, vi } from 'vitest'; +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; import { Alpaca, AlpacaClient } from './alpaca'; function mockClient(overrides: Partial = {}): AlpacaClient { @@ -14,6 +14,15 @@ function mockClient(overrides: Partial = {}): AlpacaClient { }; } +beforeEach(() => { + vi.spyOn(console, 'log').mockImplementation(() => {}); + vi.spyOn(console, 'debug').mockImplementation(() => {}); +}); + +afterEach(() => { + vi.restoreAllMocks(); +}); + describe('Alpaca', () => { it('throws when live is true', () => { expect(() => new Alpaca(true)).toThrow('not doing live yet'); diff --git a/src/alpaca.ts b/src/alpaca.ts index 9485fbe..23248cf 100644 --- a/src/alpaca.ts +++ b/src/alpaca.ts @@ -1,6 +1,8 @@ import dotenv from 'dotenv'; dotenv.config(); +import { logger } from './logger'; + // eslint-disable-next-line @typescript-eslint/no-require-imports const AlpacaJS = require('@alpacahq/alpaca-trade-api') @@ -96,15 +98,19 @@ export class Alpaca { } public async getClock() { - return this.alpaca.getClock(); + const clock = await this.alpaca.getClock(); + logger.debug(`clock: is_open=${clock.is_open}, next_open=${clock.next_open}`); + return clock; } public async getLatestAsk(symbol: string): Promise { const quote = await this.alpaca.getLatestQuote(symbol); + logger.debug(`${symbol} ask: ${quote.AskPrice}`); return quote.AskPrice; } public async getLatestBid(symbol: string): Promise { const quote = await this.alpaca.getLatestQuote(symbol); + logger.debug(`${symbol} bid: ${quote.BidPrice}`); return quote.BidPrice; } public async getLatestSpread(symbol: string): Promise { @@ -116,6 +122,7 @@ export class Alpaca { } public async buy(symbol: string, dollarAmount: number): Promise { + logger.info(`buying ${symbol} for $${dollarAmount}`); const order = await this.alpaca.createOrder({ symbol, notional: dollarAmount, @@ -123,10 +130,12 @@ export class Alpaca { type: 'market', time_in_force: 'day', }); + logger.info(`bought ${symbol} — filled at ${order.filled_avg_price}, qty ${order.filled_qty}, order ${order.id}`); return parseFloat(order.filled_avg_price); } public async sell(symbol: string, dollarAmount: number): Promise { + logger.info(`selling ${symbol} for $${dollarAmount}`); const order = await this.alpaca.createOrder({ symbol, notional: dollarAmount, @@ -134,6 +143,7 @@ export class Alpaca { type: 'market', time_in_force: 'day', }); + logger.info(`sold ${symbol} — filled at ${order.filled_avg_price}, qty ${order.filled_qty}, order ${order.id}`); return parseFloat(order.filled_avg_price); } } \ No newline at end of file diff --git a/src/bot.test.ts b/src/bot.test.ts index 2c4bcef..8bd001e 100644 --- a/src/bot.test.ts +++ b/src/bot.test.ts @@ -34,6 +34,7 @@ function mockStrategy(overrides: Partial = {}): Strategy { beforeEach(() => { vi.useFakeTimers(); vi.spyOn(console, 'log').mockImplementation(() => {}); + vi.spyOn(console, 'debug').mockImplementation(() => {}); }); afterEach(() => { @@ -102,7 +103,7 @@ describe('Bot', () => { await vi.advanceTimersByTimeAsync(0); await promise; - expect(console.log).toHaveBeenCalledWith('waiting for open'); + expect(console.log).toHaveBeenCalledWith(expect.stringContaining('[INFO]'), 'waiting for open'); }); it('skips waiting when market is already open', async () => { @@ -120,7 +121,7 @@ describe('Bot', () => { await vi.advanceTimersByTimeAsync(0); await promise; - expect(console.log).not.toHaveBeenCalledWith('waiting for open'); + expect(console.log).not.toHaveBeenCalledWith(expect.stringContaining('[INFO]'), 'waiting for open'); expect(strategy.execute).toHaveBeenCalledWith(alpaca, 10000); }); }); diff --git a/src/bot.ts b/src/bot.ts index 325cbc4..151a419 100644 --- a/src/bot.ts +++ b/src/bot.ts @@ -1,4 +1,5 @@ import { Alpaca } from "./alpaca"; +import { logger } from "./logger"; import { Strategy } from "./strategy"; import { isMarketOpen, waitForNextOpen } from "./trading"; @@ -25,11 +26,14 @@ export class Bot { async runDay(): Promise { const open = await isMarketOpen(this.alpaca); if (!open) { - console.log('waiting for open'); + logger.info('waiting for open'); await waitForNextOpen(this.alpaca); } + logger.info('market is open, running strategies'); const account = await this.alpaca.getAccount(); + logger.debug(`got account: ${JSON.stringify(account)}`); const totalCapital = parseFloat(account.cash); + logger.debug(`total capital: ${totalCapital}`); await Promise.all( this.allocations.map(async ({ strategy, capitalAllocation }) => { diff --git a/src/index.ts b/src/index.ts index 27ee854..21438ec 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,15 +1,19 @@ import { Alpaca } from "./alpaca"; import { Bot } from "./bot"; +import { logger } from "./logger"; import { wait } from "./trading"; import { MomentumStrategy } from "./momentum-strategy"; const alpaca = new Alpaca(false); const momentum = new MomentumStrategy(); const bot = new Bot(alpaca, [{ strategy: momentum, capitalAllocation: 1.0 }]); +logger.info('bot initialized'); async function main() { while(true) { + logger.info('starting trading cycle'); await bot.runDay(); + logger.info('trading cycle complete, sleeping 1h'); await wait(1000 * 60 * 60);//wait an hour before going and getting the next open } } @@ -17,10 +21,10 @@ async function main() { //run main main().then( () => { - console.log("done") + logger.info("done") } ).catch( - (e) => console.log('Error: ', e) + (e) => logger.error('Error: ', e) ).finally( () => process.exit(0) ); diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 0000000..ea21163 --- /dev/null +++ b/src/logger.ts @@ -0,0 +1,24 @@ +const levels = { debug: 0, info: 1, warn: 2, error: 3 } as const; +type Level = keyof typeof levels; + +const currentLevel: Level = + (process.env.LOG_LEVEL as Level) in levels + ? (process.env.LOG_LEVEL as Level) + : 'info'; + +function log(level: Level, ...args: unknown[]) { + if (levels[level] < levels[currentLevel]) return; + const tag = `[${new Date().toISOString()}] [${level.toUpperCase()}]`; + const fn = level === 'debug' ? console.debug + : level === 'warn' ? console.warn + : level === 'error' ? console.error + : console.log; + fn(tag, ...args); +} + +export const logger = { + debug: (...args: unknown[]) => log('debug', ...args), + info: (...args: unknown[]) => log('info', ...args), + warn: (...args: unknown[]) => log('warn', ...args), + error: (...args: unknown[]) => log('error', ...args), +}; diff --git a/src/momentum-indicator.test.ts b/src/momentum-indicator.test.ts index a90f390..83c7fa3 100644 --- a/src/momentum-indicator.test.ts +++ b/src/momentum-indicator.test.ts @@ -20,6 +20,7 @@ function mockAlpaca(overrides: Partial = {}): Alpaca { beforeEach(() => { vi.useFakeTimers(); + vi.spyOn(console, 'debug').mockImplementation(() => {}); }); afterEach(() => { diff --git a/src/momentum-indicator.ts b/src/momentum-indicator.ts index 80f9f24..838e672 100644 --- a/src/momentum-indicator.ts +++ b/src/momentum-indicator.ts @@ -1,5 +1,6 @@ import { Alpaca } from "./alpaca"; import { Indicator } from "./indicator"; +import { logger } from "./logger"; import { wait } from "./trading"; export interface MomentumResult { @@ -29,15 +30,17 @@ export class MomentumIndicator implements Indicator { } async evaluate(alpaca: Alpaca): Promise { + logger.debug(`waiting ${this.config.settleDelay}ms for market to settle`); await wait(this.config.settleDelay); const priceBefore = await alpaca.getLatestAsk(this.config.symbol); - + logger.debug(`${this.config.symbol} priceBefore: ${priceBefore}`); + await wait(this.config.sampleDelay); const priceAfter = await alpaca.getLatestAsk(this.config.symbol); - const direction = priceAfter >= priceBefore ? 'up' : 'down'; + logger.debug(`${this.config.symbol} priceAfter: ${priceAfter} → direction: ${direction}`); return { direction, priceBefore, priceAfter }; } diff --git a/src/momentum-strategy.test.ts b/src/momentum-strategy.test.ts index 2c1e146..714273d 100644 --- a/src/momentum-strategy.test.ts +++ b/src/momentum-strategy.test.ts @@ -28,6 +28,7 @@ const fastConfig = { beforeEach(() => { vi.useFakeTimers(); vi.spyOn(console, 'log').mockImplementation(() => {}); + vi.spyOn(console, 'debug').mockImplementation(() => {}); }); afterEach(() => { @@ -89,7 +90,7 @@ describe('MomentumStrategy', () => { await vi.advanceTimersByTimeAsync(1000); await promise; - expect(console.log).toHaveBeenCalledWith('[momentum] exit TQQQ — reason: target'); + expect(console.log).toHaveBeenCalledWith(expect.stringContaining('[INFO]'), '[momentum] exit TQQQ — reason: target'); expect(alpaca.sell).toHaveBeenCalledWith('TQQQ', 5000); }); @@ -108,7 +109,7 @@ describe('MomentumStrategy', () => { await vi.advanceTimersByTimeAsync(2000); await promise; - expect(console.log).toHaveBeenCalledWith('[momentum] exit TQQQ — reason: timeout'); + expect(console.log).toHaveBeenCalledWith(expect.stringContaining('[INFO]'), '[momentum] exit TQQQ — reason: timeout'); expect(alpaca.sell).toHaveBeenCalledWith('TQQQ', 5000); }); @@ -132,6 +133,6 @@ describe('MomentumStrategy', () => { await vi.advanceTimersByTimeAsync(1000); await promise; - expect(console.log).toHaveBeenCalledWith('[momentum] exit TQQQ — reason: target'); + expect(console.log).toHaveBeenCalledWith(expect.stringContaining('[INFO]'), '[momentum] exit TQQQ — reason: target'); }); }); diff --git a/src/momentum-strategy.ts b/src/momentum-strategy.ts index d1bc846..b034e75 100644 --- a/src/momentum-strategy.ts +++ b/src/momentum-strategy.ts @@ -1,4 +1,5 @@ import { Alpaca } from "./alpaca"; +import { logger } from "./logger"; import { Strategy } from "./strategy"; import { MomentumIndicator, MomentumIndicatorConfig } from "./momentum-indicator"; import { wait } from "./trading"; @@ -27,27 +28,32 @@ export class MomentumStrategy implements Strategy { } async execute(alpaca: Alpaca, capitalAmount: number): Promise { + logger.debug(`[${this.name}] executing with capital amount: ${capitalAmount}`); const result = await this.indicator.evaluate(alpaca); + logger.debug(`[${this.name}] indicator result: ${JSON.stringify(result)}`); const symbol = result.direction === 'up' ? 'TQQQ' : 'SQQQ'; const entryPrice = await alpaca.buy(symbol, capitalAmount); + logger.info(`[${this.name}] entered ${symbol} at price ${entryPrice}`); const targetPrice = entryPrice * (1 + this.config.targetGain); const deadline = Date.now() + this.config.holdTime; + logger.debug(`[${this.name}] monitoring ${symbol} for target price ${targetPrice} or timeout at ${new Date(deadline).toISOString()}`); let reason: 'target' | 'timeout' = 'timeout'; while (Date.now() < deadline) { await wait(this.config.pollInterval); const bid = await alpaca.getLatestBid(symbol); + logger.debug(`${symbol} bid: ${bid} / target: ${targetPrice}`); if (bid >= targetPrice) { reason = 'target'; break; } } - console.log(`[${this.name}] exit ${symbol} — reason: ${reason}`); + logger.info(`[${this.name}] exit ${symbol} — reason: ${reason}`); await alpaca.sell(symbol, capitalAmount); } diff --git a/src/trading.test.ts b/src/trading.test.ts index d19b3ef..6589d4c 100644 --- a/src/trading.test.ts +++ b/src/trading.test.ts @@ -29,7 +29,7 @@ afterEach(() => { describe('printAsset', () => { beforeEach(() => { - vi.spyOn(console, 'log').mockImplementation(() => {}); + vi.spyOn(console, 'debug').mockImplementation(() => {}); }); it('logs fractional when asset is fractionable', async () => { @@ -38,7 +38,7 @@ describe('printAsset', () => { }); await printAsset(alpaca, 'TQQQ'); - expect(console.log).toHaveBeenCalledWith('TQQQ is fractional'); + expect(console.debug).toHaveBeenCalledWith(expect.stringContaining('[DEBUG]'), 'TQQQ is fractional'); }); it('logs not fractional when asset is not fractionable', async () => { @@ -47,7 +47,7 @@ describe('printAsset', () => { }); await printAsset(alpaca, 'BRK.A'); - expect(console.log).toHaveBeenCalledWith('BRK.A is not fractional'); + expect(console.debug).toHaveBeenCalledWith(expect.stringContaining('[DEBUG]'), 'BRK.A is not fractional'); }); }); @@ -63,6 +63,11 @@ describe('accountBalance', () => { }); describe('waitForNextOpen', () => { + beforeEach(() => { + vi.spyOn(console, 'log').mockImplementation(() => {}); + vi.spyOn(console, 'debug').mockImplementation(() => {}); + }); + it('calls getClock and waits until next_open', async () => { const futureDate = new Date(Date.now() + 60000).toISOString(); const alpaca = mockAlpaca({ diff --git a/src/trading.ts b/src/trading.ts index 01757e4..7455265 100644 --- a/src/trading.ts +++ b/src/trading.ts @@ -1,4 +1,5 @@ import { Alpaca } from "./alpaca"; +import { logger } from "./logger"; export function wait(ms: number) { return new Promise((resolve) => { @@ -9,9 +10,9 @@ export function wait(ms: number) { export async function printAsset(alpaca: Alpaca, symbol: string) { const asset = await alpaca.getAsset(symbol); if (asset && asset.fractionable) - console.log(symbol + ' is fractional') + logger.debug(symbol + ' is fractional') else - console.log(symbol + ' is not fractional') + logger.debug(symbol + ' is not fractional') } export async function accountBalance(alpaca: Alpaca) { @@ -26,6 +27,8 @@ export async function isMarketOpen(alpaca: Alpaca): Promise { export async function waitForNextOpen(alpaca: Alpaca) { const clock = await alpaca.getClock(); - return wait(new Date(clock.next_open).valueOf() - new Date().valueOf()); + const ms = new Date(clock.next_open).valueOf() - new Date().valueOf(); + logger.info(`market closed, next open: ${clock.next_open} (waiting ${ms}ms)`); + return wait(ms); } diff --git a/vitest.config.ts b/vitest.config.ts index 5834ec5..c8d9ef2 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -4,5 +4,6 @@ export default defineConfig({ test: { globals: true, exclude: ['dist/**', 'node_modules/**'], + env: { LOG_LEVEL: 'debug' }, }, });