NPE while invoking tinylog from an AIDL remote interface callback #131

danielwilson1702 · 2020-01-13T12:38:00Z

My code is throwing an exception for this constructor:

	public ServiceLoader(final Class<? extends T> service, final Class<?>... argumentTypes) {
		this.service = service;
		this.argumentTypes = argumentTypes;
		this.classLoader = Thread.currentThread().getContextClassLoader();
		this.classes = loadClasses(classLoader, service);
	}

01-13 12:08:03.272 3989-4000/loylap.poynt.gift E/JavaBinder: *** Uncaught remote exception!  (Exceptions are not yet supported across processes.)
    java.lang.ExceptionInInitializerError
        at org.tinylog.provider.ProviderRegistry.getLoggingProvider(ProviderRegistry.java:53)
        at org.tinylog.kotlin.Logger.<clinit>(Logger.kt:27)
     Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'java.util.Enumeration java.lang.ClassLoader.getResources(java.lang.String)' on a null object reference
        at org.tinylog.configuration.ServiceLoader.loadClasses(ServiceLoader.java:128)
        at org.tinylog.configuration.ServiceLoader.<init>(ServiceLoader.java:58)
        at org.tinylog.provider.ProviderRegistry.loadLoggingProvider(ProviderRegistry.java:66)
        at org.tinylog.provider.ProviderRegistry.<clinit>(ProviderRegistry.java:36)
        at org.tinylog.provider.ProviderRegistry.getLoggingProvider(ProviderRegistry.java:53) 
        at org.tinylog.kotlin.Logger.<clinit>(Logger.kt:27)

I believe Thread.currentThread().getContextClassLoader(); is returning null in certain instances in my app. I don't understand enough about Java or AIDLs to see what's happening here, but suffice it to say calls to log functions (such as Logger.trace()) are crashing when they are invoked from very specific interface call backs in my app which use AIDL and are on a background thread. Running Logger.trace on the main thread from within the interface callback fixes the issue, but I am worried now there could be places in my code I don't make this fix, and also that I might be introducing other subtle issues I don't know about, like this one.

This is probably an Android only problem, but would love to know what the cause is and how I might mitigate it. It's super difficult for me to try and make a reproducible sample because I am seeing the error in an SDK dependency which uses TinyLog

The text was updated successfully, but these errors were encountered:

pmwmedia · 2020-01-13T12:56:26Z

@danielwilson1702 Would you be able to provide an example project? Which tinylog version and Android version are you using?

danielwilson1702 · 2020-01-16T14:07:46Z

I've tried it with a super simple AIDL / Service sample and can't repro. So it must be something relatively specific. I will try and create a very simple project with nothing but the Service I am using. Versions are:

  api 'org.tinylog:tinylog-api-kotlin:2.0.1'
  api 'org.tinylog:tinylog-impl:2.0.1'

danielwilson1702 · 2020-01-29T11:15:14Z

Ok sorry this has taken a while!

I have a small sample now located here showing the issue. Now unfortunately you won't be able to run it because the only Service I can find that is causing the issue is the one I am using which is from the Poynt SDK. Poynt are a POS company who ask you to set up an emulator (instructions) which requires a developer account in order to talk to their Services / backend.

I am thinking perhaps even without running the code it can give you some insight. The app simply connects to their "Business" Service to gather the Business details from the device / Poynt account.

I have also figured out perhaps the biggest clue, if I log in onResume, the Service callback call to log does not crash the app. If I do not log in onResume and the first call to log is the one in the Service callback, the app crashes. Let me know if that makes sense!

So I believe right now the solution is just to log something in a regular platform lifecycle call back such as App / Activity / Fragment onCreate() to give the library a chance to initialize itself correctly, and allow me to log anywhere.

pmwmedia · 2020-02-02T22:59:49Z

The problem seems to be that Poynt creates threads with null class loaders. This is not really standard and will make troubles with any framework that uses services loaders. However, I think we can bypass the class loader issue. I have integrated three different ways of getting a class loader.

@danielwilson1702 Could you test the attached snapshots and provide the logger output?

~~tinylog-2.1-SNAPSHOT.zip~~

danielwilson1702 · 2020-02-03T08:22:00Z

Brilliant ok thanks for looking in to it. It is reassuring to know that Poynt are doing unusual things with their SDK and it's not the first time I've said that 😄

