Network on Main Thread

[DavidEdwards]

The issue

My issue is extremely intermittent. It does not appear every time. Infact, only quite rarely. Perhaps a couple of times per week.

In the first step, you see that I am directly starting a new Thread for running my blocking function in.

In the last step, I even check that the Thread is not running on the Main Thread.

Could okhttp be pushing the request onto the Main Thread?

My Exception

01-31 09:29:58.459 15392-15814/dae.evepi E/UncaughtException: android.os.NetworkOnMainThreadException
	  at android.os.StrictMode$AndroidBlockGuardPolicy.onNetwork(StrictMode.java:1303)
	  at com.android.org.conscrypt.Platform.blockGuardOnNetwork(Platform.java:300)
	  at com.android.org.conscrypt.OpenSSLSocketImpl$SSLOutputStream.write(OpenSSLSocketImpl.java:808)
	  at okio.Okio$1.write(SourceFile:78)
	  at okio.AsyncTimeout$1.write(SourceFile:179)
	  at okio.RealBufferedSink.flush(SourceFile:216)
	  at okhttp3.internal.http2.Http2Writer.flush(SourceFile:121)
	  at okhttp3.internal.http2.Http2Connection.newStream(SourceFile:239)
	  at okhttp3.internal.http2.Http2Connection.newStream(SourceFile:205)
	  at okhttp3.internal.http2.Http2Codec.writeRequestHeaders(SourceFile:105)
	  at okhttp3.internal.http.CallServerInterceptor.intercept(SourceFile:43)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:67)
	  at dae.evepi.network.LoggingInterceptor.intercept(SourceFile:20) /* duplicate of your LoggingInterceptor recipe */
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.connection.ConnectInterceptor.intercept(SourceFile:45)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:67)
	  at okhttp3.internal.cache.CacheInterceptor.intercept(SourceFile:93)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:67)
	  at okhttp3.internal.http.BridgeInterceptor.intercept(SourceFile:93)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(SourceFile:120)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:92)
	  at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:67)
	  at okhttp3.RealCall.b(SourceFile:179)
	  at okhttp3.RealCall.execute(SourceFile:63)
	  at dae.evepi.network.Api.a(SourceFile:188)
	  at dae.evepi.network.Api.getPlanetLayoutBlocking(SourceFile:713)
	  at dae.evepi.network.Api$7.run(SourceFile:753)
	  at java.lang.Thread.run(Thread.java:761)

My code

	// at dae.evepi.network.Api$7.run(SourceFile:753)
    public void getPlanetLayout(@NonNull final Character c, @NonNull final Planet p, @NonNull final PinCallback callback) {
        new Thread(new Runnable() {
            @Override
            public void run() {
                getPlanetLayoutBlocking(c, p, callback);
            }
        }).start();
    }

	// at dae.evepi.network.Api.getPlanetLayoutBlocking(SourceFile:713)
    @WorkerThread
    @Nullable
    public List<Pin> getPlanetLayoutBlocking(@NonNull final Character c, @NonNull final Planet p, @NonNull final PinCallback callback) {
        final String CACHE_KEY = "Api.getPlanetLayout(Character="+c.getId()+",Planet="+p.getId()+",PinCallback)";
        if(isCached(CACHE_KEY)) {
            LogUtils.log("W::Planet pins are cached. Don't refresh.");
            EventBus.getDefault().post(new EsiCacheEvent(getCacheExpireTime(CACHE_KEY)));
            return null;
        }

        Response response = null;

        try {
            Request request = new Request.Builder()
                    .url(String.format(Locale.US, AN_API_CALL, c.getId(), p.getId()))
                    .header("User-Agent", USER_AGENT)
                    .header("Authorization", "...")
                    .header("Host", "...")
                    .build();
            response = retryWithBackoff(request);

            if(response != null && response.code() == 200) {
                // Some stuff
            } else {
                // Some other stuff
            }
        } catch (MalformedURLException e) {
            LogUtils.log("E::e: "+e);
            e.printStackTrace();
            callback.onError(response, e);
        } catch (IOException e) {
            LogUtils.log("E::e: "+e);
            e.printStackTrace();
            callback.onError(response, e);
        } catch (JSONException e) {
            LogUtils.log("E::e: "+e);
            e.printStackTrace();
            callback.onError(response, e);
        }
        return null;
    }

	// at dae.evepi.network.Api.a(SourceFile:188)
    @WorkerThread
    @Nullable
    private Response retryWithBackoff(@NonNull Request request) throws IOException {
        Response response = null;

        int retryAttempt = 0;
        int backoffTime = 500;

        while(++retryAttempt <= MAX_RETRIES) {
            if(retryAttempt > 1) {
                LogUtils.log("W::There was an error accessing the API. We will try again in "+backoffTime+"ms");
                Utils.sleep(backoffTime); /* just a wrapped Thread.sleep(...); */
                backoffTime *= RETRY_DEPLAY_MULTIPLIER;
            }

            try {
                // This if block is never entered
                if(Looper.myLooper() == Looper.getMainLooper()) {
                    LogUtils.log("CRIT", "WTF::Attempting to call '"+request.url().toString()+"' on the main thread ("+retryAttempt+"/"+MAX_RETRIES+").");
                    LogUtils.logCaller("Trace critical error of network on main thread.");
                }

                response = mClient.newCall(request).execute();

                if (response.code() == 200) {
                    break;
                }
            } catch (SocketTimeoutException e) {
                LogUtils.log("E::Socket request timed out for '"+request.url().toString()+"'");
            }
        }

        return response;
    }

