Malformed Event(s) JSON using 1.10.2 SDK

mariusgherman commented 1 year ago

Expected Behavior

Generated events JSON should be valid

Current Behavior

Generated events JSON is invalid

Malformed JSON string #1

[{
"event_type": "[Amplitude] Deep Link Opened",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158000413,
"event_properties": {
    "[Amplitude] Link Referrer": "android-app:\/\/org.myapp.app"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 69,
"session_id": 1689157052211,
"insert_id": "a2582cf2-b330-491f-80c1-5f994d0d98e2",
"library": "amplitude-analytics-android\/1.10.2"
}, {
"event_type": "[Amplitude] Deep Link Opened",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158000414,
"event_properties": {
    "[Amplitude] Link Referrer": "android-app:\/\/org.myapp.app"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 37,
"session_id": 1689157052211,
"insert_id": "e847b4d5-a8db-4f96-bad8-f22b2a83a790",
"library": "amplitude-analytics-android\/1.10.2"
}, {
"event_type": "[Amplitude] Screen Viewed",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158000510,
"event_properties": {
    "[Amplitude] Screen Name": "Settings"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 70,
"session_id": 1689157052211,
"insert_id": "7c018ed5-ef84-49ec-9edb-36273a4f894b",
"library": "amplitude-analytics-android\/1.10.2"
}, {
"event_type": "[Amplitude] Screen Viewed",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158000510,
"event_properties": {
    "[Amplitude] Screen Name": "Settings"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 38,
"session_id": 1689157052211,
"insert_id": "82b03424-333b-4e27-9026-717abfbed5a8",
"library": "amplitude-analytics-android\/1.10.2"
}]]

Malformed JSON string example #2

[{
"event_type": "[Amplitude] Screen Viewed",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158345037,
"event_properties": {
    "[Amplitude] Screen Name": "Screen Name"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 72,
"session_id": 1689157052211,
"insert_id": "20bedb1a-b5bc-4c9e-b58b-fd4ae430878a",
"library": "amplitude-analytics-android\/1.10.2"
}, {
"event_type": "[Amplitude] Screen Viewed",
"user_id": "vqC3pq54Tj6Od096jMqr7w",
"device_id": "6a974754-0c50-4af7-af7f-3f6bc2b984e5",
"time": 1689158345038,
"event_properties": {
    "[Amplitude] Screen Name": "Screen name"
},
"user_properties": {},
"groups": {},
"group_properties": {},
"platform": "Android",
"os_name": "android",
"os_version": "13",
"device_brand": "google",
"device_manufacturer": "Google",
"device_model": "sdk_gphone64_arm64",
"carrier": "T-Mobile",
"language": "en",
"ip": "$remote",
"version_name": "local",
"adid": "94d655e5-cd08-41b5-be5c-0f2348d09c39",
"event_id": 40,
"session_id": 1689157052211,
"insert_id": "dca283f0-d4b2-4973-8437-16d42feb2605",
"library": "amplitude-analytics-android\/1.10.2"
}]]

Possible Solution

extra ']' is inserted at the end of the event JSON Array should be removed
Issue seems to be only reproducing with com.amplitude.android.utilities.AndroidStorage implementation

Steps to Reproduce

Setup Amplitude Client

Amplitude(
        Configuration(
            context = context.applicationContext,
            apiKey = AMPLITUDE_API_KEY,
            trackingSessionEvents = true,
            defaultTracking = DefaultTrackingOptions.ALL,
        )
    )

Log events + deep links + screen views
Observe stored events JSON string and sent HTTP payloads

Environment

Device: Android Emulator sdk_gphone64_arm64
Device OS and Version: Android OS 13

yuhao900914 commented 1 year ago

Thank you for choosing Amplitude. We are actively addressing this issue and will keep you updated on any progress.

Mercy811 commented 1 year ago

Hi @mariusgherman, did you have this issue with earlier versions or it starts happening after 1.10.2? I set up a local example and send several events. All events were sent successfully. Not sure how you observe stored events JSON string and sent HTTP payloads. Could you elaborate on it?

mariusgherman commented 1 year ago

@Mercy811 unfortunately i have only used the 1.10.2 (i will try with earlier versions to confirm and post my findings). For HTTP content i setup a localhost simple server that does JSON payload validation and payload logging. I used it as the SDK Configuration#serverUrl and posted events to it.

mariusgherman commented 1 year ago

@Mercy811 i've just tried with SDK version 1.10.1. I'm not seeing anymore malformed events in the server logs. However, i've set up a SDK Logger using Configuration#loggerProvider and i'm seeing a few error messages Error when upload event: End of input at character 0 of

Mercy811 commented 1 year ago

Hi @mariusgherman, thanks for your clarification and confirmation. I will investigate more.

Mercy811 commented 1 year ago

Hi @mariusgherman, would like to keep you updated. v1.20.2 starts migrating legacy data. So it’s likely that something wrong in this PR.

Error when upload event: End of input at character 0 of It is probably caused by getEventsString returning an invalid JSON string.

Thanks for the info you provided. They really help me narrow the bug down. I will continue working on this.

Mercy811 commented 1 year ago

@mariusgherman Did you use the legacy SDK on the same device?

justin-fiedler commented 1 year ago

Hi @mariusgherman is it possible you are creating/using multiple instances of the Amplitude()? We noticed the event_id's are out of order 69,37,70,38 which makes us think there could be 2 instances of Amplitude sharing the same storage.

mariusgherman commented 1 year ago

@mariusgherman Did you use the legacy SDK on the same device?

we are in the process of upgrading our amplitude legacy SDK to the kotlin SDK, so yes, this will be the production use case indeed

mariusgherman commented 1 year ago

Hi @mariusgherman is it possible you are creating/using multiple instances of the Amplitude()? We noticed the event_id's are out of order 69,37,70,38 which makes us think there could be 2 instances of Amplitude sharing the same storage.

Not the case. We are ensuring that we have a single instance of Amplitude though usage of Dagger injection scoping.Could it be the case that we are logging multiple events at the same time from different threads ?

justin-fiedler commented 1 year ago

Thanks @mariusgherman.

logging multiple events at the same time from different threads

I don't think this is the case the provided output. A single instance should maintain a single "latestEvenId" that is used to increate the event_id's. So I think in the multithread case both would read the same value latestEvenId, and the last set lastEventId would win vs having multiple intermixed eventIds.

We noticed each pair has the same event_type, event_properties, timestamp (+/- 1 millisecond), new library, etc - except insert_id. I think, it is highly unlikely that events 37, 38, 40 were migrated from old SDK - in this case they would have legacy library and old timestamps.

Can you please share the Dagger configuration you are using to enforce the single instance of Amplitude?

We also notice a difference in casing (Screen Name/ Screen name) in event_properties for events 72/40, maybe that can help locate where each is being tracked.

mariusgherman commented 1 year ago

@justin-fiedler these are the relevant files where we have declared the analytics instance and the dagger module where we provide the Amplitude single instance wrapper

class AmplitudeAnalyticsProvider(
    context: Context,
    private val amplitudeConfigProvider: AmplitudeConfigProvider,
    coroutineDispatcher: CoroutineDispatcher
) {
    private val coroutineScope = CoroutineScope(coroutineDispatcher + SupervisorJob())
    private val coroutineExceptionHandler = CoroutineExceptionHandler { _, throwable ->
        Log.w("Amplitude Config", "Failed to configure device id for amplitude analytics", throwable)
    }

    internal val amplitudeClient by lazy {
        Amplitude(
            Configuration(
                context = context.applicationContext,
                apiKey = amplitudeConfigProvider.getKeyValue(),
                serverUrl = amplitudeConfigProvider.getServerUrl(),
                trackingSessionEvents = true,
                defaultTracking = DefaultTrackingOptions.ALL,
                loggerProvider = object : LoggerProvider {
                    override fun getLogger(amplitude: com.amplitude.core.Amplitude): Logger =
                        AmplitudeLogger(if (BuildConfig.DEBUG) Logger.LogMode.DEBUG else Logger.LogMode.INFO)
                }
            )
        )
    }

    fun initialize() {
        coroutineScope.launch(coroutineExceptionHandler) {
            val deviceId = amplitudeConfigProvider.getDeviceId()
            amplitudeClient.setDeviceId(deviceId)
        }
    }

    fun reset() {
        amplitudeClient.reset()
    }

    fun setUserId(userId: String?) {
        amplitudeClient.setUserId(userId)
    }

    fun identify(userProperties: Map<String, Any?>) {
        amplitudeClient.identify(userProperties)
    }

    fun setGroup(groupType: String, groupName: String, groupProperties: Map<String, Any?> = mutableMapOf()) {
        amplitudeClient.groupIdentify(groupType, groupName, groupProperties)
    }
}

class AmplitudeLogger(override var logMode: Logger.LogMode) : Logger {
    override fun debug(message: String) {
        Log.d(TAG, message)
    }

    override fun error(message: String) {
        Log.e(TAG, message)
    }

    override fun info(message: String) {
        Log.i(TAG, message)
    }

    override fun warn(message: String) {
        Log.w(TAG, message)
    }  
}

@Module
class AnalyticsModule {

    @ApplicationScope
    @Provides
    fun providesAmplitudeAnalyticsProvider(
        context: Context,
        amplitudeConfigProvider: AmplitudeConfigProvider,
        coroutineDispatcher: Dispatchers.Default
    ): AmplitudeAnalyticsProvider {
        return AmplitudeAnalyticsProvider(context, amplitudeConfigProvider, coroutineDispatcher)
    }
    ...
}

justin-fiedler commented 1 year ago

Thanks @mariusgherman, could you add some logging to confirm that only a single instance is created?

internal val amplitudeClient by lazy {
        // LOG 1
        Amplitude(
            Configuration(
                context = context.applicationContext,
                apiKey = amplitudeConfigProvider.getKeyValue(),
                serverUrl = amplitudeConfigProvider.getServerUrl(),
                trackingSessionEvents = true,
                defaultTracking = DefaultTrackingOptions.ALL,
                loggerProvider = object : LoggerProvider {
                    override fun getLogger(amplitude: com.amplitude.core.Amplitude): Logger =
                        AmplitudeLogger(if (BuildConfig.DEBUG) Logger.LogMode.DEBUG else Logger.LogMode.INFO)
                }
            )
        )
    }

    @ApplicationScope
    @Provides
    fun providesAmplitudeAnalyticsProvider(
        context: Context,
        amplitudeConfigProvider: AmplitudeConfigProvider,
        coroutineDispatcher: Dispatchers.Default
    ): AmplitudeAnalyticsProvider {
        // LOG 2
        return AmplitudeAnalyticsProvider(context, amplitudeConfigProvider, coroutineDispatcher)
    }

mariusgherman commented 1 year ago

@justin-fiedler sorry for the late reply so the code looks now like this

class AmplitudeAnalyticsProvider(
    context: Context,
    private val amplitudeConfigProvider: AmplitudeConfigProvider,
    coroutineDispatcher: CoroutineDispatcher
) {
    private val coroutineScope = CoroutineScope(coroutineDispatcher + SupervisorJob())
    private val coroutineExceptionHandler = CoroutineExceptionHandler { _, throwable ->
        Log.w("Amplitude Config", "Failed to configure device id for amplitude analytics", throwable)
    }

    init {
        Log.w("AMPLITUDE_TAG", "Wrapper instance init hashcode ${this@AmplitudeAnalyticsProvider.hashCode()}")
    }

    internal val amplitudeClient by lazy {
        Log.w("AMPLITUDE_TAG", "Wrapper instance lazy hashcode ${this@AmplitudeAnalyticsProvider.hashCode()}")
        val client = Amplitude(
            Configuration(
                context = context.applicationContext,
                apiKey = amplitudeConfigProvider.getKeyValue(),
                trackingSessionEvents = true,
                defaultTracking = DefaultTrackingOptions.ALL,
                loggerProvider = object : LoggerProvider {
                    override fun getLogger(amplitude: Amplitude): Logger =
                        AmplitudeLogger(if (BuildConfig.DEBUG) Logger.LogMode.DEBUG else Logger.LogMode.INFO)
                }
            )
        )
        client
    }

@ApplicationScope
    @Provides
    fun providesAmplitudeAnalyticsProvider(
        context: Context,
        amplitudeConfigProvider: AmplitudeConfigProvider,
        coroutineDispatcher: Dispatchers.Default
    ): AmplitudeAnalyticsProvider {
        val amplitudeAnalyticsProvider = AmplitudeAnalyticsProvider(context, amplitudeConfigProvider, coroutineDispatcher)
        Log.w("AMPLITUDE_TAG", "Wrapper instance dagger hashcode ${amplitudeAnalyticsProvider.hashCode()}")
        return amplitudeAnalyticsProvider
    }

and here is the logcat output

ajay-nagarajan commented 10 months ago

Hey @justin-fiedler @yuhao900914 @Mercy811 Are there any updates regarding this. I'm facing this issue on 1.10.4 as well and it is impacting our customers. I don't see any updates on the release notes regarding this fix either. Will updating the SDK help with this issue?

ajay-nagarajan commented 10 months ago

Alternatively it would be great if we could have an option in the SDK to ignore very old events or even clear the old events from the system. If there already is, could you please let me know, it would be greatly appreciated

izaaz commented 4 weeks ago

@ajay-nagarajan this issue is fixed in our newer SDK versions. We validate the data to make sure its a valid json before we send it over to Amplitude. So this should no longer be happening.

amplitude / Amplitude-Kotlin