idevicebackup restore fails (iPhone 3GS 3.1.3 not jailbroken)
Reported by aubin | June 30th, 2010 @ 04:48 AM | in 1.2.0 Release
I have compiled libimobiledevice, usbmuxd, libusb-1.0.8 and
libplist from sources. the rest of the requirements for
libimobiledevice were installed from suse 11.2 development
packages. libimobiledevice, and usbmuxd are latest git, as is
libplist. libusb is from latest 1.0.8 src bz2ball download.
idevicebackup backup proceeded successfully, creating a directory full of backup information. then i deleted some nonessential items from the phone and tried to do a restore. it restored all the files but failed to restore the first application it tried. attached is the restore log from running idevicebackup with the -d option for debug verbosity (libimobiledevice and associated tools were compiled with debug code enabled)
here's the tail end of the restore log output (the full restore file is 300M (!) and even bzip2 only got it down to 178 (!!) so it will not attach here...
Restored 1397 files on device.
Restoring Application com.rockpocketgames.thepackage 1/29
(3%)...21:22:46 property_list_service.c:142 internal_plist_send():
sending 1414 bytes
21:22:46 property_list_service.c:147 internal_plist_send(): sent
1414 bytes
21:22:46 property_list_service.c:148 internal_plist_send():
printing 2634 bytes plist:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN"
"http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<string>DLMessageProcessMessage</string>
<dict>
<key>AppInfo</key>
<dict>
<key>CFBundleVersion</key>
<string>1.04</string>
<key>UIInterfaceOrientation</key>
<string>UIInterfaceOrientationLandscapeRight</string>
<key>EnvironmentVariables</key>
<dict>
<key>CFFIXED_USER_HOME</key>
<string>/private/var/mobile/Applications/398A24E2-3B73-4D7E-A631-528649774AB4</string>
<key>HOME</key>
<string>/private/var/mobile/Applications/398A24E2-3B73-4D7E-A631-528649774AB4</string>
<key>TMPDIR</key>
<string>/private/var/mobile/Applications/398A24E2-3B73-4D7E-A631-528649774AB4/tmp</string>
</dict>
<key>CFBundleIdentifier</key>
<key>com.rockpocketgames.thepackage</key>
<key>ApplicationType</key>
<string>User</string>
<key>Container</key>
<string>/private/var/mobile/Applications/398A24E2-3B73-4D7E-A631-528649774AB4</string>
<key>SignerIdentity</key>
<string>Apple iPhone OS Application Signing</string>
<key>DTSDKName</key>
<string>iphoneos3.0</string>
<key>UIStatusBarHidden</key>
<true/>
<key>UIStatusBarStyle</key>
<string>UIStatusBarStyleDefault</string>
<key>MinimumOSVersion</key>
<string>3.0</string>
<key>CFBundleDevelopmentRegion</key>
<string>en</string>
<key>ApplicationDSID</key>
<integer>56076616</integer>
<key>DTPlatformVersion</key>
<string>3.2</string>
<key>CFBundleResourceSpecification</key>
<string>ResourceRules.plist</string>
<key>CFBundlePackageType</key>
<string>APPL</string>
<key>CFBundleName</key>
<string>thepackage</string>
<key>Path</key>
<string>/private/var/mobile/Applications/398A24E2-3B73-4D7E-A631-528649774AB4/thepackage.app</string>
<key>CFBundleIconFile</key>
<string>Icon.png</string>
<key>UIRequiresPersistentWiFi</key>
<false/>
<key>CFBundleExecutable</key>
<string>thepackage</string>
<key>DTPlatformName</key>
<string>iphoneos</string>
<key>UIPrerenderedIcon</key>
<true/>
<key>CFBundleInfoDictionaryVersion</key>
<string>6.0</string>
<key>CFBundleSupportedPlatforms</key>
<array>
<string>iPhoneOS</string>
</array>
<key>UIDeviceFamily</key>
<array>
<integer>1</integer>
</array>
<key>CFBundleDisplayName</key>
<string>thepackage</string>
<key>LSRequiresIPhoneOS</key>
<true/>
</dict>
<key>BackupMessageTypeKey</key>
<string>BackupMessageRestoreApplicationSent</string>
</dict>
21:22:47 notification_proxy.c:44 np_lock(): NP: Locked
21:22:48 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:48 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:48 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:48 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:49 notification_proxy.c:44 np_lock(): NP: Locked
21:22:49 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:49 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:49 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:49 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:50 notification_proxy.c:44 np_lock(): NP: Locked
21:22:51 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:51 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:51 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:51 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:52 notification_proxy.c:44 np_lock(): NP: Locked
21:22:52 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:52 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:52 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:52 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:53 notification_proxy.c:44 np_lock(): NP: Locked
21:22:54 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:54 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:54 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:54 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:55 notification_proxy.c:44 np_lock(): NP: Locked
21:22:55 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:55 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:55 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:55 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:56 notification_proxy.c:44 np_lock(): NP: Locked
21:22:56 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:56 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
ERROR: Failed to receive an ack from the device for this
application due to error -3. Aborting...
Failed to restore applications.
Restore Failed.
21:22:56 notification_proxy.c:138 np_client_free(): joining np
callback
21:22:57 property_list_service.c:224
internal_plist_receive_timeout(): initial read=0
21:22:57 property_list_service.c:226
internal_plist_receive_timeout(): initial read failed!
21:22:57 notification_proxy.c:276 np_get_notification():
NotificationProxy: no notification received!
21:22:57 notification_proxy.c:55 np_unlock(): NP: Unlocked
21:22:58 property_list_service.c:142 internal_plist_send(): sending
104 bytes
21:22:58 property_list_service.c:147 internal_plist_send(): sent
104 bytes
21:22:58 property_list_service.c:148 internal_plist_send():
printing 289 bytes plist:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN"
"http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<string>DLMessageDisconnect</string>
<string>All done, thanks for the memories</string>
and the syslog on the idevice at the time of the failure, added:
Jun 29 20:51:59 unknown /usr/libexec/notification_proxy[56] :
Could not receive size of message
Tue Jun 29 20:51:59 unknown /usr/libexec/notification_proxy[56] :
Could not receive message
Jun 29 20:52:03 unknown /usr/libexec/BackupAgent[58] : 58:8445952|SocketStreamHandler.c:SocketLogCallback| ERROR: SocketSend (data): error 32: Broken pipe Tue Jun 29 20:52:03 unknown /usr/libexec/BackupAgent[58] : 58:8445952|StreamHandler.c:WriteFunc| ERROR: Error sending data: Can't send data
Tue Jun 29 20:52:03 unknown /usr/libexec/BackupAgent[58] : 58:8445952|DeviceLinkConnection.c:_DLSendDataAndDisconnectOnError| ERROR: Could not send data: 'Error writing data'
Tue Jun 29 20:52:03 unknown SpringBoard[38] : Reloading and rendering all application icons.
Tue Jun 29 20:52:04 unknown SpringBoard[38] : SB RESTORE: SBRestoreEnded
Tue Jun 29 20:52:04 unknown SpringBoard[38] : SB RESTORE: didEndRestoring 1
Tue Jun 29 20:52:06 unknown CommCenter[28] : QUIT received. Setting flag to shut down.\n
it appears as if the device was simply unplugged, but it was not - the restore process fails at the same point each time - it is able to ALWAYS restore 1397 files and NEVER restore the first application. for some reason, when an application restore is attempted, BackupAgent fails to receive the size of the message and bails.
I hope this can help you guys figure out what's up - this project is amazing and if I could get restore fully working I'd be a happy camper. :) (not that i'm not already - fantastic work!)
-a
Comments and changes to this ticket
-
aubin June 30th, 2010 @ 07:43 AM
doing it a few more times i noticed it wasn't always the same app that failed. maybe i can just increase a timeout somewhere? I don't know the code well (yet...) but it seems odd that sometimes a reply message would come and sometimes it wouldn't...
-
aubin June 30th, 2010 @ 07:54 AM
just tried a different usb cable/case - so it's not that. first runs were with stock apple cable - now device is inside a mophie juice pack air which connects to computer with micro-usb... - same behavior
-
Martin S. June 30th, 2010 @ 10:09 AM
- Milestone set to “1.2.0 Release”
- State changed from “new” to “open”
- Milestone order changed from “190869” to “0”
Thanks, this is a nice report you did here with exactly the information we need!
My guess would be that the installation of the application which is triggered by sending the AppInfo plist takes longer than our timeout to read a response from the device.
So once our receive timeout (3500ms) runs out, we get no ACK and the restore aborts, but the device will apparently still attempt to send the ACK later and that would explain the BrokenPipe error seen in the device syslog.
In order to test if we can fix it we need to implement handling the "com.apple.mobile.application_installed" notification and only then proceed at reading the ACK once we got it.
Fortunately this was already marked as a TODO to be implemented. Just needs someone to take a shot at it. :)
-
Martin S. March 26th, 2011 @ 10:10 AM
- Tag changed from “restore mode, idevicebackup, iphone3gs” to “iphone 3gs, restore mode, idevicebackup, notification_proxy, timeout”
I think this is related to Notification Proxy timing out too soon. A similar issue can be seen for huge application files in ideviceinstaller.
Please Sign in or create a free account to add a new ticket.
With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.
Create new ticket
Create your profile
Help contribute to this project by taking a few moments to create your personal profile. Create your profile ยป
A project around supporting the iPhone in Linux.
See http://libimobiledevice.org
aubin
Martin S.