Error When App Starts from NFC Tag Scan Event

PowerOfM commented 2 years ago

When the app starts from an NFC tag scan event, the channelCallback is null, causing an NPE.

E/AndroidRuntime: FATAL EXCEPTION: pool-3-thread-1
    java.lang.NullPointerException: Attempt to invoke virtual method 'void org.apache.cordova.CallbackContext.sendPluginResult(org.apache.cordova.PluginResult)' on a null object reference
        at com.chariotsolutions.nfc.plugin.NfcPlugin.sendEvent(NfcPlugin.java:740)
        at com.chariotsolutions.nfc.plugin.NfcPlugin.fireNdefEvent(NfcPlugin.java:749)
        at com.chariotsolutions.nfc.plugin.NfcPlugin.lambda$parseMessage$10$NfcPlugin(NfcPlugin.java:708)
        at com.chariotsolutions.nfc.plugin.-$$Lambda$NfcPlugin$8qvszOgjpGqW46Vg-QVXuocmsg8.run(Unknown Source:2)
        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:919)

gercobrandwijk commented 2 years ago

I do also experience this issue. The PR that you provided prevents indeed the NULL pointer exception, but in my opinion this is not really a solution, because this means it will simply not trigger the listener at all (because it is not send through the channel anymore).

The scenario where I have this problem is as follows:

Go to home screen
Really stop app (swipe it out of memory OR stop via Settings -> Apps)
Scan NFC tag
In the log you see that the app is starting, but that the NfcPlugin wants to pass the scanned tag throught the Cordova/Bridge channel, which fails because the channel connection is not made yet (I think)

