Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(logging): enable log rotation and set retry on full log store sync #3699

Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ class DartQueuedItemStore implements QueuedItemStore, Closeable {
}

@override
FutureOr<bool> isFull(int maxSizeInMB) {
bool isFull(int maxSizeInMB) {
throw UnimplementedError('isFull() has not been implemented.');
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ class DartQueuedItemStore implements QueuedItemStore, Closeable {
}

@override
Future<bool> isFull(int maxSizeInMB) {
bool isFull(int maxSizeInMB) {
return _database.isFull(maxSizeInMB);
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -14,8 +14,8 @@ class DartQueuedItemStore
// ignore: avoid_unused_constructor_parameters
DartQueuedItemStore(String? storagePath);

late final Future<QueuedItemStore> _database = () async {
if (await IndexedDbAdapter.checkIsIndexedDBSupported()) {
late final QueuedItemStore _database = () {
if (IndexedDbAdapter.checkIsIndexedDBSupported()) {
return IndexedDbAdapter();
}
logger.warn(
Expand All @@ -34,8 +34,7 @@ class DartQueuedItemStore
String timestamp, {
bool enableQueueRotation = false,
}) async {
final db = await _database;
await db.addItem(
await _database.addItem(
string,
timestamp,
enableQueueRotation: enableQueueRotation,
Expand All @@ -44,34 +43,29 @@ class DartQueuedItemStore

@override
Future<void> deleteItems(Iterable<QueuedItem> items) async {
final db = await _database;
await db.deleteItems(items);
await _database.deleteItems(items);
}

@override
Future<Iterable<QueuedItem>> getCount(int count) async {
final db = await _database;
return db.getCount(count);
return _database.getCount(count);
}

@override
Future<Iterable<QueuedItem>> getAll() async {
final db = await _database;
return db.getAll();
return _database.getAll();
}

@override
Future<bool> isFull(int maxSizeInMB) async {
final db = await _database;
return db.isFull(maxSizeInMB);
bool isFull(int maxSizeInMB) {
return _database.isFull(maxSizeInMB);
}

/// Clear IndexedDB data.
@override
@visibleForTesting
Future<void> clear() async {
final db = await _database;
return db.clear();
return _database.clear();
}

@override
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -104,7 +104,7 @@ class DriftQueuedItemStore extends _$DriftQueuedItemStore
}

@override
Future<bool> isFull(int maxSizeInMB) async {
bool isFull(int maxSizeInMB) {
final maxBytes = maxSizeInMB * 1024 * 1024;
return _currentTotalByteSize >= maxBytes;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -150,7 +150,7 @@ class IndexedDbAdapter implements QueuedItemStore {
}

@override
Future<bool> isFull(int maxSizeInMB) async {
bool isFull(int maxSizeInMB) {
final maxBytes = maxSizeInMB * 1024 * 1024;
return _currentTotalByteSize >= maxBytes;
}
Expand All @@ -167,15 +167,14 @@ class IndexedDbAdapter implements QueuedItemStore {
void close() {}

/// Check that IndexDB will work on this device.
static Future<bool> checkIsIndexedDBSupported() async {
static bool checkIsIndexedDBSupported() {
if (indexedDB == null) {
return false;
}
// indexedDB will be non-null in Firefox private browsing,
// but will fail to open.
try {
final openRequest = indexedDB!.open('test', 1);
await openRequest.future;
indexedDB!.open('test', 1).result;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you explain this change?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

QueuedItemStore.isFull() is a sync method. however it was implemented async because the web implementation calls checkIsIndexedDBSupported to either use indexedDB or InMemoryQueuedItemStore. Because the checkIsIndexedDBSupported was async all the web APIs had to be async.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But why would this be guaranteed to throw in the same way as before?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

based on the docs If the operation is successful, the value of result is a connection to the database. If the request failed and the result is not available, an InvalidStateError exception is thrown.

return true;
} on Object {
return false;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -233,14 +233,14 @@ void main() {
await db.addItem(largeItem, DateTime.now().toIso8601String());
}

var result = await db.isFull(capacityLimit);
var result = db.isFull(capacityLimit);
expect(result, isFalse);

for (var i = 0; i < 100; i++) {
await db.addItem(largeItem, DateTime.now().toIso8601String());
}

result = await db.isFull(capacityLimit);
result = db.isFull(capacityLimit);
expect(result, isTrue);
},
);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -32,9 +32,10 @@ import 'package:meta/meta.dart';
const int _maxNumberOfLogEventsInBatch = 10000;
const int _maxLogEventsBatchSize = 1048576;
const int _baseBufferSize = 26;
const int _maxLogEventsTimeSpanInBatch = Duration.millisecondsPerDay;
const int _maxLogEventSize = 256000;
final int _maxLogEventsTimeSpanInBatch =
const Duration(hours: 24).inMilliseconds;
const Duration _minusMaxLogEventTimeInFuture = Duration(hours: -2);
const Duration _baseRetryInterval = Duration(seconds: 10);

typedef _LogBatch = (List<QueuedItem> logQueues, List<InputLogEvent> logEvents);

Expand Down Expand Up @@ -123,7 +124,8 @@ class CloudWatchLoggerPlugin extends AWSLoggerPlugin
bool _enabled;
StoppableTimer? _timer;
RemoteLoggingConstraintProvider? _remoteLoggingConstraintProvider;

int _retryCount = 0;
DateTime? _retryTime;
set remoteLoggingConstraintProvider(
RemoteLoggingConstraintProvider remoteProvider,
) {
Expand All @@ -139,32 +141,89 @@ class CloudWatchLoggerPlugin extends AWSLoggerPlugin
Future<void> startSyncing() async {
final batchStream = _getLogBatchesToSync();
await for (final (logs, events) in batchStream) {
final response = await _sendToCloudWatch(events);
// TODO(nikahsn): handle tooOldLogEventEndIndex
// and expiredLogEventEndIndex.
if (response.rejectedLogEventsInfo?.tooNewLogEventStartIndex != null) {
// TODO(nikahsn): throw and exception to enable log rotation if the
// log store is full.
break;
_TooNewLogEventException? tooNewException;
while (logs.isNotEmpty && events.isNotEmpty) {
final rejectedLogEventsInfo =
(await _sendToCloudWatch(events)).rejectedLogEventsInfo;
if (rejectedLogEventsInfo == null) {
await _logStore.deleteItems(logs);
break;
}

final (tooOldEndIndex, tooNewStartIndex) =
rejectedLogEventsInfo.parse(events.length);

if (_isValidIndex(tooNewStartIndex, events.length)) {
tooNewException = _TooNewLogEventException(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not throw it here? The control flow would be easier to follow

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we want to continue with syncing the current batch after sanitizing the events in the current batch and then throw to stop syncing next batches

events[tooNewStartIndex!].timestamp.toInt(),
);
// set logs to end before the index.
logs.removeRange(tooNewStartIndex, events.length);
// set events to end before the index.
events.removeRange(tooNewStartIndex, events.length);
}
if (_isValidIndex(tooOldEndIndex, events.length)) {
// remove old logs from log store.
await _logStore.deleteItems(logs.sublist(0, tooOldEndIndex! + 1));
// set logs to start after the index.
logs.removeRange(0, tooOldEndIndex + 1);
// set events to start after the index.
events.removeRange(0, tooOldEndIndex + 1);
}
}
// after sending each batch to CloudWatch check if the batch has
// `tooNewException` and throw to stop syncing next batches.
if (tooNewException != null) {
throw tooNewException;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this would be cleaner if you just returned the retry time instead of throwing

}
await _logStore.deleteItems(logs);
}
}

if (!_syncing) {
// TODO(nikahsn): disable log rotation.
_syncing = true;
DateTime? nextRetry;
try {
await startSyncing();
} on _TooNewLogEventException catch (e) {
nextRetry =
DateTime.fromMillisecondsSinceEpoch(e.timeInMillisecondsSinceEpoch)
.add(_minusMaxLogEventTimeInFuture);
} on Exception catch (e) {
logger.error('Failed to sync logs to CloudWatch.', e);
// TODO(nikahsn): enable log rotation if the log store is full
} finally {
_handleFullLogStoreAfterSync(
retryTime: nextRetry,
);
_syncing = false;
}
}
}

void _handleFullLogStoreAfterSync({
DateTime? retryTime,
}) {
final isLogStoreFull =
_logStore.isFull(_pluginConfig.localStoreMaxSizeInMB);
if (!isLogStoreFull) {
_retryCount = 0;
_retryTime = null;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why would you not respect retryTime here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it is reseting retry if log store is not full. it retries to sync only if log store is full otherwise can wait till next sync.

return;
}
if (retryTime != null && retryTime.isAfter(DateTime.timestamp())) {
_retryTime = retryTime;
return;
}
_retryCount += 1;
_retryTime = DateTime.timestamp().add((_baseRetryInterval * _retryCount));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems like a long time for a basic backoff

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

flushIntervalInSeconds = const Duration(seconds: 60). updated the _baseRetryInterval to 10 secs so there will be 2-3 retries within the flush interval.

}

bool _shouldSyncOnFullLogStore() {
if (_retryTime == null) {
return true;
}
return !(_retryTime!.isAfter(DateTime.timestamp()));
}

void _onTimerError(Object e) {
logger.error('Failed to sync logs to CloudWatch.', e);
}
Expand Down Expand Up @@ -235,11 +294,17 @@ class CloudWatchLoggerPlugin extends AWSLoggerPlugin
return;
}
final item = logEntry.toQueuedItem();
final isLogStoreFull =
_logStore.isFull(_pluginConfig.localStoreMaxSizeInMB);
final shouldEnableQueueRotation = isLogStoreFull && _retryTime != null;

await _logStore.addItem(
item.value,
item.timestamp,
enableQueueRotation: shouldEnableQueueRotation,
);
if (await _logStore.isFull(_pluginConfig.localStoreMaxSizeInMB)) {

if (isLogStoreFull && _shouldSyncOnFullLogStore()) {
await _startSyncingIfNotInProgress();
}
}
Expand All @@ -263,6 +328,8 @@ class CloudWatchLoggerPlugin extends AWSLoggerPlugin
_enabled = false;
_timer?.stop();
await _logStore.clear();
_retryCount = 0;
_retryTime = null;
}

/// Sends logs on-demand to CloudWatch.
Expand Down Expand Up @@ -295,3 +362,34 @@ extension on LogEntry {
);
}
}

extension on RejectedLogEventsInfo {
(int? pastEndIndex, int? futureStartIndex) parse(int length) {
int? pastEndIndex;
int? futureStartIndex;

if (_isValidIndex(tooOldLogEventEndIndex, length)) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this allowed to be false? I would use RangeError.checkValidIndex to assert these are valid.

pastEndIndex = tooOldLogEventEndIndex;
}
if (_isValidIndex(expiredLogEventEndIndex, length)) {
pastEndIndex = pastEndIndex == null
? expiredLogEventEndIndex
: max(pastEndIndex, expiredLogEventEndIndex!);
}
if (_isValidIndex(tooNewLogEventStartIndex, length)) {
futureStartIndex = tooNewLogEventStartIndex;
}
return (pastEndIndex, futureStartIndex);
}
}

class _TooNewLogEventException implements Exception {
const _TooNewLogEventException(
this.timeInMillisecondsSinceEpoch,
);
final int timeInMillisecondsSinceEpoch;
}

bool _isValidIndex(int? index, int length) {
return index != null && index >= 0 && index <= length - 1;
}
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ abstract interface class QueuedItemStore {
FutureOr<Iterable<QueuedItem>> getAll();

/// Whether the queue size is reached [maxSizeInMB].
FutureOr<bool> isFull(int maxSizeInMB);
bool isFull(int maxSizeInMB);

/// Clear the queue of items.
FutureOr<void> clear();
Expand Down
Loading