murgo / IrssiNotifier

notifies android phones from irc private messages
Apache License 2.0
171 stars 63 forks source link

Not working on Android 9 Beta (June 5, 2018 build) #195

Closed contyk closed 6 years ago

contyk commented 6 years ago

After updating to the June 5 build of Android 9 Beta, IrssiNotifier appears to have stopped working. I wasn't getting any notifications so I decided to check my token, clear the data & cache and reinitialize the app.

Now I'm stuck on "Registering to GCM..." which never completes. Running the app also pops up a warning that it's been built for an old version of Android and may not work properly.

murgo commented 6 years ago

Hmm... That's weird. I don't have Android 9 easily available for me yet, so it's not easy to test.

Checking out the Android 9 developer documentation I can't see any easy explanations why it wouldn't work any more.

Have you tried restarting your device? 😄

contyk commented 6 years ago

Yes, I have :)

Anything I could provide then?

contyk commented 6 years ago

Updated to July 5, 2018 build. The issue still persists.

phellarv commented 6 years ago

Still not working on Android 9 - Build PPR1.180610.009

halstead commented 6 years ago

My new PH-1 is Android 9 and IrssiNotifier+ is stuck on "Registering to GCM...". Working great on my Nexus6p with Android 8.1.0 for now. Let me know if there is anything I can test.

hefax commented 6 years ago

I only get a warning that Irssinotifier is build for older version of android, but the application actually works without issues with my Pixel. I have not made any changes or re-registered since updating to android 9.

halstead commented 6 years ago

I get the same warning about the older version of Android on my PH-1 with both IrssiNotifier and IrssiNotifier+. Each waits on "Registering to GCM..." indefinitely. I wiped and installed from the factory image. @hefax did you upgrade from a previous version of Android?

hefax commented 6 years ago

Yes, I did an upgrade from previous version of android. So the service was registered already for my accounts/scripts.

contyk commented 6 years ago

For the record, I'm on Pixel 2 XL. I'm running v9 stable now but, as noted by others, it's still broken in exactly the same way.

murgo commented 6 years ago

Hopefully I'll get Android 9 on my phone (OnePlus 3t) soon-ish so I can properly take a look at this. If not I'll have to try to fix it on emulator.

Logs could contain some clues, if someone with issues could post a logcat with all output from IrssiNotifier (each log message should contain irssinotifier in the tag).

contyk commented 6 years ago

From starting the app, I think...

08-26 22:36:55.474  1162  4873 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.IrssiNotifierActivity bnds=[854,2397][1123,2778]} from uid 10015
08-26 22:36:55.514  1162  1209 I ActivityManager: Start proc 24171:fi.iki.murgo.irssinotifier.plus/u0a214 for activity fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.IrssiNotifierActivity
08-26 22:36:55.521 12598 12598 I Finsky  : [2] com.google.android.finsky.externalreferrer.u.c(15): Package first launch for fi.iki.murgo.irssinotifier.plus
08-26 22:36:55.537 12598 12598 I Finsky  : [2] com.google.android.finsky.externalreferrer.f.a(85): Backfilling empty external referrer for fi.iki.murgo.irssinotifier.plus
08-26 22:36:55.598 24171 24171 I fi.iki.murgo.irssinotifier.IrssiNotifierActivity: Startup
08-26 22:36:55.601 24171 24171 D fi.iki.murgo.irssinotifier.IrssiNotifierActivity: Asking for initial settings
08-26 22:36:55.602  1162  2932 I ActivityManager: START u0 {cmp=fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.InitialSettingsActivity} from uid 10214
08-26 22:36:55.918   610  1853 W SurfaceFlinger: Attempting to set client state on removed layer: Splash Screen fi.iki.murgo.irssinotifier.plus#0
08-26 22:36:55.918   610  1853 W SurfaceFlinger: Attempting to destroy on removed layer: Splash Screen fi.iki.murgo.irssinotifier.plus#0
08-26 22:36:56.055   610   648 W SurfaceFlinger: Attempting to set client state on removed layer: Surface(name=AppWindowToken{690ba5f token=Token{f4d62fe ActivityRecord{d6cdeb9 u0 fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.IrssiNotifierActivity t8618}}})/@0x1a92f0d - animation-leash#0
08-26 22:36:56.055   610   648 W SurfaceFlinger: Attempting to destroy on removed layer: Surface(name=AppWindowToken{690ba5f token=Token{f4d62fe ActivityRecord{d6cdeb9 u0 fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.IrssiNotifierActivity t8618}}})/@0x1a92f0d - animation-leash#0
08-26 22:37:09.526 24171 24171 D fi.iki.murgo.irssinotifier.InitialSettingsActivity: Changing state: 0
08-26 22:37:09.541 24171 24199 I fi.iki.murgo.irssinotifier.GCMRegistrationTask: Registering to GCM
08-26 22:37:09.543 24171 24199 D GCMRegistrar: resetting backoff for fi.iki.murgo.irssinotifier.plus
08-26 22:37:09.551   610   610 D SurfaceFlinger: duplicate layer name: changing fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.InitialSettingsActivity to fi.iki.murgo.irssinotifier.plus/fi.iki.murgo.irssinotifier.InitialSettingsActivity#1
08-26 22:37:09.552 24171 24199 V GCMRegistrar: Registering app fi.iki.murgo.irssinotifier.plus of senders 710677821747

