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

6 files changed, 44 insertions, 45 deletions

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<FSTMaybeDocument *> *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 <random>
 
-#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<size_t>(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.