fix: ConsoleLogger.warn() severity + add rate-limit sleep span (#17623)

## Description

Fixes two bugs surfaced in a community thread investigating high latency
(~67s wall-clock) in a 10-step agent:

1. **`ConsoleLogger.warn()` called `console.info()` instead of
`console.warn()`** — warn-level logs were misclassified as info/stdout,
making rate-limit warnings invisible in log backends filtering by
severity.

2. **Rate-limit sleep had no OTel span** — the hardcoded 10s `delay()`
when `x-ratelimit-remaining-tokens < 2000` only emitted a warn log
(which was invisible per bug #1). Added a `rate-limit-sleep` child span
with `{ remainingTokens, delayMs }` metadata so the sleep is visible in
traces.

3. **Fixed lockfile resolution** — `agent-sdks/openai` had a stale
`eslint@10.3.0` lockfile entry after a merge; updated to `10.4.1`.

### Changes

- `packages/_internal-core/src/logger/index.ts`: `console.info()` →
`console.warn()` in `ConsoleLogger.warn()`
- `packages/core/src/llm/model/model.ts`: Added `rate-limit-sleep` span
in both `__text` and `__stream` paths
- `packages/core/src/llm/model/model.loop.ts`: Added `rate-limit-sleep`
span in agentic loop path
- `packages/core/src/logger/console-logger.test.ts`: Updated 3 tests to
assert `console.warn`
- `packages/core/src/llm/model/model.test.ts`: New test verifying span
creation with correct name/metadata when rate-limit fires
- `observability/sentry/src/tracing.test.ts`: Updated test that was
codifying the same `console.info` bug
- `pnpm-lock.yaml`: Fixed stale `eslint@10.3.0` → `10.4.1` for
`agent-sdks/openai`

## Related issue(s)

Community-reported latency investigation (Slack thread). No GitHub
issue.

## Type of change

- [x] Bug fix (non-breaking change that fixes an issue)
- [x] Test update

## Checklist

- [x] I have linked the related issue(s) in the description above
- [x] I have made corresponding changes to the documentation (if
applicable)
- [x] I have added tests that prove my fix is effective or that my
feature works
- [ ] I have addressed all Coderabbit comments on this PR

Link to Devin session:
https://app.devin.ai/sessions/ce59a3645593455aa14f4397eda972d7
Requested by: @roaminro

<!-- This is an auto-generated comment: release notes by coderabbit.ai
-->

## ELI5

This PR fixes two observability problems: warning messages were being
sent to the wrong console stream, and a repeated 10-second pause used
for rate-limiting was invisible in traces—both are now fixed so logs and
traces accurately show warnings and delay time.

---

## Overview

This PR includes two fixes from a latency investigation:

1. ConsoleLogger.warn() now calls console.warn() (previously
console.info()), so warn-level logs are classified correctly by log
backends.
2. The hardcoded 10s rate-limit backpressure sleep (triggered when
x-ratelimit-remaining-tokens < 2000) is now wrapped in a
"rate-limit-sleep" OpenTelemetry child span with attributes
remainingTokens and delayMs and the warn log now includes
remainingTokens.

---

## Changes

- packages/_internal-core/src/logger/index.ts
  - ConsoleLogger.warn() uses console.warn() instead of console.info().

- packages/core/src/llm/model/model.ts
- In MastraLLMV1.__text and __stream: create a "rate-limit-sleep" child
span around the 10s sleep, record remainingTokens and delayMs, end the
span after sleep, and include remainingTokens in the warn message.

- packages/core/src/llm/model/model.loop.ts
- In MastraLLMVNext.stream (onStepFinish): add the same
"rate-limit-sleep" child span and warn message including
remainingTokens.

- Tests
- packages/core/src/logger/console-logger.test.ts: updated assertions to
expect console.warn for warn-level logs.
- observability/sentry/src/tracing.test.ts: updated to spy on
console.warn for DSN-missing warning.
- packages/core/src/llm/model/model.test.ts: added regression test
verifying creation and lifecycle of the rate-limit-sleep span
(attributes remainingTokens and delayMs), the warn log, and that the
span ends after the 10s fake-timer sleep.

- Documentation/changesets
- .changeset/* files updated to document the ConsoleLogger fix and
rate-limit span instrumentation.

---

## Impact

- Warn-level logs will be routed and classified correctly by logging
backends.
- Rate-limit backpressure delays are now visible in distributed traces
as "rate-limit-sleep" spans containing remainingTokens and delayMs,
aiding latency investigations where repeated 10s sleeps caused
unaccounted trace time.

<!-- end of auto-generated comment: release notes by coderabbit.ai -->

---------

Co-authored-by: Romain <97863888+roaminro@users.noreply.github.com>
Co-authored-by: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>
Co-authored-by: Abhi Aiyer <abhiaiyer91@gmail.com>

Author: 3 people

.changeset/all-hounds-doubt.md

@@ -0,0 +1,5 @@
+---
+'@mastra/core': patch
+---
+
+Fixed ConsoleLogger.warn() to correctly call console.warn() instead of console.info(), ensuring warn-level logs are routed to stderr and properly classified by log backends (e.g. Datadog)

.changeset/lazy-rings-punch.md

@@ -0,0 +1,5 @@
+---
+'@mastra/core': patch
+---
+
+Added OTel span instrumentation for the hardcoded 10-second rate-limit backpressure sleep, making it visible in traces as a 'rate-limit-sleep' span with remainingTokens and delayMs metadata

observability/sentry/src/tracing.test.ts

@@ -105,8 +105,7 @@ describe('SentryExporter', () => {
       const originalEnv = process.env.SENTRY_DSN;
       delete process.env.SENTRY_DSN;
 
-      // ConsoleLogger uses console.info for warn level logging
-      const mockConsoleInfo = vi.spyOn(console, 'info').mockImplementation(() => {});
+      const mockConsoleWarn = vi.spyOn(console, 'warn').mockImplementation(() => {});
 
       // Clear mock to isolate this test from previous Sentry.init calls
       SentryMock.init.mockClear();
@@ -115,13 +114,13 @@ describe('SentryExporter', () => {
 
       expect(exporterWithoutDsn.name).toBe('sentry');
       // Verify warning was logged about missing DSN
-      expect(mockConsoleInfo).toHaveBeenCalledWith(expect.stringContaining('DSN'));
+      expect(mockConsoleWarn).toHaveBeenCalledWith(expect.stringContaining('DSN'));
       // Verify exporter is disabled
       expect(exporterWithoutDsn.isDisabled).toBe(true);
       // Should not have initialized Sentry without DSN
       expect(SentryMock.init).not.toHaveBeenCalled();
 
-      mockConsoleInfo.mockRestore();
+      mockConsoleWarn.mockRestore();
       process.env.SENTRY_DSN = originalEnv;
     });
 

packages/_internal-core/src/logger/index.ts

@@ -297,7 +297,7 @@ export class ConsoleLogger extends MastraLogger {
       (this.level === LogLevel.WARN || this.level === LogLevel.INFO || this.level === LogLevel.DEBUG) &&
       this.shouldLog(LogLevel.WARN, message, args)
     ) {
-      console.info(`${this.prefix()}${message}`, ...args);
+      console.warn(`${this.prefix()}${message}`, ...args);
     }
   }
 

packages/core/src/llm/model/model.loop.ts

@@ -270,8 +270,14 @@ export class MastraLLMVNext extends MastraBase {
 
             const remainingTokens = parseInt(props?.response?.headers?.['x-ratelimit-remaining-tokens'] ?? '', 10);
             if (!isNaN(remainingTokens) && remainingTokens > 0 && remainingTokens < 2000) {
-              this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId });
+              this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId, remainingTokens });
+              const rateLimitSpan = modelSpan?.createChildSpan({
+                name: 'rate-limit-sleep',
+                type: SpanType.GENERIC,
+                metadata: { remainingTokens, delayMs: 10_000 },
+              });
               await delay(10 * 1000);
+              rateLimitSpan?.end();
             }
           },
 

packages/core/src/llm/model/model.test.ts

@@ -877,4 +877,78 @@ describe('MastraLLM', () => {
       expect(errorMastra.logger.error).toHaveBeenCalled();
     });
   });
+
+  describe('rate-limit span instrumentation', () => {
+    it('should create a rate-limit-sleep span when remaining tokens are below threshold in __text', async () => {
+      const rateLimitMastra = {
+        logger: {
+          debug: vi.fn(),
+          warn: vi.fn(),
+          info: vi.fn(),
+          error: vi.fn(),
+          trackException: vi.fn(),
+        } as any,
+      };
+
+      const rateLimitModel = new MockLanguageModelV1({
+        doGenerate: async () => ({
+          rawCall: { rawPrompt: null, rawSettings: {} },
+          finishReason: 'stop' as const,
+          usage: { promptTokens: 10, completionTokens: 20 },
+          text: 'hello',
+          rawResponse: { headers: { 'x-ratelimit-remaining-tokens': '1500' } },
+        }),
+        doStream: async () => {
+          throw new Error('not used');
+        },
+      });
+
+      const llm = new MastraLLMV1({ model: rateLimitModel });
+      llm.__registerPrimitives(rateLimitMastra);
+
+      const mockRateLimitSpan = { end: vi.fn() };
+      const mockLlmSpan = {
+        createChildSpan: vi.fn().mockReturnValue(mockRateLimitSpan),
+        end: vi.fn(),
+        error: vi.fn(),
+        update: vi.fn(),
+        executeInContext: vi.fn(async (fn: any) => fn()),
+        executeInContextSync: vi.fn((fn: any) => fn()),
+      };
+      const mockCurrentSpan = {
+        createChildSpan: vi.fn().mockReturnValue(mockLlmSpan),
+      };
+
+      const tracingCtx = {
+        tracingContext: { currentSpan: mockCurrentSpan },
+      };
+
+      // Use fake timers so the 10s delay completes instantly
+      vi.useFakeTimers();
+
+      const textPromise = llm.__text({
+        messages: [{ role: 'user', content: 'test' }],
+        requestContext: new RequestContext(),
+        ...tracingCtx,
+      });
+
+      // Advance past the 10s delay
+      await vi.advanceTimersByTimeAsync(11_000);
+      await textPromise;
+
+      vi.useRealTimers();
+
+      expect(rateLimitMastra.logger.warn).toHaveBeenCalledWith(
+        'Rate limit approaching, waiting 10 seconds',
+        expect.objectContaining({ remainingTokens: 1500 }),
+      );
+      expect(mockLlmSpan.createChildSpan).toHaveBeenCalledWith(
+        expect.objectContaining({
+          name: 'rate-limit-sleep',
+          metadata: { remainingTokens: 1500, delayMs: 10_000 },
+        }),
+      );
+      expect(mockRateLimitSpan.end).toHaveBeenCalled();
+    });
+  });
 });

packages/core/src/llm/model/model.ts

@@ -257,8 +257,14 @@ export class MastraLLMV1 extends MastraBase {
 
         const remainingTokens = parseInt(props?.response?.headers?.['x-ratelimit-remaining-tokens'] ?? '', 10);
         if (!isNaN(remainingTokens) && remainingTokens > 0 && remainingTokens < 2000) {
-          this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId });
+          this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId, remainingTokens });
+          const rateLimitSpan = llmSpan?.createChildSpan({
+            name: 'rate-limit-sleep',
+            type: SpanType.GENERIC,
+            metadata: { remainingTokens, delayMs: 10_000 },
+          });
           await delay(10 * 1000);
+          rateLimitSpan?.end();
         }
       },
       experimental_output: schema
@@ -608,8 +614,14 @@ export class MastraLLMV1 extends MastraBase {
 
         const remainingTokens = parseInt(props?.response?.headers?.['x-ratelimit-remaining-tokens'] ?? '', 10);
         if (!isNaN(remainingTokens) && remainingTokens > 0 && remainingTokens < 2000) {
-          this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId });
+          this.logger.warn('Rate limit approaching, waiting 10 seconds', { runId, remainingTokens });
+          const rateLimitSpan = llmSpan?.createChildSpan({
+            name: 'rate-limit-sleep',
+            type: SpanType.GENERIC,
+            metadata: { remainingTokens, delayMs: 10_000 },
+          });
           await delay(10 * 1000);
+          rateLimitSpan?.end();
         }
       },
       onFinish: async props => {

packages/core/src/logger/console-logger.test.ts

@@ -22,12 +22,15 @@ describe('ConsoleLogger', () => {
 
       // Verify by checking the child only logs at WARN level (inherited from parent)
       const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+      const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
       child.info('should not log');
       child.warn('should log');
 
-      expect(infoSpy).toHaveBeenCalledTimes(1);
-      expect(infoSpy).toHaveBeenCalledWith('[AGENT] should log');
+      expect(infoSpy).not.toHaveBeenCalled();
+      expect(warnSpy).toHaveBeenCalledTimes(1);
+      expect(warnSpy).toHaveBeenCalledWith('[AGENT] should log');
       infoSpy.mockRestore();
+      warnSpy.mockRestore();
     });
 
     it('inherits filter from parent', () => {
@@ -113,6 +116,7 @@ describe('ConsoleLogger', () => {
       const logger = new ConsoleLogger({ level: LogLevel.DEBUG, filter });
 
       const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+      const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
       const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {});
 
       logger.debug('d');
@@ -126,6 +130,7 @@ describe('ConsoleLogger', () => {
       expect(filter).toHaveBeenCalledWith(expect.objectContaining({ level: LogLevel.ERROR }));
 
       infoSpy.mockRestore();
+      warnSpy.mockRestore();
       errorSpy.mockRestore();
     });
 
@@ -188,19 +193,22 @@ describe('ConsoleLogger', () => {
       const logger = new ConsoleLogger({ level: LogLevel.WARN });
 
       const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {});
+      const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
       const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {});
 
       logger.debug('debug');
       logger.info('info');
       logger.warn('warn');
       logger.error('error');
 
-      expect(infoSpy).toHaveBeenCalledTimes(1); // only warn
-      expect(infoSpy).toHaveBeenCalledWith('warn');
+      expect(infoSpy).not.toHaveBeenCalled();
+      expect(warnSpy).toHaveBeenCalledTimes(1);
+      expect(warnSpy).toHaveBeenCalledWith('warn');
       expect(errorSpy).toHaveBeenCalledTimes(1);
       expect(errorSpy).toHaveBeenCalledWith('error');
 
       infoSpy.mockRestore();
+      warnSpy.mockRestore();
       errorSpy.mockRestore();
     });
   });