Nothing happens after this. The screen is stuck on "Registering to GCM...".

zqad commented 6 years ago

Chiming in with a "me too". Same apparent error using +-version, "Registering to GCM", nothing seems to help.

Pixel 1, Android 9 (patch level: September 5, 2018)

tlokenjo commented 6 years ago

metoo let's hope for a update soon!

Oneplus 6, pie

stwalkerster commented 6 years ago

Some quick debugging on my OnePlus 6 running Pie has revealed that GCMIntentService.registerToGcm(...) returns very quickly without firing the callback, and thus the while(!done) loop in GCMRegistrationTask causes it to spinlock.

I modified GCMIntentService.registerToGcm(...) to be the following:

    public static void registerToGcm(Context context) throws Exception {
        Log.d(TAG,"GCM - Checking device");
        GCMRegistrar.checkDevice(context);
        Log.d(TAG,"GCM - Checking manifest");
        GCMRegistrar.checkManifest(context);
        Log.d(TAG,"GCM - registering");
        GCMRegistrar.register(context, SENDER_ID);
        Log.d(TAG,"GCM - Registered");

        boolean registered = GCMRegistrar.isRegistered(context);

        if(!registered) {
            throw new Exception("Not registered!");
        }
    }

... and I ended up getting my debugging exception raised pretty quickly after all four log messages are logged. It seems that the GCM registration is failing but not throwing an exception for some reason.

I'm hesitant to spend more time on this given GCM's imminent deprecation, and I am wondering if it's not working on Pie because of GCM's imminent deprecation. I'm also unsure if it's failing for me in debug mode because I'm not the app developer, or if it's an actual reproduction of the problem. The lack of error message here is mildly infuriating.

The full log of my debug session is below - beware I have had to make quite a few changes to this to get it to build and run on my machine, also listed below. I'm also aware that there's probably going to be a lot of crossover to #182 with this too.

Debug log

$ adb shell am start -n "fi.iki.murgo.irssinotifier/fi.iki.murgo.irssinotifier.IrssiNotifierActivity" -a android.intent.action.MAIN -c android.intent.category.LAUNCHER -D
Waiting for application to come online: fi.iki.murgo.irssinotifier | fi.iki.murgo.irssinotifier.test
Waiting for application to come online: fi.iki.murgo.irssinotifier | fi.iki.murgo.irssinotifier.test
Connecting to fi.iki.murgo.irssinotifier
Capturing and displaying logcat messages from application. This behavior can be disabled in the "Logcat output" section of the "Debugger" settings page.
I/System.out: Debugger has connected
    waiting for debugger to settle...
Connected to the target VM, address: 'localhost:8612', transport: 'socket'
I/chatty: uid=10223(fi.iki.murgo.irssinotifier) identical 5 lines
I/System.out: waiting for debugger to settle...
I/System.out: debugger has settled (1307)
I/o.irssinotifie: The ClassLoaderContext is a special shared library.
W/o.irssinotifie: JIT profile information will not be recorded: profile file does not exits.
I/chatty: uid=10223(fi.iki.murgo.irssinotifier) identical 10 lines
W/o.irssinotifie: JIT profile information will not be recorded: profile file does not exits.
I/Perf: Connecting to perf service.
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399811): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
I/InstantRun: starting instant run server: is main process
I/fi.iki.murgo.irssinotifier.IrssiNotifierActivity: Startup
D/fi.iki.murgo.irssinotifier.IrssiNotifierActivity: Asking for initial settings
W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@7872e66
D/OpenGLRenderer: Skia GL Pipeline
W/o.irssinotifier: type=1400 audit(0.0:399813): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
D/DecorView: onWindowFocusChangedFromViewRoot hasFocus: true, DecorView@fb5a697[InitialSettingsActivity]
I/Adreno: QUALCOMM build                   : 0bf40b0, I486bafd568
    Build Date                       : 08/22/18
    OpenGL ES Shader Compiler Version: EV031.25.03.00
    Local Branch                     : 
    Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.7.3.R1.08.00.00.423.039
    Remote Branch                    : NONE
    Reconstruct Branch               : NOTHING
    Build Config                     : S P 6.0.3 AArch64
W/RenderThread: type=1400 audit(0.0:399815): avc: denied { search } for name="proc" dev="debugfs" ino=15046 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:qti_debugfs:s0 tclass=dir permissive=0
I/Adreno: PFP: 0x016ee170, ME: 0x00000000
I/ConfigStore: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasWideColorDisplay retrieved: 1
    android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasHDRDisplay retrieved: 0
