Add granular logging across all source files

Introduce logger infrastructure and add structured logging to every layer:
alpaca.ts (buy/sell/quote/clock), momentum-indicator.ts (evaluate flow),
momentum-strategy.ts (poll loop), index.ts (startup/cycle), and trading.ts
(market timing). Replace raw console.log calls with leveled logger. Update
all tests with appropriate console spies.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

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> = {}): AlpacaClient {
@@ -14,6 +14,15 @@ function mockClient(overrides: Partial<AlpacaClient> = {}): 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');

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<number> {
         const quote = await this.alpaca.getLatestQuote(symbol);
+        logger.debug(`${symbol} ask: ${quote.AskPrice}`);
         return quote.AskPrice;
     }
     public async getLatestBid(symbol: string): Promise<number> {
         const quote = await this.alpaca.getLatestQuote(symbol);
+        logger.debug(`${symbol} bid: ${quote.BidPrice}`);
         return quote.BidPrice;
     }
     public async getLatestSpread(symbol: string): Promise<number> {
@@ -116,6 +122,7 @@ export class Alpaca {
     }
 
     public async buy(symbol: string, dollarAmount: number): Promise<number> {
+        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<number> {
+        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);
     }
 }

src/bot.test.ts

@@ -34,6 +34,7 @@ function mockStrategy(overrides: Partial<Strategy> = {}): 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);
         });
     });

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<void> {
         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 }) => {

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)
 );

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),
+};

src/momentum-indicator.test.ts

@@ -20,6 +20,7 @@ function mockAlpaca(overrides: Partial<Alpaca> = {}): Alpaca {
 
 beforeEach(() => {
     vi.useFakeTimers();
+    vi.spyOn(console, 'debug').mockImplementation(() => {});
 });
 
 afterEach(() => {

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<MomentumResult> {
     }
 
     async evaluate(alpaca: Alpaca): Promise<MomentumResult> {
+        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 };
     }

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');
     });
 });

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<void> {
+        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);
     }

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({

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<boolean> {
 
 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);
 }
 

vitest.config.ts

@@ -4,5 +4,6 @@ export default defineConfig({
     test: {
         globals: true,
         exclude: ['dist/**', 'node_modules/**'],
+        env: { LOG_LEVEL: 'debug' },
     },
 });