Tracking down cause of ConcurrentModificationException after network call-CodePudding

I've created an Android SDK and I'm hearing reports of ConcurrentModificationExceptions being thrown but I've been unable to replicate on my device. Isn't that always the way!

The logcat from where the exception occurs looks like this:

11-01 11:13:11.277 22956 22988 D OpenGLRenderer: createReliableSurface : 0xbe861ec0, 0xec295000
11-01 11:13:11.278 22956 22988 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
11-01 11:13:11.279  3293  3293 W WindowManager: removeWindowToken: Attempted to remove non-existing token: android.os.Binder@6c754b3
11-01 11:13:11.280  2843  9611 D tfa_container: [NXP] tfaContWriteFile: end
11-01 11:13:11.280  2843  9611 D tfa98xxApp: [NXP] tfa_setvolumestep: tfa set volume successful
11-01 11:13:11.280  2843  9611 D tfa98xxApp: [NXP] tfa_setvolumestep: end
11-01 11:13:11.280  2843  9611 D tfa_dsp : [NXP] tfa98xx_set_forced_start: set force by 0 [0xf]
11-01 11:13:11.281  2843  9611 D tfa_usrdrv: [NXP] tfa_show_status_device: /dev/i2c-20 0x34, device = 0, status = 0xd05e, WDS = 0, ACS = 0, CHSA = 2, DCA = 1, CHS12 = 3, SWS = 1, PLLS = 1, SBSL = 1, RCV = 0, INPLVL = 0, PWDN = 0, re0 = 0x1848 (6.0703 ohm)
11-01 11:13:11.281  2843  9611 D tfa98xxApp: [NXP] tfa_enable: end
11-01 11:13:11.281  2843  9611 V audio_hw_primary: start_output_stream-
11-01 11:13:11.283  3014 25269 I Camera3-Status: markComponent: Component 1 is now idle - RequestThread
11-01 11:13:11.285 22956 22956 E DecorView: mWindow.mActivityCurrentConfig is null
11-01 11:13:11.293  3293  4829 D WindowManager: finishDrawingWindow: Window{87b2f1c u0 com.mycode.demo/com.mycode.mysdk.main.UIActivity} mDrawState=DRAW_PENDING
11-01 11:13:11.294 22956 22956 D CameraViewModel: response here: 
11-01 11:13:11.296 22956 23255 W System.err: java.util.ConcurrentModificationException
11-01 11:13:11.297  3293  3332 I WindowManager: Reparenting to leash, surface=Surface(name=87b2f1c com.mycode.demo/com.mycode.mysdk.main.UIActivity)/@0xce0b0a1
11-01 11:13:11.298  2873  4356 I SurfaceFlinger: createSurf start. lock debugging [Surface(name=87b2f1c com.mycode.demo/com.mycode.mysdk.main.UIActivity)/@0xce0b0a1 - animation-leash]
11-01 11:13:11.298  2873  4356 I SurfaceFlinger: id=1211 createSurf (0x0),-1 flag=80004, Surface(name=87b2f1c com.mycode.demo/com.mycode.mysdk.main.UIActivity)/@0xce0b0a1 - animation-leash#0
11-01 11:13:11.298  3293  3332 D WindowManager: makeSurface duration=1 leash=Surface(name=Surface(name=87b2f1c com.mycode.demo/com.mycode.mysdk.main.UIActivity)/@0xce0b0a1 - animation-leash)/@0xf0272c6
11-01 11:13:11.298 22956 23255 W System.err:    at java.util.ArrayList$Itr.next(ArrayList.java:860)
11-01 11:13:11.298 22956 23255 W System.err:    at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.write(CollectionTypeAdapterFactory.java:96)
11-01 11:13:11.298 22956 23255 W System.err:    at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.write(CollectionTypeAdapterFactory.java:61)
11-01 11:13:11.299 22956 23255 W System.err:    at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69)
11-01 11:13:11.299 22956 23255 W System.err:    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:127)
11-01 11:13:11.299 22956 23255 W System.err:    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:245)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.converter.gson.GsonRequestBodyConverter.convert(GsonRequestBodyConverter.java:47)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.converter.gson.GsonRequestBodyConverter.convert(GsonRequestBodyConverter.java:30)
11-01 11:13:11.299  2873  4356 I SurfaceFlinger: createSurf start. lock debugging [Dim Layer for - Task=5150]
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.ParameterHandler$Body.apply(ParameterHandler.java:429)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.RequestFactory.create(RequestFactory.java:129)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.OkHttpCall.createRawCall(OkHttpCall.java:208)
11-01 11:13:11.299  2873  4356 I SurfaceFlinger: id=1212 createSurf (0x0),-1 flag=24004, Dim Layer for - Task=5150#0
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.OkHttpCall.enqueue(OkHttpCall.java:130)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.KotlinExtensions.await(KotlinExtensions.kt:36)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.HttpServiceMethod$SuspendForBody.adapt(HttpServiceMethod.java:231)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.HttpServiceMethod.invoke(HttpServiceMethod.java:146)
11-01 11:13:11.299 22956 23255 W System.err:    at retrofit2.Retrofit$1.invoke(Retrofit.java:160)
11-01 11:13:11.299 22956 23255 W System.err:    at java.lang.reflect.Proxy.invoke(Proxy.java:1006)
11-01 11:13:11.299 22956 23255 W System.err:    at $Proxy1.postPartialMeasurementResults(Unknown Source)
11-01 11:13:11.299 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.retrofit.RetrofitMeasurementsDataRepository$postPartialMeasurementResults$2.invokeSuspend(RetrofitMeasurementsDataRepository.kt:21)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.retrofit.RetrofitMeasurementsDataRepository$postPartialMeasurementResults$2.invoke(Unknown Source:8)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.retrofit.RetrofitMeasurementsDataRepository$postPartialMeasurementResults$2.invoke(Unknown Source:2)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.network.datasource.NetworkDataSource.getResult$suspendImpl(NetworkDataSource.kt:16)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.network.datasource.NetworkDataSource.getResult(Unknown Source:0)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.retrofit.RetrofitMeasurementsDataRepository.postPartialMeasurementResults(RetrofitMeasurementsDataRepository.kt:20)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.MeasurementsRepository$sendPartialMeasurements$1.invokeSuspend(MeasurementsRepository.kt:39)
11-01 11:13:11.300 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.MeasurementsRepository$sendPartialMeasurements$1.invoke(Unknown Source:8)
11-01 11:13:11.300  2861 25701 I ExynosCameraMCPipe: [CAM_ID(1)][PIPE_3AA]-INFO(m_getBuffer[2254]):InternalFrame(5) frameCount(1230)                    : captureNodeCount == 0 || checkRet(0) != NO_ERROR.                    so, setFrameState(FRAME_STATE_SKIPPED)
11-01 11:13:11.302 22956 23255 W System.err:    at com.mycode.mysdk.data.repository.measurement.MeasurementsRepository$sendPartialMeasurements$1.invoke(Unknown Source:4)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.SafeFlow.collectSafely(Builders.kt:61)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.AbstractFlow.collect(Flow.kt:212)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.internal.ChannelFlowOperatorImpl.flowCollect(ChannelFlow.kt:207)
11-01 11:13:11.302  2870  2963 D AudioFlinger: mixer(0xe76d4500) Spend too much time to write: delta 220(effect 1, stage 0)
11-01 11:13:11.302  2870  2963 I SoundAlive_SRC384 arch32: SRC384 Destroy
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.internal.ChannelFlowOperator.collectTo$suspendImpl(ChannelFlow.kt:169)
11-01 11:13:11.302  2870  2963 I SoundAlive_SRC384 arch32: ~SoundAlive_SRC384() 
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.internal.ChannelFlowOperator.collectTo(Unknown Source:0)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.flow.internal.ChannelFlow$collectToFun$1.invokeSuspend(ChannelFlow.kt:60)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
11-01 11:13:11.302 22956 23255 W System.err:    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
11-01 11:13:11.303 22956 23255 W System.err:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:738)
11-01 11:13:11.303 22956 23255 W System.err:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
11-01 11:13:11.303 22956 23255 W System.err:    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)
11-01 11:13:11.303  3293  3332 I WindowManager: Reparenting to leash, surface=Surface(name=Dim Layer for - Task=5150)/@0xe276287
11-01 11:13:11.304  2873  2944 I SurfaceFlinger: createSurf start. lock debugging [Surface(name=Dim Layer for - Task=5150)/@0xe276287 - animation-leash]
11-01 11:13:11.304  2873  2944 I SurfaceFlinger: id=1213 createSurf (0x0),-1 flag=80004, Surface(name=Dim Layer for - Task=5150)/@0xe276287 - animation-leash#0
11-01 11:13:11.304  3293  3332 D WindowManager: makeSurface duration=1 leash=Surface(name=Surface(name=Dim Layer for - Task=5150)/@0xe276287 - animation-leash)/@0x23445b4
11-01 11:13:11.311  3293  4829 W ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:1087 com.android.server.notification.DisplayToast.sendIntentForToastDumpLog:156 com.android.server.notification.DisplayToast.outFile:106 com.android.server.notification.DisplayToast.out:62 com.android.server.notification.NotificationManagerService$12.enqueueToastForLog:2664 
11-01 11:13:11.312  2873  2944 I SurfaceFlinger: createSurf start. lock debugging [WindowToken{122f552 android.os.Binder@ab6b5dd}]
11-01 11:13:11.312  2873  2944 I SurfaceFlinger: id=1214 createSurf (0x0),-1 flag=80004, WindowToken{122f552 android.os.Binder@ab6b5dd}#0
11-01 11:13:11.315 22956 22956 E Response: Response(...redacted...)