Using the snapshot jar seems to produce a stack overflow exception:

02-03 07:51:04.760 23328 23339 W System.err: 	at org.tinylog.runtime.RuntimeProvider.getClassLoader(RuntimeProvider.java:46)
02-03 07:51:04.839 23328 23339 W System.err: 	at org.tinylog.configuration.ServiceLoader.<init>(ServiceLoader.java:59)
02-03 07:51:04.839 23328 23339 W System.err: 	at org.tinylog.provider.ProviderRegistry.loadLoggingProvider(ProviderRegistry.java:66)
02-03 07:51:04.839 23328 23339 W System.err: 	at org.tinylog.provider.ProviderRegistry.<clinit>(ProviderRegistry.java:36)
02-03 07:51:04.839 23328 23339 W System.err: 	at org.tinylog.provider.ProviderRegistry.getLoggingProvider(ProviderRegistry.java:53)
02-03 07:51:04.839 23328 23339 W System.err: 	at org.tinylog.Logger.<clinit>(Logger.java:37)
02-03 07:51:04.839 23328 23339 W System.err: 	at com.sp.myapplication.MainActivity$poyntBusinessServiceListener$1.onResponse(MainActivity.kt:27)
02-03 07:51:04.839 23328 23339 W System.err: 	at co.poynt.os.services.v1.IPoyntBusinessReadListener$Stub.onTransact(IPoyntBusinessReadListener.java:62)
02-03 07:51:04.839 23328 23339 W System.err: 	at android.os.Binder.execTransact(Binder.java:453)
02-03 07:51:04.839 23328 23339 E JavaBinder: Forcefully exiting

02-03 07:56:16.474 23513 23524 W System.err: java.lang.StackOverflowError: stack size 1014KB
02-03 07:56:16.474 23513 23524 W System.err: 	at java.lang.AbstractStringBuilder.append0(AbstractStringBuilder.java:146)
02-03 07:56:16.474 23513 23524 W System.err: 	at java.lang.StringBuilder.append(StringBuilder.java:216)
02-03 07:56:16.474 23513 23524 W System.err: 	at org.tinylog.provider.InternalLogger.log(InternalLogger.java:38)
02-03 07:56:16.474 23513 23524 W System.err: 	at org.tinylog.runtime.RuntimeProvider.getClassLoader(RuntimeProvider.java:41)
02-03 07:56:16.474 23513 23524 W System.err: 	at org.tinylog.runtime.RuntimeProvider.getClassLoader(RuntimeProvider.java:46)

Full logs (probably too much info here but you get the gist!)

It doesn't seem to get in to this if statement:

    if (classLoader == null) {
        InternalLogger.log(Level.INFO, "Get system class loader");
        classLoader = ClassLoader.getSystemClassLoader();
    }

pmwmedia · 2020-02-03T10:19:06Z

It is always a bit tricky to develop something that you cannot test by yourself :-D I have fixed the endless recursion.

@danielwilson1702 Could you test again?

tinylog-2.1-SNAPSHOT.zip

danielwilson1702 · 2020-02-03T12:42:58Z

I'm sure it is! Ok I tested it and it looks like it's working perfectly now:

