diff --git a/.changeset/v6-desktop-capture-v1.md b/.changeset/v6-desktop-capture-v1.md index 19d67a5b..644d4aa4 100644 --- a/.changeset/v6-desktop-capture-v1.md +++ b/.changeset/v6-desktop-capture-v1.md @@ -3,5 +3,6 @@ --- - **Breaking:** on every platform, events now go to capture v1 (`/i/v1/analytics/events`) instead of `/batch/`: iOS and macOS through `posthog-ios` 4.x, Android through `posthog-android` 4.x, and Windows and Linux in the Dart client. If you send events through your own reverse proxy, update it before you upgrade: forward `/i/v1/analytics/events` and `/i/v1/ai/events`, pass `Authorization` (the project token, sent as `Bearer `), every `PostHog-*` header, `Content-Type`, `Content-Encoding` and `User-Agent` through unchanged, and accept request bodies up to 20 MB. PostHog's managed reverse proxy already does this. See the [iOS](https://github.com/PostHog/posthog-ios/blob/main/docs/migration-3.x-to-4.0.md#hosts-without-capture-v1) and [Android](https://github.com/PostHog/posthog-android/blob/main/docs/migration-3.x-to-4.0.md#hosts-without-capture-v1) migration guides -- **Breaking:** on Windows and Linux, a reverse proxy or self-hosted instance must serve the new path: a 404 drops the events. Events queued before the upgrade are sent through the new endpoint -- **Breaking:** on Windows and Linux, a 429 or a redirect drops the batch instead of retrying it (only same-origin 307/308 redirects are followed), and a `Retry-After` wait is capped at 30 seconds +- **Breaking:** on Windows and Linux, a reverse proxy or self-hosted instance must serve the new path: a 404 is retried, the events stay queued, and the SDK prints a warning once, also without `debug`. Events queued before the upgrade are sent through the new endpoint +- **Breaking:** on Windows and Linux, a redirect drops the batch instead of retrying it (only same-origin 307/308 redirects are followed, while a 404 or 429 is retried), and a `Retry-After` wait is capped at 30 seconds +- On Windows and Linux, a failed batch, or one whose events the server asks to retry, is no longer resent within the same flush: the queue backs off like the iOS and Android SDKs, waiting 1 second and doubling up to 30 seconds with ±25% jitter, until a batch is delivered. A `Retry-After` is a floor under that wait rather than a replacement diff --git a/posthog_flutter/lib/src/core/capture_v1.dart b/posthog_flutter/lib/src/core/capture_v1.dart index 1e5adc5b..14e6d886 100644 --- a/posthog_flutter/lib/src/core/capture_v1.dart +++ b/posthog_flutter/lib/src/core/capture_v1.dart @@ -27,9 +27,11 @@ List takeCaptureV1Batch( } /// Capture v1 statuses worth retrying. Everything else is terminal, -/// including 429 and 3xx; 413 halves the batch instead. +/// including 3xx; 413 halves the batch instead. bool isRetriableCaptureV1Status(int status) => + status == 404 || status == 408 || + status == 429 || status == 500 || status == 502 || status == 503 || diff --git a/posthog_flutter/lib/src/core/file_storage.dart b/posthog_flutter/lib/src/core/file_storage.dart index 4c3a7402..96175bfc 100644 --- a/posthog_flutter/lib/src/core/file_storage.dart +++ b/posthog_flutter/lib/src/core/file_storage.dart @@ -310,6 +310,10 @@ class FileEventQueue { /// this client. final Map> _unwritten = {}; + /// The serialized size of each queued event, by id, and their total. + final Map _sizes = {}; + int _byteCount = 0; + List get _ids => _loadedIds ??= _load(); String _pathOf(String id) => @@ -319,7 +323,8 @@ class FileEventQueue { try { return [ for (final entity in Directory(_directory).listSync()) - if (entity is File && entity.path.endsWith(_extension)) _idOf(entity), + if (entity is File && entity.path.endsWith(_extension)) + _track(_idOf(entity), _lengthOf(entity)), ]..sort(); } on PathNotFoundException { return []; @@ -332,6 +337,22 @@ class FileEventQueue { } } + static int _lengthOf(File file) { + try { + return file.lengthSync(); + } on FileSystemException { + return 0; + } + } + + String _track(String id, int size) { + _sizes[id] = size; + _byteCount += size; + return id; + } + + void _untrack(String id) => _byteCount -= _sizes.remove(id) ?? 0; + static String _idOf(File file) { final name = file.uri.pathSegments.last; return name.substring(0, name.length - _extension.length); @@ -340,19 +361,31 @@ class FileEventQueue { /// The number of queued events. int get length => _ids.length; + /// The serialized size of the queued events, in bytes. + int get byteCount { + _ids; // Loads the queue, and the sizes, on first use. + return _byteCount; + } + /// Adds [event] at the end of the queue. void add(Map event) { // Loaded before the new file exists, which would otherwise be listed // on top of being added. final ids = _ids; final id = generateUuidV7(); - ids.add(id); + String? encoded; + try { + encoded = jsonEncode(event); + } catch (_) { + // Reported below when it is written. + } + ids.add(_track(id, encoded == null ? 0 : utf8.encode(encoded).length)); if (_directory.isEmpty) { _unwritten[id] = event; return; } try { - _writeAtomically(File(_pathOf(id)), jsonEncode(event)); + _writeAtomically(File(_pathOf(id)), encoded ?? jsonEncode(event)); } catch (e) { _unwritten[id] = event; _logger()?.warn( @@ -372,7 +405,10 @@ class FileEventQueue { final event = _unwritten[id] ?? _read(id, gone); if (event != null) events.add((id: id, event: event)); } - if (gone.isNotEmpty) _ids.removeWhere(gone.contains); + if (gone.isNotEmpty) { + _ids.removeWhere(gone.contains); + gone.forEach(_untrack); + } return events; } @@ -413,6 +449,7 @@ class FileEventQueue { } void _forget(String id) { + _untrack(id); if (_unwritten.remove(id) == null && _directory.isNotEmpty) { _delete(File(_pathOf(id))); } diff --git a/posthog_flutter/lib/src/core/posthog_core_stateless.dart b/posthog_flutter/lib/src/core/posthog_core_stateless.dart index 601f7e72..ee30b2df 100644 --- a/posthog_flutter/lib/src/core/posthog_core_stateless.dart +++ b/posthog_flutter/lib/src/core/posthog_core_stateless.dart @@ -1,7 +1,9 @@ import 'dart:async'; import 'dart:convert'; import 'dart:io'; +import 'dart:math'; +import 'package:flutter/foundation.dart' show debugPrint; import 'package:meta/meta.dart'; import '../posthog_config.dart'; @@ -52,12 +54,40 @@ bool _isRetryableFlagsError(Object err) => err is PostHogFetchNetworkError || (err is PostHogFetchHttpError && (err.status == 502 || err.status == 504)); +/// The largest fraction a capture retry wait moves either way, so clients +/// refused together don't all come back at the same moment. +const _retryJitter = 0.25; + +/// The wait before capture is sent again after the [attempt]-th failure in a +/// row: 1 second doubling up to 30 seconds, scaled by a jitter factor in +/// `[1 - _retryJitter, 1 + _retryJitter)` drawn from [jitterUnit] and capped +/// again. A server [retryAfter], capped at 30 seconds, is a floor applied +/// after the jitter, so a retry never comes earlier than the server asked. +/// A [jitterUnit] outside `[0, 1)` leaves the delay unjittered. +@visibleForTesting +Duration captureRetryDelay({ + required int attempt, + required double jitterUnit, + Duration? retryAfter, +}) { + const initialMs = 1000.0; + const maxMs = 30000.0; + final computed = + min(initialMs * pow(2, (attempt < 1 ? 1 : attempt) - 1), maxMs); + final factor = jitterUnit >= 0 && jitterUnit < 1 + ? 1 - _retryJitter + 2 * _retryJitter * jitterUnit + : 1.0; + final jittered = min(computed * factor, maxMs).round(); + final floor = min(retryAfter?.inMilliseconds ?? 0, maxMs.toInt()); + return Duration(milliseconds: jittered > floor ? jittered : floor); +} + /// Base stateless PostHog client: the queue of events, consent, super /// properties and the requests to PostHog. abstract class PostHogCoreStateless { final String _apiKey; final String _host; - final int _flushAt; + int _flushAt; int _maxBatchSize; final int _maxQueueSize; final Duration _flushInterval; @@ -65,17 +95,25 @@ abstract class PostHogCoreStateless { final bool _defaultOptIn; + /// How long a request may go without progress: connecting, a chunk of + /// the body taken by the socket, the response headers, or a chunk of the + /// response body. A slow but moving upload never times out. static const _requestTimeout = Duration(seconds: 10); - // A batch is retried after a transient failure; a flags request only after - // a network error or a gateway timeout. - static const _fetchRetryCount = 3; - static const _fetchRetryDelay = Duration(seconds: 3); + /// How long the response body may take in total, so a body that trickles + /// in without end can't hold the flush. + static const _responseBodyTimeout = Duration(seconds: 30); + + /// The size of the body chunks handed to the socket, each one progress. + static const _bodyChunkSize = 64 * 1024; + + // A flags request is retried only after a network error or a gateway + // timeout. A batch is not retried within a flush: the queue backs off. static const _flagsRetryCount = 1; static const _flagsRetryDelay = Duration(milliseconds: 300); - /// The longest `Retry-After` pause honored for events. - static const _maxRetryAfter = Duration(seconds: 30); + /// The [_failedFlushes] at which the backoff reaches its 30 second cap. + static const _maxBackoffStep = 6; /// How many same-origin 307/308 redirects a capture request follows. static const _maxCaptureRedirects = 5; @@ -84,6 +122,20 @@ abstract class PostHogCoreStateless { /// retried. Kept in memory: after a restart the retry is a new request. CaptureV1Identity? _pendingCaptureIdentity; + /// Flushes in a row whose batch failed with a transient error or had + /// events the server asked to retry. Each one pauses the queue for longer, + /// see [captureRetryDelay], so a failure that lasts, like a missing + /// capture route, doesn't resend the batch with every capture. A delivered + /// or dropped batch resets it. + int _failedFlushes = 0; + + /// The source of the backoff jitter: a uniform value in `[0, 1)`. + @visibleForTesting + double Function() jitterUnit = Random().nextDouble; + + /// Whether this client already warned that capture returned a 404. + bool _warnedCaptureNotFound = false; + /// The latest consent decision made through this client. It wins over the /// stored one: [clearPersistedOptOut] removes the stored decision while /// this client keeps honoring it, and a decision the storage cannot @@ -107,7 +159,8 @@ abstract class PostHogCoreStateless { @protected final FileStorage storage; - final _httpClient = HttpClient(); + final _httpClient = HttpClient() + ..connectionTimeout = PostHogCoreStateless._requestTimeout; PostHogCoreStateless( PostHogConfig config, { @@ -436,7 +489,9 @@ abstract class PostHogCoreStateless { events.emit(type, prepared); - if (queue.length >= _flushAt) { + // A full request's worth of bytes flushes like flushAt does, so large + // events go out before the queue starts dropping them. + if (queue.length >= _flushAt || queue.byteCount >= captureV1MaxBatchBytes) { _flushBackground(); } @@ -476,15 +531,22 @@ abstract class PostHogCoreStateless { _flushTimer = null; } - /// Stops sending events for [delay], the server's `Retry-After`, kept - /// between the retry delay and [_maxRetryAfter]. + /// Counts one more failed flush and stops sending events for the backoff + /// it calls for, at least the server's [retryAfter]. + void _backOff(Duration? retryAfter) { + if (_failedFlushes < _maxBackoffStep) _failedFlushes++; + _pauseFlush(captureRetryDelay( + attempt: _failedFlushes, + jitterUnit: jitterUnit(), + retryAfter: retryAfter, + )); + } + + /// Stops sending events for [delay]. void _pauseFlush(Duration delay) { _clearFlushTimer(); _retryAfterTimer?.cancel(); - final pause = delay < _fetchRetryDelay - ? _fetchRetryDelay - : (delay > _maxRetryAfter ? _maxRetryAfter : delay); - _retryAfterTimer = Timer(pause, () { + _retryAfterTimer = Timer(delay, () { _retryAfterTimer = null; if (!_closed && _flushInterval > Duration.zero && @@ -534,85 +596,80 @@ abstract class PostHogCoreStateless { } } - /// Sends [batch] to capture v1, retrying what is worth it, and removes - /// from the queue the events that are done: delivered, or dropped for - /// good. Adds the delivered ones to [sent]. + /// Sends [batch] to capture v1 and removes from the queue the events that + /// are done: delivered, or dropped for good. Adds the delivered ones to + /// [sent]. /// /// Returns whether the flush goes on with the rest of the queue. It stops - /// while events of [batch] wait for a later retry; the periodic flush or - /// the server's `Retry-After` sends them again. + /// while events of [batch] wait for a later retry: the queue backs off, + /// and sends them again once the pause is over. It also stops after a 413 + /// halves the batch size. Future _sendBatch( List batch, List> sent, ) async { final queue = storage.queue; - var pending = batch; - for (var attempt = 0;; attempt++) { - if (attempt > 0) { - await Future.delayed(_fetchRetryDelay); - // A client closed meanwhile leaves the queue to the next one. - if (_closed) return false; - } - - final Set retryUuids; - final Duration? retryAfter; - try { - (:retryUuids, :retryAfter) = await _postCaptureV1(pending); - } catch (e) { - if (_closed) rethrow; - if (e is PostHogFetchHttpError && - e.status == HttpStatus.requestEntityTooLarge && - pending.length > 1) { - _maxBatchSize = (pending.length ~/ 2).clamp(1, _maxBatchSize); - logger.warn('Received 413, reducing batch size to $_maxBatchSize'); - return true; - } - final transient = _isTransientCaptureError(e); - final retryAfter = e is PostHogFetchHttpError ? e.retryAfter : null; - if (transient && retryAfter == null && attempt < _fetchRetryCount) { - continue; - } - if (!transient) { - queue.remove([for (final queued in pending) queued.id]); - } - // Re-arm the periodic flush: otherwise queued events sit until the - // next capture (forever in an idle app after an offline failure). - if (transient && retryAfter != null) { - _pauseFlush(retryAfter); - } else { - _scheduleFlush(); - } - events.emit('error', e); - rethrow; - } - - final retained = [ - for (final queued in pending) - if (retryUuids.contains(queued.event['uuid'])) queued, - ]; - final delivered = [ - for (final queued in pending) - if (!retryUuids.contains(queued.event['uuid'])) queued, - ]; - // Removed by id: the queue may have changed while the batch was in - // flight, e.g. its oldest events dropped to make room. - queue.remove([for (final queued in delivered) queued.id]); - sent.addAll([for (final queued in delivered) queued.event]); - if (retained.isEmpty) return true; - - // Counts only: uuids and server details can identify users. - logger.info('Capture asked to retry ${retained.length} of ' - '${pending.length} events.'); - pending = retained; - if (retryAfter != null) { - _pauseFlush(retryAfter); + final Set retryUuids; + final Duration? retryAfter; + try { + (:retryUuids, :retryAfter) = await _postCaptureV1(batch); + } catch (e) { + if (_closed) rethrow; + if (e is PostHogFetchHttpError && + e.status == HttpStatus.requestEntityTooLarge && + batch.length > 1) { + // flushAt stays within the batch size, so the queue doesn't pile up + // more events than one batch can carry. + _maxBatchSize = (batch.length ~/ 2).clamp(1, _maxBatchSize); + _flushAt = (_flushAt ~/ 2).clamp(1, _maxBatchSize); + logger.warn('Received 413, reducing batch size to $_maxBatchSize'); + // The smaller batches go out with the next flush, not right away. + _scheduleFlush(); return false; } - if (attempt >= _fetchRetryCount) { + if (e is PostHogFetchHttpError && + e.status == HttpStatus.notFound && + !_warnedCaptureNotFound) { + _warnedCaptureNotFound = true; + // Printed even without debug: the events stay queued, and nothing + // else tells the app that the route is missing. + debugPrint('[PostHog] [WARN] $captureV1Path returned 404. ' + 'Events stay queued and are retried. If you use a reverse ' + 'proxy or self-host PostHog, make sure it serves ' + '$captureV1Path.'); + } + // The pause re-arms the periodic flush: otherwise queued events sit + // until the next capture (forever in an idle app after an offline + // failure). + if (_isTransientCaptureError(e)) { + _backOff(e is PostHogFetchHttpError ? e.retryAfter : null); + } else { + queue.remove([for (final queued in batch) queued.id]); + _failedFlushes = 0; _scheduleFlush(); - return false; } + events.emit('error', e); + rethrow; } + + final delivered = [ + for (final queued in batch) + if (!retryUuids.contains(queued.event['uuid'])) queued, + ]; + // Removed by id: the queue may have changed while the batch was in + // flight, e.g. its oldest events dropped to make room. + queue.remove([for (final queued in delivered) queued.id]); + sent.addAll([for (final queued in delivered) queued.event]); + if (delivered.length == batch.length) { + _failedFlushes = 0; + return true; + } + + // Counts only: uuids and server details can identify users. + logger.info('Capture asked to retry ${batch.length - delivered.length} ' + 'of ${batch.length} events.'); + _backOff(retryAfter); + return false; } /// Posts [batch] to capture v1 and returns the uuids of the events the @@ -742,10 +799,11 @@ abstract class PostHogCoreStateless { ); } - /// Sends one request, bounded by [_requestTimeout]. A transport failure - /// is thrown as [PostHogFetchNetworkError], except, with - /// [deliveredOnBodyFailure], one that happens after a 2xx status arrived: - /// the response is then returned without a body. + /// Sends one request, aborted once it makes no progress for + /// [_requestTimeout]. A transport failure is thrown as + /// [PostHogFetchNetworkError], except, with [deliveredOnBodyFailure], one + /// that happens after a 2xx status arrived: the response is then returned + /// without a body. Future< ({ int status, @@ -758,15 +816,9 @@ abstract class PostHogCoreStateless { Map headers = const {}, bool deliveredOnBodyFailure = false, }) async { - final attempt = _FetchAttempt(); + final attempt = _FetchAttempt(_requestTimeout, _responseBodyTimeout); try { - return await _fetch(url, body, attempt, headers).timeout( - _requestTimeout, - onTimeout: () async { - await attempt.cancel(); - throw attempt.timeout; - }, - ); + return await attempt.guard(_fetch(url, body, attempt, headers)); } catch (e) { final status = attempt.status; if (deliveredOnBodyFailure && @@ -834,9 +886,18 @@ abstract class PostHogCoreStateless { payload = bytes; } request.contentLength = payload.length; - request.add(payload); + // In chunks, so the socket taking each one counts as progress: it stops + // taking them while its buffers are full. + await request.addStream(() async* { + for (var start = 0; start < payload.length; start += _bodyChunkSize) { + attempt.progress(); + yield payload.sublist( + start, min(start + _bodyChunkSize, payload.length)); + } + }()); final response = await request.close(); + attempt.progress(); final retryAfter = _parseRetryAfter(response.headers.value(HttpHeaders.retryAfterHeader)); attempt @@ -866,7 +927,14 @@ abstract class PostHogCoreStateless { } class _FetchAttempt { + _FetchAttempt(this._idleTimeout, this._bodyTimeout); + + final Duration _idleTimeout; + final Duration _bodyTimeout; final timeout = TimeoutException('PostHog request timed out'); + Timer? _idleTimer; + Timer? _bodyTimer; + void Function()? _onIdle; HttpClientRequest? _request; @@ -877,7 +945,42 @@ class _FetchAttempt { Completer? _responseBody; bool _cancelled = false; + /// Completes with [work], or fails with [timeout] once the request has + /// made no [progress] for the idle timeout or its response body has taken + /// longer than the body timeout. The request is cancelled + /// before that failure is reported, so a retry never overlaps it. + Future guard(Future work) { + final result = Completer(); + var idle = false; + _onIdle = () async { + idle = true; + await cancel(); + if (!result.isCompleted) result.completeError(timeout); + }; + progress(); + work.then((value) { + if (!idle && !result.isCompleted) result.complete(value); + }, onError: (Object error, StackTrace stackTrace) { + if (!idle && !result.isCompleted) { + result.completeError(error, stackTrace); + } + }); + return result.future.whenComplete(() { + _idleTimer?.cancel(); + _bodyTimer?.cancel(); + }); + } + + /// Restarts the idle timeout. + void progress() { + _idleTimer?.cancel(); + if (_cancelled) return; + final onIdle = _onIdle; + if (onIdle != null) _idleTimer = Timer(_idleTimeout, onIdle); + } + void attachRequest(HttpClientRequest request) { + progress(); _request = request; if (_cancelled) { request.abort(timeout); @@ -886,12 +989,17 @@ class _FetchAttempt { } Future readBody(HttpClientResponse response) { + final onIdle = _onIdle; + if (onIdle != null) _bodyTimer = Timer(_bodyTimeout, onIdle); final contents = StringBuffer(); final body = Completer(); late final StreamSubscription subscription; subscription = response.transform(const Utf8Decoder(allowMalformed: true)).listen( - contents.write, + (chunk) { + progress(); + contents.write(chunk); + }, onError: (Object error, StackTrace stackTrace) { if (!body.isCompleted) body.completeError(error, stackTrace); }, diff --git a/posthog_flutter/test/core/capture_v1_test.dart b/posthog_flutter/test/core/capture_v1_test.dart index 87b280ed..65b35069 100644 --- a/posthog_flutter/test/core/capture_v1_test.dart +++ b/posthog_flutter/test/core/capture_v1_test.dart @@ -191,6 +191,38 @@ void main() { }); }); + group('captureRetryDelay', () { + Duration delay(int attempt, double unit, [int? retryAfterSeconds]) => + captureRetryDelay( + attempt: attempt, + jitterUnit: unit, + retryAfter: retryAfterSeconds == null + ? null + : Duration(seconds: retryAfterSeconds), + ); + + test('doubles from 1 second up to 30 seconds', () { + expect([for (var a = 1; a <= 7; a++) delay(a, 0.5).inSeconds], + [1, 2, 4, 8, 16, 30, 30]); + }); + + test('jitters by up to 25 percent and stays under 30 seconds', () { + expect(delay(1, 0), const Duration(milliseconds: 750)); + expect(delay(3, 0.75), const Duration(milliseconds: 4500)); + expect(delay(6, 0), const Duration(milliseconds: 22500)); + expect(delay(6, 0.999), const Duration(seconds: 30)); + expect(delay(1, double.nan), const Duration(seconds: 1)); + expect(delay(1, 1), const Duration(seconds: 1)); + }); + + test('takes Retry-After as a floor after the jitter, at most 30 s', () { + expect(delay(1, 0, 5), const Duration(seconds: 5)); + expect(delay(4, 0.5, 1), const Duration(seconds: 8)); + expect(delay(4, 0, 7), const Duration(seconds: 7)); + expect(delay(1, 0.5, 120), const Duration(seconds: 30)); + }); + }); + group('Capture v1 results', () { test('resends only the events the server asks to retry', () { final api = InProcessPostHogApi(); @@ -279,6 +311,43 @@ void main() { }); }); + test('a partial retry advances the backoff, a full delivery resets it', () { + final api = InProcessPostHogApi(); + final storage = tempStorage(); + var partial = 3; + api.respond = (request) => partial-- > 0 + ? PostHogResponse.results( + request, (name) => name == 'later' ? 'retry' : null) + : PostHogResponse.results(request, (_) => 'ok'); + fakeAsync((async) { + final client = testClient(api, storage: storage); + client.capture('now'); + client.capture('later'); + client.flush(); + async.elapse(Duration.zero); + + var now = Duration.zero; + var requests = 1; + for (final next in [1, 3, 7]) { + async.elapse(Duration(seconds: next) - now - _ms); + expect(api.batchRequests, hasLength(requests)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(++requests)); + now = Duration(seconds: next); + } + expect(getQueue(storage), isEmpty); + + api.respond = (_) => const PostHogResponse(HttpStatus.badGateway); + client.capture('next'); + client.flush().catchError((Object _) {}); + async.elapse(const Duration(seconds: 1) - _ms); + expect(api.batchRequests, hasLength(5)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(6), + reason: 'the backoff starts over at 1 second'); + }); + }); + test('starts a new request when new events join a retried batch', () { final api = InProcessPostHogApi(); final storage = tempStorage(); @@ -313,7 +382,7 @@ void main() { fakeAsync((async) { final client = testClient(api); client.capture('evt'); - client.flush(); + client.flush().catchError((Object _) {}); async.elapse(const Duration(seconds: 6)); final requests = api.batchRequests; @@ -353,20 +422,27 @@ void main() { expect(getQueue(storage), isEmpty); }); - test('drops the batch on 404 without falling back to /batch', () async { - final server = await LocalPostHogServer.start(); + test('retries a 404 without falling back to /batch', () { + final api = InProcessPostHogApi() + ..respond = (request) => request.isFlags + ? PostHogResponse.json({'flags': {}}) + : const PostHogResponse(HttpStatus.notFound); final storage = tempStorage(); - final client = testClient(server, storage: storage); - server.respond = (request) => request.isFlags - ? PostHogResponse.json({'flags': {}}) - : const PostHogResponse(HttpStatus.notFound); + fakeAsync((async) { + final client = testClient(api, storage: storage); + Object? error; - client.capture('evt'); - await expectLater(client.flush(), throwsA(isA())); + client.capture('evt'); + client.flush().catchError((Object e) { + error = e; + }); + async.elapse(const Duration(seconds: 9)); - expect([for (final r in server.requests) r.path], - ['/i/v1/analytics/events']); - expect(getQueue(storage), isEmpty); + expect(error, isA()); + expect([for (final r in api.requests) r.path], + List.filled(4, '/i/v1/analytics/events')); + expect(getQueue(storage), hasLength(1)); + }); }); }); @@ -456,3 +532,5 @@ void main() { expect(Directory('${dir.path}/posthog_queue').listSync(), isEmpty); }); } + +const _ms = Duration(milliseconds: 1); diff --git a/posthog_flutter/test/core/file_queue_test.dart b/posthog_flutter/test/core/file_queue_test.dart index 4da822af..75dfad4b 100644 --- a/posthog_flutter/test/core/file_queue_test.dart +++ b/posthog_flutter/test/core/file_queue_test.dart @@ -44,6 +44,32 @@ void main() { hasLength(1)); }); + test('counts the serialized bytes of the queued events', () { + int size(Map event) => + utf8.encode(jsonEncode(event)).length; + final first = {'event': 'first', 'padding': 'é' * 10}; + final second = {'event': 'second'}; + final third = {'event': 'third'}; + final storage = FileStorage(dir.path); + final queue = storage.queue + ..add(first) + ..add(second) + ..add(third); + expect(queue.byteCount, size(first) + size(second) + size(third)); + + queue.removeOldest(1); + expect(queue.byteCount, size(second) + size(third)); + + // Read back from the files by the next process. + storage.close(); + final next = FileStorage(dir.path); + addTearDown(next.close); + final restored = next.queue; + expect(restored.byteCount, size(second) + size(third)); + restored.remove([restored.peek(1).single.id]); + expect(restored.byteCount, size(third)); + }); + test('keeps the queue order across a restart', () async { final before = client(); for (var i = 0; i < 50; i++) { diff --git a/posthog_flutter/test/core/queue_flush_test.dart b/posthog_flutter/test/core/queue_flush_test.dart index 48f6aaa8..f5483cc5 100644 --- a/posthog_flutter/test/core/queue_flush_test.dart +++ b/posthog_flutter/test/core/queue_flush_test.dart @@ -2,6 +2,7 @@ import 'dart:async'; import 'dart:io'; import 'package:fake_async/fake_async.dart'; +import 'package:flutter/foundation.dart' show debugPrint; import 'package:flutter_test/flutter_test.dart'; import 'package:posthog_flutter/src/core/file_storage.dart'; import 'package:posthog_flutter/src/core/persistence.dart'; @@ -68,27 +69,67 @@ void main() { expect(getQueue(storage), isEmpty); }); - test('halves the batch size on HTTP 413 until the server accepts', - () async { + test('halves the batch size and flushAt on HTTP 413, sending next flush', + () { + final api = InProcessPostHogApi() + // This server rejects anything bigger than two events per request. + ..respond = (request) => PostHogResponse(request.events.length > 2 + ? HttpStatus.requestEntityTooLarge + : HttpStatus.ok); final storage = tempStorage(); - final client = testClient(server, storage: storage); - // This server rejects anything bigger than two events per request. - server.respond = (request) => PostHogResponse(request.events.length > 2 - ? HttpStatus.requestEntityTooLarge - : HttpStatus.ok); + fakeAsync((async) { + final client = testClient(api, + config: testConfig(flushAt: 10, maxBatchSize: 10), + storage: storage); + List sizes() => + [for (final request in api.batchRequests) request.events.length]; - for (var i = 0; i < 8; i++) { - client.capture('event_$i'); - } - await client.flush(); + for (var i = 0; i < 10; i++) { + client.capture('event_$i'); + } + async.elapse(Duration.zero); + expect(sizes(), [10], reason: 'a 413 ends the flush'); - final batches = [ - for (final request in server.batchRequests) request.eventNames, - ]; - expect(batches.map((batch) => batch.length).toList(), [8, 4, 2, 2, 2, 2]); - expect(batches.skip(2).expand((batch) => batch).toList(), - [for (var i = 0; i < 8; i++) 'event_$i']); - expect(getQueue(storage), isEmpty); + // flushAt is 5 now: the next capture flushes. + client.capture('event_10'); + async.elapse(Duration.zero); + expect(sizes(), [10, 5]); + + // flushAt is 2 now, as is the batch size. + client.capture('event_11'); + async.elapse(Duration.zero); + expect(sizes(), [10, 5, 2, 2, 2, 2, 2, 2]); + expect(api.batchRequests.skip(2).expand((r) => r.eventNames).toList(), + [for (var i = 0; i < 12; i++) 'event_$i']); + expect(getQueue(storage), isEmpty); + + client.capture('event_12'); + async.elapse(Duration.zero); + expect(getQueue(storage), hasLength(1), + reason: 'flushAt stays at 2 after the deliveries'); + }); + }); + + test('sends the halved batches with the periodic flush after a 413', () { + final api = InProcessPostHogApi() + ..respond = (request) => PostHogResponse(request.events.length > 2 + ? HttpStatus.requestEntityTooLarge + : HttpStatus.ok); + final storage = tempStorage(); + fakeAsync((async) { + final client = testClient(api, storage: storage); + for (var i = 0; i < 4; i++) { + client.capture('event_$i'); + } + client.flush(); + async.elapse(Duration.zero); + expect(api.batchRequests, hasLength(1)); + expect(getQueue(storage), hasLength(4)); + + async.elapse(const Duration(seconds: 30)); + expect([for (final r in api.batchRequests) r.events.length], [4, 2, 2]); + expect(getQueue(storage), isEmpty); + }); }); test('shares one network cycle between concurrent calls', () async { @@ -122,7 +163,8 @@ void main() { expect(getQueue(storage), isEmpty); }); - test('retries a transient failure three times, three seconds apart', () { + test('backs off 1, 2, 4, 8, 16, then 30 seconds after transient failures', + () { final api = InProcessPostHogApi() ..respond = (_) => const PostHogResponse(HttpStatus.serviceUnavailable); final storage = tempStorage(); @@ -136,20 +178,42 @@ void main() { }); async.elapse(Duration.zero); + expect(error, isA(), + reason: 'a flush does not wait for the backoff'); expect(api.batchRequests, hasLength(1)); - for (final attempts in [2, 3, 4]) { - async.elapse(const Duration(milliseconds: 2999)); - expect(api.batchRequests, hasLength(attempts - 1)); - async.elapse(const Duration(milliseconds: 1)); - expect(api.batchRequests, hasLength(attempts)); + var now = Duration.zero; + var requests = 1; + for (final next in [1, 3, 7, 15, 31, 61, 91]) { + async.elapse(Duration(seconds: next) - now - _ms); + expect(api.batchRequests, hasLength(requests)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(++requests)); + now = Duration(seconds: next); } - expect(error, isA()); expect(getQueue(storage), hasLength(1)); }); }); - for (final status in [408, 500, 502, 503, 504]) { - test('HTTP $status keeps the batch queued after the retries', () { + test('jitters the backoff by up to 25 percent either way', () { + for (final (unit, first) in [(0.0, 750), (0.999, 1250)]) { + final api = InProcessPostHogApi() + ..respond = + (_) => const PostHogResponse(HttpStatus.serviceUnavailable); + fakeAsync((async) { + final client = testClient(api, jitterUnit: unit); + client.capture('evt'); + client.flush().catchError((Object _) {}); + async.elapse(Duration(milliseconds: first - 1)); + expect(api.batchRequests, hasLength(1), reason: 'unit $unit'); + async.elapse(_ms); + expect(api.batchRequests, hasLength(2), reason: 'unit $unit'); + client.close(); + }); + } + }); + + for (final status in [404, 408, 429, 500, 502, 503, 504]) { + test('HTTP $status keeps the batch queued and backs off', () { final api = InProcessPostHogApi() ..respond = (_) => PostHogResponse(status); final storage = tempStorage(); @@ -170,9 +234,7 @@ void main() { }); } - // Capture v1 retries only the statuses above: a rate limit, a redirect - // it does not follow, or a missing route fails the same way again. - for (final status in [301, 302, 307, 308, 401, 403, 404, 429, 501]) { + for (final status in [301, 302, 307, 308, 401, 403, 501]) { test('HTTP $status drops the batch without a retry', () { final api = InProcessPostHogApi() ..respond = (_) => PostHogResponse(status, @@ -219,16 +281,60 @@ void main() { }); }); + test('a delivered batch resets the backoff', () { + final api = InProcessPostHogApi(); + var status = HttpStatus.notFound; + api.respond = (_) => PostHogResponse(status); + final storage = tempStorage(); + fakeAsync((async) { + final client = + testClient(api, storage: storage, config: testConfig(flushAt: 1)); + + client.capture('first'); + async.elapse(const Duration(seconds: 9)); + status = HttpStatus.ok; + async.elapse(const Duration(seconds: 6)); + expect(api.batchRequests, hasLength(5)); + expect(getQueue(storage), isEmpty); + + status = HttpStatus.serviceUnavailable; + client.capture('second'); + async.elapse(const Duration(seconds: 9)); + expect(api.batchRequests, hasLength(9)); + }); + }); + + test('warns once about a 404, also without debug', () { + final printed = []; + final originalDebugPrint = debugPrint; + debugPrint = (String? message, {int? wrapWidth}) => printed.add(message); + addTearDown(() => debugPrint = originalDebugPrint); + final api = InProcessPostHogApi() + ..respond = (_) => const PostHogResponse(HttpStatus.notFound); + fakeAsync((async) { + final client = testClient(api, config: testConfig(flushAt: 1)); + + client.capture('evt'); + async.elapse(const Duration(seconds: 60)); + + expect(api.batchRequests.length, greaterThan(4)); + expect(printed, [ + '[PostHog] [WARN] /i/v1/analytics/events returned 404. ' + 'Events stay queued and are retried. If you use a reverse ' + 'proxy or self-host PostHog, make sure it serves ' + '/i/v1/analytics/events.', + ]); + }); + }); + test('the timer firing while a flush is in flight stays re-armable', () { final api = InProcessPostHogApi(); final storage = tempStorage(); fakeAsync((async) { final release = Completer(); - var online = false; api.respond = (_) async { await release.future; - return PostHogResponse( - online ? HttpStatus.ok : HttpStatus.serviceUnavailable); + return const PostHogResponse(HttpStatus.ok); }; final client = testClient(api, config: testConfig(flushInterval: const Duration(milliseconds: 20)), @@ -241,22 +347,20 @@ void main() { client.capture('second'); async.elapse(const Duration(milliseconds: 60)); release.complete(); - // The flush and its retries fail. - async.elapse(const Duration(seconds: 9)); - expect(api.batchRequests, hasLength(4)); + async.elapse(Duration.zero); + expect(getQueue(storage), isEmpty); - online = true; + client.capture('third'); async.elapse(const Duration(milliseconds: 20)); - expect(api.batchRequests.last.eventNames, ['first', 'second'], + expect(api.batchRequests.last.eventNames, ['third'], reason: 'only a re-armed timer sends the queue again'); - expect(getQueue(storage), isEmpty); }); }); }); group('Retry-After', () { - for (final status in [503]) { + for (final status in [429, 503]) { test('HTTP $status pauses every send path and resumes the queue', () { final api = InProcessPostHogApi(); final storage = tempStorage(); @@ -308,7 +412,7 @@ void main() { '', 'Sun, 06 Nov 1994 08:49:37 GMT', ]) { - test('ignores Retry-After "$header" and keeps three retries', () { + test('ignores Retry-After "$header" and backs off as without it', () { final api = InProcessPostHogApi() ..respond = (_) => PostHogResponse(HttpStatus.serviceUnavailable, headers: {'retry-after': header}); @@ -459,27 +563,40 @@ void main() { }); }); - test('a new rate limit starts a new pause with the minimum delay', () { + test('Retry-After is a floor under the backoff, not a replacement', () { final api = InProcessPostHogApi() ..respond = (_) => const PostHogResponse(HttpStatus.serviceUnavailable, - headers: {'retry-after': '20'}); + headers: {'retry-after': '5'}); final storage = tempStorage(); fakeAsync((async) { final client = testClient(api, storage: storage); client.capture('event'); client.flush().catchError((Object _) {}); async.elapse(Duration.zero); + // Over the 1 second backoff: the server's 5 seconds win. + async.elapse(const Duration(seconds: 5) - _ms); + expect(api.batchRequests, hasLength(1)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(2)); + // 2, then 4 seconds of backoff are under it: 5 seconds again, then + // the 8 seconds of the 4th failure are over it. + async.elapse(const Duration(seconds: 10)); + expect(api.batchRequests, hasLength(4)); api.respond = (_) => const PostHogResponse( HttpStatus.serviceUnavailable, headers: {'retry-after': '1'}); - async.elapse(const Duration(seconds: 20)); - expect(api.batchRequests, hasLength(2)); + async.elapse(const Duration(seconds: 8) - _ms); + expect(api.batchRequests, hasLength(4)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(5)); + + // A short Retry-After does not resend every second: the 5th + // failure's 16 second backoff wins. api.respond = (_) => const PostHogResponse(HttpStatus.ok); - client.flush(); - async.elapse(const Duration(milliseconds: 2999)); - expect(api.batchRequests, hasLength(2)); - async.elapse(const Duration(milliseconds: 1)); - expect(api.batchRequests, hasLength(3)); + async.elapse(const Duration(seconds: 16) - _ms); + expect(api.batchRequests, hasLength(5)); + async.elapse(_ms); + expect(api.batchRequests, hasLength(6)); expect(getQueue(storage), isEmpty); }); }); @@ -614,6 +731,27 @@ void main() { }); }); + test('flushes once 5 MiB of serialized events are queued', () { + final api = InProcessPostHogApi(); + final storage = tempStorage(); + fakeAsync((async) { + final client = testClient(api, storage: storage); + final padding = 'x' * (2 * 1024 * 1024 + 512 * 1024); + + client.capture('event_0', properties: {'padding': padding}); + async.elapse(Duration.zero); + expect(api.batchRequests, isEmpty); + + client.capture('event_1', properties: {'padding': padding}); + async.elapse(Duration.zero); + expect( + [for (final r in api.batchRequests) r.eventNames].expand((n) => n), + ['event_0', 'event_1'], + reason: 'well below flushAt and before the periodic flush'); + expect(getQueue(storage), isEmpty); + }); + }); + test('closes a batch at 5 MiB of serialized events', () { final api = InProcessPostHogApi(); final storage = tempStorage(); @@ -837,3 +975,5 @@ void main() { }); }); } + +const _ms = Duration(milliseconds: 1); diff --git a/posthog_flutter/test/core/requests_test.dart b/posthog_flutter/test/core/requests_test.dart index c5204a24..004768ce 100644 --- a/posthog_flutter/test/core/requests_test.dart +++ b/posthog_flutter/test/core/requests_test.dart @@ -1,9 +1,12 @@ import 'dart:async'; +import 'dart:convert'; import 'dart:io'; +import 'dart:math'; import 'package:fake_async/fake_async.dart'; import 'package:flutter_test/flutter_test.dart'; import 'package:posthog_flutter/src/core/posthog_core_stateless.dart'; +import 'package:posthog_flutter/src/posthog_desktop_client.dart'; import 'package:posthog_flutter/src/posthog_flutter_version.dart'; import '../posthog_api_fake.dart'; @@ -163,6 +166,122 @@ void main() { }); }); + test('keeps a slow upload that makes progress going past 10 seconds', () { + fakeAsync((async) { + late final _ControlledRequest request; + final http = + _ControlledHttpClient((_) async => request = _ControlledRequest( + takeChunk: () => + Future.delayed(const Duration(seconds: 6)), + )); + final storage = tempStorage(); + late final client = HttpOverrides.runZoned( + () => testClient(server, storage: storage), + createHttpClient: (_) => http, + ); + _captureLargeEvent(client); + Object? error; + var flushed = false; + client.flush().then((_) => flushed = true, onError: (Object e) { + error = e; + }); + async.elapse(const Duration(seconds: 60)); + + expect(request.chunks, greaterThan(2)); + expect(error, isNull); + expect(flushed, isTrue); + expect(request.abortCalls, 0); + expect(getQueue(storage), isEmpty); + }); + }); + + test('times out an upload that stalls for 10 seconds', () { + fakeAsync((async) { + final stalled = Completer(); + var taken = 0; + final request = _ControlledRequest( + takeChunk: () => taken++ == 0 ? Future.value() : stalled.future, + ); + final http = _ControlledHttpClient((_) async => request); + final storage = tempStorage(); + late final client = HttpOverrides.runZoned( + () => testClient(server, storage: storage), + createHttpClient: (_) => http, + ); + _captureLargeEvent(client); + Object? error; + client.flush().catchError((Object e) { + error = e; + }); + async.elapse(const Duration(seconds: 10) - _ms); + expect(error, isNull); + async.elapse(_ms); + + expect(error, isA()); + expect(request.abortCalls, 1); + expect(getQueue(storage), hasLength(1)); + client.close(); + }); + }); + + test('keeps a response that trickles in going past 10 seconds', () { + fakeAsync((async) { + final body = StreamController>(); + final http = _ControlledHttpClient((_) async => + _ControlledRequest(response: _ControlledResponse(body.stream))); + late final client = HttpOverrides.runZoned( + () => testClient(server), + createHttpClient: (_) => http, + ); + client.capture('evt'); + Object? error; + var flushed = false; + client.flush().then((_) => flushed = true, onError: (Object e) { + error = e; + }); + for (var i = 0; i < 4; i++) { + async.elapse(const Duration(seconds: 6)); + body.add(utf8.encode(' ')); + } + body.close(); + async.flushMicrotasks(); + + expect(error, isNull); + expect(flushed, isTrue); + }); + }); + + test('times out a response that trickles in for 30 seconds', () { + fakeAsync((async) { + final body = + StreamController>(onCancel: () => Future.value()); + final http = _ControlledHttpClient((_) async => _ControlledRequest( + response: _ControlledResponse(body.stream, + statusCode: HttpStatus.serviceUnavailable))); + final storage = tempStorage(); + late final client = HttpOverrides.runZoned( + () => testClient(server, storage: storage), + createHttpClient: (_) => http, + ); + client.capture('evt'); + Object? error; + client.flush().catchError((Object e) { + error = e; + }); + for (var i = 0; i < 5; i++) { + async.elapse(const Duration(seconds: 6) - _ms); + body.add(utf8.encode(' ')); + } + async.flushMicrotasks(); + expect(error, isNull); + async.elapse(const Duration(seconds: 1)); + + expect(error, isA()); + expect(getQueue(storage), hasLength(1)); + client.close(); + }); + }); + test('counts a 2xx whose body times out as delivered', () { fakeAsync((async) { // Cancelled in this zone: fake_async does not run the root zone's @@ -203,6 +322,9 @@ class _ControlledHttpClient implements HttpClient { @override Future postUrl(Uri url) => openRequest(url); + @override + Duration? connectionTimeout; + @override void close({bool force = false}) {} @@ -211,12 +333,17 @@ class _ControlledHttpClient implements HttpClient { } class _ControlledRequest implements HttpClientRequest { - _ControlledRequest({HttpClientResponse? response}) + _ControlledRequest({HttpClientResponse? response, this.takeChunk}) : _response = response ?? _ControlledResponse(Stream.value([])); final HttpClientResponse _response; + + /// How long the socket takes to accept each body chunk; immediate when + /// null. + final Future Function()? takeChunk; int abortCalls = 0; int closeCalls = 0; + int chunks = 0; @override final headers = _ControlledHeaders(); @@ -230,6 +357,14 @@ class _ControlledRequest implements HttpClientRequest { @override void add(List data) {} + @override + Future addStream(Stream> stream) async { + await for (final _ in stream) { + await takeChunk?.call(); + chunks++; + } + } + @override void abort([Object? exception, StackTrace? stackTrace]) { abortCalls++; @@ -245,6 +380,16 @@ class _ControlledRequest implements HttpClientRequest { dynamic noSuchMethod(Invocation invocation) => super.noSuchMethod(invocation); } +/// A request whose body is several 64 KiB chunks once compressed: random +/// text does not compress much. +void _captureLargeEvent(DesktopPostHog client) { + final random = Random(1); + client.capture('large', properties: { + 'padding': + base64.encode([for (var i = 0; i < 200000; i++) random.nextInt(256)]), + }); +} + class _ControlledResponse extends StreamView> implements HttpClientResponse { _ControlledResponse(super.stream, {this.statusCode = HttpStatus.ok}); @@ -269,3 +414,5 @@ class _ControlledHeaders implements HttpHeaders { @override dynamic noSuchMethod(Invocation invocation) => super.noSuchMethod(invocation); } + +const _ms = Duration(milliseconds: 1); diff --git a/posthog_flutter/test/core/test_client.dart b/posthog_flutter/test/core/test_client.dart index 62a96f13..5af59e7f 100644 --- a/posthog_flutter/test/core/test_client.dart +++ b/posthog_flutter/test/core/test_client.dart @@ -44,13 +44,16 @@ FileStorage tempStorage() => FileStorage(tempDirectory().path); /// A client of [api] with [config], closed at the end of the test. It keeps /// its state in [storage], a new temporary directory by default, and -/// attaches [context] and [timezone] to its events. +/// attaches [context] and [timezone] to its events. Its backoff has no +/// jitter unless [jitterUnit] says otherwise, so retries come 1, 2, 4, 8, 16 +/// and then 30 seconds apart. DesktopPostHog testClient( PostHogApiFake api, { PostHogConfig? config, FileStorage? storage, Map context = const {}, String? timezone, + double jitterUnit = 0.5, }) { final client = api.connect( () => DesktopPostHog( @@ -60,6 +63,7 @@ DesktopPostHog testClient( timezone: timezone, ), ); + client.jitterUnit = () => jitterUnit; addTearDown(client.close); return client; } diff --git a/posthog_flutter/test/posthog_api_fake.dart b/posthog_flutter/test/posthog_api_fake.dart index 312e0b36..b2c7646c 100644 --- a/posthog_flutter/test/posthog_api_fake.dart +++ b/posthog_flutter/test/posthog_api_fake.dart @@ -254,6 +254,9 @@ class _InProcessHttpClient implements HttpClient { Future postUrl(Uri url) async => _InProcessRequest(_api, url); + @override + Duration? connectionTimeout; + @override void close({bool force = false}) {} @@ -283,6 +286,9 @@ class _InProcessRequest implements HttpClientRequest { @override void add(List data) => _body.addAll(data); + @override + Future addStream(Stream> stream) => stream.forEach(add); + @override void abort([Object? exception, StackTrace? stackTrace]) { if (!_aborted.isCompleted) {