Export to GitHub

android-developer-preview - issue #2272

PFTBT : Error -1002 backing up


Posted on Jun 4, 2015 by Happy Monkey

* Which version of the SDK are you using?

SDK Manager's About box reports 24.3.

* Which Android build are you using? (e.g. MPZ44Q)

MPZ44Q

* What device are you using?

Nexus 5

* What steps will reproduce the problem? (Please provide the minimal reproducible test case.)

Enable backups via Settings > Backup and reset.

Then, following the documentation (http://developer.android.com/preview/backup/index.html), run:

adb shell bmgr run

then:

adb shell bmgr fullbackup <PACKAGE>

for an application that has run and has data in internal storage.

* What is the expected output?

No output, but for a backup to happen.

* What do you see instead?

In LogCat, we get:

06-04 09:29:56.702 2321 2333 I GmsBackupTransport: Attempt to do full backup on com.commonsware.android.frw 06-04 09:29:56.714 1385 1385 V GLSActivity: AuthDelegateWrapperCreated with selected intent: Intent { cmp=com.google.android.gms/.auth.DefaultAuthDelegateService } 06-04 09:29:56.731 1385 2652 I GLSUser : [GLSUser] getTokenFromCache: [account: <ELLIDED:29678>, callingPkg: com.google.android.gms, service: android] 06-04 09:29:56.740 2321 2333 V GmsBackupTransport: create full backup for : com.commonsware.android.frw 06-04 09:29:56.750 2321 20463 V GmsBackupTransport: Start scotty uploading. 06-04 09:29:56.751 753 20464 D BackupManagerService: Binding to full backup agent : com.commonsware.android.frw 06-04 09:29:56.760 753 20464 I ActivityManager: Start proc 20467:com.commonsware.android.frw/u0a89 for backup android/FullBackupAgent 06-04 09:29:56.760 753 20464 D BackupManagerService: awaiting agent for ApplicationInfo{3320de7 com.commonsware.android.frw} 06-04 09:29:56.762 20467 20467 I art : Late-enabling -Xcheck:jni 06-04 09:29:56.780 20467 20473 I art : Debugger is no longer active 06-04 09:29:56.791 753 1873 D BackupManagerService: agentConnected pkg=com.commonsware.android.frw agent=android.os.BinderProxy@6fb50f3 06-04 09:29:56.796 753 1194 D VoldConnector: SND -> {36 volume mkdirs /storage/emulated/0/Android/data/com.commonsware.android.frw/files/} 06-04 09:29:56.798 753 852 D VoldConnector: RCV <- {200 36 Command succeeded} 06-04 09:29:56.803 20467 20467 I Process : Sending signal. PID: 20467 SIG: 9 06-04 09:29:56.827 753 1196 I ActivityManager: Process com.commonsware.android.frw (pid 20467) has died 06-04 09:29:56.905 2321 20463 E GmsBackupTransport: Scotty transfer exception. null 06-04 09:29:56.905 753 20461 E PFTBT : Error -1002 backing up com.commonsware.android.frw 06-04 09:29:56.911 753 20461 I PFTBT : Transport suggested backoff=0 06-04 09:29:56.911 20445 20445 D AndroidRuntime: Shutting down VM 06-04 09:29:56.925 20445 20454 I art : Debugger is no longer active

(where com.commonsware.android.frw is <PACKAGE>)

If we attempt to restore via adb shell bmgr restore <PACKAGE>, we get:

Unable to restore package <PACKAGE> done

* Relevant logcat output.

See above.

Comment #1

Posted on Jun 16, 2015 by Swift Elephant

Thank you for reporting this issue. We have passed this on to the development team and will update this issue with more information as it becomes available.

Comment #2

Posted on Jun 16, 2015 by Grumpy Elephant

This is probably due to the transport rejecting the back-up b/c it is too large (over 25MBS) however you can confirm this is the case by turning on verbose logging for the transport component adb shell setprop log.tag.GmsBackupTransport VERBOSE when you attempt the backup pass with adb shell bmgr fullbackup around where the PerformFullTransportBackupTask reports "Error -1002 backing up com.commonsware.android.frw"

there should be a log from GmsBackupTransport will the specifics of why the backup was rejected

Comment #3

Posted on Jun 16, 2015 by Happy Monkey

The problem definitely wasn't data volume -- the test would have been much less than 25MB. It should have been less than 2.5KB.

That being said, I am not able to reproduce the exact symptoms anymore. Perhaps GmsBackupTransport was updated OTA and the problem is now fixed. I am having other problems (data claims to have been restored but does not show up), but I will need to do more experiments and file a fresh issue.

Thanks for your help!

Comment #4

Posted on Jun 16, 2015 by Grumpy Elephant

please reach out to me directly at ...ams@ if you have issues

Comment #5

Posted on Jun 19, 2015 by Happy Rabbit

I encountered the same problem and could get a verbose log entry:

06-19 15:51:10.171 8606-8606/? D/AndroidRuntime﹕ Calling main entry com.android.commands.bmgr.Bmgr 06-19 15:51:10.181 2005-2046/? I/GmsBackupTransport﹕ Attempt to do full backup on com.masrepus.vplanapp 06-19 15:51:10.204 1341-1341/? V/GLSActivity﹕ AuthDelegateWrapperCreated with selected intent: Intent { cmp=com.google.android.gms/.auth.DefaultAuthDelegateService } 06-19 15:51:10.227 1341-1590/? I/GLSUser﹕ [GLSUser] getTokenFromCache: [account: , callingPkg: com.google.android.gms, service: android] 06-19 15:51:10.245 2005-2046/? V/GmsBackupTransport﹕ create full backup for : com.masrepus.vplanapp 06-19 15:51:10.249 772-8628/? D/BackupManagerService﹕ Binding to full backup agent : com.masrepus.vplanapp 06-19 15:51:10.249 2005-8627/? V/GmsBackupTransport﹕ Start scotty uploading. 06-19 15:51:10.252 772-8628/? D/BackupManagerService﹕ awaiting agent for ApplicationInfo{645d867 com.masrepus.vplanapp} 06-19 15:51:10.253 772-20192/? D/BackupManagerService﹕ agentConnected pkg=com.masrepus.vplanapp agent=android.os.BinderProxy@a2fa2b3 06-19 15:51:10.256 7879-7893/com.masrepus.vplanapp V/BackupXmlParserLogging﹕ android:fullBackupContent - found xml resource 06-19 15:51:10.257 7879-7893/com.masrepus.vplanapp V/BackupXmlParserLogging﹕ [ 06-19 15:51:10.257 7879: 7893 V/BackupXmlParserLogging ] ==================================================== 06-19 15:51:10.257 7879-7893/com.masrepus.vplanapp V/BackupXmlParserLogging﹕ Found valid fullBackupContent; parsing xml resource. 06-19 15:51:10.257 7879-7893/com.masrepus.vplanapp V/BackupXmlParserLogging﹕ ==================================================== 06-19 15:51:10.257 7879-7893/? V/BackupXmlParserLogging﹕ [ 06-19 15:51:10.257 7879: 7893 V/BackupXmlParserLogging ] ...parsed /data/data/com.masrepus.vplanapp/databases/timetable.db for domain "database" 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ ...automatically generated /data/data/com.masrepus.vplanapp/databases/timetable.db-journal. Ignore if nonexistant. 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ ...parsed /data/data/com.masrepus.vplanapp/shared_prefs/mPrefs.xml for domain "sharedpref" 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ ...parsed /data/data/com.masrepus.vplanapp/shared_prefs/com.masrepus.vplanapp_preferences.xml for domain "sharedpref" 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ [ 06-19 15:51:10.258 7879: 7893 V/BackupXmlParserLogging ] Xml resource parsing complete. 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ Final tally. 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ Includes: 06-19 15:51:10.258 7879-7893/? V/BackupXmlParserLogging﹕ domain=db 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ /data/data/com.masrepus.vplanapp/databases/timetable.db-journal 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ /data/data/com.masrepus.vplanapp/databases/timetable.db 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ domain=sp 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ /data/data/com.masrepus.vplanapp/shared_prefs/mPrefs.xml 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ /data/data/com.masrepus.vplanapp/shared_prefs/com.masrepus.vplanapp_preferences.xml 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ Excludes: 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ ...nothing to exclude. 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ [ 06-19 15:51:10.259 7879: 7893 V/BackupXmlParserLogging ] ==================================================== 06-19 15:51:10.259 7879-7893/? V/BackupXmlParserLogging﹕ [ 06-19 15:51:10.266 2005: 8626 D/DiffBuilder ] Exception java.io.IOException: Transfer cancelled by framework. at com.google.android.gms.backup.ab.a(SourceFile:154) at com.google.android.gms.backup.b.a.read(SourceFile:41) at com.google.android.gms.backup.b.a.read(SourceFile:35) at com.google.android.gms.backup.b.c.run(SourceFile:56) 06-19 15:51:10.267 7879-7879/? I/Process﹕ Sending signal. PID: 7879 SIG: 9 06-19 15:51:10.272 772-876/? E/WifiStateMachine﹕ WifiLinkLayerStats: my bss beacon rx: 0 RSSI mgmt: 0 BE : rx=0 tx=0 lost=0 retries=0 BK : rx=26 tx=3 lost=6226036 retries=7077985 VI : rx=0 tx=6007 lost=9595 retries=0 VO : rx=0 tx=0 lost=0 retries=0 on_time : 0 tx_time=0 rx_time=0 scan_time=0 06-19 15:51:10.291 772-7271/? I/ActivityManager﹕ Process com.masrepus.vplanapp (pid 7879) has died 06-19 15:51:10.492 2005-8627/? E/GmsBackupTransport﹕ Scotty transfer exception. null 06-19 15:51:10.493 772-8625/? E/PFTBT﹕ Error -1002 backing up com.masrepus.vplanapp 06-19 15:51:10.494 772-8625/? I/PFTBT﹕ Transport suggested backoff=0

Comment #6

Posted on Aug 3, 2015 by Massive Elephant

Issue 2876 has been merged into this issue.

Comment #7

Posted on Oct 21, 2015 by Happy Kangaroo

Hey there -- Android Marshmallow has been released publicly and our M Developer Preview has ended. If you would like to provide feedback on public releases of Android, please file a bug at https://code.google.com/p/android/issues/list. Thanks for helping to make Android better by participating in our preview!

Comment #8

Posted on Oct 28, 2015 by Grumpy Elephant

Can you enable verbose logging in the transport and upload some logs? adb shell setprop log.tag.GmsBackupTransport VERBOSE thanks

Comment #9

Posted on Oct 28, 2015 by Grumpy Rhino

I get the same error with

10-28 22:58:06.980 600-5578/? I/PFTBT: Initiating full-data transport backup of com.myapp.package 10-28 22:58:06.981 7891-14015/? I/GmsBackupTransport: Attempt to do full backup on com.myapp.package 10-28 22:58:06.982 600-5578/? I/PFTBT: Transport rejected backup of com.myapp.package, skipping 10-28 22:58:06.982 600-5578/? I/PFTBT: Full backup completed. 10-28 22:58:06.982 600-610/? D/BackupManagerService: Done with full transport backup.

I tried enable adb shell setprop log.tag.BackupXmlParserLogging VERBOSE and adb shell setprop log.tag.GmsBackupTransport VERBOSE but I don't see any more information in the logcat in Android Studio even if it's set to verbose there. How to see the verbose output?

Comment #10

Posted on Oct 28, 2015 by Grumpy Rhino

After turning backup on and off a few times i get this error instead. How to see the legal text?

10-28 23:45:44.428 1633 1677 V GmsBackupTransport: Rejecting full data backup. user has not seen up to date legal text

I tried rebooting the tablet, but no difference.

Status: PreviousRelease

Labels:
Type-Defect Release-M Defect-21645078