diff --git a/channels/1ds-post-js/src/PostChannel.ts b/channels/1ds-post-js/src/PostChannel.ts index 5ec3ffb3f..3174c781b 100644 --- a/channels/1ds-post-js/src/PostChannel.ts +++ b/channels/1ds-post-js/src/PostChannel.ts @@ -805,7 +805,6 @@ export class PostChannel extends BaseTelemetryPlugin implements IChannelControls } function _performAutoFlush(isAsync: boolean, doFlush?: boolean) { - // Only perform the auto flush check if the httpManager has an idle connection and we are not in a backoff situation if (_httpManager.canSendRequest() && !_currentBackoffCount) { if (_autoFlushEventsLimit > 0 && _queueSize > _autoFlushEventsLimit) { // Force flushing @@ -813,8 +812,46 @@ export class PostChannel extends BaseTelemetryPlugin implements IChannelControls } if (doFlush && _flushCallbackTimer == null) { - // Auto flush the queue, adding a callback to avoid the creation of a promise - _self.flush(isAsync, () => {}, SendRequestReason.MaxQueuedEvents); + // Auto flush is fire-and-forget (the callback is a no-op). Historically it + // called flush(), whose async path defers the send via a 0ms timer and then + // calls _waitForIdleManager(), which re-arms _flushCallbackTimer and polls + // (every FlushCheckTimer) until the HttpManager reports it is "completely idle" + // (no outstanding requests AND an empty send queue). While _flushCallbackTimer + // is non-null BOTH the normal scheduled timer (_scheduleTimer) and any further + // auto flush are suppressed. Under sustained intermittent failures (e.g. a load + // balancer recycling connections) there is almost always a retry in-flight or a + // re-queued batch, so the manager is rarely completely idle at the polling + // instant: the wait never completes, _flushCallbackTimer stays set and the + // channel stops draining permanently (the in-memory queue then saturates and + // telemetry is silently dropped as QueueFull) until the process is restarted. + // + // We keep the original deferred fire-and-forget behaviour (so the queue/discard + // semantics are unchanged) but tell _flushImpl NOT to wait for the manager to + // become idle: after the send it just resumes the normal schedule, so a + // busy/non-idle manager can no longer wedge draining. + if (isAsync) { + // Clear the normal schedule timer as we are going to try and flush ASAP + _clearScheduledTimer(); + + // Move all queued events to the HttpManager so that we don't discard new events (Auto flush scenario) + _queueBatches(EventLatencyValue.Normal, EventSendType.Batched, SendRequestReason.MaxQueuedEvents); + + _flushCallbackTimer = _createTimer(() => { + _flushCallbackTimer = null; + // waitForIdle = false -> fire-and-forget: do not park the scheduler + _flushImpl(() => { /* no-op */ }, SendRequestReason.MaxQueuedEvents, false); + }, 0); + } else { + let cleared = _clearScheduledTimer(); + + // Now cause all queued events to be sent synchronously + _sendEventsForLatencyAndAbove(EventLatencyValue.Normal, EventSendType.Synchronous, SendRequestReason.MaxQueuedEvents); + + if (cleared) { + // restart the normal event timer if it was cleared + _scheduleTimer(); + } + } } } } @@ -961,15 +998,17 @@ export class PostChannel extends BaseTelemetryPlugin implements IChannelControls * @param callback - The callback method to call after the flush is complete * @param sendReason - The reason why the flush is being called */ - function _flushImpl(callback: () => void, sendReason: SendRequestReason) { + function _flushImpl(callback: () => void, sendReason: SendRequestReason, waitForIdle?: boolean) { // Add any additional queued events and cause all queued events to be sent asynchronously _sendEventsForLatencyAndAbove(EventLatencyValue.Normal, EventSendType.Batched, sendReason); // All events (should) have been queue -- lets just make sure the queue counts are correct to avoid queue exhaustion (previous bug #9685112) _resetQueueCounts(); - _waitForIdleManager(() => { - // Only called AFTER the httpManager does not have any outstanding requests + let onFlushComplete = () => { + // Only called AFTER the httpManager does not have any outstanding requests, or + // immediately for a fire-and-forget auto flush (waitForIdle === false), which must + // not park the scheduler waiting for a manager that may never become idle. if (callback) { callback(); } @@ -986,7 +1025,13 @@ export class PostChannel extends BaseTelemetryPlugin implements IChannelControls // Restart the normal timer schedule _scheduleTimer(); } - }); + }; + + if (waitForIdle === false) { + onFlushComplete(); + } else { + _waitForIdleManager(onFlushComplete); + } } function _waitForIdleManager(callback: () => void) { diff --git a/channels/1ds-post-js/test/Unit/src/PostChannelTest.ts b/channels/1ds-post-js/test/Unit/src/PostChannelTest.ts index 5cf2d1b9a..15cedeee5 100644 --- a/channels/1ds-post-js/test/Unit/src/PostChannelTest.ts +++ b/channels/1ds-post-js/test/Unit/src/PostChannelTest.ts @@ -4004,6 +4004,70 @@ export class PostChannelTest extends AITestClass { } }); + this.testCase({ + name: "Regression (permanent stall): auto flush does not wedge behind the flush() wait-for-idle timer", + useFakeTimers: true, + test: () => { + // Fully controllable transport: record each request and let the test decide + // if/when it completes. + let sentRequests: Array<{ oncomplete: (status: number, headers: any) => void }> = []; + this.config.extensionConfig[this.postChannel.identifier] = { + httpXHROverride: { + sendPOST: (payload: IPayloadData, oncomplete: (status: number, headers: { [headerName: string]: string }) => void, sync?: boolean) => { + sentRequests.push({ oncomplete: oncomplete }); + } + }, + // Drive auto flush purely from the queued-event count (not the per-batch limit). + autoFlushEventsLimit: 5, + disableAutoBatchFlushLimit: true, + eventsLimitInMem: 1000 + }; + + this.core.initialize(this.config, [this.postChannel]); + this.clock.tick(1); + + let addEvents = (count: number) => { + for (let lp = 0; lp < count; lp++) { + this.postChannel.processTelemetry({ + name: "stallEvt", + latency: EventLatency.Normal, + iKey: "testIkey" + } as IPostTransmissionTelemetryItem); + } + // Let any 0ms timer settle (the fix drains synchronously; this is defensive). + this.clock.tick(1); + }; + + // First burst crosses autoFlushEventsLimit -> auto flush triggers -> request #1 is sent. + addEvents(6); + QUnit.assert.equal(sentRequests.length, 1, "request #1 should have been sent, got " + sentRequests.length); + + // Complete request #1. This clears the "first response" (clock-skew) gate so more + // requests are allowed to be sent again. Note we only advance the clock by 1ms, so any + // pending timer with a larger delay does NOT fire yet. + sentRequests[0].oncomplete(200, {}); + this.clock.tick(1); + + // A second burst crosses the auto flush limit again. + // + // Before the fix, the auto flush in the first burst routed through + // flush() -> _flushImpl -> _waitForIdleManager, which parked _flushCallbackTimer as a + // poll timer (fires on the FlushCheckTimer interval, not within our 1ms tick). While + // _flushCallbackTimer is non-null BOTH the scheduled timer and any further auto flush + // are suppressed, so this second burst would NOT be sent here (the channel is wedged + // waiting for the manager to become "completely idle"). With the fix, auto flush drains + // directly and never sets _flushCallbackTimer, so request #2 goes out immediately. + addEvents(6); + QUnit.assert.equal(sentRequests.length, 2, "request #2 must be sent - auto flush must not be wedged behind the flush() wait-for-idle timer (got " + sentRequests.length + ")"); + + // And it must keep working for subsequent bursts too. + sentRequests[1].oncomplete(200, {}); + this.clock.tick(1); + addEvents(6); + QUnit.assert.equal(sentRequests.length, 3, "request #3 must be sent - the channel keeps draining (got " + sentRequests.length + ")"); + } + }); + } } diff --git a/common/config/rush/pnpm-config.json b/common/config/rush/pnpm-config.json index 205210a6d..2e4a1fb3d 100644 --- a/common/config/rush/pnpm-config.json +++ b/common/config/rush/pnpm-config.json @@ -2,7 +2,7 @@ "$schema": "https://developer.microsoft.com/json-schemas/rush/v5/pnpm-config.schema.json", "globalOverrides": { "minimatch": ">=3.1.5", - "tar": ">=7.5.13", + "tar": ">=7.5.16", "glob": ">=7.2.3", "lodash": ">=4.18.1", "postcss": ">=8.5.14", diff --git a/package.json b/package.json index 903f5788b..d96e42b65 100644 --- a/package.json +++ b/package.json @@ -78,7 +78,7 @@ "overrides": { "basic-ftp": ">=5.2.0", "form-data": "^2.5.5", - "tar": "^7.5.13", + "tar": ">=7.5.16", "glob": "^7.2.3", "lodash": "^4.18.1", "minimatch": "^3.1.5"