TransferService causes ForegroundServiceDidNotStartInTimeException

[yaroslav-v]

Before opening, please confirm:

• [X] I have searched for duplicate or closed issues and discussions.

Language and Async Model

Java

Amplify Categories

Authentication, Storage

Gradle script dependencies

implementation "com.amplifyframework:core:1.36.4"
implementation "com.amplifyframework:aws-storage-s3:1.36.4"
implementation "com.amplifyframework:aws-auth-cognito:1.36.4"

Environment information

------------------------------------------------------------
Gradle 7.0.2
------------------------------------------------------------

Build time:   2021-05-14 12:02:31 UTC
Revision:     1ef1b260d39daacbf9357f9d8594a8a743e2152e

Kotlin:       1.4.31
Groovy:       3.0.7
Ant:          Apache Ant(TM) version 1.10.9 compiled on September 27 2020
JVM:          1.8.0_301 (Oracle Corporation 25.301-b09)
OS:           Mac OS X 10.16 x86_64

Please include any relevant guides or documentation you're referencing

No response

Describe the bug

Hi!

One of the latest versions 1.36.4 causes fatal exceptions. The cause is obvious from the crash description - Context.startForegroundService() did not then call Service.startForeground() ... com.amazonaws.mobileconnectors.s3.transferutility.TransferService

ActivityThread.java line 2147
android.app.ActivityThread.throwRemoteServiceException

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{2637b1f u0 com.example.package/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}

We've observed the crash on Android 9, 11, 12.

And the following list of devices at the moment: Galaxy S20+ 5G Galaxy A13 5G Galaxy A13 Galaxy S10 moto g stylus 5G (2022) Lenovo Tab M10 (FHD) Galaxy A12

We've reverted back to one the previous versions for now, so actually there might be more of them. The data is obtained from Firebase crash reports.

Reproduction steps (if applicable)

Use amplifyframework v1.36.4

Code Snippet

// Initialization in Application class

LogFactory.setLevel(LogFactory.Level.OFF);

Amplify.addPlugin(new AWSCognitoAuthPlugin());
Amplify.addPlugin(new AWSS3StoragePlugin());

AmplifyConfiguration amplifyConfig = AmplifyConfiguration.builder(context)
		.devMenuEnabled(false)
		.build();
Amplify.configure(amplifyConfig, context);



// Uploading, somewhere in the app

DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ssZ", Locale.US);
dateFormat.setTimeZone(TimeZone.getTimeZone("UTC"));

Map<String, String> metadata = new ArrayMap<>(4);
metadata.put("date", dateFormat.format(date));
metadata.put("token", authToken);

StorageUploadFileOptions options =
		StorageUploadFileOptions.builder()
				.accessLevel(StorageAccessLevel.PUBLIC)
				.contentType(mimeType)
				.metadata(metadata)
				.build();

Amplify.Storage.uploadFile(
		"gl_" + new Date().getTime() + "_" + fileName,
		file,
		options,
		result -> {
			// write success logs
		},
		failure -> {
			// write failure logs
		}
);

Log output

for Android 12

ActivityThread.java line 2147
android.app.ActivityThread.throwRemoteServiceException

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{2637b1f u0 com.example.package/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}

android.app.ActivityThread.throwRemoteServiceException (ActivityThread.java:2147)
android.app.ActivityThread.access$2900 (ActivityThread.java:310)
android.app.ActivityThread$H.handleMessage (ActivityThread.java:2376)
android.os.Handler.dispatchMessage (Handler.java:106)
android.os.Looper.loopOnce (Looper.java:226)
android.os.Looper.loop (Looper.java:313)
android.app.ActivityThread.main (ActivityThread.java:8663)
java.lang.reflect.Method.invoke (Method.java)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:567)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1135)

-----

for Android 9

ActivityThread.java line 1749
android.app.ActivityThread$H.handleMessage

Fatal Exception: android.app.RemoteServiceException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{ca31769 u0 com.example.package/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}

android.app.ActivityThread$H.handleMessage (ActivityThread.java:1749)
android.os.Handler.dispatchMessage (Handler.java:106)
android.os.Looper.loop (Looper.java:193)
android.app.ActivityThread.main (ActivityThread.java:6758)
java.lang.reflect.Method.invoke (Method.java)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:493)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:858)