I/OpenGLRenderer: Initialized EGL, version 1.4
D/OpenGLRenderer: Swap behavior 2
D/fi.iki.murgo.irssinotifier.InitialSettingsActivity: Changing state: 0
W/o.irssinotifie: Verification of java.lang.Boolean fi.iki.murgo.irssinotifier.GCMRegistrationTask.doInBackground(java.lang.Void[]) took 208.218ms
W/o.irssinotifier: type=1400 audit(0.0:399816): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399818): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399820): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399822): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
I/fi.iki.murgo.irssinotifier.GCMRegistrationTask: Registering to GCM
D/fi.iki.murgo.irssinotifier.GCMIntentService: GCM - Checking device
D/fi.iki.murgo.irssinotifier.GCMIntentService: GCM - Checking manifest
D/fi.iki.murgo.irssinotifier.GCMIntentService: GCM - registering
D/GCMRegistrar: resetting backoff for fi.iki.murgo.irssinotifier
V/GCMRegistrar: Registering app fi.iki.murgo.irssinotifier of senders 710677821747
D/fi.iki.murgo.irssinotifier.GCMIntentService: GCM - Registered
E/fi.iki.murgo.irssinotifier.GCMRegistrationTask: Error trying to register to GCM
    java.lang.Exception: Not registered!
        at fi.iki.murgo.irssinotifier.GCMIntentService.registerToGcm(GCMIntentService.java:43)
        at fi.iki.murgo.irssinotifier.GCMRegistrationTask.doInBackground(GCMRegistrationTask.java:32)
        at fi.iki.murgo.irssinotifier.GCMRegistrationTask.doInBackground(GCMRegistrationTask.java:7)
        at android.os.AsyncTask$2.call(AsyncTask.java:333)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:764)
D/DecorView: onWindowFocusChangedFromViewRoot hasFocus: true, DecorView@fb5a697[InitialSettingsActivity]
W/o.irssinotifier: type=1400 audit(0.0:399826): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
    type=1400 audit(0.0:399827): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399828): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
E/libc: Access denied finding property "vendor.perf.iop_v3.enable.debug"
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
W/o.irssinotifier: type=1400 audit(0.0:399830): avc: denied { read } for name="u:object_r:vendor_iop_prop:s0" dev="tmpfs" ino=22369 scontext=u:r:untrusted_app_25:s0:c512,c768 tcontext=u:object_r:vendor_iop_prop:s0 tclass=file permissive=0
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"
E/libc: Access denied finding property "vendor.perf.iop_v3.enable"
    Access denied finding property "vendor.perf.iop_v3.enable.debug"

Additional changes made

UserHelper

Added this to the start of getAccounts(...):

        if (ContextCompat.checkSelfPermission(context, android.Manifest.permission.GET_ACCOUNTS) != PackageManager.PERMISSION_GRANTED) {
            ActivityCompat.requestPermissions((Activity)context, new String[]{android.Manifest.permission.GET_ACCOUNTS}, 0);
        }
murgo commented 6 years ago

Thanks @stwalkerster!

Could you do a PR from your changes? I started trying to replicate this issue with debugger couple of days ago but didn't have enough time as many of the tools in the chain were deprecated and didn't work. Gradle didn't play nice with my IDE or the new android build tools.

Damn projects melting on their own, I haven't done any Android developing for quite some time so my environment isn't nearly up to date :P

If you could send a PR with the newer build stuff I'd appreciate it so I could focus on the real issue (which might very well be the GCM phase out).

murgo commented 6 years ago

Yeah, it is broken on Emulator running Pie too. Seems like maybe updating to newer Google Cloud Messaging libs might resolve this, but I'm going to do the Firebase migration since the GCM is deprecated anyways.

It shouldn't be a big job. FCM is thankfully really close to GCM and it's backwards compatible so no need to update all devices. The cloud messaging Android APIs are so much cleaner now than what they were in 2012 when I first created this project. So it's mostly deleting old bloat and just some lines of new stuff.

When it's done, I hope some of you with actual Android 9 devices will test APK I'll provide so I can know the app works on actual devices.

murgo commented 6 years ago

Hoo boy... I got it all fixed and running and just noticed that Google Play doesn't allow apps targeting lower than API level 26 starting this November, so I need to target newest API level. This of course happens to have breaking changes to the way the app authenticates to the server.

Patience is a virtue they say.

murgo commented 6 years ago

This should finally be fixed!

There was quite a few things I had to fix to make it work on Android 9 but now as a result we have Notification Channels on Android 8+ & Firebase messaging & bunch of bugfixes.

Tested the fixes only on emulator so I can't know for sure if it works on real Android 9 phones, someone please confirm it works after you update. Update is live on Google Play for both IrssiNotifier and IrssiNotifier+.

stwalkerster commented 6 years ago

Just updated and it seems to be working again for me! Thanks a lot :)

contyk commented 6 years ago

FWIW, also confirming. Cheers.