onRestore not invoked for my custom BackupAgent

Question

There are some data in my Android app that I would like to backup and restore. For that purpose I have created a custom implementation of BackupAgent.

In my manifest in have included the backup agent as you can see below

<manifest xmlns:android="http://schemas.android.com/apk/res/android"
    android:installLocation="auto"
    package="com.myapp"
    android:versionCode="14"
    android:versionName="1.13" >

    <application
        android:backupAgent="com.myapp.MyBackupAgent">

        <meta-data
            android:name="com.google.android.backup.api_key"
            android:value="my key" />

I have included the backup service api key, although I am testing with the emulator (Android 2.2) and it should not be necessary, because it uses the local backup transport.

In order to do the test of the backup and restore I have done the following:

• Start the emulator with my application installed.

• Enable backup

  adb shell bmgr enable true

• Call the part of my code were the dataChanged method in the BackupManager class is called.

• Initiate manually the backup operation

  adb shell bmgr run

• Checked in the log that the onBackup method of my custom BackupAgent was called.

• Uninstall the app
• Reinstall the app
• Check in the log if the onRestore method is called.

The thing is that the onRestore method does not seem to be called and I don't know why. After reinstalling the app or manually triggering the restore with adb I see the following in the console.

$adb shell bmgr restore com.myapp
restoreStarting: 2 packages
restoreFinished: 0
done

and this other in the log

D/AndroidRuntime( 8259):
D/AndroidRuntime( 8259): >>>>>>>>>>>>>> AndroidRuntime START <<<<<<<<<<<<<<
D/AndroidRuntime( 8259): CheckJNI is ON
D/AndroidRuntime( 8259): --- registering native functions ---
D/BackupManagerService(   59): MSG_RUN_RESTORE observer=android.app.backup.IRestoreObserver$Stub$Proxy@450e16a8
V/LocalTransport(   59): start restore 1
V/LocalTransport(   59):   nextRestorePackage() = @pm@
V/LocalTransport(   59):   getRestoreData() found 7 key files
V/LocalTransport(   59):     ... key=com.android.providers.settings size=1208
V/LocalTransport(   59):     ... key=com.myapp size=501
V/LocalTransport(   59):     ... key=android size=1208
V/LocalTransport(   59):     ... key=com.android.providers.userdictionary size=1208
V/LocalTransport(   59):     ... key=com.android.browser size=1208
V/LocalTransport(   59):     ... key=com.android.inputmethod.latin size=1208
V/LocalTransport(   59):     ... key=@meta@ size=11
V/LocalTransport(   59):   no more packages to restore
V/LocalTransport(   59): finishRestore()
V/LocalTransport(   59): finishRestore()
D/AndroidRuntime( 8259): Shutting down VM

but I don't see that the call to onRestore is actually made (I have some logging statements just at the beginning of it?

Has this ever happen to you? Is there any reason by the onRestore method is not called, even in the onBackup was called?

Answer 1

In my experience, for some odd reason (which I have yet to identify), logging statements made in BackupAgents don't show up in the logs. Nonetheless, I have been able to confirm that the onRestore method is in fact properly run.

In your question you indicate that the onRestore method "does not seem to be called" because you are unable to see the proper logs. Can you instead confirm that the result is failing (i.e. that data that should be properly restored isn't)?

Answer 2

I had this problem and the root cause was that I had a bug in my onBackup preventing it from completing, so onBackup was called but onRestore was not. Fixing the exception in onBackup caused onRestore to be called.

Also Log messages in onBackup and onRestore do show up in the logs. If you set a log filter on the tag "backup" and use something with backup in it for your log tag. You will see logging from the system and yours. Here is what I get

09-08 17:06:56.581      294-352/system_process V/BackupServiceBinder﹕ doBackup() invoked
09-08 17:06:56.591      294-352/system_process D/PerformBackupTask﹕ starting agent for backup of BackupRequest{pkg=android}
09-08 17:06:56.591      294-352/system_process D/BackupManagerService﹕ awaiting agent for ApplicationInfo{40d5efc0 android}
09-08 17:06:56.591      294-308/system_process D/BackupManagerService﹕ agentConnected pkg=android agent=android.app.backup.BackupAgent$BackupServiceBinder@4112a228
09-08 17:06:56.601      294-352/system_process V/BackupServiceBinder﹕ doBackup() invoked
09-08 17:06:56.601      294-352/system_process D/BackupHelperDispatcher﹕ handling existing helper 'wallpaper' android.app.backup.WallpaperBackupHelper@41149150
09-08 17:06:56.621      294-352/system_process D/PerformBackupTask﹕ starting agent for backup of BackupRequest{pkg=com.catglo.sellpr}
09-08 17:06:56.661      294-352/system_process D/BackupManagerService﹕ awaiting agent for ApplicationInfo{41074748 com.catglo.sellpr}
09-08 17:06:56.781      294-514/system_process D/BackupManagerService﹕ agentConnected pkg=com.catglo.sellpr agent=android.os.BinderProxy@410768c8
09-08 17:06:56.791    2263-2274/com.catglo.sellpr V/BackupServiceBinder﹕ doBackup() invoked
09-08 17:06:56.791    2263-2274/com.catglo.sellpr I/backup﹕ onBackup called
09-08 17:06:57.251      294-352/system_process I/PerformBackupTask﹕ Backup pass finished.

in the above log com.catglo.sellpr is from my app and the line that reads com.catglo.sellpr I/backup﹕ onBackup called is the log message in my code. For the onRestore I get

09-08 17:13:34.431      294-352/system_process D/BackupManagerService﹕ MSG_RUN_RESTORE observer=android.app.backup.IRestoreObserver$Stub$Proxy@413132c0
09-08 17:13:34.511      294-352/system_process V/BackupServiceBinder﹕ doRestore() invoked
09-08 17:13:34.561      294-352/system_process D/BackupManagerService﹕ awaiting agent for ApplicationInfo{41074748 com.catglo.sellpr}
09-08 17:13:34.561      294-427/system_process D/BackupManagerService﹕ agentConnected pkg=com.catglo.sellpr agent=android.os.BinderProxy@41127ee0
09-08 17:13:34.571    2263-2276/com.catglo.sellpr V/BackupServiceBinder﹕ doRestore() invoked
09-08 17:13:34.571    2263-2276/com.catglo.sellpr I/backup﹕ onRestore called

Earlier I had an exception in onBackup and my log from onRestore was never called but the system messages related to restore were.

The app will not Force Close because of an exception in the backup.