[swankjesse]

I’ve never seen that before. That's a bug in strict mode. Can you reproduce locally? Which devices does this impact?

[DavidEdwards]

I cannot reproduce it. It just "happens" sometimes. Usually when starting the App.

It has happened to me specifically on a Pixel (7.1.1).

So this is a bug I should forward to the AOSP team?

[swankjesse]

Yup. It's their bug.

[DavidEdwards]

OK, thanks for taking the time to look at it!

[swankjesse]

Actually I'm wrong. It's a Conscrypt bug.
FYI @kruton

[DavidEdwards]

OK, I will make an issue report there.

[swankjesse]

Ugh, I keep following the stacktrace and implicating the wrong code.

How are you installing strict mode? Basically it looks like the background thread is getting a strict mode that forbids network I/O, which is typically a thing you only restrict on the main thread.

[swankjesse]

(the exception message is a bit distracting, to be pedantic it means NetworkOnForbiddenThread because the policy doesn’t actually know or care about the main thread’s special status.)

[DavidEdwards]

I am setting StrictMode in the onCreate() method of my Application class.

    @Override
    public void onCreate() {
        super.onCreate();
        Fabric.with(this, new Crashlytics());

        if (BuildConfig.APP_DEBUG) {
            StrictMode.setThreadPolicy(new StrictMode.ThreadPolicy.Builder()
                    .detectDiskReads()
                    .detectDiskWrites()
                    .detectNetwork()   // or .detectAll() for all detectable problems
                    .penaltyLog()
                    .build());
            StrictMode.setVmPolicy(new StrictMode.VmPolicy.Builder()
                    .detectLeakedSqlLiteObjects()
                    .detectLeakedClosableObjects()
                    .penaltyLog()
//                    .penaltyDeath()
                    .build());
        }
    }

[DavidEdwards]

However, I thought that this StrictMode check is built into Nougat? Not as part of initializing StrictMode myself.

https://developer.android.com/about/versions/nougat/android-7.0-changes.html

Due to a bug in previous versions of Android, the system did not flag writing to a TCP socket on the main thread as a strict-mode violation. Android 7.0 fixes this bug. Apps that exhibit this behavior now throw an android.os.NetworkOnMainThreadException. Generally, performing network operations on the main thread is a bad idea because these operations usually have a high tail latency that causes ANRs and jank.

[swankjesse]

From the trace of the exception it looks like a network policy is enabled for your background thread.

[DavidEdwards]

Searched my code and found another place I use StrictMode:

oldThreadPolicy = StrictMode.getThreadPolicy();
oldVmPolicy = StrictMode.getVmPolicy();
StrictMode.setThreadPolicy(new StrictMode.ThreadPolicy.Builder()
		.permitAll()
		.build());
StrictMode.setVmPolicy(new StrictMode.VmPolicy.Builder()
		.build());
		
// Working on preferences.

StrictMode.setThreadPolicy(oldThreadPolicy);
StrictMode.setVmPolicy(oldVmPolicy);

Used in a library to avoid causing StrictMode logs from accessing SharedPreferences. That could be called from a background thread.

However, it would only set permissive and reset back to original policies.

[swankjesse]

I'm lost. Can you set up a breakpoint and inspect which policy it’s using when it fails? I’m specifically interested in whether it’s a policy you installed and whether it's the same policy instance as you’re using on the main thread.

[DavidEdwards]

Unfortunately, I have no way of testing that. I have no way to cause the error. I will do some testing, perhaps I can trigger the error with the above StrictMode code.

In any case, it isn't an okhttp issue, so I'll stop posting here about it! However, if you are curious to the resolution of it, I can post it here once I have it figured out. Let me know.