FirePerf: use FPRLogDebug instead of FPRLogError for logging events when FirePerf is disabled

[leotianlizhan]

Discussion

• Firebase Performance logs too much when data collection disabled (2) #8423

Cause/Result

Log level from most verbose to least verbose is:

Debug, Info, Notice, Warning, Error

With those 5, levels, Notice, Warning, and Error logs will show even without -FIRDebugEnabled being set. Due to that, FPRLogError(kFPRClientPerfNotConfigured, @"Dropping event since data collection is disabled."); will spam log if gauge metrics are being collected (if they are being collected, they are firing on a timer, like every second). With this PR, only when -FIRDebugEnabled is set, will those log message show up in logs, if you are lucky enough to be selected for sampling in the first place (more on this below).

Investigation/Details

Reproducing this issue was difficult at first because of sampling. Long before gauge metrics collection start, in FPRSessionManager.updateSessionId, there is a check called isGaugeCollectionEnabledForSessionId that decides if current session should be sampled, around 1% chance. Even if selected for sampling, gauge metrics collection usually will not be started at all when FirePerf is disabled (see FPRGaugeManager.gaugeCollectionEnabled), so no log should appear. Only during cold start, due to technical reasons (too slow to check RemoteConfig), will gauge metrics collection always start. In that case, we must drop gauge events at the dispatch stage, which is where the "Dropping event..." is being logged.

In the linked issue above, it is referring to an older issue, in which the author said the log spam was solved by changing FIRInfoEnabled to FIRDebugEnabled. That makes no sense because Debug is higher verbosity than Info. I suspect the author was just lucky (pretty hard to be unlucky since sampling at 1% rate) that their next app-run's sessions weren't selected for sampling.

Other possible issues

There is a weird behaviour I ran into with FIRLogInfo and FIRInfoEnabled in that it does not log its own level at all With further testing, I don't think FIRInfoEnabled is even a flag at all, or any of FIRNoticeEnabled, FIRWarningEnabled, and FIRErrorEnabled. I don't think they have any effect on logging. I can only confirm the following behaviors on my machine:

1. See Notice, Warning, Error logs when -FIRDebugEnabled is not set,
2. See Debug, Info, Notice, Warning, Error logs when -FIRDebugEnabled is set.

Either FIRDebugEnabled is the only flag, or something is wrong with FIRLogging, which would be a whole separate issue with another team.

[google-oss-bot]

Coverage Report

Affected SDKs

• FirebasePerformance-iOS-FirebasePerformance.framework

  SDK overall coverage changed from 92.35% (e2802b5) to 92.49% (4b3f98e) by +0.14%.

  Filename	Base (e2802b5)	Head (4b3f98e)	Diff
  FPRGaugeManager.m	94.89%	98.86%	+3.98%
  FPRSessionManager.m	85.71%	88.31%	+2.60%

Test Logs

• Base (e2802b50): https://github.com/firebase/firebase-ios-sdk/actions/runs/1198780423
• Head (4b3f98e0): https://github.com/firebase/firebase-ios-sdk/actions/runs/1210224781

[google-oss-bot]

Binary Size Report

Affected SDKs

No changes between base commit (e2802b5) and head commit (4b3f98e).

Test Logs

• Base (e2802b50): https://github.com/firebase/firebase-ios-sdk/actions/runs/1198780423
• Head (4b3f98e0): https://github.com/firebase/firebase-ios-sdk/actions/runs/1210224781

[jeremyjiang-dev]

The Changes LGTM. Thanks for the detailed PR description!
Could you follow up with iCore to understand the expected behavior?
Could you update the CHANGELOG.md as well?