2021-11-04 14:37:24.743 1757-1863/? I/ActivityManager: Start proc 23254:com.example.myapp/u0a257 for pre-top-activity {com.example.myapp/com.example.myapp.MainActivity}
2021-11-04 14:37:24.744 23254-23254/? I/t.brightbookin: Late-enabling -Xcheck:jni
2021-11-04 14:37:24.789 23254-23254/com.example.myapp D/ApplicationLoaders: Returning zygote-cached class loader: /system/framework/android.test.base.jar
2021-11-04 14:37:24.809 3098-3098/? I/GsaVoiceInteractionSrv: Handling ACTION_STOP_HOTWORD
2021-11-04 14:37:24.851 23254-23254/com.example.myapp D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2021-11-04 14:37:24.852 23254-23254/com.example.myapp D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2021-11-04 14:37:24.860 23254-23254/com.example.myapp W/ComponentDiscovery: Class com.google.firebase.dynamicloading.DynamicLoadingRegistrar is not an found.
2021-11-04 14:37:24.866 23254-23254/com.example.myapp I/FirebaseApp: Device unlocked: initializing all Firebase APIs for app [DEFAULT]
2021-11-04 14:37:24.888 23254-23254/com.example.myapp I/FirebaseInitProvider: FirebaseApp initialization successful
2021-11-04 14:37:24.894 639-2057/? W/DisplayIdentification: Invalid EDID: falling back to serial number due to missing display name.
2021-11-04 14:37:24.894 639-2057/? W/DisplayIdentification: Invalid EDID: falling back to ASCII text due to missing serial number.
2021-11-04 14:37:24.959 23254-23254/com.example.myapp E/t.brightbookin: Invalid ID 0x00000000.
2021-11-04 14:37:24.960 23254-23254/com.example.myapp E/t.brightbookin: Invalid ID 0x00000000.
2021-11-04 14:37:24.969 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/view/View;->computeFitSystemWindows(Landroid/graphics/Rect;Landroid/graphics/Rect;)Z (greylist, reflection, allowed)
2021-11-04 14:37:24.970 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/view/ViewGroup;->makeOptionalFitsSystemWindows()V (greylist, reflection, allowed)
2021-11-04 14:37:24.992 23254-23254/com.example.myapp I/WebViewFactory: Loading com.google.android.webview version 95.0.4638.50 (code 463805033)
2021-11-04 14:37:25.008 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/os/Trace;->isTagEnabled(J)Z (greylist, reflection, allowed)
2021-11-04 14:37:25.008 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/os/Trace;->traceBegin(JLjava/lang/String;)V (greylist, reflection, allowed)
2021-11-04 14:37:25.008 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/os/Trace;->traceEnd(J)V (greylist, reflection, allowed)
2021-11-04 14:37:25.008 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/os/Trace;->asyncTraceBegin(JLjava/lang/String;I)V (greylist, reflection, allowed)
2021-11-04 14:37:25.008 23254-23254/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/os/Trace;->asyncTraceEnd(JLjava/lang/String;I)V (greylist, reflection, allowed)
2021-11-04 14:37:25.011 23254-23254/com.example.myapp I/cr_WVCFactoryProvider: Loaded version=95.0.4638.50 minSdkVersion=29 isBundle=true multiprocess=true packageId=2
2021-11-04 14:37:25.027 23254-23254/com.example.myapp E/t.brightbookin: Invalid ID 0x00000000.
2021-11-04 14:37:25.027 23254-23254/com.example.myapp E/t.brightbookin: Invalid ID 0x00000000.
2021-11-04 14:37:25.030 23254-23254/com.example.myapp I/cr_LibraryLoader: Successfully loaded native library
2021-11-04 14:37:25.031 23254-23254/com.example.myapp I/cr_CachingUmaRecorder: Flushed 8 samples from 8 histograms.
2021-11-04 14:37:25.034 23254-23254/com.example.myapp I/TetheringManager: registerTetheringEventCallback:com.example.myapp
2021-11-04 14:37:25.047 1757-5682/? D/CompatibilityChangeReporter: Compat change id reported: 135634846; UID 10257; state: DISABLED
2021-11-04 14:37:25.048 1757-1863/? D/CompatibilityChangeReporter: Compat change id reported: 143937733; UID 10257; state: ENABLED
2021-11-04 14:37:25.057 2296-2296/? D/Zygote: Forked child process 23293
2021-11-04 14:37:25.059 1757-5682/? D/CompatibilityChangeReporter: Compat change id reported: 136274596; UID 10257; state: ENABLED
2021-11-04 14:37:25.069 23293-23293/? E/ocessService0:: Not starting debugger since process cannot load the jdwp agent.
2021-11-04 14:37:25.074 1757-1863/? I/ActivityManager: Start proc 23293:com.google.android.webview:sandboxed_process0:org.chromium.content.app.SandboxedProcessService0:0/u0i47 for  {com.example.myapp/org.chromium.content.app.SandboxedProcessService0:0}
2021-11-04 14:37:25.079 21332-21332/? D/BoundBrokerSvc: onBind: Intent { act=com.google.android.gms.safetynet.service.START pkg=com.google.android.gms }
2021-11-04 14:37:25.079 21332-21332/? D/BoundBrokerSvc: Loading bound service for intent: Intent { act=com.google.android.gms.safetynet.service.START pkg=com.google.android.gms }
2021-11-04 14:37:25.079 1757-2382/? D/CompatibilityChangeReporter: Compat change id reported: 136274596; UID 10257; state: ENABLED
2021-11-04 14:37:25.101 23254-23254/com.example.myapp E/chromium: [ERROR:network_service_instance_impl.cc(179)] Failed to grant sandbox access to network context data for /data/user/0/com.example.myapp/app_webview/Default with result 7: No such file or directory (2)
2021-11-04 14:37:25.102 23293-23293/? D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2021-11-04 14:37:25.103 23293-23293/? D/NetworkSecurityConfig: No Network Security Config specified, using platform default
2021-11-04 14:37:25.104 23293-23293/? I/cr_WebViewApkApp: Launched version=95.0.4638.50 minSdkVersion=29 isBundle=true processName=com.google.android.webview:sandboxed_process0:org.chromium.content.app.SandboxedProcessService0:0
2021-11-04 14:37:25.107 23293-23293/? I/cr_ChildProcessService: Creating new ChildProcessService pid=23293
2021-11-04 14:37:25.116 1757-3511/? D/ConnectivityService: requestNetwork for uid/pid:10257/23254 NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ]
2021-11-04 14:37:25.117 1757-2107/? D/ConnectivityService: NetReassign [723 : null → 108]
2021-11-04 14:37:25.118 1757-2103/? D/WifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ] with score 60 and providerId 5
2021-11-04 14:37:25.118 1757-2103/? D/UntrustedWifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ] with score 60 and providerId 5
2021-11-04 14:37:25.118 1757-2148/? D/WIFI_AWARE_FACTORY: got request NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ] with score 60 and providerId 5
2021-11-04 14:37:25.118 1757-2149/? D/Ethernet: got request NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ] with score 60 and providerId 5
2021-11-04 14:37:25.119 2537-2537/? D/PhoneSwitcherNetworkRequstListener: got request NetworkRequest [ TRACK_DEFAULT id=723, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10257 AdministratorUids: [] RequestorUid: 10257 RequestorPackageName: com.example.myapp] ] with score 60 and providerId 5
2021-11-04 14:37:25.120 1757-2107/? D/ConnectivityService: NetReassign [no changes]
2021-11-04 14:37:25.139 23254-23254/com.example.myapp D/Capacitor: Starting BridgeActivity
2021-11-04 14:37:25.157 23254-23254/com.example.myapp D/IonicDeeplinkPlugin: IonicDeepLinkPlugin: firing up...
2021-11-04 14:37:25.158 23254-23254/com.example.myapp D/IonicDeeplinkPlugin: Got a new intent: https://deeplink.gobright.cloud/nfc?t=s&i=aaAAbbBBccCC https android.nfc.action.NDEF_DISCOVERED https://deeplink.XXXXXX.cloud/nfc?t=s&i=aaAAbbBBccCC
2021-11-04 14:37:25.168 23254-23254/com.example.myapp D/Capacitor: Registering plugin: WebView
2021-11-04 14:37:25.171 23254-23254/com.example.myapp D/Capacitor: Registering plugin: App
2021-11-04 14:37:25.172 23254-23254/com.example.myapp D/Capacitor: Registering plugin: Browser
2021-11-04 14:37:25.174 23254-23254/com.example.myapp D/Capacitor: Registering plugin: Haptics
2021-11-04 14:37:25.176 23254-23254/com.example.myapp D/Capacitor: Registering plugin: Keyboard
2021-11-04 14:37:25.177 23254-23254/com.example.myapp D/Capacitor: Registering plugin: LocalNotifications
2021-11-04 14:37:25.183 23254-23254/com.example.myapp D/Capacitor: Registering plugin: PushNotifications
2021-11-04 14:37:25.186 23254-23254/com.example.myapp D/Capacitor: Registering plugin: SplashScreen
2021-11-04 14:37:25.217 3144-23253/? D/NativeNfcTag: Tag lost, restarting polling loop
2021-11-04 14:37:25.219 3144-23253/? D/NfcService: Discovery configuration equal, not updating.
2021-11-04 14:37:25.219 3144-23253/? D/NativeNfcTag: Stopping background presence check
2021-11-04 14:37:25.226 23254-23254/com.example.myapp D/Capacitor: Registering plugin: StatusBar
2021-11-04 14:37:25.254 23254-23254/com.example.myapp D/Capacitor: Loading app at http://192.168.236.115:8100
2021-11-04 14:37:25.263 23254-23317/com.example.myapp W/t.brightbookin: Accessing hidden method Landroid/media/AudioManager;->getOutputLatency(I)I (greylist, reflection, allowed)
2021-11-04 14:37:25.267 23254-23331/com.example.myapp I/AdrenoGLES-0: QUALCOMM build                   : 85da404, I46ff5fc46f
    Build Date                       : 11/30/20
    OpenGL ES Shader Compiler Version: EV031.31.04.01
    Local Branch                     : promo490_3_Google
    Remote Branch                    : 
    Remote Branch                    : 
    Reconstruct Branch               : 