amplifyconfiguration.json

No response

GraphQL Schema

// Put your schema below this line

Additional information and screenshots

No response

[yaroslav-v]

I can confirm that crashes keep coming for this version on Android 8+ (including Android 8, 9, 11, 12) and a wide range of devices (including Samsung, Motorola, Lenovo, ZTE, Wiko etc.)

[tylerjroach]

Hi @yaroslav-v, please upgrade to Amplify 1.36.5. After releasing 1.36.4 on July 26, we observed the crash internally and through a customer report on July 27. We released a hotfix (1.36.5) on July 28 to resolve the issue. If you see any issues on Amplify 1.36.5, please report back.

[cmllamosas]

@tylerjroach

I got the same issue reported here with amplifyframework v1.36.5

Error

RemoteServiceException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{faf28c2 u0 com.example.package/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}

Code Snippet

val options = StorageDownloadFileOptions.builder()
    .accessLevel(StorageAccessLevel.PRIVATE)
    .build()
val file = File("${applicationContext().filesDir}/${image}")
Amplify.Storage.downloadFile(
    "DownloadImage",
    file,
    options,
    {
        Log.i("DownloadImage", "Successfully downloaded: ${it.file.name}")
    },
    {
        Log.e("DownloadImage",  "Download Failure", it)
    }
)

[tylerjroach]

@cmllamosas

Are you seeing this in a release, or possibly debugging with breakpoints?

The Android OS has a requirement that when startForegroundService() is called, startForeground() must be called within the next 5 seconds. While debugging, this could happen by slowing down the app or having breakpoints set. The initial crash was determined to be an if block that would result in startForeground() sometimes not getting called.

If the above scenario is not the case, can you run ./gradlew :app:dependencies and ensure that com.amazonaws:aws-android-sdk-s3:2.50.1 is being used, and not an older version.

Any information that can be provided will help us. What device and OS version are you seeing this with?

[cmllamosas]

@tylerjroach

Information about device and OS

I made a release build apk and then I tried it in the following device

========================================= Let me check about ./gradlew :app:dependencies

[cmllamosas]

@tylerjroach

It seems that we are using that version com.amazonaws:aws-android-sdk-s3:2.50.1

[sdhuka]

@cmllamosas Thanks for your prompt response!

Could you please also confirm following as we look further into the issue:

1. frequency of this crash and also whether it is easily reproable on your device?
2. Your app version 0.10.0 represents the version with latest amplify release?

[cmllamosas]

@sdhuka

1.- 100% times 2.- Yes, 0.10.0 represents the version with latest amplify release

[tylerjroach]

@cmllamosas

Thank you, again, for your prompt response!

• What targetSdkVersion is the app using?
• Where are you starting the upload process? (Ex: Activity, Service)?
• Are you seeing this after starting a single download, or starting multiple at the same time?
• Are you doing anything to try and hide the Foreground Notification by stopping TransferService yourself?
• Is there any chance your application is removing the FOREGROUND_PERMISSION? I am able to replicate this crash if I remove FOREGROUND_SERVICE from the application. Ex: <uses-permission android:name="android.permission.FOREGROUND_SERVICE" tools:node="remove" />

An easy way to check to see if Foreground permission is allowed in the application is to go to Settings -> Apps & Notificat ions -> {Your Application} -> Permissions -> All Permissions (Found in 3 dot menu on top right) -> and you should see "run foreground service" under "Other app capabilities.

Once again, thank you for response. As soon as we can replicate this, we will work to identify a fix.

[yaroslav-v]

@tylerjroach Hi! Thx for the reply.

I've tried to do some tests with v1.36.5 locally and it looks good. I haven't been able to reproduce the issue with the production build yet. However, it's occurred once while I've been playing with the debug build.

Not sure if you need it, but here are some answers to your questions above:

• targetSdkVersion = 30
• from an extension of androidx.work.Worker, normally in the background
• hard to say exactly, because uploading is triggered by some events. However, normally there shouldn't be many of them at the same time
• nope
• nope, we use FOREGROUND_SERVICE too