I appreciate there's a lot in this log but from what I can see, the CameraViewModel gets a response from the API (CameraViewModel: response here: ), then the ConcurrentModificationException happens, then finally the response is actually logged (Response: Response(...redacted...)).

Can anyone help me understand what else I'm seeing in these logs? Is there any clue to what might be causing the exception or where it might be happening? I understand that it's thrown when a list is modified while being iterated over but I can't see anywhere that might be the case. Any clues would be greatly appreciated.

Edit

The code at RetrofitMeasurementsDataRepository.kt:21 is:

    override suspend fun postResults(data: Data): RequestResult<Response?> {
        return networkDataSource.getResult {
            api.postResults(data)
        }
    }

The response here somehow(?) triggers:

    private fun handleResult() {
        lifecycleOwner.lifecycleScope.launch {
            viewModel.getResponse(
                entries
            ).collect {
                it?.let {
                    listener.onResultReceived(it)
                }
            }
        }
    }

The function being called here looks like:

    fun getResponse(data: Data): Flow<Result?> {
        return repository.send(data).map {
            Log.d(TAG, "partial response here: ")
            entries.clear()
        }
    }

CodePudding user response：

Probably entries.clear() got called while gson was still working on it in a different thread. Looks like a race condition here, that's why it's not always reproducible. I would suggest passing a copy of entries to retrofit instead of the original object which you are modifying.

CodePudding user response：

I see entries.clear() as a major red flag since you're working with stuff in parallel. Avoid using mutable collections if you are passing collections between threads, and if you do use mutable collections, you must synchronize on something whenever using them. ConcurrentModificationException happens if two threads are modifying the same collection at once, or if one thread is modifying it while another thread is iterating it.