02-03 12:36:32.511 23691-23691/? I/art: Not late-enabling -Xcheck:jni (already on)
02-03 12:36:32.527 23691-23696/? E/art: Failed sending reply to debugger: Broken pipe
02-03 12:36:32.527 23691-23696/? I/art: Debugger is no longer active
02-03 12:36:32.558 23691-23691/? I/ActivityThread: Switching default density from 320 to 213
02-03 12:36:32.570 23691-23691/? W/System: ClassLoader referenced unknown path: /data/app/com.sp.myapplication-1/lib/x86
02-03 12:36:32.615 23691-23691/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:32.622 23691-23691/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:32.625 23691-23691/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:32.694 23691-23691/? W/art: Before Android 4.1, method android.graphics.PorterDuffColorFilter androidx.vectordrawable.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
02-03 12:36:32.881 23691-23691/? I/art: Rejecting re-init on previously-failed class java.lang.Class<androidx.core.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>
02-03 12:36:32.882 23691-23691/? I/art: Rejecting re-init on previously-failed class java.lang.Class<androidx.core.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>
02-03 12:36:32.918 23691-23717/? D/OpenGLRenderer: Use EGL_SWAP_BEHAVIOR_PRESERVED: true
02-03 12:36:32.963 23691-23717/? I/OpenGLRenderer: Initialized EGL, version 1.4
02-03 12:36:32.964 23691-23717/? W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
02-03 12:36:32.974 23691-23717/? D/EGL_emulation: eglCreateContext: 0xae5145a0: maj 3 min 1 rcv 4
02-03 12:36:33.001 23691-23717/? D/EGL_emulation: eglMakeCurrent: 0xae5145a0: ver 3 1 (tinfo 0xae7a2090)
02-03 12:36:33.003 23691-23717/? E/eglCodecCommon: glUtilsParamSize: unknow param 0x000082da
02-03 12:36:33.003 23691-23717/? E/eglCodecCommon: glUtilsParamSize: unknow param 0x00008cdf
02-03 12:36:33.004 23691-23717/? E/eglCodecCommon: glUtilsParamSize: unknow param 0x00008824
02-03 12:36:33.051 23691-23702/? D/Business:  MEASURE_TIME Received bytes 3343 json size:15491
02-03 12:36:33.091 23691-23702/? D/Business:  Gson Json string size:15491
02-03 12:36:33.091 23691-23702/? D/Business:  MEASURE_TIME Total read time 49
02-03 12:36:33.092 23691-23702/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:33.092 23691-23702/? W/System.err: LOGGER INFO: Get class loader from class
02-03 12:36:33.094 23691-23702/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:33.094 23691-23702/? W/System.err: LOGGER INFO: Get class loader from class
02-03 12:36:33.096 23691-23702/? W/System.err: LOGGER INFO: Get class loader from thread
02-03 12:36:33.096 23691-23702/? W/System.err: LOGGER INFO: Get class loader from class
02-03 12:36:33.099 23691-23702/? V/MainActivity: tinylog Logging Business response! c3582fe1-c4bc-4767-91eb-3e97b0c8c63f

I will close this bug and be careful around any crazy Poynt functions until you roll it out. Thanks a lot 🎉 👌

pmwmedia · 2020-02-03T12:57:51Z

Then I can merge my change into the v2.1 branch.

@danielwilson1702 Thank you for testing!

Fixes #131

github-actions · 2022-10-09T12:18:43Z

This closed issue has been locked automatically. However, please feel free to file a new issue.

pmwmedia added bug waiting for response labels Jan 13, 2020

pmwmedia added this to the 2.1 milestone Feb 2, 2020

danielwilson1702 closed this as completed Feb 3, 2020

pmwmedia removed the waiting for response label Feb 3, 2020

pmwmedia added a commit that referenced this issue Feb 3, 2020

Provide a valid class loader even if there is none from thread context

08afcca

Fixes #131

github-actions bot locked as resolved and limited conversation to collaborators Oct 9, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NPE while invoking tinylog from an AIDL remote interface callback #131

NPE while invoking tinylog from an AIDL remote interface callback #131

danielwilson1702 commented Jan 13, 2020

pmwmedia commented Jan 13, 2020

danielwilson1702 commented Jan 16, 2020

danielwilson1702 commented Jan 29, 2020

pmwmedia commented Feb 2, 2020 •

edited

Loading

danielwilson1702 commented Feb 3, 2020

pmwmedia commented Feb 3, 2020 •

edited

Loading

danielwilson1702 commented Feb 3, 2020

pmwmedia commented Feb 3, 2020

github-actions bot commented Oct 9, 2022

NPE while invoking tinylog from an AIDL remote interface callback #131

NPE while invoking tinylog from an AIDL remote interface callback #131

Comments

danielwilson1702 commented Jan 13, 2020

pmwmedia commented Jan 13, 2020

danielwilson1702 commented Jan 16, 2020

danielwilson1702 commented Jan 29, 2020

pmwmedia commented Feb 2, 2020 • edited Loading

danielwilson1702 commented Feb 3, 2020

pmwmedia commented Feb 3, 2020 • edited Loading

danielwilson1702 commented Feb 3, 2020

pmwmedia commented Feb 3, 2020

github-actions bot commented Oct 9, 2022

pmwmedia commented Feb 2, 2020 •

edited

Loading

pmwmedia commented Feb 3, 2020 •

edited

Loading