[yaroslav-v]

It might be important to mention that in this case the system shut down VM - AndroidRuntime: Shutting down VM

Here is the crash log:

2022-08-03 10:00:21.273 1380-1380/com.example.package I/UploadWorker: [main] AWS capture uploaded: cpt_1659513617339.jpg
2022-08-03 10:00:21.486 1380-1380/com.example.package D/AndroidRuntime: Shutting down VM
2022-08-03 10:00:21.528 1380-1380/com.example.package E/AndroidRuntime: FATAL EXCEPTION: main
    Process: com.example.package, PID: 1380
    android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{4a5d341 u0 com.example.package/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}
        at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1923)
        at android.app.ActivityThread.access$2700(ActivityThread.java:247)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2148)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loopOnce(Looper.java:201)
        at android.os.Looper.loop(Looper.java:288)
        at android.app.ActivityThread.main(ActivityThread.java:7839)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1003)

[tylerjroach]

@yaroslav-v Thank you for the provided details.

From the 1.36.4 release, to the 1.36.5 release, we made a change that we are confident should reduce the instances of this crash. In 1.36.4, we were only calling startForeground after startForegroundService if the service was not already running in the foreground. This was done to try and prevent flickering of the foreground notification. Unfortunately, even if the service was already running in the foreground, the startForeground call was found to be necessary on some devices.

This change doesn't entirely remove the possibility of this crash. There are many reports in Google's Issue Tracker that this crash can happen periodically: https://issuetracker.google.com/issues/76112072, especially when the device is slowed down.

While using the debug build, was your phone connected to the computer? If so, LogCat, profiler, etc could be slowing down the phone enough to cause this crash. It would be even more likely if you had a debug breakpoint set.