2021-11-04 14:37:25.267 23254-23331/com.example.myapp I/AdrenoGLES-0: Build Config                     : S P 10.0.4 AArch64
2021-11-04 14:37:25.267 23254-23331/com.example.myapp I/AdrenoGLES-0: Driver Path                      : /vendor/lib64/egl/libGLESv2_adreno.so
2021-11-04 14:37:25.271 23254-23331/com.example.myapp I/AdrenoGLES-0: PFP: 0x016ee189, ME: 0x00000000
2021-11-04 14:37:25.271 23293-23324/? I/cr_LibraryLoader: Successfully loaded native library
2021-11-04 14:37:25.272 23293-23324/? I/cr_CachingUmaRecorder: Flushed 2 samples from 2 histograms.
2021-11-04 14:37:25.273 23254-23331/com.example.myapp W/AdrenoUtils: <ReadGpuID_from_sysfs:197>: Failed to open /sys/class/kgsl/kgsl-3d0/gpu_model
2021-11-04 14:37:25.273 23254-23331/com.example.myapp W/AdrenoUtils: <ReadGpuID:221>: Failed to read chip ID from gpu_model. Fallback to use the GSL path
2021-11-04 14:37:25.275 23254-23317/com.example.myapp W/cr_media: Requires BLUETOOTH permission
2021-11-04 14:37:25.279 23254-23254/com.example.myapp D/IonicDeeplinkPlugin: Got a new intent: https://deeplink.XXXXXX.cloud/nfc?t=s&i=aaAAbbBBccCC https android.nfc.action.NDEF_DISCOVERED https://deeplink.XXXXXX.cloud/nfc?t=s&i=aaAAbbBBccCC
2021-11-04 14:37:25.280 23254-23254/com.example.myapp D/NfcPlugin: onNewIntent Intent { act=android.nfc.action.NDEF_DISCOVERED dat=https://deeplink.XXXXXX.cloud/... flg=0x10000000 cmp=com.example.myapp/.MainActivity (has extras) }
2021-11-04 14:37:25.280 23254-23254/com.example.myapp D/Capacitor: App started
2021-11-04 14:37:25.281 23254-23333/com.example.myapp D/NfcPlugin: parseMessage Intent { act=android.nfc.action.NDEF_DISCOVERED dat=https://deeplink.XXXXXX.cloud/... flg=0x10000000 cmp=com.example.myapp/.MainActivity (has extras) }
2021-11-04 14:37:25.281 23254-23333/com.example.myapp D/NfcPlugin: action android.nfc.action.NDEF_DISCOVERED
2021-11-04 14:37:25.283 23254-23254/com.example.myapp D/Capacitor/AppPlugin: Firing change: true
2021-11-04 14:37:25.283 23254-23254/com.example.myapp V/Capacitor/AppPlugin: Notifying listeners for event appStateChange
2021-11-04 14:37:25.283 23254-23254/com.example.myapp D/Capacitor/AppPlugin: No listeners found for event appStateChange
2021-11-04 14:37:25.286 23293-23324/? W/SystemServiceRegistry: No service published for: uimode
2021-11-04 14:37:25.287 23254-23254/com.example.myapp V/Capacitor/BrowserPlugin: Notifying listeners for event browserFinished
2021-11-04 14:37:25.287 23254-23254/com.example.myapp D/Capacitor/BrowserPlugin: No listeners found for event browserFinished
2021-11-04 14:37:25.288 23254-23254/com.example.myapp D/NfcPlugin: onResume Intent { act=android.nfc.action.NDEF_DISCOVERED dat=https://deeplink.XXXXXX.cloud/... flg=0x10000000 cmp=com.example.myapp/.MainActivity (has extras) }

    --------- beginning of crash
2021-11-04 14:37:25.288 23254-23333/com.example.myapp E/AndroidRuntime: FATAL EXCEPTION: pool-10-thread-1
    Process: com.example.myapp, PID: 23254
    java.lang.NullPointerException: Attempt to invoke virtual method 'void org.apache.cordova.CallbackContext.sendPluginResult(org.apache.cordova.PluginResult)' on a null object reference
        at com.chariotsolutions.nfc.plugin.NfcPlugin.sendEvent(NfcPlugin.java:740)
        at com.chariotsolutions.nfc.plugin.NfcPlugin.fireNdefEvent(NfcPlugin.java:749)
        at com.chariotsolutions.nfc.plugin.NfcPlugin.lambda$parseMessage$10$NfcPlugin(NfcPlugin.java:708)
        at com.chariotsolutions.nfc.plugin.-$$Lambda$NfcPlugin$8qvszOgjpGqW46Vg-QVXuocmsg8.run(Unknown Source:2)
        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:923)
2021-11-04 14:37:25.294 23254-23254/com.example.myapp D/Capacitor: App resumed
2021-11-04 14:37:25.296 1757-23335/? I/DropBoxManagerService: add tag=data_app_crash isTagEnabled=true flags=0x2
2021-11-04 14:37:25.297 1757-3511/? W/ActivityTaskManager:   Force finishing activity com.example.myapp/.MainActivity
2021-11-04 14:37:25.303 1757-1862/? W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
2021-11-04 14:37:25.304 1757-1862/? W/BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
2021-11-04 14:37:25.314 23254-23333/com.example.myapp I/Process: Sending signal. PID: 23254 SIG:

I initialize an eventlistener in the app.page.ts when the platform is ready:

Did experience the same things @PowerOfM?

PowerOfM commented 2 years ago

@gercobrandwijk You bring up a valid point. I think a more thorough solution would be to enqueue the event and send it to the bridge once it's fully initialized.

I'm actually using CapacitorJS instead of PhoneGap/Cordova, and the ndef data gets passed in as a launch-url to the app. So I haven't had any issues and a cold-start of the app from an NFC event works as expected. I hope you're able to figure it out!

paulq1984 commented 2 years ago

Watching this as I'm having similar issues when using PhoneGap/Cordova plugin in Capacitor 3 and Ionic 5.

gercobrandwijk commented 2 years ago

I ended up override the NfcPlugin.java with some custom code, please see this gist (contains 4 files including a README.md): https://gist.github.com/gercobrandwijk/e1ef9b2cb56a1cba17d5d0aa20876819

Basically after an npm install I run that copy-to-node-modules.js script that is attached to the gist, which makes sure that my own NfcPlugin.java is used.

The main problem that is solved in the gist/NfcPlugin.java is that the scanned NFC tag is not lost when the app is not started yet (which causes an exception in the 'normal' NfcPlugin.java code, see the comments above) by remembering the last scanned tag in the variable postponedPluginResult, which is send to the application when the communication channel is setted up (see line 124-142).

PowerOfM commented 2 years ago

@gercobrandwijk That looks great! Would you be interested in submitting an PR?

It also looks like other people are trying to tackle the same issue: https://github.com/chariotsolutions/phonegap-nfc/pull/460

avargaskun commented 2 years ago

@PowerOfM - thanks for referencing my PR above. I took a slightly different approach: I enqueue the event and expose a new plugin API that allows fetching the scanned tag. I needed to do this because my app needs to perform further initialization after Cordova calls the ready event, so this pattern better matched my requirements.

My app has been using the variation referenced in the PR for a few months now and have not run into any issues yet. Unfortunately, I don't think the PR has yet been looked at yet by the owner of the main repo.

somq commented 1 year ago

For anyone that looks for a bundled solution with Android 12 compat. This fork groups both fixes:

@gercobrandwijk fix for intennt filter and tag dispatch at app launch
Android 12 compat (FLAG_IMMUTABLE)

You can directly reference the branch in package.json

[...]
  "dependencies": {
    "phonegap-nfc": "somq/phonegap-nfc#fix/nfc-launch",
    [...]
  }

Edit: proposed the PR as !470 as a reference even though commits are not really clean...

chariotsolutions / phonegap-nfc

Error When App Starts from NFC Tag Scan Event #457