search

newrelic / newrelic-android-agent

SDK to enable instrumentation of Android mobile apps in New Relic
Apache License 2.0
13 stars 12 forks source link

LogInstrumentation logs long stack trace on normal behavior #280

Open TWiStErRob opened 4 days ago

TWiStErRob commented 4 days ago

Description

There's log spam when code calls Log.x("TAG", "message", null").

Steps to Reproduce

android.util.Log.i("TEST", "null exception 1");
android.util.Log.i("TEST", "null exception 2", null);

Expected Behavior

No stack trace printed.

2024-09-25 16:18:39.827 21454-21454 TEST                    com.example       I  null exception 1
2024-09-25 16:18:39.827 21454-21454 TEST                    com.example       I  null exception 2

Actual Behavior

2024-09-25 15:26:29.864 24747-24747 TEST                    com.example       I  null exception 1
2024-09-25 15:26:29.864 24747-24747 newrelic                com.example       I  newrelic: {level=INFO,tag=TEST,message=null exception 1}
2024-09-25 15:26:29.864 24747-24747 TEST                    com.example       I  null exception 2
2024-09-25 15:26:29.865 24747-24747 newrelic                com.example       I  newrelic: java.lang.IllegalArgumentException
    at com.newrelic.agent.android.logging.MessageValidator.validate(MessageValidator.java:72)
    at com.newrelic.agent.android.logging.LogReporting$AgentLogger.logAll(LogReporting.java:190)
    at com.newrelic.agent.android.instrumentation.LogInstrumentation.i(LogInstrumentation.java:78)
    at com.example.MyActivity.onCreate(MyActivity.kt:50)
    at android.app.Activity.performCreate(Activity.java:8305)
    at android.app.Activity.performCreate(Activity.java:8284)
    at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1417)
    at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:3626)
    at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:3782)
    at android.app.servertransaction.LaunchActivityItem.execute(LaunchActivityItem.java:101)
    at android.app.servertransaction.TransactionExecutor.executeCallbacks(TransactionExecutor.java:135)
    at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:95)
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2307)
    at android.os.Handler.dispatchMessage(Handler.java:106)
    at android.os.Looper.loopOnce(Looper.java:201)
    at android.os.Looper.loop(Looper.java:288)
    at android.app.ActivityThread.main(ActivityThread.java:7872)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)
 {level=INFO,tag=TEST,message=null exception 2}

Your Environment

Additional context

Why is this a problem? There are many logging abstractions out there, and it's easy to imagine them being written in Kotlin. This means that we can have signatures like

fun Logger.info(message: String, throwable: Throwable? = null) {
    Log.i(this.tag, message, throwable)
}

notice the default argument. That means the 2nd variant in repro is always going to be called when the user does this.logger.info("Hello"), meaning for every non-erroring log line NewRelic will print a full stack trace, because it's "missing" an exception.

Even the signature of Log.i allows for a @Nullable Throwable, so LogInstrumentation should handle that:

https://github.com/newrelic/newrelic-android-agent/blob/2265f8f57a1f8f96f170fe9b69d5fef7f156bb3a/agent-core/src/main/java/com/newrelic/agent/android/logging/LogReporting.java#L190-L194

https://github.com/newrelic/newrelic-android-agent/blob/2265f8f57a1f8f96f170fe9b69d5fef7f156bb3a/agent-core/src/main/java/com/newrelic/agent/android/logging/MessageValidator.java#L71-L73

Note: in the repro I removed all the unnecessary baggage (3rd party lib, Kotlin), just focused on the bytecode that minimally triggers this behavior.

A real case of this "imaginary logger" can be found at Interface definition with default args and implementation with call to Log.i.

Stack trace from Chucker's usage ``` java.lang.IllegalArgumentException at com.newrelic.agent.android.logging.MessageValidator.validate(MessageValidator.java:72) at com.newrelic.agent.android.logging.LogReporting$AgentLogger.logAll(LogReporting.java:190) at com.newrelic.agent.android.instrumentation.LogInstrumentation.i(LogInstrumentation.java:78) at com.chuckerteam.chucker.api.Chucker$logger$1.info(Chucker.kt:82) at com.chuckerteam.chucker.internal.support.Logger$Companion.info(Logger.kt:14) at com.chuckerteam.chucker.internal.support.Logger$DefaultImpls.info$default(Logger.kt:6) at com.chuckerteam.chucker.internal.support.RequestProcessor$decodePayload$1.invoke(RequestProcessor.kt:75) at com.chuckerteam.chucker.internal.support.RequestProcessor$decodePayload$1.invoke(RequestProcessor.kt:73) at kotlin.sequences.TransformingSequence$iterator$1.next(Sequences.kt:210) at kotlin.sequences.FilteringSequence$iterator$1.calcNext(Sequences.kt:170) at kotlin.sequences.FilteringSequence$iterator$1.hasNext(Sequences.kt:194) at kotlin.sequences.SequencesKt___SequencesKt.firstOrNull(_Sequences.kt:168) at com.chuckerteam.chucker.internal.support.RequestProcessor.decodePayload(RequestProcessor.kt:81) at com.chuckerteam.chucker.internal.support.RequestProcessor.processPayload(RequestProcessor.kt:64) at com.chuckerteam.chucker.internal.support.RequestProcessor.process(RequestProcessor.kt:22) at com.chuckerteam.chucker.api.ChuckerInterceptor.intercept(ChuckerInterceptor.kt:76) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637) at java.lang.Thread.run(Thread.java:1012) ```

Additionally we could argue that in general double-printing logs (even when they're not printing stack traces) is noisy in LogCat.

TWiStErRob commented 4 days ago

Another instance of the same issue:

newrelic: java.lang.IllegalArgumentException
    at com.newrelic.agent.android.logging.MessageValidator$-CC.$default$validate(MessageValidator.java:72)
    at com.newrelic.agent.android.logging.LogReporting$AgentLogger$1.validate(Unknown Source:0)
    at com.newrelic.agent.android.logging.LogReporting$AgentLogger.logAll(LogReporting.java:190)
    at com.newrelic.agent.android.instrumentation.LogInstrumentation.i(LogInstrumentation.java:78)
    at com.google.firebase.crashlytics.internal.Logger.i(Logger.java:56)
    at com.google.firebase.crashlytics.internal.Logger.i(Logger.java:81)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsController.getResourceAsStream(CrashlyticsController.java:663)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsController.getVersionControlInfo(CrashlyticsController.java:645)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsController.saveVersionControlInfo(CrashlyticsController.java:634)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsCore.doBackgroundInitialization(CrashlyticsCore.java:235)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsCore.access$000(CrashlyticsCore.java:48)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsCore$1.call(CrashlyticsCore.java:222)
    at com.google.firebase.crashlytics.internal.common.CrashlyticsCore$1.call(CrashlyticsCore.java:219)
    at com.google.firebase.crashlytics.internal.common.Utils.lambda$callTask$3(Utils.java:78)
    at com.google.firebase.crashlytics.internal.common.Utils$$ExternalSyntheticLambda4.run(Unknown Source:6)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
    at com.google.firebase.crashlytics.internal.common.ExecutorUtils$1$1.onRun(ExecutorUtils.java:67)
    at com.google.firebase.crashlytics.internal.common.BackgroundPriorityRunnable.run(BackgroundPriorityRunnable.java:27)
    at java.lang.Thread.run(Thread.java:1012)

where com.google.firebase.crashlytics.internal.Logger.i is:

  public void i(String text) {
    i(text, null);
  }
ndesai-newrelic commented 4 days ago

@TWiStErRob thanks for your feedback, we will look into it.