From af19a1b07245b7d0be4fd492bd3731964937c7c6 Mon Sep 17 00:00:00 2001 From: Gil Date: Wed, 23 May 2018 07:00:05 -0700 Subject: Reimplement C++ logging (#1313) * Add direct support for formatting Objective-C objects * Rewrite log.h * Convert FSTWarn to LOG_WARN * Convert FSTLog to LOG_DEBUG * Remove FSTLogger --- Firestore/Source/Remote/FSTDatastore.mm | 12 ++++---- Firestore/Source/Remote/FSTExponentialBackoff.mm | 9 +++--- Firestore/Source/Remote/FSTOnlineStateTracker.mm | 12 ++++---- Firestore/Source/Remote/FSTRemoteEvent.mm | 5 ++-- Firestore/Source/Remote/FSTRemoteStore.mm | 15 +++++----- Firestore/Source/Remote/FSTStream.mm | 36 ++++++++++++------------ 6 files changed, 44 insertions(+), 45 deletions(-) (limited to 'Firestore/Source/Remote') diff --git a/Firestore/Source/Remote/FSTDatastore.mm b/Firestore/Source/Remote/FSTDatastore.mm index f0852fe..d45af6b 100644 --- a/Firestore/Source/Remote/FSTDatastore.mm +++ b/Firestore/Source/Remote/FSTDatastore.mm @@ -33,7 +33,6 @@ #import "Firestore/Source/Remote/FSTStream.h" #import "Firestore/Source/Util/FSTAssert.h" #import "Firestore/Source/Util/FSTDispatchQueue.h" -#import "Firestore/Source/Util/FSTLogger.h" #import "Firestore/Protos/objc/google/firestore/v1beta1/Firestore.pbrpc.h" @@ -43,6 +42,7 @@ #include "Firestore/core/src/firebase/firestore/model/database_id.h" #include "Firestore/core/src/firebase/firestore/model/document_key.h" #include "Firestore/core/src/firebase/firestore/util/error_apple.h" +#include "Firestore/core/src/firebase/firestore/util/log.h" #include "Firestore/core/src/firebase/firestore/util/string_apple.h" namespace util = firebase::firestore::util; @@ -217,8 +217,8 @@ typedef GRPCProtoCall * (^RPCFactory)(void); /** Logs the (whitelisted) headers returned for an GRPCProtoCall RPC. */ + (void)logHeadersForRPC:(GRPCProtoCall *)rpc RPCName:(NSString *)rpcName { if ([FIRFirestore isLoggingEnabled]) { - FSTLog(@"RPC %@ returned headers (whitelisted): %@", rpcName, - [FSTDatastore extractWhiteListedHeaders:rpc.responseHeaders]); + LOG_DEBUG("RPC %s returned headers (whitelisted): %s", rpcName, + [FSTDatastore extractWhiteListedHeaders:rpc.responseHeaders]); } } @@ -239,7 +239,7 @@ typedef GRPCProtoCall * (^RPCFactory)(void); handler:^(GCFSCommitResponse *response, NSError *_Nullable error) { error = [FSTDatastore firestoreErrorForError:error]; [self.workerDispatchQueue dispatchAsync:^{ - FSTLog(@"RPC CommitRequest completed. Error: %@", error); + LOG_DEBUG("RPC CommitRequest completed. Error: %s", error); [FSTDatastore logHeadersForRPC:rpc RPCName:@"CommitRequest"]; completion(error); }]; @@ -272,7 +272,7 @@ typedef GRPCProtoCall * (^RPCFactory)(void); error = [FSTDatastore firestoreErrorForError:error]; [self.workerDispatchQueue dispatchAsync:^{ if (error) { - FSTLog(@"RPC BatchGetDocuments completed. Error: %@", error); + LOG_DEBUG("RPC BatchGetDocuments completed. Error: %s", error); [FSTDatastore logHeadersForRPC:rpc RPCName:@"BatchGetDocuments"]; completion(nil, error); return; @@ -285,7 +285,7 @@ typedef GRPCProtoCall * (^RPCFactory)(void); closure->results.insert({doc.key, doc}); } else { // Streaming response is done, call completion - FSTLog(@"RPC BatchGetDocuments completed successfully."); + LOG_DEBUG("RPC BatchGetDocuments completed successfully."); [FSTDatastore logHeadersForRPC:rpc RPCName:@"BatchGetDocuments"]; FSTAssert(!response, @"Got response after done."); NSMutableArray *docs = diff --git a/Firestore/Source/Remote/FSTExponentialBackoff.mm b/Firestore/Source/Remote/FSTExponentialBackoff.mm index 20b50a5..2bddbf7 100644 --- a/Firestore/Source/Remote/FSTExponentialBackoff.mm +++ b/Firestore/Source/Remote/FSTExponentialBackoff.mm @@ -18,10 +18,10 @@ #include -#include "Firestore/core/src/firebase/firestore/util/secure_random.h" - #import "Firestore/Source/Util/FSTDispatchQueue.h" -#import "Firestore/Source/Util/FSTLogger.h" + +#include "Firestore/core/src/firebase/firestore/util/log.h" +#include "Firestore/core/src/firebase/firestore/util/secure_random.h" using firebase::firestore::util::SecureRandom; @@ -71,8 +71,7 @@ using firebase::firestore::util::SecureRandom; // First schedule the block using the current base (which may be 0 and should be honored as such). NSTimeInterval delayWithJitter = _currentBase + [self jitterDelay]; if (_currentBase > 0) { - FSTLog(@"Backing off for %.2f seconds (base delay: %.2f seconds)", delayWithJitter, - _currentBase); + LOG_DEBUG("Backing off for %s seconds (base delay: %s seconds)", delayWithJitter, _currentBase); } self.timerCallback = diff --git a/Firestore/Source/Remote/FSTOnlineStateTracker.mm b/Firestore/Source/Remote/FSTOnlineStateTracker.mm index e782397..e512a3c 100644 --- a/Firestore/Source/Remote/FSTOnlineStateTracker.mm +++ b/Firestore/Source/Remote/FSTOnlineStateTracker.mm @@ -18,7 +18,8 @@ #import "Firestore/Source/Remote/FSTRemoteStore.h" #import "Firestore/Source/Util/FSTAssert.h" #import "Firestore/Source/Util/FSTDispatchQueue.h" -#import "Firestore/Source/Util/FSTLogger.h" + +#include "Firestore/core/src/firebase/firestore/util/log.h" NS_ASSUME_NONNULL_BEGIN @@ -83,10 +84,9 @@ static const NSTimeInterval kOnlineStateTimeout = 10; FSTAssert( self.state == FSTOnlineStateUnknown, @"Timer should be canceled if we transitioned to a different state."); - FSTLog( - @"Watch stream didn't reach Online or Offline within %f seconds. " - @"Considering " - "client offline.", + LOG_DEBUG( + "Watch stream didn't reach Online or Offline within %s seconds. " + "Considering client offline.", kOnlineStateTimeout); [self logClientOfflineWarningIfNecessary]; [self setAndBroadcastState:FSTOnlineStateOffline]; @@ -138,7 +138,7 @@ static const NSTimeInterval kOnlineStateTimeout = 10; - (void)logClientOfflineWarningIfNecessary { if (self.shouldWarnClientIsOffline) { - FSTWarn(@"Could not reach Firestore backend."); + LOG_WARN("Could not reach Firestore backend."); self.shouldWarnClientIsOffline = NO; } } diff --git a/Firestore/Source/Remote/FSTRemoteEvent.mm b/Firestore/Source/Remote/FSTRemoteEvent.mm index 438072e..ebd9b93 100644 --- a/Firestore/Source/Remote/FSTRemoteEvent.mm +++ b/Firestore/Source/Remote/FSTRemoteEvent.mm @@ -24,9 +24,10 @@ #import "Firestore/Source/Remote/FSTWatchChange.h" #import "Firestore/Source/Util/FSTAssert.h" #import "Firestore/Source/Util/FSTClasses.h" -#import "Firestore/Source/Util/FSTLogger.h" + #include "Firestore/core/src/firebase/firestore/model/document_key.h" #include "Firestore/core/src/firebase/firestore/util/hashing.h" +#include "Firestore/core/src/firebase/firestore/util/log.h" using firebase::firestore::model::DocumentKey; using firebase::firestore::model::SnapshotVersion; @@ -577,7 +578,7 @@ initWithSnapshotVersion:(SnapshotVersion)snapshotVersion } break; default: - FSTWarn(@"Unknown target watch change type: %ld", (long)targetChange.state); + LOG_WARN("Unknown target watch change type: %s", targetChange.state); } } } diff --git a/Firestore/Source/Remote/FSTRemoteStore.mm b/Firestore/Source/Remote/FSTRemoteStore.mm index 0ea4887..e0adb4e 100644 --- a/Firestore/Source/Remote/FSTRemoteStore.mm +++ b/Firestore/Source/Remote/FSTRemoteStore.mm @@ -32,11 +32,11 @@ #import "Firestore/Source/Remote/FSTStream.h" #import "Firestore/Source/Remote/FSTWatchChange.h" #import "Firestore/Source/Util/FSTAssert.h" -#import "Firestore/Source/Util/FSTLogger.h" #include "Firestore/core/src/firebase/firestore/auth/user.h" #include "Firestore/core/src/firebase/firestore/model/document_key.h" #include "Firestore/core/src/firebase/firestore/model/snapshot_version.h" +#include "Firestore/core/src/firebase/firestore/util/log.h" #include "Firestore/core/src/firebase/firestore/util/string_apple.h" namespace util = firebase::firestore::util; @@ -205,7 +205,7 @@ static const int kMaxPendingWrites = 10; #pragma mark Shutdown - (void)shutdown { - FSTLog(@"FSTRemoteStore %p shutting down", (__bridge void *)self); + LOG_DEBUG("FSTRemoteStore %s shutting down", (__bridge void *)self); [self disableNetworkInternal]; // Set the FSTOnlineState to Unknown (rather than Offline) to avoid potentially triggering // spurious listener events with cached data, etc. @@ -213,7 +213,7 @@ static const int kMaxPendingWrites = 10; } - (void)userDidChange:(const User &)user { - FSTLog(@"FSTRemoteStore %p changing users: %s", (__bridge void *)self, user.uid().c_str()); + LOG_DEBUG("FSTRemoteStore %s changing users: %s", (__bridge void *)self, user.uid()); if ([self isNetworkEnabled]) { // Tear down and re-create our network streams. This will ensure we get a fresh auth token // for the new user and re-fill the write pipeline with new mutations from the LocalStore @@ -408,7 +408,7 @@ static const int kMaxPendingWrites = 10; } if (trackedRemote.size() != static_cast(filter.count)) { - FSTLog(@"Existence filter mismatch, resetting mapping"); + LOG_DEBUG("Existence filter mismatch, resetting mapping"); // Make sure the mismatch is exposed in the remote event [remoteEvent handleExistenceFilterMismatchForTargetID:target]; @@ -490,8 +490,7 @@ static const int kMaxPendingWrites = 10; - (void)cleanUpWriteStreamState { self.lastBatchSeen = kFSTBatchIDUnknown; - FSTLog(@"Stopping write stream with %lu pending writes", - (unsigned long)[self.pendingWrites count]); + LOG_DEBUG("Stopping write stream with %s pending writes", [self.pendingWrites count]); [self.pendingWrites removeAllObjects]; } @@ -618,8 +617,8 @@ static const int kMaxPendingWrites = 10; // stream is no longer valid. if ([FSTDatastore isPermanentWriteError:error] || [FSTDatastore isAbortedError:error]) { NSString *token = [self.writeStream.lastStreamToken base64EncodedStringWithOptions:0]; - FSTLog(@"FSTRemoteStore %p error before completed handshake; resetting stream token %@: %@", - (__bridge void *)self, token, error); + LOG_DEBUG("FSTRemoteStore %s error before completed handshake; resetting stream token %s: %s", + (__bridge void *)self, token, error); self.writeStream.lastStreamToken = nil; [self.localStore setLastStreamToken:nil]; } diff --git a/Firestore/Source/Remote/FSTStream.mm b/Firestore/Source/Remote/FSTStream.mm index f4ec675..0e45418 100644 --- a/Firestore/Source/Remote/FSTStream.mm +++ b/Firestore/Source/Remote/FSTStream.mm @@ -29,7 +29,6 @@ #import "Firestore/Source/Util/FSTAssert.h" #import "Firestore/Source/Util/FSTClasses.h" #import "Firestore/Source/Util/FSTDispatchQueue.h" -#import "Firestore/Source/Util/FSTLogger.h" #import "Firestore/Protos/objc/google/firestore/v1beta1/Firestore.pbrpc.h" @@ -38,6 +37,7 @@ #include "Firestore/core/src/firebase/firestore/model/database_id.h" #include "Firestore/core/src/firebase/firestore/model/snapshot_version.h" #include "Firestore/core/src/firebase/firestore/util/error_apple.h" +#include "Firestore/core/src/firebase/firestore/util/log.h" #include "Firestore/core/src/firebase/firestore/util/string_apple.h" namespace util = firebase::firestore::util; @@ -258,7 +258,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; return; } - FSTLog(@"%@ %p start", NSStringFromClass([self class]), (__bridge void *)self); + LOG_DEBUG("%s %s start", NSStringFromClass([self class]), (__bridge void *)self); FSTAssert(self.state == FSTStreamStateInitial, @"Already started"); self.state = FSTStreamStateAuth; @@ -311,7 +311,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; /** Backs off after an error. */ - (void)performBackoffWithDelegate:(id)delegate { - FSTLog(@"%@ %p backoff", NSStringFromClass([self class]), (__bridge void *)self); + LOG_DEBUG("%s %s backoff", NSStringFromClass([self class]), (__bridge void *)self); [self.workerDispatchQueue verifyIsCurrentQueue]; FSTAssert(self.state == FSTStreamStateError, @"Should only perform backoff in an error case"); @@ -381,13 +381,13 @@ static const NSTimeInterval kIdleTimeout = 60.0; // If this is an intentional close ensure we don't delay our next connection attempt. [self.backoff reset]; } else if (error != nil && error.code == FIRFirestoreErrorCodeResourceExhausted) { - FSTLog(@"%@ %p Using maximum backoff delay to prevent overloading the backend.", [self class], - (__bridge void *)self); + LOG_DEBUG("%s %s Using maximum backoff delay to prevent overloading the backend.", [self class], + (__bridge void *)self); [self.backoff resetToMax]; } if (finalState != FSTStreamStateError) { - FSTLog(@"%@ %p Performing stream teardown", [self class], (__bridge void *)self); + LOG_DEBUG("%s %s Performing stream teardown", [self class], (__bridge void *)self); [self tearDown]; } @@ -395,7 +395,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; // Clean up the underlying RPC. If this close: is in response to an error, don't attempt to // call half-close to avoid secondary failures. if (finalState != FSTStreamStateError) { - FSTLog(@"%@ %p Closing stream client-side", [self class], (__bridge void *)self); + LOG_DEBUG("%s %s Closing stream client-side", [self class], (__bridge void *)self); @synchronized(self.requestsWriter) { [self.requestsWriter finishWithError:nil]; } @@ -426,7 +426,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; } - (void)stop { - FSTLog(@"%@ %p stop", NSStringFromClass([self class]), (__bridge void *)self); + LOG_DEBUG("%s %s stop", NSStringFromClass([self class]), (__bridge void *)self); if ([self isStarted]) { [self closeWithFinalState:FSTStreamStateStopped error:nil]; } @@ -550,7 +550,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; * Called by the stream when the underlying RPC has been closed for whatever reason. */ - (void)handleStreamClose:(nullable NSError *)error { - FSTLog(@"%@ %p close: %@", NSStringFromClass([self class]), (__bridge void *)self, error); + LOG_DEBUG("%s %s close: %s", NSStringFromClass([self class]), (__bridge void *)self, error); FSTAssert([self isStarted], @"handleStreamClose: called for non-started stream."); // In theory the stream could close cleanly, however, in our current model we never expect this @@ -577,9 +577,9 @@ static const NSTimeInterval kIdleTimeout = 60.0; if (!self.messageReceived) { self.messageReceived = YES; if ([FIRFirestore isLoggingEnabled]) { - FSTLog(@"%@ %p headers (whitelisted): %@", NSStringFromClass([self class]), - (__bridge void *)self, - [FSTDatastore extractWhiteListedHeaders:self.rpc.responseHeaders]); + LOG_DEBUG("%s %s headers (whitelisted): %s", NSStringFromClass([self class]), + (__bridge void *)self, + [FSTDatastore extractWhiteListedHeaders:self.rpc.responseHeaders]); } } NSError *error; @@ -665,7 +665,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; request.addTarget = [_serializer encodedTarget:query]; request.labels = [_serializer encodedListenRequestLabelsForQueryData:query]; - FSTLog(@"FSTWatchStream %p watch: %@", (__bridge void *)self, request); + LOG_DEBUG("FSTWatchStream %s watch: %s", (__bridge void *)self, request); [self writeRequest:request]; } @@ -677,7 +677,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; request.database = [_serializer encodedDatabaseID]; request.removeTarget = targetID; - FSTLog(@"FSTWatchStream %p unwatch: %@", (__bridge void *)self, request); + LOG_DEBUG("FSTWatchStream %s unwatch: %s", (__bridge void *)self, request); [self writeRequest:request]; } @@ -686,7 +686,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; * watchStreamDidChange:snapshotVersion: callback. */ - (void)handleStreamMessage:(GCFSListenResponse *)proto { - FSTLog(@"FSTWatchStream %p response: %@", (__bridge void *)self, proto); + LOG_DEBUG("FSTWatchStream %s response: %s", (__bridge void *)self, proto); [self.workerDispatchQueue verifyIsCurrentQueue]; // A successful response means the stream is healthy. @@ -765,7 +765,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; // TODO(dimond): Support stream resumption. We intentionally do not set the stream token on the // handshake, ignoring any stream token we might have. - FSTLog(@"FSTWriteStream %p initial request: %@", (__bridge void *)self, request); + LOG_DEBUG("FSTWriteStream %s initial request: %s", (__bridge void *)self, request); [self writeRequest:request]; } @@ -783,7 +783,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; request.writesArray = protos; request.streamToken = self.lastStreamToken; - FSTLog(@"FSTWriteStream %p mutation request: %@", (__bridge void *)self, request); + LOG_DEBUG("FSTWriteStream %s mutation request: %s", (__bridge void *)self, request); [self writeRequest:request]; } @@ -792,7 +792,7 @@ static const NSTimeInterval kIdleTimeout = 60.0; * that on to the mutationResultsHandler. */ - (void)handleStreamMessage:(GCFSWriteResponse *)response { - FSTLog(@"FSTWriteStream %p response: %@", (__bridge void *)self, response); + LOG_DEBUG("FSTWriteStream %s response: %s", (__bridge void *)self, response); [self.workerDispatchQueue verifyIsCurrentQueue]; // Always capture the last stream token. -- cgit v1.2.3