harishrpatel commented 3 years ago

Preliminary Info

What Airship dependencies are you using?

    implementation("com.urbanairship.android:urbanairship-fcm:${Versions.URBAN_AIRSHIP_VERSION}")
    // Message Center
    implementation("com.urbanairship.android:urbanairship-message-center:${Versions.URBAN_AIRSHIP_VERSION}")
    // In-App Automation
    implementation("com.urbanairship.android:urbanairship-automation:${Versions.URBAN_AIRSHIP_VERSION}")
    // Location
    implementation("com.urbanairship.android:urbanairship-location:${Versions.URBAN_AIRSHIP_VERSION}")
    implementation("com.urbanairship.android:gimbal-adapter:${Versions.URBAN_AIRSHIP_GIMBAL_ADAPTER}")

URBAN_AIRSHIP_VERSION = 14.0.3 (Tried with latest, but same result).
URBAN_AIRSHIP_GIMBAL_ADAPTER = 6.1.0

What are the versions of any relevant development tools you are using?

Android Studio Arctic Fox | 2020.3.1 Canary 4
Charles v4.6.1

Report

What unexpected behavior are you seeing?

Analytics.addEvent() is misfiring. We pushed 70 events and only 6 showed up on Airship Console.

        GlobalScope.launch(Dispatchers.IO) {
            val customEvent = CustomEvent.Builder(event)
                .setEventProperty(prop1)
                .setEventProperty(prop2)
                .setEventProperty(prop3)
                .setEventProperty(prop4)
                .build()

            customEvent.track()

What is the expected behavior?

All events should be POSTED.

What are the steps to reproduce the unexpected behavior?

Just calling the code snippet mentioned above. This had been working perfectly but seems to have broken in last month or so.

Do you have logging for the issue?

Here is what I see on logcat:

2021-01-28 17:34:07.103 19029-19133/? V/ Abc123 - UALib: PreferenceDataStore - Saving preference: com.urbanairship.remotedata.LAST_REFRESH_TIME value: 1611876847102
2021-01-28 17:34:07.103 19029-19104/? V/ Abc123 - UALib: Job - Finished: JobInfo{action=ACTION_REFRESH, id=10, extras='{}', airshipComponentName='tf.a', isNetworkAccessRequired=true, initialDelay=0, persistent=false} with result: 0
2021-01-28 17:34:07.104 19029-19165/? V/ Abc123 - UALib: AirshipService - Component finished job with startId: 1
2021-01-28 17:34:07.170 19029-19166/? V/ Abc123 - UALib: InboxJobHandler - Fetch inbox messages response: Response{responseBody='{
      "messages" : [ ],
      "badge" : 0
    }
    ', responseHeaders={null=[HTTP/1.1 200 OK], Alt-Svc=[clear], Cache-Control=[no-cache, no-store, must revalidate], Connection=[keep-alive], Content-Type=[application/json;charset=utf-8], Date=[Thu, 28 Jan 2021 23:34:05 GMT], Transfer-Encoding=[chunked], Vary=[Accept-Encoding], Via=[1.1 google], X-Android-Received-Millis=[1611876847125], X-Android-Response-Source=[NETWORK 200], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1611876847048]}, status=200, lastModified=0}
2021-01-28 17:34:07.170 19029-19166/? I/ Abc123 - UALib: Received 0 inbox messages.
2021-01-28 17:34:07.181 19029-19166/? V/ Abc123 - UALib: Job - Finished: JobInfo{action=ACTION_RICH_PUSH_MESSAGES_UPDATE, id=-1, extras='{}', airshipComponentName='com.urbanairship.messagecenter.f', isNetworkAccessRequired=false, initialDelay=0, persistent=false} with result: 0
2021-01-28 17:34:07.181 19029-19165/? V/ Abc123 - UALib: AirshipService - Component finished job with startId: 2
2021-01-28 17:34:07.181 19029-19165/? V/ Abc123 - UALib: AirshipService - All jobs finished, stopping with last startId: 2
2021-01-28 17:34:07.589 19029-19141/? V/ Abc123 - UALib: Analytics - Adding event: enhanced_custom_event
2021-01-28 17:34:07.590 19029-19146/? D/ Abc123 - UALib: Automation - Updating triggers with type: 5
2021-01-28 17:34:07.590 19029-19141/? D/Push: addEvent: myEventName: isAppClip="true",reservationId="88243",restaurantName="Abcd",preferenceId="11444"
2021-01-28 17:34:07.597 19029-19166/? V/ Abc123 - UALib: EventManager - Requesting to schedule event upload with delay 10000 ms.
2021-01-28 17:34:07.597 19029-19166/? V/ Abc123 - UALib: EventManager - Event upload already scheduled for an earlier time.

harishrpatel commented 3 years ago

We are seeing this behavior on both instant app as well as full app.
On Charles I never see these events being posted.
I wait for 10+ seconds, but nothing shows up.

rlepinski commented 3 years ago

@harishrpatel could you provide logs showing the event being added. We will either log Analytics - Invalid event: or Analytics - Adding event: if its valid. Ill see if I can reproduce locally.

nvm, i see that its being added. Do you see any logs about events uploading ever?

rlepinski commented 3 years ago

@harishrpatel The only thing I can see that would cause the upload to not happen is if something is cancelling our jobs or scheduling over. Are you using work manager, cancelling work, or cancelling jobs?

harishrpatel commented 3 years ago

@rlepinski I am not doing any of that. We use kotlin coroutines, so not doing anything directly with work manager. Is there any way to flush the event queue by app?

harishrpatel commented 3 years ago

Also on a previous question. When our QA tested, we had production build and we sent 35 events from instant app and full app each. Console saw only 6 of these 70. Unfortunaly we don't have any logs. And I tried about 10 times with debug logging and I never saw a single event on charles. @rlepinski

rlepinski commented 3 years ago

@harishrpatel Ill have to see what tools are available for debugging the JobManager stuff. Ill get back to you in the AM.

rlepinski commented 3 years ago

@harishrpatel Right now I am thinking that some other library is either calling [cancelAll](https://developer.android.com/reference/android/app/job/JobScheduler#cancelAll()) on the JobScheduler, or maybe using one of the Airship IDs and scheduling over our Job. Are you able to reproduce this easily? If so, we can rule out the ID conflict by adding this to your manifest under the application entry:

        <meta-data android:name="com.urbanairship.job.JOB_ID_START" android:value="11797" />

11797 is just a random number, can be anything. We default to 3000000.

If it's still not working, then I believe something is calling cancelAll(). In your combined manifest, you should see other SDK job services listed. Example:

      <service
            android:name="com.urbanairship.job.AndroidJobService"
            android:permission="android.permission.BIND_JOB_SERVICE" />

The BIND_JOB_SERVICE is the permission to look for. Could you provide the dependencies that have this job service? I can take a look at those SDKs to see whats going on. If something else is calling cancelAll(), that will break our jobs and be very hard to recover from. It's unfortunate that Android exposes that API and not a way to cancel based on a named space.

Finally, you can actually see all scheduled jobs by running adb shell dumpsys jobscheduler | grep <YOUR_PACKAGE_NAME>. The job ID for uploading events is JOB_ID_START + 0, so 3000000 or whatever you set the JOB_ID_START in your package. Could you provide this output for me. Here is the output for our internal test app (com.urbanairship.goat):

 adb shell dumpsys jobscheduler | grep com.urbanairship.goat
    <0>com.urbanairship.goat::.schedulePersisted():
    <0>com.urbanairship.goat::.schedulePersisted():
  JOB #u0a316/3000000: 712cc1e com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    u0a316 tag=*job*/com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.urbanairship.job.AndroidJobService
  JOB #u0a316/3000004: ceaa0a8 com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    u0a316 tag=*job*/com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.urbanairship.job.AndroidJobService
  JOB #u0a316/95305998: 6cba31 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
    u0a316 tag=*job*/com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
  #u0a316/3000004 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/3000000 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/95305998 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/3000004 from u0a316: com.urbanairship.goat RUNNABLE
  #u0a316/3000000 from u0a316: com.urbanairship.goat RUNNABLE
  #u0a316/95305998 from u0a316: com.urbanairship.goat RUNNABLE
    10316: {com.urbanairship.goat}
  Timer{<0>com.urbanairship.goat} NOT active, 0 running bg jobs
    <0>com.urbanairship.goat
  u0a316 / com.urbanairship.goat:
  u0a316 / com.urbanairship.goat:
  u0a316 / com.urbanairship.goat:
           -5s749ms START-P: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
           -4s335ms   START: #u0a316/3000005 com.urbanairship.goat/com.urbanairship.job.AndroidJobService
           -4s103ms    STOP: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService cancelled while waiting for bind
           -4s086ms START-P: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
           -3s378ms    STOP: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService onStartJob returned false
           -3s348ms  STOP-P: #u0a316/3000005 com.urbanairship.goat/com.urbanairship.job.AndroidJobService app called jobFinished

While you are doing that, I will see if we can do a better job recovering if something cancels our upload job.

harishrpatel commented 3 years ago

@harishrpatel Right now I am thinking that some other library is either calling [cancelAll](https://developer.android.com/reference/android/app/job/JobScheduler#cancelAll()) on the JobScheduler, or maybe using one of the Airship IDs and scheduling over our Job. Are you able to reproduce this easily? If so, we can rule out the ID conflict by adding this to your manifest under the application entry:
        <meta-data android:name="com.urbanairship.job.JOB_ID_START" android:value="11797" />
11797 is just a random number, can be anything. We default to 3000000.

If it's still not working, then I believe something is calling cancelAll(). In your combined manifest, you should see other SDK job services listed. Example:
      <service
            android:name="com.urbanairship.job.AndroidJobService"
            android:permission="android.permission.BIND_JOB_SERVICE" />
The BIND_JOB_SERVICE is the permission to look for. Could you provide the dependencies that have this job service? I can take a look at those SDKs to see whats going on. If something else is calling cancelAll(), that will break our jobs and be very hard to recover from. It's unfortunate that Android exposes that API and not a way to cancel based on a named space.

Finally, you can actually see all scheduled jobs by running adb shell dumpsys jobscheduler | grep <YOUR_PACKAGE_NAME>. The job ID for uploading events is JOB_ID_START + 0, so 3000000 or whatever you set the JOB_ID_START in your package. Could you provide this output for me. Here is the output for our internal test app (com.urbanairship.goat):
 adb shell dumpsys jobscheduler | grep com.urbanairship.goat
    <0>com.urbanairship.goat::.schedulePersisted():
    <0>com.urbanairship.goat::.schedulePersisted():
  JOB #u0a316/3000000: 712cc1e com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    u0a316 tag=*job*/com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.urbanairship.job.AndroidJobService
  JOB #u0a316/3000004: ceaa0a8 com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    u0a316 tag=*job*/com.urbanairship.goat/com.urbanairship.job.AndroidJobService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.urbanairship.job.AndroidJobService
  JOB #u0a316/95305998: 6cba31 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
    u0a316 tag=*job*/com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
    Source: uid=u0a316 user=0 pkg=com.urbanairship.goat
      Service: com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
  #u0a316/3000004 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/3000000 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/95305998 from u0a316 active: com.urbanairship.goat [RUN_ANY_IN_BACKGROUND allowed] RUNNABLE
  #u0a316/3000004 from u0a316: com.urbanairship.goat RUNNABLE
  #u0a316/3000000 from u0a316: com.urbanairship.goat RUNNABLE
  #u0a316/95305998 from u0a316: com.urbanairship.goat RUNNABLE
    10316: {com.urbanairship.goat}
  Timer{<0>com.urbanairship.goat} NOT active, 0 running bg jobs
    <0>com.urbanairship.goat
  u0a316 / com.urbanairship.goat:
  u0a316 / com.urbanairship.goat:
  u0a316 / com.urbanairship.goat:
           -5s749ms START-P: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
           -4s335ms   START: #u0a316/3000005 com.urbanairship.goat/com.urbanairship.job.AndroidJobService
           -4s103ms    STOP: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService cancelled while waiting for bind
           -4s086ms START-P: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService
           -3s378ms    STOP: #u0a316/95305998 com.urbanairship.goat/com.gimbal.android.jobs.JobManagerService onStartJob returned false
           -3s348ms  STOP-P: #u0a316/3000005 com.urbanairship.goat/com.urbanairship.job.AndroidJobService app called jobFinished
While you are doing that, I will see if we can do a better job recovering if something cancels our upload job.

Thanks so much, let me try that.

harishrpatel commented 3 years ago

@rlepinski I tried all the things you asked above, but no luck. I emailed you output of adb command response.

Seems like Airship is the only component that is using Job Scheduler.
Could there be some constraint blocking these jobs to be queued?
Are there any more verbose settings in SDK that can run with?

Thanks.

rlepinski commented 3 years ago

For anyone with the same problem, this was related to JobService not working for instant apps on Android O+. We moved to work manager in 14.2.0 for better foreground job scheduling and we will now schedule an event upload as soon as the app moves to the background.

urbanairship / android-library

Analytics.addEvent() intermittently does not post all custom events #169

Preliminary Info

What Airship dependencies are you using?

What are the versions of any relevant development tools you are using?

Report

What unexpected behavior are you seeing?

What is the expected behavior?

What are the steps to reproduce the unexpected behavior?

Do you have logging for the issue?