After reading further possibilities of the cause in the IssueTracker, this crash can also be cause if stopService(Intent(context, TransferService::class.java) is called before startForeground is called. I have not been able to repeat it, but this could possibly happen if startForegroundService is called due to a call to Amplify.Storage.downloadFile or Amplify.Storage.uploadFile, but before the TransferService receives the onStartCommand to call startForeground`, all other transfers complete and the service is stopped.

@cmllamosas, Since you are reporting 100% crash rate on initiating a transfer, can you please confirm the permission isn't getting removed, or that you aren't manually calling stopService(Intent(context, TransferService::class.java) immediately after starting a transfer?

[cmllamosas]

@tylerjroach

Yesterday I realized that using targetSdkVersion 33 might be the problem because is still in beta as far as I know ApiLevels, after downgrade targetSdkVersion to version 32 the problem is still present

• What targetSdkVersion is the app using? A: targetSdkVersion: 33 and targetSdkVersion:32
• Where are you starting the upload process? (Ex: Activity, Service)? A: In our case the problem is with Amplify.Storage.downloadFile
• Are you seeing this after starting a single download, or starting multiple at the same time? A: In our case we are using Amplify.Storage.downloadFile We are using the following code

private fun downloadUserImage(image: String, user: User) {
  val options = StorageDownloadFileOptions.builder()
      .accessLevel(StorageAccessLevel.PRIVATE)
      .build()
  val file = File("${applicationContext().filesDir}/${image}")
  Amplify.Storage.downloadFile(
      "DownloadImage",
      file,
      options,
      {
          Log.i("DownloadImage", "Successfully downloaded: ${it.file.name}")
      },
      {
          Log.e("DownloadImage",  "Download Failure", it)
      }
  )
}

• Are you doing anything to try and hide the Foreground Notification by stopping TransferService yourself? A: I was searching if there is something related, I think It doesn't exist anything for that

• Is there any chance your application is removing the FOREGROUND_PERMISSION? I am able to replicate this crash if I remove FOREGROUND_SERVICE from the application. Ex: A: I don't have any permission defined for "FOREGROUND_SERVICE"

Note*: In my test the image doesn't exist

On the other hand I was able to replicate this issue in other device.

Error

More information

[tylerjroach]

@cmllamosas In the image you attached, please select the "3-dot" icon on the top right. You should then have a menu item to click for "All permissions". Please report back with that screenshot.

[cmllamosas]

@tylerjroach sorry about that, these are all the permissions

About this comment

or that you aren't manually calling stopService(Intent(context, TransferService::class.java) immediately after starting a transfer?

I was looking for some text in all the project that was related but I didn't found anything

[tylerjroach]

@cmllamosas I see that you have "run foreground service" permission so that speculated cause is not the issue. Earlier you had responded that the crash happens 100% of the time. Does this mean that you are seeing a crash every time you make a call to Amplify.Storage.downloadFile()?

Are you seeing any message in onError of this call before the crash? ex: Log.e("DownloadImage", "Download Failure", it)

[cmllamosas]

@tylerjroach I will back with you when I have more information

[cmllamosas]

@tylerjroach

Before the crash, the file was not found (because in this use case the user didn't have image profile, that's why it returns this error but it never crash the application)

I hope this log help.

2022-08-03 13:38:10.138 31242-31558/com.example.app D/AWSMobileClient: Inspecting user state details
2022-08-03 13:38:10.152 31242-31558/com.example.app D/AWSMobileClient: hasFederatedToken: true provider: cognito-idp.us-east-1.amazonaws.com/us-east-1_......
2022-08-03 13:38:10.152 31242-31558/com.example.app D/AWSMobileClient: waitForSignIn: userState:SIGNED_IN
2022-08-03 13:38:10.152 31242-31558/com.example.app D/AWSMobileClient: getCredentials: Validated user is signed-in
2022-08-03 13:38:53.620 31242-31242/com.example.app E/DownloadUserImage: Download Failure
    StorageException{message=Something went wrong with your AWS S3 Storage download file operation, cause=com.amazonaws.services.s3.model.AmazonS3Exception: The specified key does not exist. (Service: Amazon S3; Status Code: 404; Error Code: NoSuchKey; Request ID: YMNCSHWHTM48ETGG), S3 Extended Request ID: ya169S0OcmXlgWCqajtprDghREVD/PNfre6iyhqzirmi0Qfrcsv+MYhP5AGRhZieXqDHaBdJPCo=, recoverySuggestion=See attached exception for more information and suggestions}
        at com.amplifyframework.storage.s3.operation.AWSS3StorageDownloadFileOperation$DownloadTransferListener.onError(AWSS3StorageDownloadFileOperation.java:188)
        at com.amazonaws.mobileconnectors.s3.transferutility.TransferStatusUpdater$4.run(TransferStatusUpdater.java:333)
        at android.os.Handler.handleCallback(Handler.java:883)
        at android.os.Handler.dispatchMessage(Handler.java:100)
        at android.os.Looper.loop(Looper.java:214)
        at android.app.ActivityThread.main(ActivityThread.java:7356)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)
     Caused by: com.amazonaws.services.s3.model.AmazonS3Exception: The specified key does not exist. (Service: Amazon S3; Status Code: 404; Error Code: NoSuchKey; Request ID: YMNCSHWHTM48ETGG), S3 Extended Request ID: ya169S0OcmXlgWCqajtprDghREVD/PNfre6iyhqzirmi0Qfrcsv+MYhP5AGRhZieXqDHaBdJPCo=
        at com.amazonaws.http.AmazonHttpClient.handleErrorResponse(AmazonHttpClient.java:742)
        at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:420)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:229)
        at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:4829)
        at com.amazonaws.services.s3.AmazonS3Client.getObject(AmazonS3Client.java:1585)
        at com.amazonaws.mobileconnectors.s3.transferutility.DownloadTask.call(DownloadTask.java:102)
        at com.amazonaws.mobileconnectors.s3.transferutility.DownloadTask.call(DownloadTask.java:42)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        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)
2022-08-03 13:39:16.112 31242-31242/com.example.app D/AndroidRuntime: Shutting down VM
    
    
    --------- beginning of crash
2022-08-03 13:39:16.113 31242-31242/com.example.app E/AndroidRuntime: FATAL EXCEPTION: main
    Process: com.example.app, PID: 31242
    android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{c5bb90a u0 com.example.app/com.amazonaws.mobileconnectors.s3.transferutility.TransferService}
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1945)
        at android.os.Handler.dispatchMessage(Handler.java:107)
        at android.os.Looper.loop(Looper.java:214)
        at android.app.ActivityThread.main(ActivityThread.java:7356)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)
2022-08-03 13:39:16.168 31242-31242/com.example.app I/Process: Sending signal. PID: 31242 SIG: 9
2022-08-03 13:39:16.326 32179-32179/? I/ample:app Late-enabling -Xcheck:jni
2022-08-03 13:39:16.343 32179-32179/? E/ample:app Unknown bits set in runtime_flags: 0x8000

[tylerjroach]

Editing this message, sorry for the confusion. I thought that I could replicate this error by providing a download with a non-existent key, however, I had left in a line to manually stopService in my test app that was instead forcing the crash..

@cmllamosas Could you enable logging on Amplify and also our S3 SDK? Seeing a crash report along with the logs should help us identify the sequence causing the crash.

Ex: in your Amplify configuration code, please add the lines below in your debug build:

Amplify.addPlugin(JavaLoggingPlugin(LogLevel.VERBOSE)) // above your Amplify.configure
Amplify.configure(applicationContext)
LogFactory.setLevel(LogFactory.Level.ALL) // below your Amplify.configure

[cmllamosas]

@tylerjroach for S3 SDK the following lines will work too?

Amplify.addPlugin(JavaLoggingPlugin(LogLevel.VERBOSE)) // above your Amplify.configure
Amplify.configure(applicationContext)
LogFactory.setLevel(LogFactory.Level.ALL) // below your Amplify.configure

Plz tell me when you download my log to erase it.

[tylerjroach]

@cmllamosas Downloaded. I'll folllow-up after review.

[tylerjroach]

@cmllamosas I can see 2 instances where TransferService is being moved to the foreground and then stopped. A pdf download and a failed image download. If there were any more transfer requests than those two, then we may be close to identifying the issue. If it were only those two transfer requests, it's difficult to see the reason for the crash, as I can point to 2 calls to us calling startForeground, and 2 service stops.

Would you be willing to join our discord (https://discord.com/invite/amplify) and reach out to me there? Maybe we can set up a Video chat where we can take a look at your specific setup and see what we can discover.

@yaroslav-v, let me know if you see the crash again, or if the reason for the crash you observed may be debug app related as discussed.

[yaroslav-v]

@tylerjroach Sure. I'll keep my finger on the pulse when we release an update with the latest Amplify version.

Btw I've tested it locally a little bit longer and was able to reproduce the issue once with the release build. Looks like it may happen when we start multiple simultaneous requests. However, it happened only once and there are no distinct steps to reproduce, so...

[tylerjroach]

@yaroslav-v Thank you for the update.

I believe you may be running into a scenario where startForegroundService is called on the TransferService. This should trigger TransferService.onStartCommand, which calls the required startForeground method. In the time it takes to move from startForegroundService to startForeground, it is possible that all existing transfers complete between that time, and stopForeground ends up being called.

This is a case we will be working on a fix for.

We have a call scheduled with @cmllamosas today to research if he is running into a different scenario.

[tylerjroach]

@yaroslav-v Are these transfers you are initiating downloadFile, uploadFile, or uploadInputStream, or a combination of multiple transfer types? If you would like to talk more synchronously about the instances of the crash that you are seeing, I would love to continue chatting on our Discord (https://discord.com/invite/amplify).

[yaroslav-v]

Hi! Sure, I'll get in touch.

We use uploadFile calls only.

[tylerjroach]

Hi @yaroslav-v and @cmllamosas, Amplify Android 1.37.1 has been released. We have reworked how the ForegroundService notification is created and it no longer uses the startForegroundService method that was causing problems. Let us know if this release resolves the problems you were seeing.

[cmllamosas]

@tylerjroach The issue seems to have gone away; I tested on my physical phone, which crashed every time I tried.

Thanks

[tylerjroach]

I am going to go ahead and close the issue since this specific crash should no longer be possible on Amplify Android 1.37.1. @yaroslav-v, Please reach back out if you experience any issues with the upgrade.

[github-actions[bot]]

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see. If you need more assistance, please either tag a team member or open a new issue that references this one. If you wish to keep having a conversation with other community members under this issue feel free to do so.