doronz88 / pymobiledevice3

Pure python3 implementation for working with iDevices (iPhone, etc...).
https://discord.gg/52mZGC3JXJ
GNU General Public License v3.0
1.34k stars 186 forks source link

`pymobiledevice3.exceptions.ConnectionTerminatedError` on backup start #1165

Open tcrasset opened 2 weeks ago

tcrasset commented 2 weeks ago

Test environment

❯ pymobiledevice3 usbmux list
[
    {
        "BuildVersion": "20G75",
        "ConnectionType": "USB",
        "DeviceClass": "iPhone",
        "DeviceName": "iPhone",
        "Identifier": "REDACTED",
        "ProductType": "iPhone12,8",
        "ProductVersion": "16.6",
        "UniqueDeviceID": "REDACTED"
    }
]

Describe the bug

I'm getting the following error (cfr logs) as soon as I start the backup process.

I first tried with libimobiledevice's idevicebackup2, and it was able to download a few files at the start, then errored out with error code (-4) indicating a SSL error.

Then, any further attempts crashed immediately with the same error code, it wouldn't backup any other files, whether with the same output directory for an incremental backup, or a brand new one for a fresh start.

Building libimobiledevice from source yielded the same error, and afterward yielded error code -256.

This is why I tried pymobiledevice3 which is more maintained (thanks BTW for that nice package).

I'm suspecting an issue with my openssl version, but not sure.

I know you probably won't be able to reproduce, but could you point me somewhere I could look to see debug?

To Reproduce

pymobiledevice3 backup2 backup --udid REDACTED --verbose ~/Documents/iphoneJadeBackup123

Logs:

  0%|                                                                        | 0/100 [00:05<?, ?it/s]
Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 365, in device_link
    yield dl
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 91, in backup
    dl.dl_loop(progress_callback)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 48, in dl_loop
    message = self.receive_message()
              ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 188, in receive_message
    return self.service.recv_plist()
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 177, in recv_plist
    return parse_plist(self.recv_prefixed(endianity=endianity))
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 147, in recv_prefixed
    size = self.recvall(4)
           ^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 141, in recvall
    raise ConnectionAbortedError()
ConnectionAbortedError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 124, in sendall
    self.socket.sendall(data)
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/ssl.py", line 1273, in sendall
    v = self.send(byte_view[count:])
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/ssl.py", line 1242, in send
    return self._sslobj.write(data)
           ^^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2427)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/bin/pymobiledevice3", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/__main__.py", line 110, in main
    cli()
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/cli/cli_common.py", line 150, in wrap_callback_calling
    callback(service_provider=service_provider, **kwargs)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/cli/backup.py", line 46, in backup
    backup_client.backup(full=full, backup_directory=backup_directory, progress_callback=update_bar)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 60, in backup
    with self.device_link(backup_directory) as dl, \
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 367, in device_link
    dl.disconnect()
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 191, in disconnect
    self.service.send_plist(['DLMessageDisconnect', '___EmptyParameterString___'])
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 183, in send_plist
    return self.sendall(build_plist(d, endianity, fmt))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 126, in sendall
    raise ConnectionTerminatedError from e
pymobiledevice3.exceptions.ConnectionTerminatedError
doronz88 commented 2 weeks ago

That probably won't be too easy to figure out. Maybe you can try to perform the backup on one terminal, while the other performs the following:

pymobiledevice3 syslog live -mi backup

This could provide useful hints arround what happened when the error occurred.

exculibar commented 2 weeks ago

That probably won't be too easy to figure out. Maybe you can try to perform the backup on one terminal, while the other performs the following:

pymobiledevice3 syslog live -mi backup

This could provide useful hints arround what happened when the error occurred.

I had a similar problem when I executed the backup2 command using a wifi connection. (The syslog can not found any error)

First, watching the syslog image

Then, execute backup image

But, when I filter the error log in syslog, these following lines be print

2024-08-27 13:53:58.954690 remoted{Network}[51] <ERROR>: nw_path_necp_check_for_updates Failed to copy updated result (22)
2024-08-27 13:53:59.058468 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.073090 CommCenter{CommCenter}[94] <ERROR>: Unknown device type.
2024-08-27 13:53:59.073771 CommCenter{CommCenter}[94] <ERROR>: Unknown device type.
2024-08-27 13:53:59.074550 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.083503 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.395532 remotepairingdeviced{remotepairingdeviced}[404] <ERROR>: Pairing deletion failed with error: <private>
2024-08-27 13:53:59.500675 remoted{Network}[51] <ERROR>: [C125 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.500976 remoted{Network}[51] <ERROR>: [C125 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.502799 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.503076 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.503489 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.505273 remoted{RemoteXPC}[51] <NOTICE>: [0x3a00fcf00] Cancel complete, delivering XPC_ERROR_CONNECTION_INVALID
2024-08-27 13:53:59.505894 remoted{Network}[51] <ERROR>: nw_socket_handle_socket_event <private> Socket SO_ERROR [54: Connection reset by peer]

Other command on wifi is well image

doronz88 commented 2 weeks ago

Technically the remoted and lockdownd are two completely different protocol stacks so lets keep the focus on the lockdown connection. The attached syslog are non relevant for lockdownd